Merge pull request #4867 from keszybz/catalog-messages

Catalog message improvements

catalog/systemd.catalog.in

@@ -172,8 +172,8 @@ Defined-By: systemd
 Support: %SUPPORT_URL%
 
 All system services necessary queued for starting at boot have been
-successfully started. Note that this does not mean that the machine is
+started. Note that this does not mean that the machine is now idle as services
-now idle as services might still be busy with completing start-up.
+might still be busy with completing start-up.
 
 Kernel start-up required @KERNEL_USEC@ microseconds.
 
@@ -181,6 +181,17 @@ Initial RAM disk start-up required @INITRD_USEC@ microseconds.
 
 Userspace start-up required @USERSPACE_USEC@ microseconds.
 
+-- eed00a68ffd84e31882105fd973abdd1
+Subject: User manager start-up is now complete
+Defined-By: systemd
+Support: %SUPPORT_URL%
+
+The user manager instance for user @_UID@ has been started. All services queued
+for starting have been started. Note that other services might still be starting
+up or be started at any later time.
+
+Startup of the manager took @USERSPACE_USEC@ microseconds.
+
 -- 6bbd95ee977941e497c48be27c254128
 Subject: System sleep state @SLEEP@ entered
 Defined-By: systemd

src/basic/log.c

@@ -500,7 +500,7 @@ static int log_do_header(
                  line ? "CODE_LINE=" : "",
                  line ? 1 : 0, line, /* %.0d means no output too, special case for 0 */
                  line ? "\n" : "",
-                 isempty(func) ? "" : "CODE_FUNCTION=",
+                 isempty(func) ? "" : "CODE_FUNC=",
                  isempty(func) ? "" : func,
                  isempty(func) ? "" : "\n",
                  error ? "ERRNO=" : "",
@@ -1134,8 +1134,8 @@ int log_syntax_internal(
 
         PROTECT_ERRNO;
         char buffer[LINE_MAX];
-        int r;
         va_list ap;
+        const char *unit_fmt = NULL;
 
         if (error < 0)
                 error = -error;
@@ -1154,24 +1154,15 @@ int log_syntax_internal(
         va_end(ap);
 
         if (unit)
-                r = log_struct_internal(
+                unit_fmt = getpid() == 1 ? "UNIT=%s" : "USER_UNIT=%s";
-                                level, error,
-                                file, line, func,
-                                getpid() == 1 ? "UNIT=%s" : "USER_UNIT=%s", unit,
-                                LOG_MESSAGE_ID(SD_MESSAGE_INVALID_CONFIGURATION),
-                                "CONFIG_FILE=%s", config_file,
-                                "CONFIG_LINE=%u", config_line,
-                                LOG_MESSAGE("[%s:%u] %s", config_file, config_line, buffer),
-                                NULL);
-        else
-                r = log_struct_internal(
-                                level, error,
-                                file, line, func,
-                                LOG_MESSAGE_ID(SD_MESSAGE_INVALID_CONFIGURATION),
-                                "CONFIG_FILE=%s", config_file,
-                                "CONFIG_LINE=%u", config_line,
-                                LOG_MESSAGE("[%s:%u] %s", config_file, config_line, buffer),
-                                NULL);
 
-        return r;
+        return log_struct_internal(
+                        level, error,
+                        file, line, func,
+                        LOG_MESSAGE_ID(SD_MESSAGE_INVALID_CONFIGURATION),
+                        "CONFIG_FILE=%s", config_file,
+                        "CONFIG_LINE=%u", config_line,
+                        LOG_MESSAGE("%s:%u: %s", config_file, config_line, buffer),
+                        unit_fmt, unit,
+                        NULL);
 }

src/core/manager.c

@@ -2950,7 +2950,7 @@ static void manager_notify_finished(Manager *m) {
                 total_usec = userspace_usec = m->finish_timestamp.monotonic - m->userspace_timestamp.monotonic;
 
                 log_struct(LOG_INFO,
-                           LOG_MESSAGE_ID(SD_MESSAGE_STARTUP_FINISHED),
+                           LOG_MESSAGE_ID(SD_MESSAGE_USER_STARTUP_FINISHED),
                            "USERSPACE_USEC="USEC_FMT, userspace_usec,
                            LOG_MESSAGE("Startup finished in %s.",
                                        format_timespan(sum, sizeof(sum), total_usec, USEC_PER_MSEC)),

src/systemd/sd-messages.h

@@ -53,6 +53,7 @@ _SD_BEGIN_DECLARATIONS;
 #define SD_MESSAGE_TIMEZONE_CHANGE  SD_ID128_MAKE(45,f8,2f,4a,ef,7a,4b,bf,94,2c,e8,61,d1,f2,09,90)
 
 #define SD_MESSAGE_STARTUP_FINISHED SD_ID128_MAKE(b0,7a,24,9c,d0,24,41,4a,82,dd,00,cd,18,13,78,ff)
+#define SD_MESSAGE_USER_STARTUP_FINISHED SD_ID128_MAKE(ee,d0,0a,68,ff,d8,4e,31,88,21,05,fd,97,3a,bd,d1)
 
 #define SD_MESSAGE_SLEEP_START      SD_ID128_MAKE(6b,bd,95,ee,97,79,41,e4,97,c4,8b,e2,7c,25,41,28)
 #define SD_MESSAGE_SLEEP_STOP       SD_ID128_MAKE(88,11,e6,df,2a,8e,40,f5,8a,94,ce,a2,6f,8e,bf,14)

tools/catalog-report.py

@@ -0,0 +1,87 @@
+#!/usr/bin/python3
+# -*- Mode: python; coding: utf-8; indent-tabs-mode: nil -*- */
+#
+# This file is part of systemd. It is distrubuted under the MIT license, see
+# below.
+#
+# Copyright 2016 Zbigniew Jędrzejewski-Szmek
+#
+# The MIT License (MIT)
+#
+# Permission is hereby granted, free of charge, to any person obtaining a copy
+# of this software and associated documentation files (the "Software"), to deal
+# in the Software without restriction, including without limitation the rights
+# to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
+# copies of the Software, and to permit persons to whom the Software is
+# furnished to do so, subject to the following conditions:
+#
+# The above copyright notice and this permission notice shall be included in
+# all copies or substantial portions of the Software.
+#
+# THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+# IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
+# FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
+# AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
+# LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
+# OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE
+# SOFTWARE.
+
+"""
+Prints out journal entries with no or bad catalog explanations.
+"""
+
+import re
+from systemd import journal, id128
+
+j = journal.Reader()
+
+logged = set()
+pattern = re.compile('@[A-Z0-9_]+@')
+
+mids = {v:k for k,v in id128.__dict__.items()
+        if k.startswith('SD_MESSAGE')}
+
+freq = 1000
+
+def log_entry(x):
+    if 'CODE_FILE' in x:
+        # some of our code was using 'CODE_FUNCTION' instead of 'CODE_FUNC'
+        print('{}:{} {}'.format(x.get('CODE_FILE', '???'),
+                                x.get('CODE_LINE', '???'),
+                                x.get('CODE_FUNC', None) or x.get('CODE_FUNCTION', '???')))
+    print('    {}'.format(x.get('MESSAGE', 'no message!')))
+    for k, v in x.items():
+        if k.startswith('CODE_') or k in {'MESSAGE_ID', 'MESSAGE'}:
+            continue
+        print('    {}={}'.format(k, v))
+    print()
+
+for i, x in enumerate(j):
+    if i % freq == 0:
+        print(i, end='\r')
+
+    try:
+        mid = x['MESSAGE_ID']
+    except KeyError:
+        continue
+    name = mids.get(mid, 'unknown')
+
+    try:
+        desc = journal.get_catalog(mid)
+    except FileNotFoundError:
+        if mid in logged:
+            continue
+
+        print('{} {.hex}: no catalog entry'.format(name, mid))
+        log_entry(x)
+        logged.add(mid)
+        continue
+
+    fields = [field[1:-1] for field in pattern.findall(desc)]
+    for field in fields:
+        index = (mid, field)
+        if field in x or index in logged:
+            continue
+        print('{} {.hex}: no field {}'.format(name, mid, field))
+        log_entry(x)
+        logged.add(index)