journal: expose last 10 high priority logs as metrics (#42621)

This commit exposes the last 10 high priority logs as metrics so that
the systemd-report reports them. The entries are reported as
`io.systemd.Journal.HighPriorityMessage` and include all fields that are
printable as strings.

This is archived via a new socket-activated unit listens on
/run/systemd/report/io.systemd.Journal

TODO.md

@@ -136,8 +136,6 @@ SPDX-License-Identifier: LGPL-2.1-or-later
     sessions, and number of sessions since boot.
   - implement metrics provider in journald that reports number of log messages
     received since boot, by log priority
-  - implement metrics provider in journalctl, that simply reports the most
-    recent 10 emergency log msgs on the system
   - allow to compile statically (together with the basic and cgroup
     backends)
   - make sure backends can also be invoked via forking off

presets/90-systemd.preset

@@ -24,6 +24,7 @@ enable systemd-boot-update.service
 enable systemd-confext.service
 enable systemd-homed.service
 enable systemd-homed-activate.service
+enable systemd-journalctl-metrics.socket
 enable systemd-journald-audit.socket
 enable systemd-mountfsd.socket
 enable systemd-network-generator.service

src/journal/journalctl-metrics.c

@@ -0,0 +1,93 @@
+/* SPDX-License-Identifier: LGPL-2.1-or-later */
+
+#include "sd-journal.h"
+#include "sd-json.h"
+#include "sd-varlink.h"
+
+#include "journalctl.h"
+#include "journalctl-filter.h"
+#include "journalctl-metrics.h"
+#include "log.h"
+#include "logs-show.h"
+#include "metrics.h"
+#include "output-mode.h"
+
+/* Fallback cap so we never stream unbounded entries when --lines= is "all" or unset. */
+#define N_RECENT_HIGH_PRIORITY 10
+
+/* Set a maximum scan factor to avoid unbound iterating through the journal */
+#define RECENT_HIGH_PRIORITY_SCAN_FACTOR 50
+
+static int recent_high_priority_generate(const MetricFamily *mf, sd_varlink *link, void *userdata) {
+        _cleanup_(sd_journal_closep) sd_journal *j = NULL;
+        int r;
+
+        assert(mf && mf->name);
+        assert(link);
+
+        r = sd_journal_open(&j, SD_JOURNAL_LOCAL_ONLY | SD_JOURNAL_SYSTEM | SD_JOURNAL_ASSUME_IMMUTABLE);
+        if (r < 0)
+                return log_debug_errno(r, "Failed to open journal, ignoring: %m");
+
+        /* Get filters (--priority=, units, matches, ...) from the command-line. */
+        r = add_filters(j, /* matches= */ NULL);
+        if (r < 0)
+                return log_debug_errno(r, "Failed to add journal filters: %m");
+
+        r = sd_journal_seek_tail(j);
+        if (r < 0)
+                return log_debug_errno(r, "Failed to seek to journal tail: %m");
+
+        /* The --lines=+N argument does not make much sense for a metrics provider so we ignore it here. */
+        if (arg_lines_oldest)
+                log_warning("--lines=+N is not supported when serving the metrics interface, ignoring.");
+
+        uint64_t max_lines = arg_lines_needs_seek_end() ? (uint64_t) arg_lines : N_RECENT_HIGH_PRIORITY;
+        uint64_t max_scan = max_lines * RECENT_HIGH_PRIORITY_SCAN_FACTOR;
+
+        for (uint64_t found = 0, scanned = 0; found < max_lines && scanned < max_scan; scanned++) {
+                _cleanup_(sd_json_variant_unrefp) sd_json_variant *entry = NULL;
+
+                r = sd_journal_previous(j);
+                if (r < 0)
+                        return log_debug_errno(r, "Failed to iterate to previous journal entry: %m");
+                if (r == 0)
+                        break;
+
+                r = journal_entry_to_json(j, OUTPUT_SHOW_ALL | OUTPUT_SKIP_UNPRINTABLE, /* output_fields= */ NULL, &entry);
+                if (r < 0) {
+                        log_debug_errno(r, "Failed to convert journal entry to JSON, skipping entry: %m");
+                        continue;
+                }
+                if (r == 0)
+                        continue;
+
+                const char *ident = sd_json_variant_string(sd_json_variant_by_key(entry, "SYSLOG_IDENTIFIER"));
+
+                r = metric_build_send_object(mf, link, /* object= */ ident, entry, /* fields= */ NULL);
+                if (r < 0)
+                        return log_debug_errno(r, "Failed to send journal metric: %m");
+
+                found++;
+        }
+
+        return 0;
+}
+
+static const MetricFamily journal_metric_family_table[] = {
+        {
+                .name = METRIC_IO_SYSTEMD_JOURNAL_PREFIX "HighPriorityMessage",
+                .description = "The most recent high-priority journal messages",
+                .type = METRIC_FAMILY_TYPE_OBJECT,
+                .generate = recent_high_priority_generate,
+        },
+        {}
+};
+
+int vl_method_describe_metrics(sd_varlink *link, sd_json_variant *parameters, sd_varlink_method_flags_t flags, void *userdata) {
+        return metrics_method_describe(journal_metric_family_table, link, parameters, flags, userdata);
+}
+
+int vl_method_list_metrics(sd_varlink *link, sd_json_variant *parameters, sd_varlink_method_flags_t flags, void *userdata) {
+        return metrics_method_list(journal_metric_family_table, link, parameters, flags, userdata);
+}

src/journal/journalctl-metrics.h

@@ -0,0 +1,9 @@
+/* SPDX-License-Identifier: LGPL-2.1-or-later */
+#pragma once
+
+#include "shared-forward.h"
+
+#define METRIC_IO_SYSTEMD_JOURNAL_PREFIX "io.systemd.Journal."
+
+int vl_method_list_metrics(sd_varlink *link, sd_json_variant *parameters, sd_varlink_method_flags_t flags, void *userdata);
+int vl_method_describe_metrics(sd_varlink *link, sd_json_variant *parameters, sd_varlink_method_flags_t flags, void *userdata);

src/journal/journalctl.c

@@ -16,6 +16,7 @@
 #include "journalctl.h"
 #include "journalctl-authenticate.h"
 #include "journalctl-catalog.h"
+#include "journalctl-metrics.h"
 #include "journalctl-misc.h"
 #include "journalctl-show.h"
 #include "journalctl-varlink.h"
@@ -40,6 +41,7 @@
 #include "syslog-util.h"
 #include "time-util.h"
 #include "varlink-io.systemd.JournalAccess.h"
+#include "varlink-io.systemd.Metrics.h"
 #include "varlink-util.h"
 
 #define DEFAULT_FSS_INTERVAL_USEC (15*USEC_PER_MINUTE)
@@ -214,6 +216,43 @@ default_noarg:
         return 0;
 }
 
+static int parse_priorities(const char *arg) {
+        assert(arg);
+
+        const char *dots = strstr(arg, "..");
+        if (dots) {
+                /* a range */
+                _cleanup_free_ char *a = strndup(arg, dots - arg);
+                if (!a)
+                        return log_oom();
+
+                int from = log_level_from_string(a),
+                      to = log_level_from_string(dots + 2);
+
+                if (from < 0 || to < 0)
+                        return log_error_errno(from < 0 ? from : to,
+                                               "Failed to parse log level range %s", arg);
+
+                arg_priorities = 0;
+                if (from < to)
+                        for (int i = from; i <= to; i++)
+                                arg_priorities |= 1 << i;
+                else
+                        for (int i = to; i <= from; i++)
+                                arg_priorities |= 1 << i;
+        } else {
+                int p = log_level_from_string(arg);
+                if (p < 0)
+                        return log_error_errno(p, "Unknown log level %s", arg);
+
+                arg_priorities = 0;
+                for (int i = 0; i <= p; i++)
+                        arg_priorities |= 1 << i;
+        }
+
+        return 0;
+}
+
 static int help_facilities(void) {
         if (!arg_quiet)
                 puts("Available facilities:");
@@ -277,13 +316,23 @@ static int vl_server(void) {
         if (r < 0)
                 return log_error_errno(r, "Failed to allocate Varlink server: %m");
 
-        r = sd_varlink_server_add_interface(varlink_server, &vl_interface_io_systemd_JournalAccess);
+        /* Serve both interfaces regardless of which socket activated us: both activating sockets share the
+         * same access controls (systemd-journal group), so anyone reaching either is already entitled to
+         * both. */
+        r = sd_varlink_server_add_interface_many(
+                        varlink_server,
+                        &vl_interface_io_systemd_JournalAccess,
+                        &vl_interface_io_systemd_Metrics);
         if (r < 0)
-                return log_error_errno(r, "Failed to add Varlink interface: %m");
+                return log_error_errno(r, "Failed to add Varlink interfaces: %m");
 
-        r = sd_varlink_server_bind_method(varlink_server, "io.systemd.JournalAccess.GetEntries", vl_method_get_entries);
+        r = sd_varlink_server_bind_method_many(
+                        varlink_server,
+                        "io.systemd.JournalAccess.GetEntries", vl_method_get_entries,
+                        "io.systemd.Metrics.List",             vl_method_list_metrics,
+                        "io.systemd.Metrics.Describe",         vl_method_describe_metrics);
         if (r < 0)
-                return log_error_errno(r, "Failed to bind Varlink method: %m");
+                return log_error_errno(r, "Failed to bind Varlink methods: %m");
 
         r = sd_varlink_server_loop_auto(varlink_server);
         if (r < 0)
@@ -319,13 +368,35 @@ static int parse_argv(int argc, char *argv[], char ***remaining_args) {
                         OPTION_COMMON_USER:
                                 arg_varlink_runtime_scope = RUNTIME_SCOPE_USER;
                                 break;
-                        }
+
+                        OPTION('p', "priority", "RANGE", "Show entries within the specified priority range"):
+                                r = parse_priorities(opts.arg);
+                                if (r < 0)
+                                        return r;
+                                break;
+
+                        OPTION_FULL(OPTION_OPTIONAL_ARG, 'n', "lines", "[+]INTEGER",
+                                    "Number of journal entries to show"): {
+                                const char *p = opts.arg ?: option_parser_peek_next_arg(&opts);
+
+                                r = parse_lines(p, /* graceful= */ !opts.arg);
+                                if (r < 0)
+                                        return r;
+                                if (r > 0 && !opts.arg)
+                                        (void) option_parser_consume_next_arg(&opts);
+
+                                break;
+                        }}
 
                 if (arg_varlink_runtime_scope < 0)
                         return log_error_errno(arg_varlink_runtime_scope, "Cannot run in Varlink mode with no runtime scope specified.");
 
                 if (option_parser_get_n_args(&opts) > 0)
-                        return log_error_errno(SYNTHETIC_ERRNO(EINVAL), "No arguments expected in Varlink mode.");
+                        return log_error_errno(SYNTHETIC_ERRNO(EINVAL), "No positional arguments expected in Varlink mode.");
+
+                /* We return early, skipping the tristate resolution the regular path does below; resolve it
+                 * here so add_filters() doesn't trip over the unresolved -1. */
+                arg_boot = false;
 
                 *remaining_args = NULL;
                 return 1;
@@ -526,42 +597,11 @@ static int parse_argv(int argc, char *argv[], char ***remaining_args) {
                                 return log_oom();
                         break;
 
-                OPTION('p', "priority", "RANGE", "Show entries within the specified priority range"): {
-
-                        const char *dots = strstr(opts.arg, "..");
-                        if (dots) {
-                                /* a range */
-                                _cleanup_free_ char *a = strndup(opts.arg, dots - opts.arg);
-                                if (!a)
-                                        return log_oom();
-
-                                int from = log_level_from_string(a),
-                                      to = log_level_from_string(dots + 2);
-
-                                if (from < 0 || to < 0)
-                                        return log_error_errno(from < 0 ? from : to,
-                                                               "Failed to parse log level range %s", opts.arg);
-
-                                arg_priorities = 0;
-                                if (from < to)
-                                        for (int i = from; i <= to; i++)
-                                                arg_priorities |= 1 << i;
-                                else
-                                        for (int i = to; i <= from; i++)
-                                                arg_priorities |= 1 << i;
-
-                        } else {
-                                int p = log_level_from_string(opts.arg);
-                                if (p < 0)
-                                        return log_error_errno(p, "Unknown log level %s", opts.arg);
-
-                                arg_priorities = 0;
-                                for (int i = 0; i <= p; i++)
-                                        arg_priorities |= 1 << i;
-                        }
-
+                OPTION('p', "priority", "RANGE", "Show entries within the specified priority range"):
+                        r = parse_priorities(opts.arg);
+                        if (r < 0)
+                                return r;
                         break;
-                }
 
                 OPTION_LONG("facility", "FACILITY…", "Show entries with the specified facilities"):
                         for (const char *p = opts.arg;;) {

src/journal/meson.build

@@ -34,6 +34,7 @@ journalctl_sources = files(
         'journalctl-authenticate.c',
         'journalctl-catalog.c',
         'journalctl-filter.c',
+        'journalctl-metrics.c',
         'journalctl-misc.c',
         'journalctl-show.c',
         'journalctl-util.c',

src/shared/logs-show.c

@@ -1039,7 +1039,8 @@ void json_escape(
         assert(f);
         assert(p);
 
-        if (!(flags & OUTPUT_SHOW_ALL) && l >= JSON_THRESHOLD)
+        if (((flags & OUTPUT_SKIP_UNPRINTABLE) && !utf8_is_printable(p, l)) ||
+            (!(flags & OUTPUT_SHOW_ALL) && l >= JSON_THRESHOLD))
                 fputs("null", f);
 
         else if (!(flags & OUTPUT_SHOW_ALL) && !utf8_is_printable(p, l)) {
@@ -1124,6 +1125,8 @@ static int update_json_data(
                 r = sd_json_variant_new_null(&v);
         else if (utf8_is_printable(value, size))
                 r = sd_json_variant_new_stringn(&v, value, size);
+        else if (flags & OUTPUT_SKIP_UNPRINTABLE)
+                r = sd_json_variant_new_null(&v);
         else
                 r = sd_json_variant_new_array_bytes(&v, value, size);
         if (r < 0)

src/shared/metrics.c

@@ -58,6 +58,7 @@ static const char * const metric_family_type_table[_METRIC_FAMILY_TYPE_MAX] = {
         [METRIC_FAMILY_TYPE_COUNTER] = "counter",
         [METRIC_FAMILY_TYPE_GAUGE]   = "gauge",
         [METRIC_FAMILY_TYPE_STRING]  = "string",
+        [METRIC_FAMILY_TYPE_OBJECT]  = "object",
 };
 
 DEFINE_STRING_TABLE_LOOKUP_TO_STRING(metric_family_type, MetricFamilyType);
@@ -229,3 +230,18 @@ int metric_build_send_double(
 
         return metric_build_send(mf, link, object, v, fields);
 }
+
+int metric_build_send_object(
+                const MetricFamily *mf,
+                sd_varlink *link,
+                const char *object,
+                sd_json_variant *value,
+                sd_json_variant *fields) {
+
+        assert(mf);
+        assert(link);
+        assert(value);
+        assert(sd_json_variant_is_object(value));
+
+        return metric_build_send(mf, link, object, value, fields);
+}

src/shared/metrics.h

@@ -7,6 +7,7 @@ typedef enum MetricFamilyType {
         METRIC_FAMILY_TYPE_COUNTER,
         METRIC_FAMILY_TYPE_GAUGE,
         METRIC_FAMILY_TYPE_STRING,
+        METRIC_FAMILY_TYPE_OBJECT,
         _METRIC_FAMILY_TYPE_MAX,
         _METRIC_FAMILY_TYPE_INVALID = -EINVAL,
 } MetricFamilyType;
@@ -39,3 +40,4 @@ int metrics_method_list(const MetricFamily mfs[], sd_varlink *link, sd_json_vari
 int metric_build_send_string(const MetricFamily* mf, sd_varlink *link, const char *object, const char *value, sd_json_variant *fields);
 int metric_build_send_unsigned(const MetricFamily* mf, sd_varlink *link, const char *object, uint64_t value, sd_json_variant *fields);
 int metric_build_send_double(const MetricFamily* mf, sd_varlink *link, const char *object, double value, sd_json_variant *fields);
+int metric_build_send_object(const MetricFamily* mf, sd_varlink *link, const char *object, sd_json_variant *value, sd_json_variant *fields);

src/shared/output-mode.h

@@ -43,12 +43,13 @@ typedef enum OutputFlags {
         OUTPUT_UTC               = 1 << 6,
         OUTPUT_NO_HOSTNAME       = 1 << 7,
         OUTPUT_TRUNCATE_NEWLINE  = 1 << 8,
+        OUTPUT_SKIP_UNPRINTABLE  = 1 << 9,
 
         /* Specific to process tree output */
-        OUTPUT_KERNEL_THREADS    = 1 << 9,
-        OUTPUT_CGROUP_XATTRS     = 1 << 10,
-        OUTPUT_CGROUP_ID         = 1 << 11,
-        OUTPUT_HIDE_EXTRA        = 1 << 12,
+        OUTPUT_KERNEL_THREADS    = 1 << 10,
+        OUTPUT_CGROUP_XATTRS     = 1 << 11,
+        OUTPUT_CGROUP_ID         = 1 << 12,
+        OUTPUT_HIDE_EXTRA        = 1 << 13,
 } OutputFlags;
 
 sd_json_format_flags_t output_mode_to_json_format_flags(OutputMode m);

src/shared/varlink-io.systemd.Metrics.c

@@ -9,7 +9,9 @@ static SD_VARLINK_DEFINE_ENUM_TYPE(
                 SD_VARLINK_FIELD_COMMENT("A gauge metric family type which is a value that can go up and down"),
                 SD_VARLINK_DEFINE_ENUM_VALUE(gauge),
                 SD_VARLINK_FIELD_COMMENT("A string metric family type"),
-                SD_VARLINK_DEFINE_ENUM_VALUE(string));
+                SD_VARLINK_DEFINE_ENUM_VALUE(string),
+                SD_VARLINK_FIELD_COMMENT("An object metric family type whose value is an arbitrary JSON object"),
+                SD_VARLINK_DEFINE_ENUM_VALUE(object));
 
 static SD_VARLINK_DEFINE_ERROR(NoSuchMetric);
 

test/units/TEST-04-JOURNAL.journalctl-metrics.sh

@@ -0,0 +1,53 @@
+#!/usr/bin/env bash
+# SPDX-License-Identifier: LGPL-2.1-or-later
+set -eux
+set -o pipefail
+
+# journalctl's Varlink server also exposes the io.systemd.Metrics provider that reports the most recent
+# high-priority journal messages, socket-activated under /run/systemd/report/.
+SOCKET="/run/systemd/report/io.systemd.Journal"
+
+# Ensure the socket is running, as some distros don't enable it by default.
+systemctl start systemd-journalctl-metrics.socket
+test -S "$SOCKET"
+
+# Both activating sockets share the same systemd-journal group access controls, so the server exposes both
+# io.systemd.Metrics and io.systemd.JournalAccess regardless of which socket was connected to.
+varlinkctl list-interfaces "$SOCKET" | grep io.systemd.Metrics >/dev/null
+varlinkctl list-interfaces "$SOCKET" | grep io.systemd.JournalAccess >/dev/null
+
+# Describe must advertise our metric family.
+varlinkctl --more call "$SOCKET" io.systemd.Metrics.Describe '{}' |
+    grep "io.systemd.Journal.HighPriorityMessage" >/dev/null
+
+# Seed a unique high-priority (crit) message right before listing, so it is guaranteed to be among the 10
+# most recent matches. The service runs with --priority=crit, so the level must be crit or higher. We run
+# as root (_UID=0), so it lands in the system journal that the provider reads.
+TAG="$(systemd-id128 new)"
+systemd-cat -t "high-$TAG" -p crit echo "metrics-hiprio-$TAG"
+# A low-priority (info) message that must NOT be reported.
+systemd-cat -t "info-$TAG" -p info echo "metrics-info-$TAG"
+journalctl --sync
+
+LIST="$(varlinkctl --more call "$SOCKET" io.systemd.Metrics.List '{}')"
+
+# Output is valid application/json-seq.
+jq --seq . >/dev/null <<<"$LIST"
+
+# The crit message is reported as the whole journal entry object in .value, with every field under its raw
+# journal name (journal_entry_to_json()). systemd-cat -t sets SYSLOG_IDENTIFIER, which maps to "object".
+[ "$(jq --seq -r --arg o "high-$TAG" 'select(.object == $o) | .value.MESSAGE' <<<"$LIST")" = "metrics-hiprio-$TAG" ]
+[ "$(jq --seq -r --arg o "high-$TAG" 'select(.object == $o) | .value.PRIORITY' <<<"$LIST")" = "2" ]
+
+# The info message is filtered out (priority below crit).
+[ -z "$(jq --seq -r --arg o "info-$TAG" 'select(.object == $o) | .value.MESSAGE' <<<"$LIST")" ]
+
+# The list is capped at 10. Seed more than that and confirm exactly 10 are returned. (Count raw .name
+# lines; jq --seq frames non-string output like `length` with an RS byte, but -r string output is clean.)
+for ((i = 0; i < 15; i++)); do
+    systemd-cat -t "cap-$TAG" -p crit echo "metrics-cap-$TAG-$i"
+done
+journalctl --sync
+LIST="$(varlinkctl --more call "$SOCKET" io.systemd.Metrics.List '{}')"
+COUNT="$(jq --seq -r '.name' <<<"$LIST" | wc -l)"
+test "$COUNT" -eq 10

units/meson.build

@@ -473,6 +473,8 @@ units = [
           'file' : 'systemd-journalctl.socket',
           'symlinks' : ['sockets.target.wants/'],
         },
+        { 'file' : 'systemd-journalctl-metrics@.service' },
+        { 'file' : 'systemd-journalctl-metrics.socket' },
         { 'file' : 'systemd-journald-audit.socket' },
         {
           'file' : 'systemd-journald-dev-log.socket',

units/systemd-journalctl-metrics.socket

@@ -0,0 +1,28 @@
+#  SPDX-License-Identifier: LGPL-2.1-or-later
+#
+#  This file is part of systemd.
+#
+#  systemd is free software; you can redistribute it and/or modify it
+#  under the terms of the GNU Lesser General Public License as published by
+#  the Free Software Foundation; either version 2.1 of the License, or
+#  (at your option) any later version.
+
+[Unit]
+Description=Journal Metrics Report Socket
+Documentation=man:journalctl(1)
+DefaultDependencies=no
+Before=sockets.target
+After=systemd-sysusers.service
+
+[Socket]
+ListenStream=/run/systemd/report/io.systemd.Journal
+FileDescriptorName=varlink
+# Same permissions as systemd-journalctl.socket for io.systemd.JournalAccess
+SocketGroup=systemd-journal
+SocketMode=0660
+Accept=yes
+MaxConnectionsPerSource=16
+RemoveOnStop=yes
+
+[Install]
+WantedBy=sockets.target

units/systemd-journalctl-metrics@.service

@@ -0,0 +1,44 @@
+#  SPDX-License-Identifier: LGPL-2.1-or-later
+#
+#  This file is part of systemd.
+#
+#  systemd is free software; you can redistribute it and/or modify it
+#  under the terms of the GNU Lesser General Public License as published by
+#  the Free Software Foundation; either version 2.1 of the License, or
+#  (at your option) any later version.
+
+[Unit]
+Description=Journal Metrics Report Service
+Documentation=man:journalctl(1)
+DefaultDependencies=no
+Conflicts=shutdown.target
+Before=shutdown.target
+RequiresMountsFor=/var/log/journal
+
+[Service]
+ExecStart=journalctl --system --lines=10 --priority=crit
+DynamicUser=yes
+User=systemd-journal-access
+SupplementaryGroups=systemd-journal
+CapabilityBoundingSet=
+DeviceAllow=
+LockPersonality=yes
+MemoryDenyWriteExecute=yes
+PrivateDevices=yes
+PrivateIPC=yes
+PrivateNetwork=yes
+PrivateTmp=disconnected
+ProtectControlGroups=yes
+ProtectHome=yes
+ProtectHostname=yes
+ProtectKernelLogs=yes
+ProtectKernelModules=yes
+ProtectKernelTunables=yes
+ProtectSystem=strict
+RestrictAddressFamilies=AF_UNIX
+RestrictNamespaces=yes
+RestrictRealtime=yes
+RuntimeMaxSec=1min
+SystemCallArchitectures=native
+SystemCallErrorNumber=EPERM
+SystemCallFilter=@system-service