From 2c349b629d937e5126bec8135efb9a6c8a9297e0 Mon Sep 17 00:00:00 2001 From: Pablo Lopez Date: Fri, 14 Jun 2024 16:13:31 +0300 Subject: [PATCH] fix(cli)_: fixed unmarshaling error and improved logging (#5351) * fix(cli)_: fixed unmarshaling error and improved logging * fix_: telemetry logger * fix_: unused var * fix_: build * fix_: build --- cmd/status-cli/main.go | 29 +++++++++---- cmd/status-cli/serve.go | 56 ++++++++++++++----------- cmd/status-cli/simulate.go | 15 +++---- cmd/status-cli/util.go | 86 +++++++++++++++++++++++++++----------- 4 files changed, 120 insertions(+), 66 deletions(-) diff --git a/cmd/status-cli/main.go b/cmd/status-cli/main.go index e5b7d166b..48a9b5490 100644 --- a/cmd/status-cli/main.go +++ b/cmd/status-cli/main.go @@ -21,6 +21,7 @@ const PortFlag = "port" const APIModulesFlag = "api-modules" const TelemetryServerURLFlag = "telemetry-server-url" const KeyUIDFlag = "key-uid" +const DebugLevel = "debug" const RetrieveInterval = 300 * time.Millisecond const SendInterval = 1 * time.Second @@ -43,6 +44,12 @@ var CommonFlags = []cli.Flag{ Aliases: []string{"t"}, Usage: "Telemetry server URL", }, + &cli.BoolFlag{ + Name: DebugLevel, + Aliases: []string{"d"}, + Usage: "Enable CLI's debug level logging", + Value: false, + }, } var SimulateFlags = append([]cli.Flag{ @@ -84,8 +91,6 @@ var ServeFlags = append([]cli.Flag{ }, }, CommonFlags...) -var logger *zap.SugaredLogger - type StatusCLI struct { name string messenger *protocol.Messenger @@ -110,7 +115,7 @@ func main() { Usage: "Start a server to send and receive messages", Flags: ServeFlags, Action: func(cCtx *cli.Context) error { - return serve(cCtx, false) + return serve(cCtx) }, }, { @@ -125,29 +130,37 @@ func main() { Required: true, }, &cli.StringFlag{ - Name: KeyUIDFlag, - Aliases: []string{"kid"}, - Usage: "Key ID of the existing user (if not provided the last account will be used)", + Name: KeyUIDFlag, + Aliases: []string{"kid"}, + Usage: "Key ID of the existing user (find them under '/keystore' on in logs when using the 'serve' command)", + Required: true, }, &cli.BoolFlag{ Name: InteractiveFlag, Aliases: []string{"i"}, Usage: "Use interactive mode to input the messages", + Value: false, }, &cli.StringFlag{ Name: AddFlag, Aliases: []string{"a"}, Usage: "Add a friend with the public key", }, + &cli.BoolFlag{ + Name: DebugLevel, + Aliases: []string{"d"}, + Usage: "Enable CLI's debug level logging", + Value: false, + }, }, Action: func(cCtx *cli.Context) error { - return serve(cCtx, true) + return serve(cCtx) }, }, }, } if err := app.Run(os.Args); err != nil { - logger.Fatal(err) + zap.L().Fatal("main", zap.Error(err)) } } diff --git a/cmd/status-cli/serve.go b/cmd/status-cli/serve.go index 5d3617a09..59ccfcf39 100644 --- a/cmd/status-cli/serve.go +++ b/cmd/status-cli/serve.go @@ -3,7 +3,6 @@ package main import ( "context" "encoding/json" - "log" "os" "os/signal" "syscall" @@ -16,18 +15,7 @@ import ( "go.uber.org/zap" ) -func serve(cCtx *cli.Context, useExistingAccount bool) error { - rawLogger, err := zap.NewDevelopment() - if err != nil { - log.Fatalf("Error initializing logger: %v", err) - } - logger = rawLogger.Sugar() - - logger.Info("Running serve command, flags passed:") - for _, flag := range ServeFlags { - logger.Infof("-%s %v", flag.Names()[0], cCtx.Value(flag.Names()[0])) - } - +func serve(cCtx *cli.Context) error { name := cCtx.String(NameFlag) port := cCtx.Int(PortFlag) apiModules := cCtx.String(APIModulesFlag) @@ -35,8 +23,18 @@ func serve(cCtx *cli.Context, useExistingAccount bool) error { interactive := cCtx.Bool(InteractiveFlag) dest := cCtx.String(AddFlag) keyUID := cCtx.String(KeyUIDFlag) + isDebugLevel := cCtx.Bool(DebugLevel) + cmdName := cCtx.Command.Name - cli, err := start(name, port, apiModules, telemetryUrl, useExistingAccount, keyUID) + logger, err := getSLogger(isDebugLevel) + if err != nil { + zap.S().Fatalf("Error initializing logger: %v", err) + } + logger.Infof("Running %v command, with:\n%v", cmdName, flagsUsed(cCtx)) + + logger = logger.Named(name) + + cli, err := start(name, port, apiModules, telemetryUrl, keyUID, logger) if err != nil { return err } @@ -47,14 +45,20 @@ func serve(cCtx *cli.Context, useExistingAccount bool) error { // and the retrieve messages loop is started when starting a node, so we needed a different appproach, // alternatively we could have implemented another notification mechanism in the messenger, but this signal is already in place msignal.SetMobileSignalHandler(msignal.MobileSignalHandler(func(s []byte) { - var ev MobileSignalEvent - if err := json.Unmarshal(s, &ev); err != nil { - logger.Error("unmarshaling signal event", zap.Error(err), zap.String("event", string(s))) + var evt EventType + if err := json.Unmarshal(s, &evt); err != nil { + logger.Error("unmarshaling event type", zap.Error(err), zap.String("event", string(s))) return } - if ev.Type == msignal.EventNewMessages { - for _, message := range ev.Event.Messages { + switch evt.Type { + case msignal.EventNewMessages: + var ev EventNewMessages + if err := json.Unmarshal(evt.Event, &ev); err != nil { + logger.Error("unmarshaling new message event", zap.Error(err), zap.Any("event", evt.Event)) + return + } + for _, message := range ev.Messages { logger.Infof("message received: %v (ID=%v)", message.Text, message.ID) // if request contact, accept it if message.ContentType == protobuf.ChatMessage_SYSTEM_MESSAGE_MUTUAL_EVENT_SENT { @@ -64,6 +68,8 @@ func serve(cCtx *cli.Context, useExistingAccount bool) error { } } } + default: + logger.Debugf("received event type '%v'\t%v", evt.Type, string(evt.Event)) } })) @@ -94,11 +100,13 @@ func serve(cCtx *cli.Context, useExistingAccount bool) error { return nil } -type MobileSignalEvent struct { - Type string `json:"type"` - Event struct { - Messages []*common.Message `json:"messages"` - } `json:"event"` +type EventType struct { + Type string `json:"type"` + Event json.RawMessage `json:"event"` +} + +type EventNewMessages struct { + Messages []*common.Message `json:"messages"` } func waitForSigExit() { diff --git a/cmd/status-cli/simulate.go b/cmd/status-cli/simulate.go index 18c7a7a6c..b50d0c2ed 100644 --- a/cmd/status-cli/simulate.go +++ b/cmd/status-cli/simulate.go @@ -3,7 +3,6 @@ package main import ( "context" "fmt" - "log" "os" "os/signal" "sync" @@ -24,28 +23,24 @@ func simulate(cCtx *cli.Context) error { cancel() }() - rawLogger, err := zap.NewDevelopment() + logger, err := getSLogger(cCtx.Bool(DebugLevel)) if err != nil { - log.Fatalf("Error initializing logger: %v", err) + zap.S().Fatalf("Error initializing logger: %v", err) } - logger = rawLogger.Sugar() - logger.Info("Running simulate command, flags passed:") - for _, flag := range SimulateFlags { - logger.Infof("-%s %v", flag.Names()[0], cCtx.Value(flag.Names()[0])) - } + logger.Infof("Running %v command, with:\n%v", cCtx.Command, flagsUsed(cCtx)) // Start messengers apiModules := cCtx.String(APIModulesFlag) telemetryUrl := cCtx.String(TelemetryServerURLFlag) - alice, err := start("Alice", 0, apiModules, telemetryUrl, false, "") + alice, err := start("Alice", 0, apiModules, telemetryUrl, "", logger.Named("alice")) if err != nil { return err } defer alice.stop() - charlie, err := start("Charlie", 0, apiModules, telemetryUrl, false, "") + charlie, err := start("Charlie", 0, apiModules, telemetryUrl, "", logger.Named("charlie")) if err != nil { return err } diff --git a/cmd/status-cli/util.go b/cmd/status-cli/util.go index 71fd8da79..27f9d9771 100644 --- a/cmd/status-cli/util.go +++ b/cmd/status-cli/util.go @@ -8,6 +8,8 @@ import ( "strings" "time" + "go.uber.org/zap" + "github.com/status-im/status-go/api" "github.com/status-im/status-go/logutils" "github.com/status-im/status-go/multiaccounts" @@ -15,7 +17,7 @@ import ( "github.com/status-im/status-go/services/wakuv2ext" "github.com/status-im/status-go/telemetry" - "go.uber.org/zap" + "github.com/urfave/cli/v2" ) func setupLogger(file string) *zap.Logger { @@ -30,32 +32,31 @@ func setupLogger(file string) *zap.Logger { CompressRotated: true, } if err := logutils.OverrideRootLogWithConfig(logSettings, false); err != nil { - logger.Fatalf("Error initializing logger: %v", err) + zap.S().Fatalf("Error initializing logger: %v", err) } - return logutils.ZapLogger() } -func start(name string, port int, apiModules string, telemetryUrl string, useExistingAccount bool, keyUID string) (*StatusCLI, error) { +func start(name string, port int, apiModules string, telemetryUrl string, keyUID string, logger *zap.SugaredLogger) (*StatusCLI, error) { var ( rootDataDir = fmt.Sprintf("./test-%s", strings.ToLower(name)) password = "some-password" ) setupLogger(name) - nlog := logger.Named(name) - nlog.Info("starting messenger") + logger.Info("starting messenger") backend := api.NewGethStatusBackend() - if useExistingAccount { + if keyUID != "" { if err := getAccountAndLogin(backend, name, rootDataDir, password, keyUID); err != nil { return nil, err } + logger.Infof("existing account, key UID: %v", keyUID) } else { acc, err := createAccountAndLogin(backend, name, rootDataDir, password, apiModules, telemetryUrl, port) if err != nil { return nil, err } - nlog.Infof("account created, key UID: %v", acc.KeyUID) + logger.Infof("account created, key UID: %v", acc.KeyUID) } wakuService := backend.StatusNode().WakuV2ExtService() @@ -64,7 +65,11 @@ func start(name string, port int, apiModules string, telemetryUrl string, useExi } if telemetryUrl != "" { - telemetryClient := telemetry.NewClient(nlog.Desugar(), telemetryUrl, backend.SelectedAccountKeyID(), name, "cli") + telemetryLogger, err := getLogger(true) + if err != nil { + return nil, err + } + telemetryClient := telemetry.NewClient(telemetryLogger, telemetryUrl, backend.SelectedAccountKeyID(), name, "cli") go telemetryClient.Start(context.Background()) backend.StatusNode().WakuV2Service().SetStatusTelemetryClient(telemetryClient) } @@ -75,14 +80,14 @@ func start(name string, port int, apiModules string, telemetryUrl string, useExi return nil, err } - nlog.Info("messenger started, public key: ", messenger.IdentityPublicKeyString()) + logger.Info("messenger started, public key: ", messenger.IdentityPublicKeyString()) time.Sleep(WaitingInterval) data := StatusCLI{ name: name, messenger: messenger, backend: backend, - logger: nlog, + logger: logger, } return &data, nil @@ -101,20 +106,18 @@ func getAccountAndLogin(b *api.GethStatusBackend, name, rootDataDir, password st return errors.New("no accounts found") } - acc := accs[0] // use last if no keyUID is provided - if keyUID != "" { - found := false - for _, a := range accs { - if a.KeyUID == keyUID { - acc = a - found = true - break - } - } - if !found { - return fmt.Errorf("account not found for keyUID: %v", keyUID) + var acc multiaccounts.Account + found := false + for _, a := range accs { + if a.KeyUID == keyUID { + acc = a + found = true + break } } + if !found { + return fmt.Errorf("account not found for keyUID: %v", keyUID) + } return b.LoginAccount(&requests.Login{ Password: password, @@ -147,6 +150,41 @@ func createAccountAndLogin(b *api.GethStatusBackend, name, rootDataDir, password func (cli *StatusCLI) stop() { err := cli.backend.StopNode() if err != nil { - logger.Error(err) + cli.logger.Error(err) } } + +func getLogger(debug bool) (*zap.Logger, error) { + at := zap.NewAtomicLevel() + if debug { + at.SetLevel(zap.DebugLevel) + } else { + at.SetLevel(zap.InfoLevel) + } + config := zap.NewDevelopmentConfig() + config.Level = at + rawLogger, err := config.Build() + if err != nil { + return nil, fmt.Errorf("initializing logger: %v", err) + } + return rawLogger, nil +} + +func getSLogger(debug bool) (*zap.SugaredLogger, error) { + l, err := getLogger(debug) + if err != nil { + return nil, err + } + return l.Sugar(), nil +} + +func flagsUsed(cCtx *cli.Context) string { + var sb strings.Builder + for _, flag := range cCtx.Command.Flags { + if flag != nil && len(flag.Names()) > 0 { + fName := flag.Names()[0] + fmt.Fprintf(&sb, "\t-%s %v\n", fName, cCtx.Value(fName)) + } + } + return sb.String() +}