From 40f71acdda7c2caf46df4d4bf6edc357f4177cb0 Mon Sep 17 00:00:00 2001 From: Leigh McCulloch Date: Fri, 8 May 2020 15:58:42 -0700 Subject: [PATCH] exp/services/recoverysigner: add basic logs (#2567) ### What Add basic logs for each action the service can perform that describe what's happening to help with identifying issues. Also fixes logs so that all existing logs carry the request ID and account ID for the current request. ### Why This is a young service and we're likely to run into issues that we will need logs to help us debug. --- .../internal/serve/account_delete.go | 19 ++++- .../internal/serve/account_get.go | 12 ++- .../internal/serve/account_list.go | 20 ++++- .../internal/serve/account_post.go | 18 ++++- .../internal/serve/account_put.go | 26 +++++- .../internal/serve/account_sign.go | 81 ++++++++++--------- .../internal/serve/auth/firebase.go | 14 ++++ .../internal/serve/auth/sep10.go | 6 ++ 8 files changed, 150 insertions(+), 46 deletions(-) diff --git a/exp/services/recoverysigner/internal/serve/account_delete.go b/exp/services/recoverysigner/internal/serve/account_delete.go index 1448544684..a4322882c7 100644 --- a/exp/services/recoverysigner/internal/serve/account_delete.go +++ b/exp/services/recoverysigner/internal/serve/account_delete.go @@ -37,12 +37,18 @@ func (h accountDeleteHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) return } + l := h.Logger.Ctx(ctx). + WithField("account", req.Address.Address()) + + l.Info("Request to delete account.") + acc, err := h.AccountStore.Get(req.Address.Address()) if err == account.ErrNotFound { + l.Info("Account not found.") notFound.Render(w) return } else if err != nil { - h.Logger.Error(err) + l.Error(err) serverError.Render(w) return } @@ -54,6 +60,7 @@ func (h accountDeleteHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) // Authorized if authenticated as the account. authorized := claims.Address == req.Address.Address() + l.Infof("Authorized with self: %v.", authorized) // Authorized if authenticated as an identity registered with the account. for _, i := range acc.Identities { @@ -66,27 +73,35 @@ func (h accountDeleteHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) (m.Type == account.AuthMethodTypeEmail && m.Value == claims.Email)) { respIdentity.Authenticated = true authorized = true + l.Infof("Authorized with %s.", m.Type) break } } resp.Identities = append(resp.Identities, respIdentity) } + + l.Infof("Authorized: %v.", authorized) if !authorized { notFound.Render(w) return } + l.Info("Deleting account.") + err = h.AccountStore.Delete(req.Address.Address()) if err == account.ErrNotFound { // It can happen if two authorized users are trying to delete the account at the same time. + l.Info("Account not found.") notFound.Render(w) return } else if err != nil { - h.Logger.Error(err) + l.Error("Error deleting account:", err) serverError.Render(w) return } + l.Info("Deleted account.") + httpjson.Render(w, resp, httpjson.JSON) } diff --git a/exp/services/recoverysigner/internal/serve/account_get.go b/exp/services/recoverysigner/internal/serve/account_get.go index c8e5a95169..7e00193fdc 100644 --- a/exp/services/recoverysigner/internal/serve/account_get.go +++ b/exp/services/recoverysigner/internal/serve/account_get.go @@ -37,12 +37,18 @@ func (h accountGetHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { return } + l := h.Logger.Ctx(ctx). + WithField("account", req.Address.Address()) + + l.Info("Request to get account.") + acc, err := h.AccountStore.Get(req.Address.Address()) if err == account.ErrNotFound { + l.Info("Account not found.") notFound.Render(w) return } else if err != nil { - h.Logger.Error(err) + l.Error(err) serverError.Render(w) return } @@ -54,6 +60,7 @@ func (h accountGetHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { // Authorized if authenticated as the account. authorized := claims.Address == req.Address.Address() + l.Infof("Authorized with self: %v.", authorized) // Authorized if authenticated as an identity registered with the account. for _, i := range acc.Identities { @@ -66,12 +73,15 @@ func (h accountGetHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { (m.Type == account.AuthMethodTypeEmail && m.Value == claims.Email)) { respIdentity.Authenticated = true authorized = true + l.Infof("Authorized with %s.", m.Type) break } } resp.Identities = append(resp.Identities, respIdentity) } + + l.Infof("Authorized: %v.", authorized) if !authorized { notFound.Render(w) return diff --git a/exp/services/recoverysigner/internal/serve/account_list.go b/exp/services/recoverysigner/internal/serve/account_list.go index 40fefd12e2..eefe50bbea 100644 --- a/exp/services/recoverysigner/internal/serve/account_list.go +++ b/exp/services/recoverysigner/internal/serve/account_list.go @@ -29,6 +29,10 @@ func (h accountListHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { return } + l := h.Logger.Ctx(ctx) + + l.Info("Request to get accounts.") + resp := accountListResponse{ Accounts: []accountResponse{}, } @@ -40,7 +44,7 @@ func (h accountListHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { if err == account.ErrNotFound { // Do nothing. } else if err != nil { - h.Logger.Error(err) + l.Error(err) serverError.Render(w) return } else { @@ -55,12 +59,15 @@ func (h accountListHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { accResp.Identities = append(accResp.Identities, accRespIdentity) } resp.Accounts = append(resp.Accounts, accResp) + l.WithField("account", acc.Address). + WithField("auth_method_type", account.AuthMethodTypeAddress). + Info("Found account with auth method type as self.") } // Find accounts that have the address listed as an owner or other identity. accs, err := h.AccountStore.FindWithIdentityAddress(claims.Address) if err != nil { - h.Logger.Error(err) + l.Error(err) serverError.Render(w) return } @@ -82,6 +89,9 @@ func (h accountListHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { accResp.Identities = append(accResp.Identities, accRespIdentity) } resp.Accounts = append(resp.Accounts, accResp) + l.WithField("account", acc.Address). + WithField("auth_method_type", account.AuthMethodTypeAddress). + Info("Found account with auth method type as identity.") } } @@ -111,6 +121,9 @@ func (h accountListHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { accResp.Identities = append(accResp.Identities, accRespIdentity) } resp.Accounts = append(resp.Accounts, accResp) + l.WithField("account", acc.Address). + WithField("auth_method_type", account.AuthMethodTypePhoneNumber). + Info("Found account with auth method type as identity.") } } @@ -140,6 +153,9 @@ func (h accountListHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { accResp.Identities = append(accResp.Identities, accRespIdentity) } resp.Accounts = append(resp.Accounts, accResp) + l.WithField("account", acc.Address). + WithField("auth_method_type", account.AuthMethodTypeEmail). + Info("Found account with auth method type as identity.") } } diff --git a/exp/services/recoverysigner/internal/serve/account_post.go b/exp/services/recoverysigner/internal/serve/account_post.go index 019206c69c..36119afaae 100644 --- a/exp/services/recoverysigner/internal/serve/account_post.go +++ b/exp/services/recoverysigner/internal/serve/account_post.go @@ -86,16 +86,25 @@ func (h accountPostHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { return } + l := h.Logger.Ctx(ctx). + WithField("account", req.Address.Address()) + + l.Info("Request to register account.") + if req.Address.Address() != claims.Address { + l.WithField("address", claims.Address). + Info("Not authorized as self, authorized as other address.") unauthorized.Render(w) return } if req.Validate() != nil { + l.Info("Request validation failed.") badRequest.Render(w) return } + authMethodCount := 0 acc := account.Account{ Address: req.Address.Address(), Identities: []account.Identity{}, @@ -109,20 +118,27 @@ func (h accountPostHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { Type: account.AuthMethodType(m.Type), Value: m.Value, }) + authMethodCount++ } acc.Identities = append(acc.Identities, accIdentity) } + l = l. + WithField("identities_count", len(acc.Identities)). + WithField("auth_methods_count", authMethodCount) err = h.AccountStore.Add(acc) if err == account.ErrAlreadyExists { + l.Info("Account already registered.") conflict.Render(w) return } else if err != nil { - h.Logger.Error(err) + l.Error(err) serverError.Render(w) return } + l.Info("Account registered.") + resp := accountResponse{ Address: acc.Address, Signer: h.SigningAddress.Address(), diff --git a/exp/services/recoverysigner/internal/serve/account_put.go b/exp/services/recoverysigner/internal/serve/account_put.go index 2055a6f355..c817d57cd0 100644 --- a/exp/services/recoverysigner/internal/serve/account_put.go +++ b/exp/services/recoverysigner/internal/serve/account_put.go @@ -81,23 +81,36 @@ func (h accountPutHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { req := accountPutRequest{} err := httpdecode.Decode(r, &req) - if err != nil || req.Address == nil || req.Validate() != nil { + if err != nil || req.Address == nil { + badRequest.Render(w) + return + } + + l := h.Logger.Ctx(ctx). + WithField("account", req.Address.Address()) + + l.Info("Request to update account.") + + if req.Validate() != nil { + l.Info("Request validation failed.") badRequest.Render(w) return } acc, err := h.AccountStore.Get(req.Address.Address()) if err == account.ErrNotFound { + l.Info("Account not found.") notFound.Render(w) return } else if err != nil { - h.Logger.Error(err) + l.Error(err) serverError.Render(w) return } // Authorized if authenticated as the account. authorized := claims.Address == req.Address.Address() + l.Infof("Authorized with self: %v.", authorized) // Authorized if authenticated as an identity registered with the account. for _, i := range acc.Identities { @@ -106,6 +119,7 @@ func (h accountPutHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { (m.Type == account.AuthMethodTypePhoneNumber && m.Value == claims.PhoneNumber) || (m.Type == account.AuthMethodTypeEmail && m.Value == claims.Email)) { authorized = true + l.Infof("Authorized with %s.", m.Type) break } } @@ -115,6 +129,7 @@ func (h accountPutHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { return } + authMethodCount := 0 accWithNewIdentiies := account.Account{ Address: req.Address.Address(), Identities: []account.Identity{}, @@ -128,13 +143,18 @@ func (h accountPutHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { Type: account.AuthMethodType(m.Type), Value: m.Value, }) + authMethodCount++ } accWithNewIdentiies.Identities = append(accWithNewIdentiies.Identities, accIdentity) } + l = l. + WithField("identities_count", len(accWithNewIdentiies.Identities)). + WithField("auth_methods_count", authMethodCount) err = h.AccountStore.Update(accWithNewIdentiies) if err == account.ErrNotFound { // It can happen if another authorized user is trying to delete the account at the same time. + l.Info("Account not found.") notFound.Render(w) return } else if err != nil { @@ -143,6 +163,8 @@ func (h accountPutHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { return } + l.Info("Account updated.") + resp := accountResponse{ Address: accWithNewIdentiies.Address, Signer: h.SigningAddress.Address(), diff --git a/exp/services/recoverysigner/internal/serve/account_sign.go b/exp/services/recoverysigner/internal/serve/account_sign.go index 99b7138233..8f2f8f1f1d 100644 --- a/exp/services/recoverysigner/internal/serve/account_sign.go +++ b/exp/services/recoverysigner/internal/serve/account_sign.go @@ -48,55 +48,42 @@ func (h accountSignHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { return } + l := h.Logger.Ctx(ctx). + WithField("account", req.Address.Address()) + + l.Info("Request to sign transaction.") + // Find the account that the request is for. acc, err := h.AccountStore.Get(req.Address.Address()) if err == account.ErrNotFound { + l.Info("Account not found.") notFound.Render(w) return } else if err != nil { + l.Error(err) serverError.Render(w) return } - // Verify that the authenticated client has access to the account. - addressAuthenticated := false - if claims.Address != "" { - if claims.Address == acc.Address { - addressAuthenticated = true - } else { - for _, i := range acc.Identities { - for _, m := range i.AuthMethods { - if m.Type == account.AuthMethodTypeAddress && m.Value == claims.Address { - addressAuthenticated = true - break - } - } - } - } - } - phoneNumberAuthenticated := false - if claims.PhoneNumber != "" { - for _, i := range acc.Identities { - for _, m := range i.AuthMethods { - if m.Type == account.AuthMethodTypePhoneNumber && m.Value == claims.PhoneNumber { - phoneNumberAuthenticated = true - break - } - } - } - } - emailAuthenticated := false - if claims.Email != "" { - for _, i := range acc.Identities { - for _, m := range i.AuthMethods { - if m.Type == account.AuthMethodTypeEmail && m.Value == claims.Email { - emailAuthenticated = true - break - } + // Authorized if authenticated as the account. + authorized := claims.Address == req.Address.Address() + l.Infof("Authorized with self: %v.", authorized) + + // Authorized if authenticated as an identity registered with the account. + for _, i := range acc.Identities { + for _, m := range i.AuthMethods { + if m.Value != "" && ((m.Type == account.AuthMethodTypeAddress && m.Value == claims.Address) || + (m.Type == account.AuthMethodTypePhoneNumber && m.Value == claims.PhoneNumber) || + (m.Type == account.AuthMethodTypeEmail && m.Value == claims.Email)) { + authorized = true + l.Infof("Authorized with %s.", m.Type) + break } } } - if !addressAuthenticated && !phoneNumberAuthenticated && !emailAuthenticated { + + l.Infof("Authorized: %v.", authorized) + if !authorized { notFound.Render(w) return } @@ -104,18 +91,32 @@ func (h accountSignHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { // Decode the request transaction. parsed, err := txnbuild.TransactionFromXDR(req.Transaction) if err != nil { + l.WithField("transaction", req.Transaction). + Info("Parsing transaction failed.") badRequest.Render(w) return } tx, ok := parsed.Transaction() if !ok { + l.Info("Transaction is not a simple transaction.") badRequest.Render(w) return } + hashHex, err := tx.HashHex(h.NetworkPassphrase) + if err != nil { + l.Error("Error hashing transaction:", err) + serverError.Render(w) + return + } + + l = l.WithField("transaction_hash", hashHex) + + l.Info("Signing transaction.") // Check that the transaction's source account and any operations it // contains references only to this account. if tx.SourceAccount().AccountID != req.Address.Address() { + l.Info("Transaction's source account is not the account in the request.") badRequest.Render(w) return } @@ -125,6 +126,7 @@ func (h accountSignHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { continue } if op.GetSourceAccount().GetAccountID() != req.Address.Address() { + l.Info("Operation's source account is not the account.") badRequest.Render(w) return } @@ -133,16 +135,19 @@ func (h accountSignHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { // Sign the transaction. hash, err := tx.Hash(h.NetworkPassphrase) if err != nil { - h.Logger.Error(err) + l.Error("Error hashing transaction:", err) serverError.Render(w) return } sig, err := h.SigningKey.SignBase64(hash[:]) if err != nil { - h.Logger.Error(err) + l.Error("Error signing transaction:", err) serverError.Render(w) return } + + l.Info("Transaction signed.") + resp := accountSignResponse{ Signer: h.SigningKey.Address(), Signature: sig, diff --git a/exp/services/recoverysigner/internal/serve/auth/firebase.go b/exp/services/recoverysigner/internal/serve/auth/firebase.go index e8a2f31dee..ed55e5a0dd 100644 --- a/exp/services/recoverysigner/internal/serve/auth/firebase.go +++ b/exp/services/recoverysigner/internal/serve/auth/firebase.go @@ -3,11 +3,13 @@ package auth import ( "context" "net/http" + "strings" firebase "firebase.google.com/go" firebaseauth "firebase.google.com/go/auth" "github.com/stellar/go/support/errors" "github.com/stellar/go/support/http/httpauthz" + "github.com/stellar/go/support/log" "google.golang.org/api/option" ) @@ -31,6 +33,18 @@ func FirebaseMiddleware(v FirebaseTokenVerifier) func(http.Handler) http.Handler if emailVerified, _ := token.Claims["email_verified"].(bool); emailVerified { auth.Email, _ = token.Claims["email"].(string) } + + authTypes := []string{} + if auth.PhoneNumber != "" { + authTypes = append(authTypes, "phone_number") + } + if auth.Email != "" { + authTypes = append(authTypes, "email") + } + log.Ctx(ctx). + WithField("auth_types", strings.Join(authTypes, ", ")). + Info("Firebase JWT verified.") + ctx = NewContext(ctx, auth) r = r.WithContext(ctx) } diff --git a/exp/services/recoverysigner/internal/serve/auth/sep10.go b/exp/services/recoverysigner/internal/serve/auth/sep10.go index 0b19cfc604..5b360516fd 100644 --- a/exp/services/recoverysigner/internal/serve/auth/sep10.go +++ b/exp/services/recoverysigner/internal/serve/auth/sep10.go @@ -7,6 +7,7 @@ import ( "github.com/stellar/go/keypair" "github.com/stellar/go/support/http/httpauthz" + "github.com/stellar/go/support/log" "gopkg.in/square/go-jose.v2" "gopkg.in/square/go-jose.v2/jwt" ) @@ -19,6 +20,11 @@ func SEP10Middleware(issuer string, k jose.JSONWebKey) func(http.Handler) http.H ctx := r.Context() auth, _ := FromContext(ctx) auth.Address = address + + log.Ctx(ctx). + WithField("address", address). + Info("SEP-10 JWT verified.") + ctx = NewContext(ctx, auth) r = r.WithContext(ctx) }