From 71170e709981706250fb128281f45cde3eb19fee Mon Sep 17 00:00:00 2001 From: Samuel Hawksby-Robinson Date: Fri, 21 Oct 2022 13:15:39 +0100 Subject: [PATCH] Added comprehensive logging --- multiaccounts/database.go | 2 - server/certs.go | 2 +- server/client.go | 19 +++++---- server/components_test.go | 4 +- server/connection_test.go | 4 +- server/events.go | 2 +- server/handlers.go | 6 +-- server/payload_manager.go | 87 ++++++++++++++++++++++++++++++++++----- server/server.go | 7 +--- server/server_media.go | 14 ++++--- server/server_pairing.go | 5 ++- 11 files changed, 112 insertions(+), 40 deletions(-) diff --git a/multiaccounts/database.go b/multiaccounts/database.go index 3e2242c21..b40d6000c 100644 --- a/multiaccounts/database.go +++ b/multiaccounts/database.go @@ -4,7 +4,6 @@ import ( "context" "database/sql" "encoding/json" - "github.com/davecgh/go-spew/spew" "github.com/ethereum/go-ethereum/log" "github.com/status-im/status-go/images" @@ -80,7 +79,6 @@ func (a *Account) FromProtobuf(ma *protobuf.MultiAccount) { a.KeycardPairing = ma.KeycardPairing a.KeyUID = ma.KeyUid a.Images = identityImages - spew.Dump("Account.FromProtobuf end", ma, a) } type MultiAccountMarshaller interface { diff --git a/server/certs.go b/server/certs.go index 6add4b664..846ae1298 100644 --- a/server/certs.go +++ b/server/certs.go @@ -214,7 +214,7 @@ func getServerCert(URL *url.URL) (*x509.Certificate, error) { conn, err := tls.Dial("tcp", URL.Host, conf) if err != nil { - signal.SendLocalPairingEvent(Event{Type: EventConnectionError, Error: err}) + signal.SendLocalPairingEvent(Event{Type: EventConnectionError, Error: err.Error()}) return nil, err } defer conn.Close() diff --git a/server/client.go b/server/client.go index cbfca2e9b..57d848d26 100644 --- a/server/client.go +++ b/server/client.go @@ -14,8 +14,8 @@ import ( "net/url" "github.com/btcsuite/btcutil/base58" - "github.com/davecgh/go-spew/spew" + "github.com/status-im/status-go/logutils" "github.com/status-im/status-go/multiaccounts" "github.com/status-im/status-go/signal" ) @@ -69,7 +69,7 @@ func NewPairingClient(c *ConnectionParams, config *PairingPayloadManagerConfig) return nil, err } - pm, err := NewPairingPayloadManager(c.aesKey, config) + pm, err := NewPairingPayloadManager(c.aesKey, config, logutils.ZapLogger().Named("PairingClient")) if err != nil { return nil, err } @@ -109,12 +109,12 @@ func (c *PairingClient) sendAccountData() error { c.baseAddress.Path = pairingReceive resp, err := c.Post(c.baseAddress.String(), "application/octet-stream", bytes.NewBuffer(c.PayloadManager.ToSend())) if err != nil { - signal.SendLocalPairingEvent(Event{Type: EventTransferError, Error: err}) + signal.SendLocalPairingEvent(Event{Type: EventTransferError, Error: err.Error()}) return err } if resp.StatusCode != http.StatusOK { - signal.SendLocalPairingEvent(Event{Type: EventTransferError, Error: err}) + signal.SendLocalPairingEvent(Event{Type: EventTransferError, Error: err.Error()}) return fmt.Errorf("status not ok, received '%s'", resp.Status) } @@ -140,25 +140,26 @@ func (c *PairingClient) receiveAccountData() error { resp, err := c.Do(req) if err != nil { + signal.SendLocalPairingEvent(Event{Type: EventTransferError, Error: err.Error()}) return err } if resp.StatusCode != http.StatusOK { - signal.SendLocalPairingEvent(Event{Type: EventTransferError, Error: err}) - return fmt.Errorf("status not ok, received '%s'", resp.Status) + err = fmt.Errorf("status not ok, received '%s'", resp.Status) + signal.SendLocalPairingEvent(Event{Type: EventTransferError, Error: err.Error()}) + return err } payload, err := ioutil.ReadAll(resp.Body) if err != nil { - signal.SendLocalPairingEvent(Event{Type: EventTransferError, Error: err}) + signal.SendLocalPairingEvent(Event{Type: EventTransferError, Error: err.Error()}) return err } signal.SendLocalPairingEvent(Event{Type: EventTransferSuccess}) err = c.PayloadManager.Receive(payload) if err != nil { - spew.Dump("c.PayloadManager.Receive(payload)", err.Error()) - signal.SendLocalPairingEvent(Event{Type: EventProcessError, Error: err}) + signal.SendLocalPairingEvent(Event{Type: EventProcessError, Error: err.Error()}) return err } signal.SendLocalPairingEvent(Event{Type: EventProcessSuccess}) diff --git a/server/components_test.go b/server/components_test.go index a580a95f4..36b604086 100644 --- a/server/components_test.go +++ b/server/components_test.go @@ -13,6 +13,8 @@ import ( "github.com/btcsuite/btcutil/base58" "github.com/stretchr/testify/require" + + "github.com/status-im/status-go/logutils" ) const ( @@ -120,7 +122,7 @@ type MockEncryptOnlyPayloadManager struct { } func NewMockEncryptOnlyPayloadManager(aesKey []byte) (*MockEncryptOnlyPayloadManager, error) { - pem, err := NewPayloadEncryptionManager(aesKey) + pem, err := NewPayloadEncryptionManager(aesKey, logutils.ZapLogger()) if err != nil { return nil, err } diff --git a/server/connection_test.go b/server/connection_test.go index c966d409b..f896d245c 100644 --- a/server/connection_test.go +++ b/server/connection_test.go @@ -4,6 +4,8 @@ import ( "testing" "github.com/stretchr/testify/suite" + + "github.com/status-im/status-go/logutils" ) var ( @@ -29,7 +31,7 @@ func (s *ConnectionParamsSuite) SetupSuite() { cert, _, err := GenerateCertFromKey(s.PK, s.NotBefore, defaultIP.String()) s.Require().NoError(err) - bs := NewServer(&cert, defaultIP.String(), func(int) {}) + bs := NewServer(&cert, defaultIP.String(), nil, logutils.ZapLogger()) err = bs.SetPort(1337) s.Require().NoError(err) diff --git a/server/events.go b/server/events.go index db113f509..eceef8651 100644 --- a/server/events.go +++ b/server/events.go @@ -20,5 +20,5 @@ const ( // Event is a type for transfer events. type Event struct { Type EventType `json:"type"` - Error error `json:"error,omitempty"` + Error string `json:"error,omitempty"` } diff --git a/server/handlers.go b/server/handlers.go index 6c10dd94f..efdc05711 100644 --- a/server/handlers.go +++ b/server/handlers.go @@ -405,7 +405,7 @@ func handlePairingReceive(ps *PairingServer) http.HandlerFunc { return func(w http.ResponseWriter, r *http.Request) { payload, err := ioutil.ReadAll(r.Body) if err != nil { - signal.SendLocalPairingEvent(Event{Type: EventTransferError, Error: err}) + signal.SendLocalPairingEvent(Event{Type: EventTransferError, Error: err.Error()}) ps.logger.Error("ioutil.ReadAll(r.Body)", zap.Error(err)) return } @@ -413,7 +413,7 @@ func handlePairingReceive(ps *PairingServer) http.HandlerFunc { err = ps.PayloadManager.Receive(payload) if err != nil { - signal.SendLocalPairingEvent(Event{Type: EventProcessError, Error: err}) + signal.SendLocalPairingEvent(Event{Type: EventProcessError, Error: err.Error()}) ps.logger.Error("ps.PayloadManager.Receive(payload)", zap.Error(err)) return } @@ -429,7 +429,7 @@ func handlePairingSend(ps *PairingServer) http.HandlerFunc { w.Header().Set("Content-Type", "application/octet-stream") _, err := w.Write(ps.PayloadManager.ToSend()) if err != nil { - signal.SendLocalPairingEvent(Event{Type: EventTransferError, Error: err}) + signal.SendLocalPairingEvent(Event{Type: EventTransferError, Error: err.Error()}) ps.logger.Error("w.Write(ps.PayloadManager.ToSend())", zap.Error(err)) return } diff --git a/server/payload_manager.go b/server/payload_manager.go index cb75101e4..b9d130af8 100644 --- a/server/payload_manager.go +++ b/server/payload_manager.go @@ -8,8 +8,8 @@ import ( "os" "path/filepath" - "github.com/davecgh/go-spew/spew" "github.com/golang/protobuf/proto" + "go.uber.org/zap" "github.com/status-im/status-go/account/generator" "github.com/status-im/status-go/eth-node/keystore" @@ -44,15 +44,19 @@ type PairingPayloadManagerConfig struct { // PairingPayloadManager is responsible for the whole lifecycle of a PairingPayload type PairingPayloadManager struct { - pp *PairingPayload + logger *zap.Logger + pp *PairingPayload *PayloadEncryptionManager ppm *PairingPayloadMarshaller ppr PayloadRepository } // NewPairingPayloadManager generates a new and initialised PairingPayloadManager -func NewPairingPayloadManager(aesKey []byte, config *PairingPayloadManagerConfig) (*PairingPayloadManager, error) { - pem, err := NewPayloadEncryptionManager(aesKey) +func NewPairingPayloadManager(aesKey []byte, config *PairingPayloadManagerConfig, logger *zap.Logger) (*PairingPayloadManager, error) { + l := logger.Named("PairingPayloadManager") + l.Debug("fired", zap.Binary("aesKey", aesKey), zap.Any("config", config)) + + pem, err := NewPayloadEncryptionManager(aesKey, l) if err != nil { return nil, err } @@ -61,6 +65,7 @@ func NewPairingPayloadManager(aesKey []byte, config *PairingPayloadManagerConfig p := new(PairingPayload) return &PairingPayloadManager{ + logger: l, pp: p, PayloadEncryptionManager: pem, ppm: NewPairingPayloadMarshaller(p), @@ -70,32 +75,52 @@ func NewPairingPayloadManager(aesKey []byte, config *PairingPayloadManagerConfig // Mount loads and prepares the payload to be stored in the PairingPayloadManager's state ready for later access func (ppm *PairingPayloadManager) Mount() error { + l := ppm.logger.Named("Mount()") + l.Debug("fired") + err := ppm.ppr.LoadFromSource() if err != nil { return err } + l.Debug("after LoadFromSource") pb, err := ppm.ppm.MarshalToProtobuf() if err != nil { return err } - - spew.Dump("PairingPayloadManager.Mount()", ppm.ppm.keys, ppm.ppm.multiaccount, ppm.ppm.password, pb) + l.Debug( + "after MarshalToProtobuf", + zap.Any("ppm.ppm.keys", ppm.ppm.keys), + zap.Any("ppm.ppm.multiaccount", ppm.ppm.multiaccount), + zap.String("ppm.ppm.password", ppm.ppm.password), + zap.Binary("pb", pb), + ) return ppm.Encrypt(pb) } // Receive takes a []byte representing raw data, parses and stores the data func (ppm *PairingPayloadManager) Receive(data []byte) error { + l := ppm.logger.Named("Receive()") + l.Debug("fired") + err := ppm.Decrypt(data) if err != nil { return err } + l.Debug("after Decrypt") err = ppm.ppm.UnmarshalProtobuf(ppm.Received()) if err != nil { return err } + l.Debug( + "after UnmarshalProtobuf", + zap.Any("ppm.ppm.keys", ppm.ppm.keys), + zap.Any("ppm.ppm.multiaccount", ppm.ppm.multiaccount), + zap.String("ppm.ppm.password", ppm.ppm.password), + zap.Binary("ppm.Received()", ppm.Received()), + ) return ppm.ppr.StoreToSource() } @@ -114,20 +139,27 @@ type EncryptionPayload struct { // PayloadEncryptionManager is responsible for encrypting and decrypting payload data type PayloadEncryptionManager struct { + logger *zap.Logger aesKey []byte toSend *EncryptionPayload received *EncryptionPayload } -func NewPayloadEncryptionManager(aesKey []byte) (*PayloadEncryptionManager, error) { - return &PayloadEncryptionManager{aesKey, new(EncryptionPayload), new(EncryptionPayload)}, nil +func NewPayloadEncryptionManager(aesKey []byte, logger *zap.Logger) (*PayloadEncryptionManager, error) { + return &PayloadEncryptionManager{logger.Named("PayloadEncryptionManager"), aesKey, new(EncryptionPayload), new(EncryptionPayload)}, nil } func (pem *PayloadEncryptionManager) EncryptPlain(plaintext []byte) ([]byte, error) { + l := pem.logger.Named("EncryptPlain()") + l.Debug("fired") + return common.Encrypt(plaintext, pem.aesKey, rand.Reader) } func (pem *PayloadEncryptionManager) Encrypt(data []byte) error { + l := pem.logger.Named("Encrypt()") + l.Debug("fired") + ep, err := common.Encrypt(data, pem.aesKey, rand.Reader) if err != nil { return err @@ -135,12 +167,29 @@ func (pem *PayloadEncryptionManager) Encrypt(data []byte) error { pem.toSend.plain = data pem.toSend.encrypted = ep + + l.Debug( + "after common.Encrypt", + zap.Binary("data", data), + zap.Binary("pem.aesKey", pem.aesKey), + zap.Binary("ep", ep), + ) + return nil } func (pem *PayloadEncryptionManager) Decrypt(data []byte) error { + l := pem.logger.Named("Decrypt()") + l.Debug("fired") + pd, err := common.Decrypt(data, pem.aesKey) - spew.Dump("common.Decrypt(data, pem.aesKey)", data, pem.aesKey, pd, err) + l.Debug( + "after common.Decrypt(data, pem.aesKey)", + zap.Binary("data", data), + zap.Binary("pem.aesKey", pem.aesKey), + zap.Binary("pd", pd), + zap.Error(err), + ) if err != nil { return err } @@ -176,6 +225,7 @@ func (pp *PairingPayload) ResetPayload() { // PairingPayloadMarshaller is responsible for marshalling and unmarshalling PairingServer payload data type PairingPayloadMarshaller struct { + logger *zap.Logger *PairingPayload } @@ -200,9 +250,17 @@ func (ppm *PairingPayloadMarshaller) accountKeysToProtobuf() []*protobuf.LocalPa } func (ppm *PairingPayloadMarshaller) UnmarshalProtobuf(data []byte) error { + l := ppm.logger.Named("UnmarshalProtobuf()") + l.Debug("fired") + pb := new(protobuf.LocalPairingPayload) err := proto.Unmarshal(data, pb) - spew.Dump("protobuf.LocalPairingPayload", pb, pb.Multiaccount, pb.Keys) + l.Debug( + "after protobuf.LocalPairingPayload", + zap.Any("pb", pb), + zap.Any("pb.Multiaccount", pb.Multiaccount), + zap.Any("pb.Keys", pb.Keys), + ) if err != nil { return err } @@ -214,6 +272,9 @@ func (ppm *PairingPayloadMarshaller) UnmarshalProtobuf(data []byte) error { } func (ppm *PairingPayloadMarshaller) accountKeysFromProtobuf(pbKeys []*protobuf.LocalPairingPayload_Key) { + l := ppm.logger.Named("accountKeysFromProtobuf()") + l.Debug("fired") + if ppm.keys == nil { ppm.keys = make(map[string][]byte) } @@ -221,7 +282,11 @@ func (ppm *PairingPayloadMarshaller) accountKeysFromProtobuf(pbKeys []*protobuf. for _, key := range pbKeys { ppm.keys[key.Name] = key.Data } - spew.Dump("PairingPayloadMarshaller.accountKeysFromProtobuf", pbKeys, ppm.keys) + l.Debug( + "after for _, key := range pbKeys", + zap.Any("pbKeys", pbKeys), + zap.Any("ppm.keys", ppm.keys), + ) } func (ppm *PairingPayloadMarshaller) multiaccountFromProtobuf(pbMultiAccount *protobuf.MultiAccount) { diff --git a/server/server.go b/server/server.go index 96cdf2215..876c9f2aa 100644 --- a/server/server.go +++ b/server/server.go @@ -9,8 +9,6 @@ import ( "net/url" "go.uber.org/zap" - - "github.com/status-im/status-go/logutils" ) type Server struct { @@ -23,13 +21,12 @@ type Server struct { portManger } -func NewServer(cert *tls.Certificate, hostname string, afterPortChanged func(int)) Server { - logger := logutils.ZapLogger() +func NewServer(cert *tls.Certificate, hostname string, afterPortChanged func(int), logger *zap.Logger) Server { return Server{ logger: logger, cert: cert, hostname: hostname, - portManger: newPortManager(logger, afterPortChanged), + portManger: newPortManager(logger.Named("Server"), afterPortChanged), } } diff --git a/server/server_media.go b/server/server_media.go index e625a5d7d..8ec002be9 100644 --- a/server/server_media.go +++ b/server/server_media.go @@ -4,11 +4,10 @@ import ( "database/sql" "net/url" - "github.com/status-im/status-go/signal" - - "github.com/status-im/status-go/multiaccounts" - "github.com/status-im/status-go/ipfs" + "github.com/status-im/status-go/logutils" + "github.com/status-im/status-go/multiaccounts" + "github.com/status-im/status-go/signal" ) type MediaServer struct { @@ -27,7 +26,12 @@ func NewMediaServer(db *sql.DB, downloader *ipfs.Downloader, multiaccountsDB *mu } s := &MediaServer{ - Server: NewServer(globalCertificate, localhost, signal.SendMediaServerStarted), + Server: NewServer( + globalCertificate, + localhost, + signal.SendMediaServerStarted, + logutils.ZapLogger().Named("MediaServer"), + ), db: db, downloader: downloader, multiaccountsDB: multiaccountsDB, diff --git a/server/server_pairing.go b/server/server_pairing.go index b3e248f8d..cd65af19b 100644 --- a/server/server_pairing.go +++ b/server/server_pairing.go @@ -12,6 +12,7 @@ import ( "github.com/gorilla/sessions" + "github.com/status-im/status-go/logutils" "github.com/status-im/status-go/multiaccounts" ) @@ -56,7 +57,8 @@ func makeCookieStore() (*sessions.CookieStore, error) { // NewPairingServer returns a *PairingServer init from the given *Config func NewPairingServer(config *Config) (*PairingServer, error) { - pm, err := NewPairingPayloadManager(config.EK, config.PairingPayloadManagerConfig) + logger := logutils.ZapLogger().Named("PairingServer") + pm, err := NewPairingPayloadManager(config.EK, config.PairingPayloadManagerConfig, logger) if err != nil { return nil, err } @@ -70,6 +72,7 @@ func NewPairingServer(config *Config) (*PairingServer, error) { config.Cert, config.Hostname, nil, + logger, ), pk: config.PK, ek: config.EK,