feat_: init logs in `InitializeApplication` (#6117)

* feat_: functional tests for logs

* feat_: init logs in `InitializeApplication`

* chore_: completely remove `MobileSystem` log setting

migrate

* chore_: condition for call startTime

* fix_: rebase issues, linter

* fix_: sql query

* test_: mark rpc TestInitializeLogging

* test_: skip TestInitializeLogging

api/defaults.go

@@ -27,11 +27,13 @@ const (
 	shardsTestClusterID      = 16
 	walletAccountDefaultName = "Account 1"
 
-	DefaultKeystoreRelativePath       = "keystore"
-	DefaultKeycardPairingDataFile     = "/ethereum/mainnet_rpc/keycard/pairings.json"
-	DefaultDataDir                    = "/ethereum/mainnet_rpc"
-	DefaultNodeName                   = "StatusIM"
-	DefaultLogFile                    = "geth.log"
+	DefaultKeystoreRelativePath   = "keystore"
+	DefaultKeycardPairingDataFile = "/ethereum/mainnet_rpc/keycard/pairings.json"
+	DefaultDataDir                = "/ethereum/mainnet_rpc"
+	DefaultNodeName               = "StatusIM"
+	DefaultLogFile                = "geth.log"
+	DefaultAPILogFile             = "api.log"
+
 	DefaultLogLevel                   = "ERROR"
 	DefaultMaxPeers                   = 20
 	DefaultMaxPendingPeers            = 20

api/geth_backend.go

@@ -494,7 +494,6 @@ func (b *GethStatusBackend) ensureWalletDBOpened(account multiaccounts.Account,
 func (b *GethStatusBackend) setupLogSettings() error {
 	logSettings := logutils.LogSettings{
 		Enabled:         b.config.LogEnabled,
-		MobileSystem:    b.config.LogMobileSystem,
 		Level:           b.config.LogLevel,
 		File:            b.config.LogFile,
 		MaxSize:         b.config.LogMaxSize,

appdatabase/migrations/sql/1732570426_.up.sql

@@ -0,0 +1 @@
+ALTER TABLE log_config DROP COLUMN mobile_system;

appdatabase/node_config_test.go

@@ -159,7 +159,6 @@ func randomNodeConfig() *params.NodeConfig {
 		IPCEnabled:                randomBool(),
 		IPCFile:                   randomString(),
 		LogEnabled:                randomBool(),
-		LogMobileSystem:           randomBool(),
 		LogDir:                    randomString(),
 		LogFile:                   randomString(),
 		LogLevel:                  randomString(),

cmd/ping-community/main.go

@@ -238,7 +238,6 @@ func setupLogging(config *params.NodeConfig) {
 
 	logSettings := logutils.LogSettings{
 		Enabled:         config.LogEnabled,
-		MobileSystem:    config.LogMobileSystem,
 		Level:           config.LogLevel,
 		File:            config.LogFile,
 		MaxSize:         config.LogMaxSize,

cmd/populate-db/main.go

@@ -282,7 +282,6 @@ func setupLogging(config *params.NodeConfig) {
 
 	logSettings := logutils.LogSettings{
 		Enabled:         config.LogEnabled,
-		MobileSystem:    config.LogMobileSystem,
 		Level:           config.LogLevel,
 		File:            config.LogFile,
 		MaxSize:         config.LogMaxSize,

cmd/status-backend/main.go

@@ -22,10 +22,9 @@ var (
 
 func init() {
 	logSettings := logutils.LogSettings{
-		Enabled:      true,
-		MobileSystem: false,
-		Level:        "INFO",
-		Colorized:    terminal.IsTerminal(int(os.Stdin.Fd())),
+		Enabled:   true,
+		Level:     "INFO",
+		Colorized: terminal.IsTerminal(int(os.Stdin.Fd())),
 	}
 	if err := logutils.OverrideRootLoggerWithConfig(logSettings); err != nil {
 		stdlog.Fatalf("failed to initialize log: %v", err)

cmd/status-cli/util.go

@@ -25,7 +25,6 @@ func setupLogger(file string) *zap.Logger {
 	logFile := fmt.Sprintf("%s.log", strings.ToLower(file))
 	logSettings := logutils.LogSettings{
 		Enabled:         true,
-		MobileSystem:    false,
 		Level:           "DEBUG",
 		File:            logFile,
 		MaxSize:         100,

cmd/statusd/main.go

@@ -396,7 +396,6 @@ func setupLogging(config *params.NodeConfig) {
 
 	logSettings := logutils.LogSettings{
 		Enabled:         config.LogEnabled,
-		MobileSystem:    config.LogMobileSystem,
 		Level:           config.LogLevel,
 		File:            config.LogFile,
 		MaxSize:         config.LogMaxSize,

logutils/override.go

@@ -11,7 +11,6 @@ import (
 
 type LogSettings struct {
 	Enabled         bool   `json:"Enabled"`
-	MobileSystem    bool   `json:"MobileSystem"`
 	Level           string `json:"Level"`
 	File            string `json:"File"`
 	MaxSize         int    `json:"MaxSize"`
@@ -39,11 +38,6 @@ func overrideCoreWithConfig(core *Core, settings LogSettings) error {
 	}
 	core.SetLevel(level)
 
-	if settings.MobileSystem {
-		core.UpdateSyncer(zapcore.Lock(os.Stdout))
-		return nil
-	}
-
 	if settings.File != "" {
 		if settings.MaxBackups == 0 {
 			// Setting MaxBackups to 0 causes all log files to be kept. Even setting MaxAge to > 0 doesn't fix it

logutils/override_test.go

@@ -41,8 +41,7 @@ func TestOverrideCoreWithConfig(t *testing.T) {
 		{
 			name: "mobile system logging",
 			settings: LogSettings{
-				Enabled:      true,
-				MobileSystem: true,
+				Enabled: true,
 			},
 			expectError: false,
 		},

mobile/callog/status_request_log.go

@@ -63,21 +63,9 @@ func getShortFunctionName(fn any) string {
 // 4. If request logging is enabled, logs method name, parameters, response, and execution duration
 // 5. Removes sensitive information before logging
 func Call(logger, requestLogger *zap.Logger, fn any, params ...any) any {
-	defer func() {
-		if r := recover(); r != nil {
-			logger.Error("panic found in call", zap.Any("error", r), zap.Stack("stacktrace"))
-			sentry.RecoverError(r)
-			panic(r)
-		}
-	}()
-
-	var startTime time.Time
-
-	requestLoggingEnabled := requestLogger != nil
-	if requestLoggingEnabled {
-		startTime = time.Now()
-	}
+	defer Recover(logger)
 
+	startTime := requestStartTime(requestLogger != nil)
 	fnValue := reflect.ValueOf(fn)
 	fnType := fnValue.Type()
 	if fnType.Kind() != reflect.Func {
@@ -97,18 +85,9 @@ func Call(logger, requestLogger *zap.Logger, fn any, params ...any) any {
 		resp = results[0].Interface()
 	}
 
-	if requestLoggingEnabled {
-		duration := time.Since(startTime)
+	if requestLogger != nil {
 		methodName := getShortFunctionName(fn)
-		paramsString := removeSensitiveInfo(fmt.Sprintf("%+v", params))
-		respString := removeSensitiveInfo(fmt.Sprintf("%+v", resp))
-
-		requestLogger.Debug("call",
-			zap.String("method", methodName),
-			zap.String("params", paramsString),
-			zap.String("resp", respString),
-			zap.Duration("duration", duration),
-		)
+		Log(requestLogger, methodName, params, resp, startTime)
 	}
 
 	return resp
@@ -129,3 +108,38 @@ func removeSensitiveInfo(jsonStr string) string {
 		return fmt.Sprintf(`%s:"***"`, parts[1])
 	})
 }
+
+func requestStartTime(enabled bool) time.Time {
+	if !enabled {
+		return time.Time{}
+	}
+	return time.Now()
+}
+
+func Recover(logger *zap.Logger) {
+	err := recover()
+	if err == nil {
+		return
+	}
+
+	logger.Error("panic found in call",
+		zap.Any("error", err),
+		zap.Stack("stacktrace"))
+
+	sentry.RecoverError(err)
+
+	panic(err)
+}
+
+func Log(logger *zap.Logger, method string, params any, resp any, startTime time.Time) {
+	if logger == nil {
+		return
+	}
+	duration := time.Since(startTime)
+	logger.Debug("call",
+		zap.String("method", method),
+		zap.String("params", removeSensitiveInfo(fmt.Sprintf("%+v", params))),
+		zap.String("resp", removeSensitiveInfo(fmt.Sprintf("%+v", resp))),
+		zap.Duration("duration", duration),
+	)
+}

mobile/status.go

@@ -49,6 +49,9 @@ import (
 	"github.com/status-im/status-go/services/wallet/wallettypes"
 	"github.com/status-im/status-go/signal"
 
+	"path"
+	"time"
+
 	"github.com/status-im/status-go/mobile/callog"
 )
 
@@ -66,7 +69,21 @@ type InitializeApplicationResponse struct {
 }
 
 func InitializeApplication(requestJSON string) string {
-	return callWithResponse(initializeApplication, requestJSON)
+	// NOTE: InitializeApplication is logs the call on its own rather than using `callWithResponse`,
+	//       because the API logging is enabled during this exact call.
+	defer callog.Recover(logutils.ZapLogger())
+
+	startTime := time.Now()
+	response := initializeApplication(requestJSON)
+	callog.Log(
+		requestlog.GetRequestLogger(),
+		"InitializeApplication",
+		requestJSON,
+		response,
+		startTime,
+	)
+
+	return response
 }
 
 func initializeApplication(requestJSON string) string {
@@ -80,38 +97,69 @@ func initializeApplication(requestJSON string) string {
 		return makeJSONResponse(err)
 	}
 
+	// Initialize logs
+	if request.LogDir == "" {
+		request.LogDir = request.DataDir
+	}
+	logSettings := logutils.LogSettings{
+		Enabled: request.LogEnabled,
+		Level:   request.LogLevel,
+		File:    path.Join(request.LogDir, api.DefaultLogFile),
+	}
+	if err = logutils.OverrideRootLoggerWithConfig(logSettings); err == nil {
+		logutils.ZapLogger().Info("logging initialised",
+			zap.Any("logSettings", logSettings),
+			zap.Bool("APILoggingEnabled", request.APILoggingEnabled),
+		)
+	} else {
+		return makeJSONResponse(err)
+	}
+
+	if request.APILoggingEnabled {
+		logRequestsFile := path.Join(request.LogDir, api.DefaultAPILogFile)
+		err = requestlog.ConfigureAndEnableRequestLogging(logRequestsFile)
+		if err != nil {
+			return makeJSONResponse(err)
+		}
+	}
+
 	// initialize metrics
 	providers.MixpanelAppID = request.MixpanelAppID
 	providers.MixpanelToken = request.MixpanelToken
 
 	statusBackend.StatusNode().SetMediaServerEnableTLS(request.MediaServerEnableTLS)
-
 	statusBackend.UpdateRootDataDir(request.DataDir)
+
+	// Read available accounts
 	err = statusBackend.OpenAccounts()
 	if err != nil {
 		return makeJSONResponse(err)
 	}
+
 	accs, err := statusBackend.GetAccounts()
 	if err != nil {
 		return makeJSONResponse(err)
 	}
-	centralizedMetricsInfo, err := statusBackend.CentralizedMetricsInfo()
+
+	// Read centralized metrics info
+	metricsInfo, err := statusBackend.CentralizedMetricsInfo()
 	if err != nil {
 		return makeJSONResponse(err)
 	}
 
 	// initialize sentry
 	statusBackend.SetSentryDSN(request.SentryDSN)
-	if centralizedMetricsInfo.Enabled {
+	if metricsInfo.Enabled {
 		err = statusBackend.EnablePanicReporting()
 		if err != nil {
 			return makeJSONResponse(err)
 		}
 	}
 
+	// Prepare response
 	response := &InitializeApplicationResponse{
 		Accounts:               accs,
-		CentralizedMetricsInfo: centralizedMetricsInfo,
+		CentralizedMetricsInfo: metricsInfo,
 	}
 	data, err := json.Marshal(response)
 	if err != nil {
@@ -2162,6 +2210,7 @@ type InitLoggingRequest struct {
 // InitLogging The InitLogging function should be called when the application starts.
 // This ensures that we can capture logs before the user login. Subsequent calls will update the logger settings.
 // Before this, we can only capture logs after user login since we will only configure the logging after the login process.
+// Deprecated: Use InitializeApplication instead
 func InitLogging(logSettingsJSON string) string {
 	var logSettings InitLoggingRequest
 	var err error

nodecfg/node_config.go

@@ -89,10 +89,10 @@ func insertHTTPConfig(tx *sql.Tx, c *params.NodeConfig) error {
 func insertLogConfig(tx *sql.Tx, c *params.NodeConfig) error {
 	_, err := tx.Exec(`
 	INSERT OR REPLACE INTO log_config (
-		enabled, mobile_system, log_dir, log_level, max_backups, max_size,
+		enabled, log_dir, log_level, max_backups, max_size,
 		file, compress_rotated, log_to_stderr, synthetic_id
-	) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, 'id'	)`,
-		c.LogEnabled, c.LogMobileSystem, c.LogDir, c.LogLevel, c.LogMaxBackups, c.LogMaxSize,
+	) VALUES (?, ?, ?, ?, ?, ?, ?, ?, 'id'	)`,
+		c.LogEnabled, c.LogDir, c.LogLevel, c.LogMaxBackups, c.LogMaxSize,
 		c.LogFile, c.LogCompressRotated, c.LogToStderr,
 	)
 
@@ -488,8 +488,8 @@ func loadNodeConfig(tx *sql.Tx) (*params.NodeConfig, error) {
 		return nil, err
 	}
 
-	err = tx.QueryRow("SELECT enabled, mobile_system, log_dir, log_level, file, max_backups, max_size, compress_rotated, log_to_stderr FROM log_config WHERE synthetic_id = 'id'").Scan(
-		&nodecfg.LogEnabled, &nodecfg.LogMobileSystem, &nodecfg.LogDir, &nodecfg.LogLevel, &nodecfg.LogFile, &nodecfg.LogMaxBackups, &nodecfg.LogMaxSize, &nodecfg.LogCompressRotated, &nodecfg.LogToStderr)
+	err = tx.QueryRow("SELECT enabled, log_dir, log_level, file, max_backups, max_size, compress_rotated, log_to_stderr FROM log_config WHERE synthetic_id = 'id'").Scan(
+		&nodecfg.LogEnabled, &nodecfg.LogDir, &nodecfg.LogLevel, &nodecfg.LogFile, &nodecfg.LogMaxBackups, &nodecfg.LogMaxSize, &nodecfg.LogCompressRotated, &nodecfg.LogToStderr)
 	if err != nil && err != sql.ErrNoRows {
 		return nil, err
 	}

params/config.go

@@ -414,9 +414,6 @@ type NodeConfig struct {
 	// LogEnabled enables the logger
 	LogEnabled bool `json:"LogEnabled"`
 
-	// LogMobileSystem enables log redirection to android/ios system logger.
-	LogMobileSystem bool
-
 	// LogFile is a folder which contains LogFile
 	LogDir string
 

protocol/requests/initialize_application.go

@@ -15,6 +15,14 @@ type InitializeApplication struct {
 	// MediaServerEnableTLS is optional, if not provided, media server will use TLS by default
 	MediaServerEnableTLS *bool  `json:"mediaServerEnableTLS"`
 	SentryDSN            string `json:"sentryDSN"`
+
+	// LogDir specifies the directory where logs are stored.
+	// If empty, logs are stored in the `DataDir`.
+	LogDir string `json:"logDir"`
+
+	LogEnabled        bool   `json:"logEnabled"`
+	LogLevel          string `json:"logLevel"`
+	APILoggingEnabled bool   `json:"apiLoggingEnabled"`
 }
 
 func (i *InitializeApplication) Validate() error {

tests-functional/tests/test_init_status_app.py

@@ -1,5 +1,6 @@
 from test_cases import StatusBackend
 import pytest
+import os
 
 
 @pytest.mark.create_account
@@ -22,7 +23,6 @@ class TestInitialiseApp:
         backend_client.restore_account_and_login()
 
         assert backend_client is not None
-        
         backend_client.verify_json_schema(
             backend_client.wait_for_signal("mediaserver.started"), "signal_mediaserver_started")
         backend_client.verify_json_schema(
@@ -31,3 +31,52 @@ class TestInitialiseApp:
             backend_client.wait_for_signal("node.ready"), "signal_node_ready")
         backend_client.verify_json_schema(
             backend_client.wait_for_signal("node.login"), "signal_node_login")
+
+
+@pytest.mark.rpc
+@pytest.mark.skip("waiting for status-backend to be executed on the same host/container")
+class TestInitializeLogging:
+
+    @pytest.mark.init
+    def test_init_logging(self, tmp_path):
+        self.check_logs(tmp_path, log_enabled=True, api_logging_enabled=True)
+
+    @pytest.mark.init
+    def test_no_logging(self, tmp_path):
+        self.check_logs(tmp_path, log_enabled=False, api_logging_enabled=False)
+
+
+    def assert_file_first_line(self, path, pattern: str, expected: bool):
+        assert os.path.exists(path) == expected
+        if not expected:
+            return
+        with open(path) as file:
+            line = file.readline()
+            line_found = line.find(pattern) >= 0
+            assert line_found == expected
+
+    def check_logs(self, path, log_enabled: bool, api_logging_enabled: bool):
+        data_dir = path / "data"
+        logs_dir = path / "logs"
+
+        data_dir.mkdir()
+        logs_dir.mkdir()
+
+        backend = StatusBackend()
+        backend.api_valid_request("InitializeApplication", {
+            "dataDir": str(data_dir),
+            "logDir": str(logs_dir),
+            "logEnabled": log_enabled,
+            "apiLoggingEnabled": api_logging_enabled,
+        })
+
+        self.assert_file_first_line(
+            logs_dir / "geth.log",
+            pattern="logging initialised",
+            expected=log_enabled)
+
+        self.assert_file_first_line(
+            logs_dir / "api.log",
+            pattern='"method": "InitializeApplication"',
+            expected=api_logging_enabled)
+