[PATCH 1/1] logging: change logging format to drop "[file:line] func():" part

[Thomas Haller <thaller redhat com>]

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 <error>, <debug> and <trace>,
  but ommited them for <info> and <warn> levels. We now print them for
  all levels, also to preserve 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 there because our logging messages
  are bad:
    "<debug> [1456397604.038226] (9) 11-dhclient succeeded"
  The solutoin to this is not
    "<debug> [1456397604.038226] [nm-dispatcher.c:358] dispatcher_results_process(): (9) 11-dhclient 
succeeded"
  but a properly worded message:
    "<debug> [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 <info> and <warn> logging, more human readable
  messages are better.
  We should find a compromise, where the log message explains what
  happens, but still contains common patterns that can be nicely
  grepped and identified visually.
---
 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 db36cb3..bbe0634 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 75e1d93..1f8316c 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
           <term><varname>backend</varname></term>
           <listitem><para>The logging backend. Supported values
           are "<literal>debug</literal>", "<literal>syslog</literal>",
-          "<literal>journal</literal>" and "<literal>journal-syslog-style</literal>.
+          "<literal>journal</literal>".
           "<literal>debug</literal>" uses syslog and logs to standard error.
-          "<literal>journal-syslog-style</literal>" prints the same message to journal
-          as it would print for "<literal>syslog</literal>", containing redundant
-          fields in the text.
           If NetworkManager is started in debug mode (<literal>--debug</literal>)
           this option is ignored and "<literal>debug</literal>" is always used.
           Otherwise, the default is "<literal>@NM_CONFIG_LOGGING_BACKEND_DEFAULT_TEXT@</literal>".
diff --git a/src/nm-logging.c b/src/nm-logging.c
index 4e56723..68feb32 100644
--- a/src/nm-logging.c
+++ b/src/nm-logging.c
@@ -69,6 +69,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;
 
 static void
@@ -110,6 +112,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", "<trace>", LOG_DEBUG,   G_LOG_LEVEL_DEBUG,   
_LOG_FORMAT_FLAG_LEVEL_DEBUG },
                [LOGL_DEBUG] = { "DEBUG", "<debug>", LOG_INFO,    G_LOG_LEVEL_DEBUG,   
_LOG_FORMAT_FLAG_LEVEL_DEBUG },
@@ -744,16 +747,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
@@ -762,7 +762,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 7758724..19da7c6 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,
-                              "*<warn>  keyfile: 802-1x.client-cert: certificate or key file 
'/CASA/dcbw/Desktop/certinfra/client.pem' does not exist*");
+                              "*<warn> * 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,
-                              "*<warn>  keyfile: 802-1x.private-key: certificate or key file 
'/CASA/dcbw/Desktop/certinfra/client.pem' does not exist*");
+                              "*<warn> * 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,
-                              "*<warn>  keyfile: 802-1x.ca-cert: certificate or key file 
'/CASA/dcbw/Desktop/certinfra/CA/eaptest_ca_cert.pem' does not exist*");
+                              "*<warn> * 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,
-                              "*<warn>  keyfile: 802-1x.client-cert: certificate or key file 
'/CASA/dcbw/Desktop/certinfra/client.pem' does not exist*");
+                              "*<warn> * 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,
-                              "*<warn>  keyfile: 802-1x.private-key: certificate or key file 
'/CASA/dcbw/Desktop/certinfra/client.pem' does not exist*");
+                              "*<warn> * 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);
-- 
2.5.0