From 24582b65e1c9f0a793f2640878b8d80e2a6e805a Mon Sep 17 00:00:00 2001 From: Thomas Haller Date: Thu, 25 Feb 2016 17:21:29 +0100 Subject: [PATCH] logging: change logging format to drop "[file:line] func():" part Choose a new logging format. - the logging format must not be configurable and it must be the same for all backends. It is neat that journal supports additional fields, but an average user still posts the output of plain journalctl, without "--output verbose" (which would also be hard to read). Also, we get used to a certain logging format, so having different formats is confusing. If one format is better then another, it should be used for all backends: syslog, journal and debug. The only question is, what is the best format. - the timestamp: I find it useful to see how much time between two events passed. The timestamp printed by syslog doesn't have sufficient granularity, and the internal journal fields are not readily available. We used to print the timestamps for , and , but ommited them for and levels. We now print them for all levels, which has a uniform alignment. - the location: the "[file:line] func():" part is mostly redundant and results in wide lines. It also causes a misalignment of the logging lines, or -- as I recently added alignment of the location -- it results in awkward whitespace and truncation. But the location is really just necessary because our logging messages are bad: " [1456397604.038226] (9) 11-dhclient succeeded" The solution to this is not " [1456397604.038226] [nm-dispatcher.c:358] dispatcher_results_process(): (9) 11-dhclient succeeded" but a properly worded message: " [1456397604.038226] dispatcher: request #9, script 11-dhclient succeeded" - logging-message: we need to write better logging messages. I like some form of "tags" that are easy to grep: "platform: signal: link changed: 4: ..." Downside is, that this is not nice to read as a full sentence. So, especially for and logging, more human readable messages are better. We should find a compromise, where the log message explains what happens, but is still concise and contains patterns that are easy to grep and identify visually. https://mail.gnome.org/archives/networkmanager-list/2016-February/msg00077.html --- configure.ac | 2 +- man/NetworkManager.conf.xml.in | 5 +---- src/nm-logging.c | 11 +++++------ src/settings/plugins/keyfile/tests/test-keyfile.c | 10 +++++----- 4 files changed, 12 insertions(+), 16 deletions(-) diff --git a/configure.ac b/configure.ac index 0f270ceb4b..f945c6fad6 100644 --- a/configure.ac +++ b/configure.ac @@ -397,7 +397,7 @@ if test "$nm_config_logging_backend_default" != 'debug' \ fi if test "$nm_config_logging_backend_default" = ""; then if test "$have_systemd_journal" = "yes"; then - nm_config_logging_backend_default='journal-syslog-style' + nm_config_logging_backend_default='journal' else nm_config_logging_backend_default='syslog' fi diff --git a/man/NetworkManager.conf.xml.in b/man/NetworkManager.conf.xml.in index 75e1d93807..1f8316cc87 100644 --- a/man/NetworkManager.conf.xml.in +++ b/man/NetworkManager.conf.xml.in @@ -483,11 +483,8 @@ unmanaged-devices=mac:00:22:68:1c:59:b1;mac:00:1E:65:30:D1:C4;interface-name:eth backend The logging backend. Supported values are "debug", "syslog", - "journal" and "journal-syslog-style. + "journal". "debug" uses syslog and logs to standard error. - "journal-syslog-style" prints the same message to journal - as it would print for "syslog", containing redundant - fields in the text. If NetworkManager is started in debug mode (--debug) this option is ignored and "debug" is always used. Otherwise, the default is "@NM_CONFIG_LOGGING_BACKEND_DEFAULT_TEXT@". diff --git a/src/nm-logging.c b/src/nm-logging.c index 5bb3660fa2..05bb10c707 100644 --- a/src/nm-logging.c +++ b/src/nm-logging.c @@ -73,6 +73,8 @@ typedef enum { LOG_FORMAT_FLAG_LOCATION_DEBUG | LOG_FORMAT_FLAG_LOCATION_ERROR | LOG_FORMAT_FLAG_ALIGN_LOCATION, + + _LOG_FORMAT_FLAG_DEFAULT = _LOG_FORMAT_FLAG_TIMESTAMP, } LogFormatFlags; void (*_nm_logging_clear_platform_logging_cache) (void); @@ -116,6 +118,7 @@ static struct { } global = { .log_level = LOGL_INFO, .log_backend = LOG_BACKEND_GLIB, + .log_format_flags = _LOG_FORMAT_FLAG_DEFAULT, .level_desc = { [LOGL_TRACE] = { "TRACE", "", LOG_DEBUG, G_LOG_LEVEL_DEBUG, _LOG_FORMAT_FLAG_LEVEL_DEBUG }, [LOGL_DEBUG] = { "DEBUG", "", LOG_INFO, G_LOG_LEVEL_DEBUG, _LOG_FORMAT_FLAG_LEVEL_DEBUG }, @@ -751,16 +754,13 @@ nm_logging_syslog_openlog (const char *logging_backend) if (!logging_backend) logging_backend = ""NM_CONFIG_LOGGING_BACKEND_DEFAULT; + log_format_flags = _LOG_FORMAT_FLAG_DEFAULT; + if (strcmp (logging_backend, "debug") == 0) { global.log_backend = LOG_BACKEND_SYSLOG; openlog (G_LOG_DOMAIN, LOG_CONS | LOG_PERROR | LOG_PID, LOG_USER); - log_format_flags = _LOG_FORMAT_FLAG_SYSLOG; #if SYSTEMD_JOURNAL } else if (strcmp (logging_backend, "syslog") != 0) { - if (strcmp (logging_backend, "journal-syslog-style") == 0) - log_format_flags = _LOG_FORMAT_FLAG_SYSLOG; - else - log_format_flags = _LOG_FORMAT_FLAG_TIMESTAMP; global.log_backend = LOG_BACKEND_JOURNAL; /* ensure we read a monotonic timestamp. Reading the timestamp the first @@ -769,7 +769,6 @@ nm_logging_syslog_openlog (const char *logging_backend) #endif } else { global.log_backend = LOG_BACKEND_SYSLOG; - log_format_flags = _LOG_FORMAT_FLAG_SYSLOG; openlog (G_LOG_DOMAIN, LOG_PID, LOG_DAEMON); } diff --git a/src/settings/plugins/keyfile/tests/test-keyfile.c b/src/settings/plugins/keyfile/tests/test-keyfile.c index c1b79ef7d7..a9df4e2b02 100644 --- a/src/settings/plugins/keyfile/tests/test-keyfile.c +++ b/src/settings/plugins/keyfile/tests/test-keyfile.c @@ -1514,9 +1514,9 @@ test_read_wired_8021x_tls_blob_connection (void) GBytes *blob; g_test_expect_message ("NetworkManager", G_LOG_LEVEL_WARNING, - "* keyfile: 802-1x.client-cert: certificate or key file '/CASA/dcbw/Desktop/certinfra/client.pem' does not exist*"); + "* * keyfile: 802-1x.client-cert: certificate or key file '/CASA/dcbw/Desktop/certinfra/client.pem' does not exist*"); g_test_expect_message ("NetworkManager", G_LOG_LEVEL_WARNING, - "* keyfile: 802-1x.private-key: certificate or key file '/CASA/dcbw/Desktop/certinfra/client.pem' does not exist*"); + "* * keyfile: 802-1x.private-key: certificate or key file '/CASA/dcbw/Desktop/certinfra/client.pem' does not exist*"); connection = nm_keyfile_plugin_connection_from_file (TEST_KEYFILES_DIR "/Test_Wired_TLS_Blob", &error); g_assert_no_error (error); g_assert (connection); @@ -1632,11 +1632,11 @@ test_read_wired_8021x_tls_old_connection (void) gboolean success; g_test_expect_message ("NetworkManager", G_LOG_LEVEL_WARNING, - "* keyfile: 802-1x.ca-cert: certificate or key file '/CASA/dcbw/Desktop/certinfra/CA/eaptest_ca_cert.pem' does not exist*"); + "* * keyfile: 802-1x.ca-cert: certificate or key file '/CASA/dcbw/Desktop/certinfra/CA/eaptest_ca_cert.pem' does not exist*"); g_test_expect_message ("NetworkManager", G_LOG_LEVEL_WARNING, - "* keyfile: 802-1x.client-cert: certificate or key file '/CASA/dcbw/Desktop/certinfra/client.pem' does not exist*"); + "* * keyfile: 802-1x.client-cert: certificate or key file '/CASA/dcbw/Desktop/certinfra/client.pem' does not exist*"); g_test_expect_message ("NetworkManager", G_LOG_LEVEL_WARNING, - "* keyfile: 802-1x.private-key: certificate or key file '/CASA/dcbw/Desktop/certinfra/client.pem' does not exist*"); + "* * keyfile: 802-1x.private-key: certificate or key file '/CASA/dcbw/Desktop/certinfra/client.pem' does not exist*"); connection = nm_keyfile_plugin_connection_from_file (TEST_KEYFILES_DIR "/Test_Wired_TLS_Old", &error); g_assert_no_error (error); g_assert (connection);