JakeHillion/storj
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

{certificates,pkg/rpcstatus}: improve error logging (#3475)

Browse Source
This commit is contained in:
Bryan White 2019-11-13 11:07:21 +01:00 committed by Fadila
parent a72bf6c254
commit 4c822b630d
9 changed files with 316 additions and 109 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

8
certificate/authorization/authorizations.go
View File

@ -39,14 +39,8 @@ var (
mon = monkit.Package()
// Error is used when an error occurs involving an authorization.
Error = errs.Class("authorization error")
// ErrDB is used when an error occurs involving the authorization database.
ErrDB = errs.Class("authorization db error")
// ErrInvalidToken is used when a token is invalid.
ErrInvalidToken = errs.Class("invalid token error")
// ErrCount is used when attempting to create an invalid number of authorizations.
ErrCount = ErrDB.New("cannot add less than one authorizations")
// ErrEmptyUserID is used when a user ID is required but not provided.
ErrEmptyUserID = ErrDB.New("userID cannot be empty")
ErrInvalidToken = errs.Class("authorization token error")
)
// Group is a slice of authorizations for convenient de/serialization.

75
certificate/authorization/db.go
View File

@ -18,6 +18,23 @@ import (
"storj.io/storj/storage/redis"
)
var (
// ErrDB is used when an error occurs involving the authorization database.
ErrDB = errs.Class("authorization db error")
// ErrEmptyUserID is used when a user ID is required but not provided.
ErrEmptyUserID = ErrDB.New("userID cannot be empty")
// ErrCount is used when attempting to create an invalid number of authorizations.
ErrCount = ErrDB.New("cannot add less than one authorization")
// ErrInvalidClaim is used when a claim is invalid due to some user input.
ErrInvalidClaim = errs.Class("authorization claim error")
// ErrAlreadyClaimed is used when a valid claim is attempted with a token that's been used already.
ErrAlreadyClaimed = errs.Class("authorization already claimed")
// ErrNotFound is used when there is no matching authorization in the DB for a given userID and token.
ErrNotFound = errs.Class("authorization not found")
// ErrDBInternal is used when an internal error occurs involving the authorization database.
ErrDBInternal = errs.Class("internal authorization db error")
)
// DB stores authorizations which may be claimed in exchange for a
// certificate signature.
type DB struct {
@ -85,27 +102,20 @@ func (authDB *DB) Close() error {
func (authDB *DB) Create(ctx context.Context, userID string, count int) (_ Group, err error) {
defer mon.Task()(&ctx, userID, count)(&err)
if len(userID) == 0 {
return nil, ErrDB.Wrap(ErrEmptyUserID)
return nil, ErrEmptyUserID
}
if count < 1 {
return nil, ErrDB.Wrap(ErrCount)
return nil, ErrCount
}
var (
newAuths Group
authErrs errs.Group
)
var newAuths Group
for i := 0; i < count; i++ {
auth, err := NewAuthorization(userID)
if err != nil {
authErrs.Add(err)
continue
return nil, ErrDBInternal.Wrap(err)
}
newAuths = append(newAuths, auth)
}
if authErrs.Err() != nil {
return nil, ErrDB.Wrap(authErrs.Err())
}
if err := authDB.add(ctx, userID, newAuths); err != nil {
return nil, err
@ -118,8 +128,11 @@ func (authDB *DB) Create(ctx context.Context, userID string, count int) (_ Group
func (authDB *DB) Get(ctx context.Context, userID string) (_ Group, err error) {
defer mon.Task()(&ctx, userID)(&err)
authsBytes, err := authDB.db.Get(ctx, storage.Key(userID))
if err != nil && !storage.ErrKeyNotFound.Has(err) {
return nil, ErrDB.Wrap(err)
if storage.ErrKeyNotFound.Has(err) {
return nil, ErrNotFound.New("userID: %s", userID)
}
if err != nil {
return nil, ErrDBInternal.Wrap(err)
}
if authsBytes == nil {
return nil, nil
@ -127,7 +140,7 @@ func (authDB *DB) Get(ctx context.Context, userID string) (_ Group, err error) {
var auths Group
if err := auths.Unmarshal(authsBytes); err != nil {
return nil, ErrDB.Wrap(err)
return nil, ErrDBInternal.Wrap(err)
}
return auths, nil
}
@ -144,7 +157,7 @@ func (authDB *DB) UserIDs(ctx context.Context) (userIDs []string, err error) {
}
return nil
})
return userIDs, err
return userIDs, ErrDBInternal.Wrap(err)
}
// List returns all authorizations in the database.
@ -162,9 +175,9 @@ func (authDB *DB) List(ctx context.Context) (auths Group, err error) {
}
auths = append(auths, nextAuths...)
}
return listErrs.Err()
return ErrDBInternal.Wrap(listErrs.Err())
})
return auths, err
return auths, ErrDBInternal.Wrap(err)
}
// Claim marks an authorization as claimed and records claim information.
@ -174,26 +187,26 @@ func (authDB *DB) Claim(ctx context.Context, opts *ClaimOpts) (err error) {
reqTime := time.Unix(opts.Req.Timestamp, 0)
if (now.Sub(reqTime) > MaxClockSkew) ||
(reqTime.Sub(now) > MaxClockSkew) {
return Error.New("claim timestamp is outside of max delay window: %d", opts.Req.Timestamp)
return ErrInvalidClaim.New("claim timestamp is outside of max skew window: %d", opts.Req.Timestamp)
}
ident, err := identity.PeerIdentityFromPeer(opts.Peer)
if err != nil {
return err
return ErrDBInternal.Wrap(err)
}
peerDifficulty, err := ident.ID.Difficulty()
if err != nil {
return err
return ErrDBInternal.Wrap(err)
}
if peerDifficulty < opts.MinDifficulty {
return Error.New("difficulty must be greater than: %d", opts.MinDifficulty)
return ErrInvalidClaim.New("difficulty must be greater than: %d", opts.MinDifficulty)
}
token, err := ParseToken(opts.Req.AuthToken)
if err != nil {
return err
return ErrInvalidClaim.Wrap(err)
}
auths, err := authDB.Get(ctx, token.UserID)
@ -201,10 +214,12 @@ func (authDB *DB) Claim(ctx context.Context, opts *ClaimOpts) (err error) {
return err
}
foundMatch := false
for i, auth := range auths {
if auth.Token.Equal(token) {
foundMatch = true
if auth.Claim != nil {
return Error.New("authorization has already been claimed: %s", auth.String())
return ErrAlreadyClaimed.New("%s", auth.String())
}
auths[i] = &Authorization{
@ -222,6 +237,12 @@ func (authDB *DB) Claim(ctx context.Context, opts *ClaimOpts) (err error) {
break
}
}
if !foundMatch {
tokenFmt := Authorization{
Token: *token,
}
return ErrNotFound.New("%s", tokenFmt.String())
}
mon.Meter("authorization_claim").Mark(1)
return nil
@ -246,7 +267,7 @@ func (authDB *DB) Unclaim(ctx context.Context, authToken string) (err error) {
return authDB.put(ctx, token.UserID, auths)
}
}
mon.Meter("authorization_claim").Mark(1)
mon.Meter("authorization_unclaim").Mark(1)
return errs.New("token not found in authorizations DB")
}
@ -254,7 +275,7 @@ func (authDB *DB) add(ctx context.Context, userID string, newAuths Group) (err e
defer mon.Task()(&ctx, userID)(&err)
auths, err := authDB.Get(ctx, userID)
if err != nil {
if err != nil && !ErrNotFound.Has(err) {
return err
}
@ -267,11 +288,11 @@ func (authDB *DB) put(ctx context.Context, userID string, auths Group) (err erro
authsBytes, err := auths.Marshal()
if err != nil {
return ErrDB.Wrap(err)
return ErrDBInternal.Wrap(err)
}
if err := authDB.db.Put(ctx, storage.Key(userID), authsBytes); err != nil {
return ErrDB.Wrap(err)
return ErrDBInternal.Wrap(err)
}
return nil
}

117
certificate/authorization/db_test.go
View File

@ -65,32 +65,21 @@ func TestAuthorizationDB_Create(t *testing.T) {
incCount,
newCount,
endCount int
errClass *errs.Class
err error
}{
{
"first authorization",
"user1@mail.test",
0, 1, 1, 1,
nil, nil,
},
{
"second authorization",
"user1@mail.test",
1, 2, 2, 3,
nil, nil,
},
{
"large authorization",
"user2@mail.test",
0, 5, 5, 5,
nil, nil,
},
{
"authorization error",
"user2@mail.test",
5, -1, 0, 5,
&ErrDB, ErrCount,
},
}
@ -101,7 +90,7 @@ func TestAuthorizationDB_Create(t *testing.T) {
if testCase.startCount == 0 {
_, err := authDB.db.Get(ctx, emailKey)
assert.Error(t, err)
require.Error(t, err, ErrNotFound)
} else {
v, err := authDB.db.Get(ctx, emailKey)
require.NoError(t, err)
@ -114,25 +103,56 @@ func TestAuthorizationDB_Create(t *testing.T) {
}
expectedAuths, err := authDB.Create(ctx, testCase.email, testCase.incCount)
if testCase.errClass != nil {
assert.True(t, testCase.errClass.Has(err))
}
if testCase.err != nil {
assert.Equal(t, testCase.err, err)
}
if testCase.errClass == nil && testCase.err == nil {
assert.NoError(t, err)
}
assert.Len(t, expectedAuths, testCase.newCount)
require.NoError(t, err)
require.Len(t, expectedAuths, testCase.newCount)
v, err := authDB.db.Get(ctx, emailKey)
assert.NoError(t, err)
assert.NotEmpty(t, v)
require.NoError(t, err)
require.NotEmpty(t, v)
var actualAuths Group
err = actualAuths.Unmarshal(v)
assert.NoError(t, err)
assert.Len(t, actualAuths, testCase.endCount)
require.NoError(t, err)
require.Len(t, actualAuths, testCase.endCount)
})
}
}
func TestAuthorizationDB_Create_error(t *testing.T) {
ctx := testcontext.New(t)
defer ctx.Cleanup()
authDB := newTestAuthDB(t, ctx)
defer ctx.Check(authDB.Close)
cases := []struct {
testID,
email string
count int
errClass *errs.Class
err error
}{
{
"empty userID",
"", 1,
&ErrDB,
ErrEmptyUserID,
},
{
"negative count",
"user@mail.test", -1,
&ErrDB,
ErrCount,
},
}
for _, c := range cases {
testCase := c
t.Run(c.testID, func(t *testing.T) {
auths, err := authDB.Create(ctx, testCase.email, testCase.count)
assert.Truef(t, testCase.errClass.Has(err), "error: %s", err)
assert.Equal(t, testCase.err, err)
assert.Empty(t, auths)
})
}
}
@ -157,35 +177,20 @@ func TestAuthorizationDB_Get(t *testing.T) {
err = authDB.db.Put(ctx, storage.Key("user@mail.test"), authsBytes)
require.NoError(t, err)
cases := []struct {
testID,
email string
result Group
}{
{
"Non-existent email",
"nouser@mail.test",
nil,
},
{
"Existing email",
"user@mail.test",
expectedAuths,
},
{
t.Log("Non-existent email")
auths, err := authDB.Get(ctx, "nouser@mail.test")
require.Error(t, err, ErrNotFound)
require.Empty(t, auths)
}
for _, c := range cases {
testCase := c
t.Run(testCase.testID, func(t *testing.T) {
auths, err := authDB.Get(ctx, testCase.email)
require.NoError(t, err)
if testCase.result != nil {
assert.NotEmpty(t, auths)
assert.Len(t, auths, len(testCase.result))
} else {
assert.Empty(t, auths)
}
})
{
t.Log("Existing email")
auths, err := authDB.Get(ctx, "user@mail.test")
require.NoError(t, err)
assert.NotEmpty(t, auths)
assert.Len(t, auths, len(expectedAuths))
assert.Equal(t, expectedAuths, auths)
}
}
@ -315,7 +320,7 @@ func TestAuthorizationDB_Claim_Invalid(t *testing.T) {
MinDifficulty: difficulty2,
})
if assert.Error(t, err) {
assert.True(t, Error.Has(err))
assert.True(t, ErrAlreadyClaimed.Has(err))
// NB: token string shouldn't leak into error message
assert.NotContains(t, err.Error(), auths[claimedIndex].Token.String())
}
@ -344,7 +349,7 @@ func TestAuthorizationDB_Claim_Invalid(t *testing.T) {
MinDifficulty: difficulty2,
})
if assert.Error(t, err) {
assert.True(t, Error.Has(err))
assert.True(t, ErrInvalidClaim.Has(err))
// NB: token string shouldn't leak into error message
assert.NotContains(t, err.Error(), auths[unclaimedIndex].Token.String())
}
@ -368,7 +373,7 @@ func TestAuthorizationDB_Claim_Invalid(t *testing.T) {
MinDifficulty: difficulty2 + 1,
})
if assert.Error(t, err) {
assert.True(t, Error.Has(err))
assert.True(t, ErrInvalidClaim.Has(err))
// NB: token string shouldn't leak into error message
assert.NotContains(t, err.Error(), auths[unclaimedIndex].Token.String())
}

2
certificate/authorization/service.go
View File

@ -39,7 +39,7 @@ func (service *Service) GetOrCreate(ctx context.Context, userID string) (_ *Toke
}
existingGroup, err := service.db.Get(ctx, userID)
if err != nil {
if err != nil && !ErrNotFound.Has(err) {
msg := "error getting authorizations"
err = ErrService.Wrap(err)
service.log.Error(msg, zap.Error(err))

2
certificate/authorization/service_test.go
View File

@ -25,7 +25,7 @@ func TestService_GetOrCreate(t *testing.T) {
{ // new user, no existing authorization tokens (create)
userID := "new@mail.test"
group, err := authorizationDB.Get(ctx, userID)
require.NoError(t, err)
require.Error(t, err, ErrNotFound)
require.Empty(t, group)
token, err := service.GetOrCreate(ctx, userID)

36
certificate/endpoint.go
View File

@ -9,6 +9,7 @@ import (
"go.uber.org/zap"
"storj.io/storj/certificate/authorization"
"storj.io/storj/internal/errs2"
"storj.io/storj/pkg/identity"
"storj.io/storj/pkg/pb"
"storj.io/storj/pkg/rpc/rpcpeer"
@ -17,6 +18,7 @@ import (
// Endpoint implements pb.CertificatesServer.
type Endpoint struct {
sanitizer *errs2.LoggingSanitizer
log *zap.Logger
ca *identity.FullCertificateAuthority
authorizationDB *authorization.DB
@ -25,7 +27,16 @@ type Endpoint struct {
// NewEndpoint creates a new certificate signing gRPC server.
func NewEndpoint(log *zap.Logger, ca *identity.FullCertificateAuthority, authorizationDB *authorization.DB, minDifficulty uint16) *Endpoint {
codeMap := errs2.CodeMap{
&authorization.ErrNotFound: rpcstatus.Unauthenticated,
&authorization.ErrInvalidClaim: rpcstatus.InvalidArgument,
&authorization.ErrInvalidToken: rpcstatus.InvalidArgument,
&authorization.ErrAlreadyClaimed: rpcstatus.AlreadyExists,
}
sanitizer := errs2.NewLoggingSanitizer(&Error, log, codeMap)
return &Endpoint{
sanitizer: sanitizer,
log: log,
ca: ca,
authorizationDB: authorizationDB,
@ -40,22 +51,19 @@ func (endpoint Endpoint) Sign(ctx context.Context, req *pb.SigningRequest) (_ *p
peer, err := rpcpeer.FromContext(ctx)
if err != nil {
msg := "error getting peer from context"
endpoint.log.Error(msg, zap.Error(err))
return nil, internalErr(msg)
return nil, endpoint.sanitizer.Error(msg, err)
}
peerIdent, err := identity.PeerIdentityFromPeer(peer)
if err != nil {
msg := "error getting peer identity"
endpoint.log.Error(msg, zap.Error(err))
return nil, internalErr(msg)
return nil, endpoint.sanitizer.Error(msg, err)
}
signedPeerCA, err := endpoint.ca.Sign(peerIdent.CA)
if err != nil {
msg := "error signing peer CA"
endpoint.log.Error(msg, zap.Error(err))
return nil, internalErr(msg)
return nil, endpoint.sanitizer.Error(msg, err)
}
signedChainBytes := [][]byte{signedPeerCA.Raw, endpoint.ca.Cert.Raw}
@ -67,19 +75,19 @@ func (endpoint Endpoint) Sign(ctx context.Context, req *pb.SigningRequest) (_ *p
MinDifficulty: endpoint.minDifficulty,
})
if err != nil {
endpoint.log.Error(zap.Error(err).String)
return nil, internalErr(zap.Error(err).String)
msg := "error claiming authorization"
return nil, endpoint.sanitizer.Error(msg, err)
}
difficulty, err := peerIdent.ID.Difficulty()
if err != nil {
endpoint.log.Error(zap.Error(err).String)
return nil, internalErr(zap.Error(err).String)
msg := "error checking difficulty"
return nil, endpoint.sanitizer.Error(msg, err)
}
token, err := authorization.ParseToken(req.AuthToken)
if err != nil {
endpoint.log.Error(zap.Error(err).String)
return nil, internalErr(zap.Error(err).String)
msg := "error parsing auth token"
return nil, endpoint.sanitizer.Error(msg, err)
}
tokenFormatter := authorization.Authorization{
Token: *token,
@ -94,7 +102,3 @@ func (endpoint Endpoint) Sign(ctx context.Context, req *pb.SigningRequest) (_ *p
Chain: signedChainBytes,
}, nil
}
func internalErr(msg string) error {
return rpcstatus.Error(rpcstatus.Internal, Error.New(msg).Error())
}

2
cmd/identity/main.go
View File

@ -210,7 +210,7 @@ func cmdAuthorize(cmd *cobra.Command, args []string) (err error) {
signedChainBytes, err := client.Sign(ctx, authToken)
if err != nil {
return errs.New("error occurred while signing certificate: %s\n(identity files were still generated and saved, if you try again existing files will be loaded)", err)
return err
}
signedChain, err := pkcrypto.CertsFromDER(signedChainBytes)

52
internal/errs2/sanatizer.go Normal file
View File

@ -0,0 +1,52 @@
// Copyright (C) 2019 Storj Labs, Inc.
// See LICENSE for copying information.
package errs2
import (
"github.com/zeebo/errs"
"go.uber.org/zap"
"storj.io/storj/pkg/rpc/rpcstatus"
)
// CodeMap is used to apply the correct rpc status code to error classes.
type CodeMap map[*errs.Class]rpcstatus.StatusCode
// LoggingSanitizer consolidates logging of original errors with sanitization of internal errors.
type LoggingSanitizer struct {
wrapper *errs.Class
log *zap.Logger
codeMap CodeMap
}
// NewLoggingSanitizer creates a new LoggingSanitizer.
func NewLoggingSanitizer(wrapper *errs.Class, log *zap.Logger, codeMap CodeMap) *LoggingSanitizer {
return &LoggingSanitizer{
wrapper: wrapper,
log: log,
codeMap: codeMap,
}
}
// Error logs the message and error to the logger and returns the sanitized error.
func (sanitizer *LoggingSanitizer) Error(msg string, err error) error {
if sanitizer.wrapper != nil {
err = sanitizer.wrapper.Wrap(err)
}
if sanitizer.log != nil {
sanitizer.log.Error(msg, zap.Error(err))
}
for errClass, code := range sanitizer.codeMap {
if errClass.Has(err) {
return rpcstatus.Error(code, err.Error())
}
}
if sanitizer.wrapper == nil {
return rpcstatus.Error(rpcstatus.Internal, msg)
}
return rpcstatus.Error(rpcstatus.Internal, sanitizer.wrapper.New(msg).Error())
}

131
internal/errs2/sanitizer_test.go Normal file
View File

@ -0,0 +1,131 @@
// Copyright (C) 2019 Storj Labs, Inc.
// See LICENSE for copying information.
package errs2
import (
"fmt"
"io/ioutil"
"os"
"strings"
"testing"
"github.com/stretchr/testify/require"
"github.com/zeebo/errs"
"go.uber.org/zap"
"storj.io/storj/internal/testcontext"
"storj.io/storj/pkg/rpc/rpcstatus"
)
func TestLoggingSanitizer_Error(t *testing.T) {
ctx := testcontext.New(t)
defer ctx.Cleanup()
logPath := ctx.File("log")
logFile, err := os.Create(logPath)
require.NoError(t, err)
defer ctx.Check(logFile.Close)
wrapper := errs.Class("wrapper class")
unauthenticatedClass := errs.Class("unauthorized class")
notFoundClass := errs.Class("not found class")
internalClass := errs.Class("internal class")
internalErr := internalClass.New("internal error")
msg := "message"
codeMap := CodeMap{
&unauthenticatedClass: rpcstatus.Unauthenticated,
&notFoundClass: rpcstatus.NotFound,
}
testLogConfig := zap.NewDevelopmentConfig()
testLogConfig.OutputPaths = []string{logPath}
testLog, err := testLogConfig.Build()
require.NoError(t, err)
scenarios := []struct {
name string
wrapper *errs.Class
log *zap.Logger
}{
{
"with wrapper and log",
&wrapper,
testLog,
},
{
"with wrapper, no log",
&wrapper,
nil,
},
{
"with log, no wrapper",
nil,
testLog,
},
{
"no wrapper or log",
nil,
nil,
},
}
for _, s := range scenarios {
s := s
t.Run(s.name, func(t *testing.T) {
sanitizer := NewLoggingSanitizer(s.wrapper, s.log, codeMap)
t.Log("exposed errors")
for errClass, code := range codeMap {
errInstance := errClass.New("%s", strings.Replace(string(*errClass), "class", "error", 1))
sanitizedErr := sanitizer.Error(msg, errInstance)
require.Error(t, sanitizedErr)
require.Equal(t, code, rpcstatus.Code(sanitizedErr))
require.Contains(t, sanitizedErr.Error(), *errClass)
if s.wrapper == nil {
require.Contains(t, sanitizedErr.Error(), errInstance.Error())
} else {
require.Contains(t, sanitizedErr.Error(), wrapper.Wrap(errInstance).Error())
}
if s.log != nil {
logData, err := ioutil.ReadAll(logFile)
require.NoError(t, err)
logStr := string(logData)
require.Contains(t, logStr, msg)
if s.wrapper == nil {
require.Contains(t, logStr, fmt.Sprintf(`"error": "%s"`, errInstance))
} else {
require.Contains(t, logStr, fmt.Sprintf(`"error": "%s: %s"`, wrapper, errInstance))
}
}
}
t.Log("internal error")
sanitizedErr := sanitizer.Error(msg, internalErr)
require.Error(t, sanitizedErr)
require.Equal(t, rpcstatus.Internal, rpcstatus.Code(sanitizedErr))
require.NotContains(t, sanitizedErr.Error(), internalClass)
if s.wrapper == nil {
require.Contains(t, sanitizedErr.Error(), msg)
} else {
require.Equal(t, wrapper.New(msg).Error(), sanitizedErr.Error())
}
if s.log != nil {
logData, err := ioutil.ReadAll(logFile)
require.NoError(t, err)
logStr := string(logData)
require.Contains(t, logStr, msg)
if s.wrapper == nil {
require.Contains(t, logStr, fmt.Sprintf(`"error": "%s"`, internalErr))
} else {
require.Contains(t, logStr, fmt.Sprintf(`"error": "%s: %s"`, wrapper, internalErr))
}
}
})
}
}