From 50933aa3286e54bfd407f109ce21eabf1417bae7 Mon Sep 17 00:00:00 2001 From: osmaczko <33099791+osmaczko@users.noreply.github.com> Date: Thu, 5 Dec 2024 15:19:24 +0100 Subject: [PATCH] feat(logging)_: enable log namespaces configuration (#6161) closes: #6128 --- .../sql/1732905829_add_log_namespaces.up.sql | 1 + logutils/logger.go | 2 +- logutils/logger_test.go | 2 +- logutils/namespaces_tree.go | 7 +++ logutils/override.go | 11 +++- logutils/override_test.go | 2 +- nodecfg/node_config.go | 15 +++-- params/config.go | 5 ++ protocol/messenger_settings.go | 8 +++ protocol/requests/set_log_namespaces.go | 11 ++++ services/ext/api.go | 18 ++++++ tests-functional/clients/status_backend.py | 31 ++++++--- tests-functional/tests/test_logging.py | 63 +++++++++++++++++++ 13 files changed, 159 insertions(+), 17 deletions(-) create mode 100644 appdatabase/migrations/sql/1732905829_add_log_namespaces.up.sql create mode 100644 protocol/requests/set_log_namespaces.go create mode 100644 tests-functional/tests/test_logging.py diff --git a/appdatabase/migrations/sql/1732905829_add_log_namespaces.up.sql b/appdatabase/migrations/sql/1732905829_add_log_namespaces.up.sql new file mode 100644 index 000000000..65e7c9185 --- /dev/null +++ b/appdatabase/migrations/sql/1732905829_add_log_namespaces.up.sql @@ -0,0 +1 @@ +ALTER TABLE log_config ADD COLUMN log_namespaces VARCHAR DEFAULT ''; diff --git a/logutils/logger.go b/logutils/logger.go index f81b2880b..f7e828f78 100644 --- a/logutils/logger.go +++ b/logutils/logger.go @@ -34,7 +34,7 @@ func defaultLogger() *zap.Logger { zapcore.AddSync(io.Discard), zap.NewAtomicLevelAt(zap.InfoLevel), ) - return zap.New(core, zap.AddCaller()) + return zap.New(newNamespaceFilteringCore(core), zap.AddCaller()) } func defaultEncoder() zapcore.Encoder { diff --git a/logutils/logger_test.go b/logutils/logger_test.go index 999304507..2dd048bce 100644 --- a/logutils/logger_test.go +++ b/logutils/logger_test.go @@ -12,7 +12,7 @@ func TestPrintOrigins(t *testing.T) { buffer := bytes.NewBuffer(nil) logger := defaultLogger() - logger.Core().(*Core).UpdateSyncer(zapcore.AddSync(buffer)) + logger.Core().(*namespaceFilteringCore).Parent().(*Core).UpdateSyncer(zapcore.AddSync(buffer)) logger.Info("hello") diff --git a/logutils/namespaces_tree.go b/logutils/namespaces_tree.go index 786d3d20f..dcdacb922 100644 --- a/logutils/namespaces_tree.go +++ b/logutils/namespaces_tree.go @@ -12,6 +12,13 @@ import ( var namespacesRegex = regexp.MustCompile(`^([a-zA-Z0-9_\.]+:(debug|info|warn|error))(,[a-zA-Z0-9_\.]+:(debug|info|warn|error))*$`) var errInvalidNamespacesFormat = fmt.Errorf("invalid namespaces format") +func ValidateNamespaces(namespaces string) error { + if namespaces != "" && !namespacesRegex.MatchString(namespaces) { + return errInvalidNamespacesFormat + } + return nil +} + type namespacesTree struct { namespaces map[string]*namespaceNode minLevel zapcore.Level diff --git a/logutils/override.go b/logutils/override.go index afb9b8cfc..36b1353c3 100644 --- a/logutils/override.go +++ b/logutils/override.go @@ -12,6 +12,7 @@ import ( type LogSettings struct { Enabled bool `json:"Enabled"` Level string `json:"Level"` + Namespaces string `json:"Namespaces"` File string `json:"File"` MaxSize int `json:"MaxSize"` MaxBackups int `json:"MaxBackups"` @@ -20,10 +21,11 @@ type LogSettings struct { } func OverrideRootLoggerWithConfig(settings LogSettings) error { - return overrideCoreWithConfig(ZapLogger().Core().(*Core), settings) + return overrideCoreWithConfig(ZapLogger().Core().(*namespaceFilteringCore), settings) } -func overrideCoreWithConfig(core *Core, settings LogSettings) error { +func overrideCoreWithConfig(filteringCore *namespaceFilteringCore, settings LogSettings) error { + core := filteringCore.Parent().(*Core) if !settings.Enabled { core.UpdateSyncer(zapcore.AddSync(io.Discard)) return nil @@ -38,6 +40,11 @@ func overrideCoreWithConfig(core *Core, settings LogSettings) error { } core.SetLevel(level) + err = filteringCore.Rebuild(settings.Namespaces) + if err != nil { + return err + } + 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 diff --git a/logutils/override_test.go b/logutils/override_test.go index 37decf5d1..f0e14801a 100644 --- a/logutils/override_test.go +++ b/logutils/override_test.go @@ -65,7 +65,7 @@ func TestOverrideCoreWithConfig(t *testing.T) { zapcore.AddSync(io.Discard), zap.NewAtomicLevelAt(zap.InfoLevel), ) - err := overrideCoreWithConfig(core, tt.settings) + err := overrideCoreWithConfig(newNamespaceFilteringCore(core), tt.settings) if tt.expectError { require.Error(t, err) } else { diff --git a/nodecfg/node_config.go b/nodecfg/node_config.go index d3dd4441f..3a4c12f77 100644 --- a/nodecfg/node_config.go +++ b/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, log_dir, log_level, max_backups, max_size, + enabled, log_dir, log_level, log_namespaces, max_backups, max_size, file, compress_rotated, log_to_stderr, synthetic_id - ) VALUES (?, ?, ?, ?, ?, ?, ?, ?, 'id' )`, - c.LogEnabled, c.LogDir, c.LogLevel, c.LogMaxBackups, c.LogMaxSize, + ) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, 'id')`, + c.LogEnabled, c.LogDir, c.LogLevel, c.LogNamespaces, 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, 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) + err = tx.QueryRow("SELECT enabled, log_dir, log_level, log_namespaces, 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.LogNamespaces, &nodecfg.LogFile, &nodecfg.LogMaxBackups, &nodecfg.LogMaxSize, &nodecfg.LogCompressRotated, &nodecfg.LogToStderr) if err != nil && err != sql.ErrNoRows { return nil, err } @@ -791,6 +791,11 @@ func SetLogLevel(db *sql.DB, logLevel string) error { return err } +func SetLogNamespaces(db *sql.DB, logNamespaces string) error { + _, err := db.Exec(`UPDATE log_config SET log_namespaces = ?`, logNamespaces) + return err +} + func SetMaxLogBackups(db *sql.DB, maxLogBackups uint) error { _, err := db.Exec(`UPDATE log_config SET max_backups = ?`, maxLogBackups) return err diff --git a/params/config.go b/params/config.go index c2fdbc892..ca3ee5bf9 100644 --- a/params/config.go +++ b/params/config.go @@ -426,6 +426,10 @@ type NodeConfig struct { // LogLevel defines minimum log level. Valid names are "ERROR", "WARN", "INFO", "DEBUG", and "TRACE". LogLevel string `validate:"eq=ERROR|eq=WARN|eq=INFO|eq=DEBUG|eq=TRACE"` + // LogNamespaces defines log level per namespace. Example: "namespace1:debug,namespace2.namespace3:error" + // It doesn't affect LogLevel for unmentioned namespaces. + LogNamespaces string + // LogMaxBackups defines number of rotated log files that will be stored. LogMaxBackups int @@ -1196,6 +1200,7 @@ func (c *NodeConfig) LogSettings() logutils.LogSettings { return logutils.LogSettings{ Enabled: c.LogEnabled, Level: c.LogLevel, + Namespaces: c.LogNamespaces, File: c.LogFile, MaxSize: c.LogMaxSize, MaxBackups: c.LogMaxBackups, diff --git a/protocol/messenger_settings.go b/protocol/messenger_settings.go index b42337862..bb3f7f350 100644 --- a/protocol/messenger_settings.go +++ b/protocol/messenger_settings.go @@ -38,6 +38,14 @@ func (m *Messenger) SetLogLevel(request *requests.SetLogLevel) error { return nodecfg.SetLogLevel(m.database, request.LogLevel) } +func (m *Messenger) SetLogNamespaces(request *requests.SetLogNamespaces) error { + if err := request.Validate(); err != nil { + return err + } + + return nodecfg.SetLogNamespaces(m.database, request.LogNamespaces) +} + func (m *Messenger) SetMaxLogBackups(request *requests.SetMaxLogBackups) error { return nodecfg.SetMaxLogBackups(m.database, request.MaxLogBackups) } diff --git a/protocol/requests/set_log_namespaces.go b/protocol/requests/set_log_namespaces.go new file mode 100644 index 000000000..3e9bb4c68 --- /dev/null +++ b/protocol/requests/set_log_namespaces.go @@ -0,0 +1,11 @@ +package requests + +import "github.com/status-im/status-go/logutils" + +type SetLogNamespaces struct { + LogNamespaces string `json:"logNamespaces"` +} + +func (c *SetLogNamespaces) Validate() error { + return logutils.ValidateNamespaces(c.LogNamespaces) +} diff --git a/services/ext/api.go b/services/ext/api.go index 93a3b12cb..e516882d5 100644 --- a/services/ext/api.go +++ b/services/ext/api.go @@ -1808,10 +1808,28 @@ func (api *PublicAPI) SetLogLevel(request *requests.SetLogLevel) error { return api.service.messenger.SetLogLevel(request) } +func (api *PublicAPI) SetLogNamespaces(request *requests.SetLogNamespaces) error { + return api.service.messenger.SetLogNamespaces(request) +} + func (api *PublicAPI) SetMaxLogBackups(request *requests.SetMaxLogBackups) error { return api.service.messenger.SetMaxLogBackups(request) } +func (api *PublicAPI) LogTest() error { + l1 := logutils.ZapLogger().Named("test1") + l2 := l1.Named("test2") + l3 := l2.Named("test3") + + for level := zap.DebugLevel; level <= zap.ErrorLevel; level++ { + for _, logger := range []*zap.Logger{l1, l2, l3} { + logger.Check(level, "test message").Write(zap.String("level", level.String())) + } + } + + return l1.Sync() +} + func (api *PublicAPI) SetCustomNodes(request *requests.SetCustomNodes) error { return api.service.messenger.SetCustomNodes(request) } diff --git a/tests-functional/clients/status_backend.py b/tests-functional/clients/status_backend.py index c6da1abfe..989a0f875 100644 --- a/tests-functional/clients/status_backend.py +++ b/tests-functional/clients/status_backend.py @@ -63,30 +63,34 @@ class StatusBackend(RpcClient, SignalClient): def init_status_backend(self, data_dir="/"): method = "InitializeApplication" data = { - "dataDir": data_dir + "dataDir": data_dir, } return self.api_valid_request(method, data) - def create_account_and_login(self, display_name=DEFAULT_DISPLAY_NAME, password=user_1.password): - data_dir = f"dataDir_{datetime.now().strftime('%Y%m%d_%H%M%S')}" + def create_account_and_login(self, data_dir="/", display_name=DEFAULT_DISPLAY_NAME, password=user_1.password): method = "CreateAccountAndLogin" data = { "rootDataDir": data_dir, "kdfIterations": 256000, "displayName": display_name, "password": password, - "customizationColor": "primary" + "customizationColor": "primary", + "logEnabled": True, + "logLevel": "INFO", } return self.api_valid_request(method, data) - def restore_account_and_login(self, display_name=DEFAULT_DISPLAY_NAME, user=user_1): + def restore_account_and_login(self, data_dir="/",display_name=DEFAULT_DISPLAY_NAME, user=user_1): method = "RestoreAccountAndLogin" data = { - "rootDataDir": "/", + "rootDataDir": data_dir, + "kdfIterations": 256000, "displayName": display_name, "password": user.password, "mnemonic": user.passphrase, "customizationColor": "blue", + "logEnabled": True, + "logLevel": "INFO", "testNetworksEnabled": True, "networkId": 31337, "networksOverride": [ @@ -107,6 +111,19 @@ class StatusBackend(RpcClient, SignalClient): } return self.api_valid_request(method, data) + def login(self, keyUid, user=user_1): + method = "LoginAccount" + data = { + "password": user.password, + "keyUid": keyUid, + "kdfIterations": 256000, + } + return self.api_valid_request(method, data) + + def logout(self, user=user_1): + method = "Logout" + return self.api_valid_request(method, {}) + def restore_account_and_wait_for_rpc_client_to_start(self, timeout=60): self.restore_account_and_login() start_time = time.time() @@ -166,4 +183,4 @@ class StatusBackend(RpcClient, SignalClient): method = "wakuext_sendOneToOneMessage" response = self.rpc_request(method, params) self.verify_is_valid_json_rpc_response(response) - return response.json() \ No newline at end of file + return response.json() diff --git a/tests-functional/tests/test_logging.py b/tests-functional/tests/test_logging.py new file mode 100644 index 000000000..d47d0ddbf --- /dev/null +++ b/tests-functional/tests/test_logging.py @@ -0,0 +1,63 @@ +import re +import time +from test_cases import StatusBackend +import pytest +import os + +@pytest.mark.rpc +@pytest.mark.skip("waiting for status-backend to be executed on the same host/container") +class TestLogging: + + @pytest.mark.init + def test_logging(self, tmp_path): + await_signals = [ + "mediaserver.started", + "node.started", + "node.ready", + "node.login", + ] + + backend_client = StatusBackend(await_signals) + assert backend_client is not None + + # Init and login + backend_client.init_status_backend(data_dir=str(tmp_path)) + backend_client.create_account_and_login(data_dir=str(tmp_path)) + key_uid = self.ensure_logged_in(backend_client) + + # Configure logging + backend_client.rpc_valid_request("wakuext_setLogLevel", [{"logLevel": "ERROR"}]) + backend_client.rpc_valid_request("wakuext_setLogNamespaces", [{"logNamespaces": "test1.test2:debug,test1.test2.test3:info"}]) + + # Re-login (logging settings take effect after re-login) + backend_client.logout() + backend_client.login(str(key_uid)) + self.ensure_logged_in(backend_client) + + # Test logging + backend_client.rpc_valid_request("wakuext_logTest") + self.expect_logs(tmp_path / "geth.log", "test message", [ + r"DEBUG\s+test1\.test2", + r"INFO\s+test1\.test2", + r"INFO\s+test1\.test2\.test3", + r"WARN\s+test1\.test2", + r"WARN\s+test1\.test2\.test3", + r"ERROR\s+test1", + r"ERROR\s+test1\.test2", + r"ERROR\s+test1\.test2\.test3", + ]) + + def expect_logs(self, log_file, filter_keyword, expected_logs): + with open(log_file, 'r') as f: + log_content = f.read() + + filtered_logs = [line for line in log_content.splitlines() if filter_keyword in line] + for expected_log in expected_logs: + assert any(re.search(expected_log, log) for log in filtered_logs), f"Log entry not found: {expected_log}" + + def ensure_logged_in(self, backend_client): + login_response = backend_client.wait_for_signal("node.login") + backend_client.verify_json_schema(login_response, "signal_node_login") + key_uid = login_response.get("event", {}).get("account", {}).get("key-uid") + assert key_uid is not None, "key-uid not found in login response" + return key_uid