feat_: Implement request logging functionality (#5812)

* feat_: Implement request logging functionality

* chore_: lint fix

* chore_: address review feedback

* test_: check panic recovery panic

* chore_: add json tags

logutils/override.go

@@ -10,13 +10,13 @@ import (
 )
 
 type LogSettings struct {
-	Enabled         bool
-	MobileSystem    bool
-	Level           string
-	File            string
-	MaxSize         int
-	MaxBackups      int
-	CompressRotated bool
+	Enabled         bool   `json:"Enabled"`
+	MobileSystem    bool   `json:"MobileSystem"`
+	Level           string `json:"Level"`
+	File            string `json:"File"`
+	MaxSize         int    `json:"MaxSize"`
+	MaxBackups      int    `json:"MaxBackups"`
+	CompressRotated bool   `json:"CompressRotated"`
 }
 
 // OverrideWithStdLogger overwrites ethereum's root logger with a logger from golang std lib.

logutils/requestlog/request_log.go

@@ -0,0 +1,59 @@
+package requestlog
+
+import (
+	"errors"
+	"sync/atomic"
+
+	"github.com/ethereum/go-ethereum/log"
+
+	"github.com/status-im/status-go/logutils"
+)
+
+var (
+	// requestLogger is the request logger object
+	requestLogger log.Logger
+	// isRequestLoggingEnabled controls whether request logging is enabled
+	isRequestLoggingEnabled atomic.Bool
+)
+
+// NewRequestLogger creates a new request logger object
+func NewRequestLogger(ctx ...interface{}) log.Logger {
+	requestLogger = log.New(ctx...)
+	return requestLogger
+}
+
+// EnableRequestLogging enables or disables RPC logging
+func EnableRequestLogging(enable bool) {
+	if enable {
+		isRequestLoggingEnabled.Store(true)
+	} else {
+		isRequestLoggingEnabled.Store(false)
+	}
+}
+
+// IsRequestLoggingEnabled returns whether RPC logging is enabled
+func IsRequestLoggingEnabled() bool {
+	return isRequestLoggingEnabled.Load()
+}
+
+// GetRequestLogger returns the RPC logger object
+func GetRequestLogger() log.Logger {
+	return requestLogger
+}
+
+func ConfigureAndEnableRequestLogging(file string) error {
+	log.Info("initialising request logger", "log file", file)
+	requestLogger := NewRequestLogger()
+	if file == "" {
+		return errors.New("log file path is required")
+	}
+	fileOpts := logutils.FileOptions{
+		Filename:   file,
+		MaxBackups: 1,
+	}
+	handler := logutils.FileHandlerWithRotation(fileOpts, log.LogfmtFormat())
+	filteredHandler := log.LvlFilterHandler(log.LvlDebug, handler)
+	requestLogger.SetHandler(filteredHandler)
+	EnableRequestLogging(true)
+	return nil
+}

mobile/init_logging_test.go

@@ -0,0 +1,47 @@
+package statusgo
+
+import (
+	"fmt"
+	"os"
+	"path"
+	"testing"
+
+	"github.com/stretchr/testify/require"
+
+	"github.com/status-im/status-go/logutils/requestlog"
+	"github.com/status-im/status-go/protocol/requests"
+)
+
+func TestInitLogging(t *testing.T) {
+	tempDir := t.TempDir()
+	t.Logf("temp dir: %s", tempDir)
+	gethLogFile := path.Join(tempDir, "geth.log")
+	requestsLogFile := path.Join(tempDir, "requests.log")
+	logSettings := fmt.Sprintf(`{"LogRequestGo": true, "LogRequestFile": "%s", "File": "%s", "Level": "INFO", "Enabled": true, "MobileSystem": false}`, requestsLogFile, gethLogFile)
+	response := InitLogging(logSettings)
+	require.Equal(t, `{"error":""}`, response)
+	_, err := os.Stat(gethLogFile)
+	require.NoError(t, err)
+	require.True(t, requestlog.IsRequestLoggingEnabled())
+
+	// requests log file should not be created yet
+	_, err = os.Stat(requestsLogFile)
+	require.Error(t, err)
+	require.True(t, os.IsNotExist(err))
+
+	createAccountRequest := &requests.CreateAccount{
+		DisplayName:        "some-display-name",
+		CustomizationColor: "#ffffff",
+		Password:           "some-password",
+		RootDataDir:        tempDir,
+		LogFilePath:        gethLogFile,
+	}
+	_, err = statusBackend.CreateAccountAndLogin(createAccountRequest)
+	require.NoError(t, err)
+	result := CallPrivateRPC(`{"jsonrpc":"2.0","method":"settings_getSettings","params":[],"id":1}`)
+	require.NotContains(t, result, "error")
+	// Check if request log file exists now
+	_, err = os.Stat(requestsLogFile)
+	require.NoError(t, err)
+	require.FileExists(t, requestsLogFile)
+}

mobile/status_request_log.go

@@ -0,0 +1,88 @@
+package statusgo
+
+import (
+	"fmt"
+	"reflect"
+	"regexp"
+	"runtime"
+	"runtime/debug"
+	"strings"
+	"time"
+
+	"github.com/ethereum/go-ethereum/log"
+	"github.com/status-im/status-go/logutils/requestlog"
+)
+
+var sensitiveRegex = regexp.MustCompile(`(?i)(".*?(password|mnemonic|openseaAPIKey|poktToken|alchemyArbitrumMainnetToken|raribleTestnetAPIKey|alchemyOptimismMainnetToken|statusProxyBlockchainUser|alchemyEthereumSepoliaToken|alchemyArbitrumSepoliaToken|infuraToken|raribleMainnetAPIKey|alchemyEthereumMainnetToken).*?")\s*:\s*("[^"]*")`)
+
+func getFunctionName(fn any) string {
+	return runtime.FuncForPC(reflect.ValueOf(fn).Pointer()).Name()
+}
+
+func getShortFunctionName(fn any) string {
+	fullName := getFunctionName(fn)
+	parts := strings.Split(fullName, ".")
+	return parts[len(parts)-1]
+}
+
+// logAndCall logs request call details and executes the fn function if logging is enabled
+func logAndCall(fn any, params ...any) any {
+	defer func() {
+		if r := recover(); r != nil {
+			// we're not sure if request logging is enabled here, so we log it use default logger
+			log.Error("panic found in logAndCall", "error", r, "stacktrace", string(debug.Stack()))
+			panic(r)
+		}
+	}()
+
+	var startTime time.Time
+
+	if requestlog.IsRequestLoggingEnabled() {
+		startTime = time.Now()
+	}
+
+	fnValue := reflect.ValueOf(fn)
+	fnType := fnValue.Type()
+	if fnType.Kind() != reflect.Func {
+		panic("fn must be a function")
+	}
+
+	args := make([]reflect.Value, len(params))
+	for i, param := range params {
+		args[i] = reflect.ValueOf(param)
+	}
+
+	results := fnValue.Call(args)
+
+	var resp any
+
+	if len(results) > 0 {
+		resp = results[0].Interface()
+	}
+
+	if requestlog.IsRequestLoggingEnabled() {
+		duration := time.Since(startTime)
+		methodName := getShortFunctionName(fn)
+		paramsString := removeSensitiveInfo(fmt.Sprintf("%+v", params))
+		respString := removeSensitiveInfo(fmt.Sprintf("%+v", resp))
+		requestlog.GetRequestLogger().Debug(methodName, "params", paramsString, "resp", respString, "duration", duration)
+	}
+
+	return resp
+}
+
+func logAndCallString(fn any, params ...any) string {
+	resp := logAndCall(fn, params...)
+	if resp == nil {
+		return ""
+	}
+	return resp.(string)
+}
+
+func removeSensitiveInfo(jsonStr string) string {
+	// see related test for the usage of this function
+	return sensitiveRegex.ReplaceAllStringFunc(jsonStr, func(match string) string {
+		parts := sensitiveRegex.FindStringSubmatch(match)
+		return fmt.Sprintf(`%s:"***"`, parts[1])
+	})
+}

mobile/status_request_log_test.go

@@ -0,0 +1,155 @@
+package statusgo
+
+import (
+	"encoding/json"
+	"fmt"
+	"strings"
+	"testing"
+
+	"github.com/stretchr/testify/require"
+
+	"github.com/status-im/status-go/logutils/requestlog"
+	"github.com/status-im/status-go/multiaccounts"
+	"github.com/status-im/status-go/multiaccounts/settings"
+	"github.com/status-im/status-go/signal"
+
+	"github.com/ethereum/go-ethereum/log"
+)
+
+func TestRemoveSensitiveInfo(t *testing.T) {
+	testCases := []struct {
+		name     string
+		input    string
+		expected string
+	}{
+		{
+			name:     "basic test",
+			input:    `{"username":"user1","password":"secret123","mnemonic":"mnemonic123 xyz"}`,
+			expected: `{"username":"user1","password":"***","mnemonic":"***"}`,
+		},
+		{
+			name:     "uppercase password field",
+			input:    `{"USERNAME":"user1","PASSWORD":"secret123"}`,
+			expected: `{"USERNAME":"user1","PASSWORD":"***"}`,
+		},
+		{
+			name:     "password field with spaces",
+			input:    `{"username":"user1", "password" : "secret123"}`,
+			expected: `{"username":"user1", "password":"***"}`,
+		},
+		{
+			name:     "multiple password fields",
+			input:    `{"password":"secret123","data":{"nested_password":"nested_secret"}}`,
+			expected: `{"password":"***","data":{"nested_password":"***"}}`,
+		},
+		{
+			name:     "no password field",
+			input:    `{"username":"user1","email":"user1@example.com"}`,
+			expected: `{"username":"user1","email":"user1@example.com"}`,
+		},
+	}
+
+	for _, tc := range testCases {
+		t.Run(tc.name, func(t *testing.T) {
+			result := removeSensitiveInfo(tc.input)
+			if result != tc.expected {
+				t.Errorf("Expected: %s, Got: %s", tc.expected, result)
+			}
+		})
+	}
+}
+
+func TestLogAndCall(t *testing.T) {
+	// Enable request logging
+	requestlog.EnableRequestLogging(true)
+
+	// Create a mock logger to capture log output
+	var logOutput string
+	mockLogger := log.New()
+	mockLogger.SetHandler(log.FuncHandler(func(r *log.Record) error {
+		logOutput += r.Msg + fmt.Sprintf("%s", r.Ctx...)
+		return nil
+	}))
+	requestlog.NewRequestLogger().SetHandler(mockLogger.GetHandler())
+
+	// Test case 1: Normal execution
+	testFunc := func(param string) string {
+		return "test result: " + param
+	}
+	testParam := "test input"
+	expectedResult := "test result: test input"
+
+	result := logAndCallString(testFunc, testParam)
+
+	// Check the result
+	if result != expectedResult {
+		t.Errorf("Expected result %s, got %s", expectedResult, result)
+	}
+
+	// Check if the log contains expected information
+	expectedLogParts := []string{getShortFunctionName(testFunc), "params", testParam, "resp", expectedResult}
+	for _, part := range expectedLogParts {
+		if !strings.Contains(logOutput, part) {
+			t.Errorf("Log output doesn't contain expected part: %s", part)
+		}
+	}
+
+	// Test case 2: Panic -> recovery -> re-panic
+	oldRootHandler := log.Root().GetHandler()
+	defer log.Root().SetHandler(oldRootHandler)
+	log.Root().SetHandler(mockLogger.GetHandler())
+	// Clear log output for next test
+	logOutput = ""
+	e := "test panic"
+	panicFunc := func() {
+		panic(e)
+	}
+
+	require.PanicsWithValue(t, e, func() {
+		logAndCall(panicFunc)
+	})
+
+	// Check if the panic was logged
+	if !strings.Contains(logOutput, "panic found in logAndCall") {
+		t.Errorf("Log output doesn't contain panic information")
+	}
+	if !strings.Contains(logOutput, e) {
+		t.Errorf("Log output doesn't contain panic message")
+	}
+	if !strings.Contains(logOutput, "stacktrace") {
+		t.Errorf("Log output doesn't contain stacktrace")
+	}
+}
+
+func TestGetFunctionName(t *testing.T) {
+	fn := getShortFunctionName(initializeApplication)
+	require.Equal(t, "initializeApplication", fn)
+}
+
+type testSignalHandler struct {
+	receivedSignal string
+}
+
+func (t *testSignalHandler) HandleSignal(data string) {
+	t.receivedSignal = data
+}
+
+func TestSetMobileSignalHandler(t *testing.T) {
+	// Setup
+	handler := &testSignalHandler{}
+	SetMobileSignalHandler(handler)
+	t.Cleanup(signal.ResetMobileSignalHandler)
+
+	// Test data
+	testAccount := &multiaccounts.Account{Name: "test"}
+	testSettings := &settings.Settings{KeyUID: "0x1"}
+	testEnsUsernames := json.RawMessage(`{"test": "test"}`)
+
+	// Action
+	signal.SendLoggedIn(testAccount, testSettings, testEnsUsernames, nil)
+
+	// Assertions
+	require.Contains(t, handler.receivedSignal, `"key-uid":"0x1"`, "Signal should contain the correct KeyUID")
+	require.Contains(t, handler.receivedSignal, `"name":"test"`, "Signal should contain the correct account name")
+	require.Contains(t, handler.receivedSignal, `"ensUsernames":{"test":"test"}`, "Signal should contain the correct ENS usernames")
+}