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

@@ -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,
+						Name:     KeyUIDFlag,
-						Aliases: []string{"kid"},
+						Aliases:  []string{"kid"},
-						Usage:   "Key ID of the existing user (if not provided the last account will be used)",
+						Usage:    "Key ID of the existing user (find them under '<data-dir>/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))
 	}
 }

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 {
+func serve(cCtx *cli.Context) 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]))
-	}
-
 	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
+		var evt EventType
-		if err := json.Unmarshal(s, &ev); err != nil {
+		if err := json.Unmarshal(s, &evt); err != nil {
-			logger.Error("unmarshaling signal event", zap.Error(err), zap.String("event", string(s)))
+			logger.Error("unmarshaling event type", zap.Error(err), zap.String("event", string(s)))
 			return
 		}
 
-		if ev.Type == msignal.EventNewMessages {
+		switch evt.Type {
-			for _, message := range ev.Event.Messages {
+		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 EventType struct {
-	Type  string `json:"type"`
+	Type  string          `json:"type"`
-	Event struct {
+	Event json.RawMessage `json:"event"`
-		Messages []*common.Message `json:"messages"`
+}
-	} `json:"event"`
+
+type EventNewMessages struct {
+	Messages []*common.Message `json:"messages"`
 }
 
 func waitForSigExit() {

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:")
+	logger.Infof("Running %v command, with:\n%v", cCtx.Command, flagsUsed(cCtx))
-	for _, flag := range SimulateFlags {
-		logger.Infof("-%s %v", flag.Names()[0], cCtx.Value(flag.Names()[0]))
-	}
 
 	// 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
 	}

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)
+	logger.Info("starting messenger")
-	nlog.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
+	var acc multiaccounts.Account
-	if keyUID != "" {
+	found := false
-		found := false
+	for _, a := range accs {
-		for _, a := range accs {
+		if a.KeyUID == keyUID {
-			if a.KeyUID == keyUID {
+			acc = a
-				acc = a
+			found = true
-				found = true
+			break
-				break
-			}
-		}
-		if !found {
-			return fmt.Errorf("account not found for keyUID: %v", keyUID)
 		}
 	}
+	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()
+}