Logging overhaul #4375

pwojcikdev · 2024-01-19T14:05:43Z

This pull request improves the logging functionality of the codebase. The new logger class aims to simplify the logging process and make it more consistent. The new logger class is using spdlog library under the hood and fmt library for formatting, with format string syntax compatible with C++20 std::format.

Out of the box, the interface presented to node administrators should be clearer and more intuitive. Each log line is categorized by node component with color coding for different log levels. The output can be configured to be written to a file, with automatic rotation and size limit. The default verbosity when running node in daemon mode is info.

Configuration

There are two ways to configure the logger. The first is to use config-log.toml file, which is located in the data directory alongside other configuration files. The second is to use NANO_LOG and NANO_LOG_LEVELS environment variables. The environment variables take precedence over the configuration file.

Configuration File `config-log.toml`

During normal node operation, the configuration file is loaded from the data directory. When running testsuites, the configuration is loaded from current working directory.

[log]
#default_level = "info"

[log.console]
#colors = true
#enable = true
#to_cerr = false

[log.file]
#enable = true
#max_size = 33554432
#rotation_count = 4

[log.levels]
#active_transactions = "info"
#all = "info"
#blockprocessor = "info"
#bootstrap = "info"
#bootstrap_lazy = "info"
#...

Environment Variables

Envionment variables override the configuration file. This is useful when running testsuites.

# Set default log level
NANO_LOG = [trace|debug|info|warn|error|critical|off]

# Set log level for individual loggers
NANO_LOG_LEVELS = logger_1=level_1[,logger_2=level_2,...]

export NANO_LOG=warn
export NANO_LOG_LEVELS=active_transactions=debug,bootstrap=debug

Unit tests

By default, the logger is disabled when running unit tests to keep the output clean. To enable it, set NANO_LOG environment variable to a desired log level.
In testsuite mode, each logline additionally contains the identifier of the node that produced the logline (first 10 characters of its node ID). This makes it easier to follow the flow of events and will become much more useful once full tracing is implemented.

Future Work

Originaly, the plan was to include both logging and tracing functionality in this pull request. However, since the amount of changes is already quite large, I decided to split the work into two pull requests. There might be some previous logging calls that were not converted to the new logger class and those should be converted into tracing calls.

I also plan to allow log calls to be divided into different categories, so that the node administrators can configure the verbosity of each category that can span multiple components.

RickiNano · 2024-01-21T10:51:13Z

nano/nano_node/daemon.cpp

-			std::cout << initialization_text << std::endl;
-			logger.always_log (initialization_text);
+			// This avoids a blank prompt during any node initialization delays
+			logger.info (nano::log::type::daemon, "Starting up Nano node...");


I think we should keep these startup messages as std::cout to make sure the initialization process is shown in the console even when configured for file logging

I believe if someone explicitly wants to disable console output for whatever reason then we should not print anything

clemahieu

My comments are mostly minor or subtle behaviour changes I noticed that don't need changing.

I was wondering about the performance since previously we short-circuited log message construction with a boolean check before constructing the actual message. I see that the spdlog library implementation forwards all of the log message arguments and checks if that particular logger is enabled before constructing the log message so I don't see this as a problem.

Very nice overhaul.

clemahieu · 2024-01-20T10:13:02Z

nano/lib/config.cpp

+	};
+
+	// First try to load config from the current working directory, then from the node data directory
+	if (auto toml = try_load_toml (config_filename); toml)


The "; toml" isn't needed as the assignment expression will yield the assigned value

nano/lib/logging.cpp

nano/nano_node/daemon.cpp

nano/node/bootstrap/bootstrap_bulk_pull.cpp

nano/node/transport/socket.cpp

nano/node/node.cpp

nano/lib/logging.cpp

dsiganos · 2024-01-24T08:58:27Z

nano/lib/config.hpp

@@ -404,4 +408,28 @@ bool is_sanitizer_build ();

 /** Set the active network to the dev network */
 void force_nano_dev_network ();
+
+/**
+ * Attempt to read a configuration file from specified directory. Returns empty tomlconfig if nothing is found.


I think it returns a file containing the overrides, if overrides are specified.

dsiganos · 2024-01-25T09:25:09Z

nano/lib/logging_enums.hpp

+
+enum class type
+{
+	all = 0, // reserved


Can you add a comment to explain what happens when someone sets the "all" log type?

It currently functions as every other logger type. The all has a special meaning for details where it allows to specify verbosity of type::detail logger separately from that for the whole type. It's currently used for tracing to limit the amount of unnecessary noise.

dsiganos · 2024-01-25T09:25:42Z

nano/lib/logging_enums.hpp

+	bootstrap_legacy,
+};
+
+enum class detail


We need an example of how a detail would be used.

dsiganos · 2024-01-25T09:32:25Z

nano/lib/logging.cpp

+	else
+	{
+		auto logger_type = logger_name.substr (0, pos);
+		auto logger_detail = logger_name.substr (pos + 1);


BUG: it should be: pos + 2

dsiganos · 2024-01-25T09:38:09Z

nano/lib/logging.cpp

+	}
+	catch (std::runtime_error const & ex)
+	{
+		std::cerr << "Unable to load log config. Using defaults. Error: " << ex.what () << std::endl;


Errors with config-log.toml are generally ignored and the program simply prints a message on seder and continues. In order to achieve that, we have extra try/catch blocks than would be necessary if we simply said that any log config errors will cause the program terminate. Why not follow the simplest approach of terminating the program if the log config has a problem?

Log types and details change often during development and experimentation phase. Terminating when any error is encountered is just a bad user experience. And logging is not critical to proper node function.

dsiganos · 2024-01-25T09:57:08Z

nano/lib/tomlconfig.hpp

@@ -171,6 +171,19 @@ class tomlconfig : public nano::configbase
 		return *this;
 	}

+	template <typename T>


It would be nice to have a comment explaining what this functions does.
For example, what happens to non-string entries in the log file?

nano/lib/utility.hpp

nano/node/blockprocessor.cpp

dsiganos · 2024-01-25T11:37:41Z

nano/secure/utility.cpp

@@ -60,15 +63,6 @@ void nano::remove_temporary_directories ()
 		{
 			std::cerr << "Could not remove temporary directory: " << ec.message () << std::endl;
 		}
-


This is a serious change of behaviour and not a logging change.
I personally agree with the change but it should not had been part of the logging PR because this affects node operators.

Can you explain how this affects node operators? I only saw this function used in unit testing. Generally there was badly implemented code, fixing badly implemented code that culminated in some strange bugs when I needed to ensure orderly node initialization.

…o th elogging overhaul in nanocurrency#4375

milahu · 2024-07-15T17:47:19Z

nano/nano_wallet/entry.cpp

@@ -25,13 +26,18 @@

 namespace
 {
+nano::logger logger{ "wallet_daemon" };


in #4679 this runs before main and breaks the assertion

nano::logger::logger (std::string identifier) : identifier{ std::move (identifier) } { release_assert (global_initialized, "logging should be initialized before creating a logger"); }

Right, I'm surprised this works on develop. I will look into it, thanks!

pwojcikdev added 19 commits January 19, 2024 14:55

Add fmt & spdlog submodules

3b79c84

Add helper functions for configuration file loading

b770297

Fix cpptoml

8f42544

Add tomlconfig::get_values ()

3be5759

Introduce new logger

6911a2d

Replace legacy logging calls

24b0d9a

Remove legacy logger

4a26ca7

Generate sample log config

11eadb0

Load node id during node initialization

035c365

Special log formatter for running tests

cbda858

Fix unique directories usage in tests

61ff7f4

Load log levels from environment variables

de28085

Store log files in node data path

8e75420

Fix setting socket local endpoint

d015478

Create log files when running node with --initialize

c14ed4c

Fix wallet.import test

f42beb8

Rename back to nano::logger

f4fee1d

Remove leftover boost::log reference

81c598b

Missing nano_lib link

a97cbff

qwahzi mentioned this pull request Jan 21, 2024

Node logging framework #4260

Closed

RickiNano reviewed Jan 21, 2024

View reviewed changes

qwahzi added this to the V27 milestone Jan 21, 2024

Fix deserialization of config with default values

cef74b9

clemahieu previously approved these changes Jan 21, 2024

View reviewed changes

Fixes & comments

b4eb3a0

pwojcikdev dismissed clemahieu’s stale review via b4eb3a0 January 22, 2024 18:40

pwojcikdev added documentation This item indicates the need for or supplies updated or expanded documentation configuration default change Change to default configuration values labels Jan 22, 2024

Warning about using cerr with colors

81e6b57

pwojcikdev merged commit b225de0 into nanocurrency:develop Jan 24, 2024
16 of 19 checks passed

dsiganos reviewed Jan 25, 2024

View reviewed changes

dsiganos mentioned this pull request Feb 7, 2024

Document the new logging and tracing system on nano docs nanocurrency/nano-docs#695

Open

gr0vity-dev pushed a commit to gr0vity-dev/nano-node that referenced this pull request Jul 4, 2024

Remove -l option. Logging to stdout works by default since we moved t…

eaa5b87

…o th elogging overhaul in nanocurrency#4375

gr0vity-dev mentioned this pull request Jul 4, 2024

Documentation for V27 logging & tracing nanocurrency/nano-docs#704

Merged

milahu mentioned this pull request Jul 15, 2024

use shared libraries #4679

Draft

milahu reviewed Jul 15, 2024

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Logging overhaul #4375

Logging overhaul #4375

pwojcikdev commented Jan 19, 2024 •

edited

Loading

RickiNano Jan 21, 2024

pwojcikdev Jan 21, 2024

clemahieu left a comment

clemahieu Jan 20, 2024

dsiganos Jan 24, 2024

dsiganos Jan 25, 2024

pwojcikdev Jan 25, 2024

dsiganos Jan 25, 2024

dsiganos Jan 25, 2024

dsiganos Jan 25, 2024

pwojcikdev Jan 25, 2024 •

edited

Loading

dsiganos Jan 25, 2024

dsiganos Jan 25, 2024

pwojcikdev Jan 25, 2024

milahu Jul 15, 2024

pwojcikdev Jul 15, 2024

Logging overhaul #4375

Logging overhaul #4375

Conversation

pwojcikdev commented Jan 19, 2024 • edited Loading

Configuration

Configuration File config-log.toml

Environment Variables

Unit tests

Future Work

Choose a reason for hiding this comment

Choose a reason for hiding this comment

clemahieu left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

pwojcikdev Jan 25, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

pwojcikdev commented Jan 19, 2024 •

edited

Loading

Configuration File `config-log.toml`

pwojcikdev Jan 25, 2024 •

edited

Loading