From 5a1d6cb19d45a0cd80ff7a116ae801c71e8e942b Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Zbigniew=20J=C4=99drzejewski-Szmek?= Date: Sun, 11 Dec 2016 11:32:28 -0500 Subject: [PATCH 1/5] pid1,catalog: use a different MESSAGE_ID for user manager startup This add a new message id for the end of user instance startup. User manager startup is a different beast then the system startup. Their descriptions are completely different too. Let's just separate them. Partially fixes #3351. Also remove "successful" from the description, since we don't know if the startup was successful or not. --- catalog/systemd.catalog.in | 15 +++++++++++++-- src/core/manager.c | 2 +- src/systemd/sd-messages.h | 1 + 3 files changed, 15 insertions(+), 3 deletions(-) diff --git a/catalog/systemd.catalog.in b/catalog/systemd.catalog.in index 2c72d312906..cb0ac0ca888 100644 --- a/catalog/systemd.catalog.in +++ b/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 -now idle as services might still be busy with completing start-up. +started. Note that this does not mean that the machine is now idle as services +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 diff --git a/src/core/manager.c b/src/core/manager.c index 21cd6062c66..1192b20b741 100644 --- a/src/core/manager.c +++ b/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)), diff --git a/src/systemd/sd-messages.h b/src/systemd/sd-messages.h index 79246ae0600..db1a21be05e 100644 --- a/src/systemd/sd-messages.h +++ b/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) From ba9534535e1dfe77b28d281658945d019a171452 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Zbigniew=20J=C4=99drzejewski-Szmek?= Date: Sun, 11 Dec 2016 14:25:45 -0500 Subject: [PATCH 2/5] tools/catalog-report.py: a script to scour the journal for bad catalog entries I think it can be a useful tool to find such issues. SD_MESSAGE_UNIT_STARTING 7d4958e842da4a758f6c1cdc7b36dcc5: no field UNIT ../src/core/unit.c:1239 unit_status_log_starting_stopping_reloading Starting Paths. SYSLOG_FACILITY=3 SYSLOG_IDENTIFIER=systemd PRIORITY=6 USER_UNIT=paths.target SD_MESSAGE_UNIT_STARTED 39f53479d3a045ac8e11786248231fbf: no field UNIT ../src/core/job.c:721 job_log_status_message Reached target Paths. SYSLOG_FACILITY=3 SYSLOG_IDENTIFIER=systemd PRIORITY=6 RESULT=done USER_UNIT=paths.target SD_MESSAGE_STARTUP_FINISHED b07a249cd024414a82dd00cd181378ff: no field KERNEL_USEC ../src/core/manager.c:2532 manager_check_finished Startup finished in 19ms. SYSLOG_FACILITY=3 SYSLOG_IDENTIFIER=systemd PRIORITY=6 USERSPACE_USEC=19670 SD_MESSAGE_STARTUP_FINISHED b07a249cd024414a82dd00cd181378ff: no field INITRD_USEC ../src/core/manager.c:2532 manager_check_finished Startup finished in 19ms. SYSLOG_FACILITY=3 SYSLOG_IDENTIFIER=systemd PRIORITY=6 USERSPACE_USEC=19670 unknown 0ce153587afa4095832d233c17a88001: no catalog entry gsm-manager.c:1366 start_phase Entering running state SYSLOG_IDENTIFIER=gnome-session PRIORITY=5 SD_MESSAGE_UNIT_STOPPING de5b426a63be47a7b6ac3eaac82e2f6f: no field UNIT ../src/core/unit.c:1239 unit_status_log_starting_stopping_reloading Stopping Default. SYSLOG_FACILITY=3 SYSLOG_IDENTIFIER=systemd PRIORITY=6 USER_UNIT=default.target SD_MESSAGE_UNIT_STOPPED 9d1aaa27d60140bd96365438aad20286: no field UNIT ../src/core/job.c:729 job_log_status_message Stopped target Default. SYSLOG_FACILITY=3 SYSLOG_IDENTIFIER=systemd PRIORITY=6 RESULT=done USER_UNIT=default.target SD_MESSAGE_TIME_CHANGE c7a787079b354eaaa9e77b371893cd27: no field REALTIME src/core/manager.c:2049 manager_dispatch_time_change_fd Time has been changed SYSLOG_FACILITY=3 SYSLOG_IDENTIFIER=systemd PRIORITY=6 unknown f3ea493c22934e26811cd62abe8e203a: no catalog entry shell-global.c:1375 shell_global_log_structured GNOME Shell started at Sat Jun 11 2016 12:37:46 GMT-0400 (EDT) SYSLOG_IDENTIFIER=gnome-shell SD_MESSAGE_UNIT_FAILED be02cf6855d2428ba40df7e9d022f03d: no field UNIT src/core/job.c:803 job_log_status_message Failed to start GNOME Terminal Server. SYSLOG_FACILITY=3 SYSLOG_IDENTIFIER=systemd RESULT=failed PRIORITY=3 USER_UNIT=gnome-terminal-server.service SD_MESSAGE_LID_CLOSED b72ea4a2881545a0b50e200e55b9b070: no catalog entry src/login/logind-button.c:198 button_dispatch Lid closed. SYSLOG_FACILITY=4 SYSLOG_IDENTIFIER=systemd-logind PRIORITY=6 SD_MESSAGE_LID_OPENED b72ea4a2881545a0b50e200e55b9b06f: no catalog entry src/login/logind-button.c:219 button_dispatch Lid opened. SYSLOG_FACILITY=4 SYSLOG_IDENTIFIER=systemd-logind PRIORITY=6 SD_MESSAGE_SUSPEND_KEY b72ea4a2881545a0b50e200e55b9b072: no catalog entry src/login/logind-button.c:177 button_dispatch Suspend key pressed. SYSLOG_FACILITY=4 SYSLOG_IDENTIFIER=systemd-logind PRIORITY=6 SD_MESSAGE_CONFIG_ERROR c772d24e9a884cbeb9ea12625c306c01: no catalog entry src/shared/conf-parser.c:469 config_parse_sec [/etc/systemd/system/systemd-networkd.service.d/override.conf:2] Failed to parse sec value, ignoring: UNIT=systemd-networkd.service SYSLOG_FACILITY=3 ERRNO=22 SYSLOG_IDENTIFIER=systemd PRIORITY=3 CONFIG_LINE=2 CONFIG_FILE=/etc/systemd/system/systemd-networkd.service.d/override.conf unknown 10dd2dc188b54a5e98970f56499d1f73: no catalog entry gsm-manager.c:308 on_display_server_failure Unrecoverable failure in required component org.gnome.Shell.desktop PRIORITY=3 SYSLOG_IDENTIFIER=gnome-session-binary unknown 52fb62f99e2c49d89cfbf9d6de5e3555: no catalog entry src/journal/test-journal-send.c:85 main Hello World! PAGE_SIZE=4096 TERM=xterm-256color SYSLOG_IDENTIFIER=lt-test-journal-send PRIORITY=5 N_CPUS=2 HOME=/home/zbyszek unknown 9348174c5cc74001a71ef26bd79d302e: no catalog entry /usr/lib/python3.5/site-packages/dnf-plugins/system_upgrade.py:422 log_status Download finished. SYSLOG_IDENTIFIER=python3 DNF_VERSION=1.1.10 TARGET_RELEASEVER=25 SYSTEM_RELEASEVER=24 PRIORITY=5 unknown fef1cc509d5047268b83a3a553f54b43: no catalog entry /usr/lib/python3.5/site-packages/dnf-plugins/system_upgrade.py:422 log_status Rebooting to perform upgrade. SYSLOG_IDENTIFIER=python3 DNF_VERSION=1.1.10 TARGET_RELEASEVER=25 SYSTEM_RELEASEVER=24 PRIORITY=5 unknown 3e0a5636d16b4ca4bbe5321d06c6aa62: no catalog entry /usr/lib/python3.5/site-packages/dnf-plugins/system_upgrade.py:422 log_status Starting system upgrade. This will take a while. SYSLOG_IDENTIFIER=python3 DNF_VERSION=1.1.10 SYSTEM_RELEASEVER=24 PRIORITY=5 TARGET_RELEASEVER=25 unknown 0123456789abcdef0123456789abcdef: no catalog entry :1 Message with ID SYSLOG_IDENTIFIER=/usr/lib/python2.7/site-packages/py/test.py LOGGER=custom_logger_name PRIORITY=4 THREAD_NAME=MainThread --- tools/catalog-report.py | 87 +++++++++++++++++++++++++++++++++++++++++ 1 file changed, 87 insertions(+) create mode 100644 tools/catalog-report.py diff --git a/tools/catalog-report.py b/tools/catalog-report.py new file mode 100644 index 00000000000..b220060cc8a --- /dev/null +++ b/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) From c2dec7029251d64692d14da800c02200ac621346 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Zbigniew=20J=C4=99drzejewski-Szmek?= Date: Sun, 11 Dec 2016 14:34:45 -0500 Subject: [PATCH 3/5] basic/log: merge two big log_struct_internal invocations into one We can take advantage of the fact a NULL argument terminates the list. --- src/basic/log.c | 31 +++++++++++-------------------- 1 file changed, 11 insertions(+), 20 deletions(-) diff --git a/src/basic/log.c b/src/basic/log.c index f5cff4cc9f0..9febe391ac7 100644 --- a/src/basic/log.c +++ b/src/basic/log.c @@ -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( - 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); + unit_fmt = getpid() == 1 ? "UNIT=%s" : "USER_UNIT=%s"; - 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); } From e697dfef649ecc077e160a077f86a06f1a1ee8ed Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Zbigniew=20J=C4=99drzejewski-Szmek?= Date: Sun, 11 Dec 2016 14:37:12 -0500 Subject: [PATCH 4/5] share/log: change log_syntax from "[a:b] " to "a:b: " MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Those square brackets don't fit how our other messages look like; we use colons everywhere else. The "[a:b]" format was originally added in ed5bcfbe3c3b68e59242c03649eea03a9707d318, and remained unchanged for 7 years, but in the meantime other conventions evolved. The new version is also one character shorter. [/etc/systemd/system/systemd-networkd.service.d/override.conf:2] Failed to parse sec value, ignoring: ... ↓ /etc/systemd/system/systemd-networkd.service.d/override.conf:2: Failed to parse sec value, ignoring: ... --- src/basic/log.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/basic/log.c b/src/basic/log.c index 9febe391ac7..4af4d55b33b 100644 --- a/src/basic/log.c +++ b/src/basic/log.c @@ -1162,7 +1162,7 @@ int log_syntax_internal( 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), + LOG_MESSAGE("%s:%u: %s", config_file, config_line, buffer), unit_fmt, unit, NULL); } From b457b33ddc4f25b51880b5c2d575cc61fa14faf3 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Zbigniew=20J=C4=99drzejewski-Szmek?= Date: Sun, 11 Dec 2016 15:40:55 -0500 Subject: [PATCH 5/5] =?UTF-8?q?basic/log:=20CODE=5FFUNCTION=20=E2=86=92=20?= =?UTF-8?q?CODE=5FFUNC?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit systemd.journal-fields(7) documents CODE_FUNC=. Internally, we were inconsistent: sd_journal_print uses CODE_FUNC=, log.h has CODE_FUNCTION=, python-systemd and bootchart also used CODE_FUNC=, when they were internal. Most external projects use sd_journal_* functions, so CODE_FUNC=, python-systemd still uses CODE_FUNC=, as does systemd-bootchart, and independent reimplementations in golang-github-coreos-go-systemd, qtbase, network manager, glib, pulseaudio. Hence, I don't think there's much choice. --- src/basic/log.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/basic/log.c b/src/basic/log.c index 4af4d55b33b..71d5a0baa29 100644 --- a/src/basic/log.c +++ b/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=" : "",