SymbX/systemd
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Various logging improvements and cleanups (#37040)

Browse Source
This commit is contained in:
Daan De Meyer
2025-04-23 15:31:44 +02:00
committed by GitHub
parent 05f2d9c080 44d50ba88e
commit 50810ff7b8
7 changed files with 359 additions and 523 deletions
Download Patch File Download Diff File Expand all files Collapse all files
man/systemd.exec.xml
+23 -16
View File
@@ -3268,23 +3268,30 @@ StandardInputData=V2XigLJyZSBubyBzdHJhbmdlcnMgdG8gbG92ZQpZb3Uga25vdyB0aGUgcnVsZX
<varlistentry>
<term><varname>LogLevelMax=</varname></term>
<listitem><para>Configures filtering by log level of log messages generated by this unit. Takes a
<command>syslog</command> log level, one of <option>emerg</option> (lowest log level, only highest priority
messages), <option>alert</option>, <option>crit</option>, <option>err</option>, <option>warning</option>,
<option>notice</option>, <option>info</option>, <option>debug</option> (highest log level, also lowest priority
messages). See <citerefentry
<listitem><para>Sets the maximum log level for log messages generated by this unit. Takes a
<command>syslog</command> log level, one of <option>emerg</option> (lowest log level, only highest
priority messages), <option>alert</option>, <option>crit</option>, <option>err</option>,
<option>warning</option>, <option>notice</option>, <option>info</option>, <option>debug</option>
(highest log level, also lowest priority messages). See <citerefentry
project='man-pages'><refentrytitle>syslog</refentrytitle><manvolnum>3</manvolnum></citerefentry> for
details. By default, no filtering is applied (i.e. the default maximum log level is <option>debug</option>). Use
this option to configure the logging system to drop log messages of a specific service above the specified
level. For example, set <varname>LogLevelMax=</varname><option>info</option> in order to turn off debug logging
of a particularly chatty unit. Note that the configured level is applied to any log messages written by any
of the processes belonging to this unit, as well as any log messages written by the system manager process
(PID 1) in reference to this unit, sent via any supported logging protocol. The filtering is applied
early in the logging pipeline, before any kind of further processing is done. Moreover, messages which pass
through this filter successfully might still be dropped by filters applied at a later stage in the logging
subsystem. For example, <varname>MaxLevelStore=</varname> configured in
<citerefentry><refentrytitle>journald.conf</refentrytitle><manvolnum>5</manvolnum></citerefentry> might
prohibit messages of higher log levels to be stored on disk, even though the per-unit
details. By default, the maximum log level is not overridden.</para>
<para>This option can be used to configure the logging system to drop log messages of a specific
service above the specified level. For example, set
<varname>LogLevelMax=</varname><option>info</option> in order to turn off debug logging of a
particularly chatty unit. Alternatively, this option can be used to enable extra logging about a
specific unit by the system or user manager processes without changing the global log level for the
system or user manager processes by setting <varname>LogLevelMax=</varname><option>debug</option>.
</para>
<para>Note that the configured level is applied to any log messages written by any of the processes
belonging to this unit, as well as any log messages written by the system or user manager processes
in reference to this unit, sent via any supported logging protocol. The override is applied early in
the logging pipeline, before any kind of further processing is done. Moreover, messages which pass
through this filter successfully might still be dropped by filters applied at a later stage in the
logging subsystem. For example, <varname>MaxLevelStore=</varname> configured in
<citerefentry><refentrytitle>journald.conf</refentrytitle><manvolnum>5</manvolnum></citerefentry>
might prohibit messages of higher log levels to be stored on disk, even though the per-unit
<varname>LogLevelMax=</varname> permitted it to be processed.</para>
<xi:include href="version-info.xml" xpointer="v236"/></listitem>
src/basic/log-context.h
+4 -1
View File
@@ -75,8 +75,11 @@ size_t log_context_num_fields(void);
void _reset_log_level(int *saved_log_level);
#define _LOG_CONTEXT_SET_LOG_LEVEL(level, l) \
_cleanup_(_reset_log_level) _unused_ int l = log_set_max_level(level);
#define LOG_CONTEXT_SET_LOG_LEVEL(level) \
_cleanup_(_reset_log_level) _unused_ int _saved_log_level_ = log_set_max_level(level);
_LOG_CONTEXT_SET_LOG_LEVEL(level, UNIQ_T(l, UNIQ))
#define LOG_CONTEXT_PUSH(...) \
LOG_CONTEXT_PUSH_STRV(STRV_MAKE(__VA_ARGS__))
src/core/exec-invoke.c
+260 -383
View File
File diff suppressed because it is too large Load Diff
src/core/execute.h
+14 -61
View File
@@ -14,6 +14,7 @@
#include "exec-util.h"
#include "fdset.h"
#include "list.h"
#include "log.h"
#include "log-context.h"
#include "namespace.h"
#include "nsflags.h"
@@ -640,6 +641,16 @@ bool exec_is_cgroup_mount_read_only(const ExecContext *context);
const char* exec_get_private_notify_socket_path(const ExecContext *context, const ExecParameters *params, bool needs_sandboxing);
static inline int exec_log_level_max(const ExecContext *context, const ExecParameters *params) {
assert(context);
assert(params);
if (params->debug_invocation)
return LOG_DEBUG;
return context->log_level_max < 0 ? log_get_max_level() : context->log_level_max;
}
/* These logging macros do the same logging as those in unit.h, but using ExecContext and ExecParameters
* instead of the unit object, so that it can be used in the sd-executor context (where the unit object is
* not available). */
@@ -649,77 +660,19 @@ const char* exec_get_private_notify_socket_path(const ExecContext *context, cons
#define LOG_EXEC_INVOCATION_ID_FIELD(ep) \
((ep)->runtime_scope == RUNTIME_SCOPE_USER ? "USER_INVOCATION_ID=" : "INVOCATION_ID=")
#define log_exec_full_errno_zerook(ec, ep, level, error, ...) \
({ \
const ExecContext *_c = (ec); \
const ExecParameters *_p = (ep); \
const int _l = (level); \
bool _do_log = _p->debug_invocation || \
_c->log_level_max < 0 || \
_c->log_level_max >= LOG_PRI(_l); \
LOG_CONTEXT_PUSH_IOV(_c->log_extra_fields, \
_c->n_log_extra_fields); \
!_do_log ? -ERRNO_VALUE(error) : \
log_object_internal(_l, error, \
PROJECT_FILE, __LINE__, __func__, \
LOG_EXEC_ID_FIELD(_p), \
_p->unit_id, \
LOG_EXEC_INVOCATION_ID_FIELD(_p), \
_p->invocation_id_string, \
##__VA_ARGS__); \
})
#define log_exec_full_errno(ec, ep, level, error, ...) \
({ \
int _error = (error); \
ASSERT_NON_ZERO(_error); \
log_exec_full_errno_zerook(ec, ep, level, _error, ##__VA_ARGS__); \
})
#define log_exec_full(ec, ep, level, ...) (void) log_exec_full_errno_zerook(ec, ep, level, 0, __VA_ARGS__)
#define log_exec_debug(ec, ep, ...) log_exec_full(ec, ep, LOG_DEBUG, __VA_ARGS__)
#define log_exec_info(ec, ep, ...) log_exec_full(ec, ep, LOG_INFO, __VA_ARGS__)
#define log_exec_notice(ec, ep, ...) log_exec_full(ec, ep, LOG_NOTICE, __VA_ARGS__)
#define log_exec_warning(ec, ep, ...) log_exec_full(ec, ep, LOG_WARNING, __VA_ARGS__)
#define log_exec_error(ec, ep, ...) log_exec_full(ec, ep, LOG_ERR, __VA_ARGS__)
#define log_exec_debug_errno(ec, ep, error, ...) log_exec_full_errno(ec, ep, LOG_DEBUG, error, __VA_ARGS__)
#define log_exec_info_errno(ec, ep, error, ...) log_exec_full_errno(ec, ep, LOG_INFO, error, __VA_ARGS__)
#define log_exec_notice_errno(ec, ep, error, ...) log_exec_full_errno(ec, ep, LOG_NOTICE, error, __VA_ARGS__)
#define log_exec_warning_errno(ec, ep, error, ...) log_exec_full_errno(ec, ep, LOG_WARNING, error, __VA_ARGS__)
#define log_exec_error_errno(ec, ep, error, ...) log_exec_full_errno(ec, ep, LOG_ERR, error, __VA_ARGS__)
/* Like LOG_MESSAGE(), but with the unit name prefixed. */
#define LOG_EXEC_MESSAGE(ep, fmt, ...) LOG_MESSAGE("%s: " fmt, (ep)->unit_id, ##__VA_ARGS__)
#define LOG_EXEC_ID(ep) LOG_ITEM("%s%s", LOG_EXEC_ID_FIELD(ep), (ep)->unit_id)
#define LOG_EXEC_INVOCATION_ID(ep) LOG_ITEM("%s%s", LOG_EXEC_INVOCATION_ID_FIELD(ep), (ep)->invocation_id_string)
#define log_exec_struct_errno(ec, ep, level, error, ...) \
({ \
const ExecContext *_c = (ec); \
const ExecParameters *_p = (ep); \
const int _l = (level); \
bool _do_log = _p->debug_invocation || \
_c->log_level_max < 0 || \
_c->log_level_max >= LOG_PRI(_l); \
LOG_CONTEXT_PUSH_IOV(_c->log_extra_fields, \
_c->n_log_extra_fields); \
!_do_log ? -ERRNO_VALUE(error) : \
log_struct_errno(_l, error, \
LOG_EXEC_ID(_p), \
LOG_EXEC_INVOCATION_ID(_p), \
__VA_ARGS__); \
})
#define log_exec_struct(ec, ep, level, ...) log_exec_struct_errno(ec, ep, level, 0, __VA_ARGS__)
#define _LOG_CONTEXT_PUSH_EXEC(ec, ep, p, c) \
const ExecContext *c = (ec); \
const ExecParameters *p = (ep); \
LOG_CONTEXT_PUSH_KEY_VALUE(LOG_EXEC_ID_FIELD(p), p->unit_id); \
LOG_CONTEXT_PUSH_KEY_VALUE(LOG_EXEC_INVOCATION_ID_FIELD(p), p->invocation_id_string); \
LOG_CONTEXT_PUSH_IOV(c->log_extra_fields, c->n_log_extra_fields)
LOG_CONTEXT_PUSH_IOV(c->log_extra_fields, c->n_log_extra_fields) \
LOG_CONTEXT_SET_LOG_LEVEL(exec_log_level_max(c, p)) \
LOG_SET_PREFIX(p->unit_id);
#define LOG_CONTEXT_PUSH_EXEC(ec, ep) \
_LOG_CONTEXT_PUSH_EXEC(ec, ep, UNIQ_T(p, UNIQ), UNIQ_T(c, UNIQ))
src/core/executor.c
+7 -5
View File
@@ -240,6 +240,8 @@ static int run(int argc, char *argv[]) {
if (r < 0)
return log_error_errno(r, "Failed to deserialize: %m");
LOG_CONTEXT_PUSH_EXEC(&context, &params);
arg_serialization = safe_fclose(arg_serialization);
fdset = fdset_free(fdset);
@@ -253,11 +255,11 @@ static int run(int argc, char *argv[]) {
const char *status = ASSERT_PTR(
exit_status_to_string(exit_status, EXIT_STATUS_LIBC | EXIT_STATUS_SYSTEMD));
log_exec_struct_errno(&context, &params, LOG_ERR, r,
LOG_MESSAGE_ID(SD_MESSAGE_SPAWN_FAILED_STR),
LOG_EXEC_MESSAGE(&params, "Failed at step %s spawning %s: %m",
status, command.path),
LOG_ITEM("EXECUTABLE=%s", command.path));
log_struct_errno(LOG_ERR, r,
LOG_MESSAGE_ID(SD_MESSAGE_SPAWN_FAILED_STR),
LOG_EXEC_MESSAGE(&params, "Failed at step %s spawning %s: %m",
status, command.path),
LOG_ITEM("EXECUTABLE=%s", command.path));
} else
/* r == 0: 'skip' is chosen in the confirm spawn prompt
* r > 0: expected/ignored failure, do not log at error level */
src/core/unit.h
+25 -22
View File
@@ -1018,10 +1018,22 @@ static inline bool unit_has_job_type(Unit *u, JobType type) {
return u && u->job && u->job->type == type;
}
static inline int unit_get_log_level_max(const Unit *u) {
if (u) {
if (u->debug_invocation)
return LOG_DEBUG;
ExecContext *ec = unit_get_exec_context(u);
if (ec && ec->log_level_max >= 0)
return ec->log_level_max;
}
return log_get_max_level();
}
static inline bool unit_log_level_test(const Unit *u, int level) {
assert(u);
ExecContext *ec = unit_get_exec_context(u);
return !ec || ec->log_level_max < 0 || ec->log_level_max >= LOG_PRI(level) || u->debug_invocation;
return LOG_PRI(level) <= unit_get_log_level_max(u);
}
/* unit_log_skip is for cases like ExecCondition= where a unit is considered "done"
@@ -1085,15 +1097,12 @@ OOMPolicy oom_policy_from_string(const char *s) _pure_;
({ \
const Unit *_u = (unit); \
const int _l = (level); \
bool _do_log = !(log_get_max_level() < LOG_PRI(_l) || \
(_u && !unit_log_level_test(_u, _l))); \
const ExecContext *_c = _do_log && _u ? \
unit_get_exec_context(_u) : NULL; \
LOG_CONTEXT_SET_LOG_LEVEL(unit_get_log_level_max(_u)); \
const ExecContext *_c = _u ? unit_get_exec_context(_u) : NULL; \
LOG_CONTEXT_PUSH_IOV(_c ? _c->log_extra_fields : NULL, \
_c ? _c->n_log_extra_fields : 0); \
!_do_log ? -ERRNO_VALUE(error) : \
_u ? log_object_internal(_l, error, PROJECT_FILE, __LINE__, __func__, unit_log_field(_u), _u->id, unit_invocation_log_field(_u), _u->invocation_id_string, ##__VA_ARGS__) : \
log_internal(_l, error, PROJECT_FILE, __LINE__, __func__, ##__VA_ARGS__); \
_u ? log_object_internal(_l, error, PROJECT_FILE, __LINE__, __func__, unit_log_field(_u), _u->id, unit_invocation_log_field(_u), _u->invocation_id_string, ##__VA_ARGS__) : \
log_internal(_l, error, PROJECT_FILE, __LINE__, __func__, ##__VA_ARGS__); \
})
#define log_unit_full_errno(unit, level, error, ...) \
@@ -1129,14 +1138,11 @@ OOMPolicy oom_policy_from_string(const char *s) _pure_;
({ \
const Unit *_u = (unit); \
const int _l = (level); \
bool _do_log = unit_log_level_test(_u, _l); \
const ExecContext *_c = _do_log && _u ? \
unit_get_exec_context(_u) : NULL; \
LOG_CONTEXT_SET_LOG_LEVEL(unit_get_log_level_max(_u)); \
const ExecContext *_c = _u ? unit_get_exec_context(_u) : NULL; \
LOG_CONTEXT_PUSH_IOV(_c ? _c->log_extra_fields : NULL, \
_c ? _c->n_log_extra_fields : 0); \
_do_log ? \
log_struct_errno(_l, error, __VA_ARGS__, LOG_UNIT_ID(_u)) : \
-ERRNO_VALUE(error); \
log_struct_errno(_l, error, __VA_ARGS__, LOG_UNIT_ID(_u)); \
})
#define log_unit_struct(unit, level, ...) log_unit_struct_errno(unit, level, 0, __VA_ARGS__)
@@ -1145,14 +1151,11 @@ OOMPolicy oom_policy_from_string(const char *s) _pure_;
({ \
const Unit *_u = (unit); \
const int _l = (level); \
bool _do_log = unit_log_level_test(_u, _l); \
const ExecContext *_c = _do_log && _u ? \
unit_get_exec_context(_u) : NULL; \
LOG_CONTEXT_SET_LOG_LEVEL(unit_get_log_level_max(_u)); \
const ExecContext *_c = _u ? unit_get_exec_context(_u) : NULL; \
LOG_CONTEXT_PUSH_IOV(_c ? _c->log_extra_fields : NULL, \
_c ? _c->n_log_extra_fields : 0); \
_do_log ? \
log_struct_iovec_errno(_l, error, iovec, n_iovec) : \
-ERRNO_VALUE(error); \
log_struct_iovec_errno(_l, error, iovec, n_iovec); \
})
#define log_unit_struct_iovec(unit, level, iovec, n_iovec) log_unit_struct_iovec_errno(unit, level, 0, iovec, n_iovec)
@@ -1222,7 +1225,7 @@ typedef struct UnitForEachDependencyData {
LOG_CONTEXT_PUSH_KEY_VALUE(unit_log_field(u), u->id); \
LOG_CONTEXT_PUSH_KEY_VALUE(unit_invocation_log_field(u), u->invocation_id_string); \
LOG_CONTEXT_PUSH_IOV(c ? c->log_extra_fields : NULL, c ? c->n_log_extra_fields : 0); \
LOG_CONTEXT_SET_LOG_LEVEL(c->log_level_max >= 0 ? c->log_level_max : log_get_max_level())
LOG_CONTEXT_SET_LOG_LEVEL(unit_get_log_level_max(u))
#define LOG_CONTEXT_PUSH_UNIT(unit) \
_LOG_CONTEXT_PUSH_UNIT(unit, UNIQ_T(u, UNIQ), UNIQ_T(c, UNIQ))
src/timedate/timedated.c
+26 -35
View File
@@ -31,6 +31,7 @@
#include "hwclock-util.h"
#include "list.h"
#include "log.h"
#include "log-context.h"
#include "main-func.h"
#include "memory-util.h"
#include "path-util.h"
@@ -71,33 +72,13 @@ typedef struct Context {
LIST_HEAD(UnitStatusInfo, units);
} Context;
#define log_unit_full_errno_zerook(unit, level, error, ...) \
({ \
const UnitStatusInfo *_u = (unit); \
_u ? log_object_internal(level, error, PROJECT_FILE, __LINE__, __func__, "UNIT=", _u->name, NULL, NULL, ##__VA_ARGS__) : \
log_internal(level, error, PROJECT_FILE, __LINE__, __func__, ##__VA_ARGS__); \
})
#define _LOG_CONTEXT_PUSH_UNIT(unit, u) \
const UnitStatusInfo *u = (unit); \
LOG_CONTEXT_PUSH_KEY_VALUE("UNIT=", u->name); \
LOG_SET_PREFIX(u->name)
#define log_unit_full_errno(unit, level, error, ...) \
({ \
int _error = (error); \
ASSERT_NON_ZERO(_error); \
log_unit_full_errno_zerook(unit, level, _error, ##__VA_ARGS__); \
})
#define log_unit_full(unit, level, ...) (void) log_unit_full_errno_zerook(unit, level, 0, ##__VA_ARGS__)
#define log_unit_debug(unit, ...) log_unit_full(unit, LOG_DEBUG, ##__VA_ARGS__)
#define log_unit_info(unit, ...) log_unit_full(unit, LOG_INFO, ##__VA_ARGS__)
#define log_unit_notice(unit, ...) log_unit_full(unit, LOG_NOTICE, ##__VA_ARGS__)
#define log_unit_warning(unit, ...) log_unit_full(unit, LOG_WARNING, ##__VA_ARGS__)
#define log_unit_error(unit, ...) log_unit_full(unit, LOG_ERR, ##__VA_ARGS__)
#define log_unit_debug_errno(unit, error, ...) log_unit_full_errno(unit, LOG_DEBUG, error, ##__VA_ARGS__)
#define log_unit_info_errno(unit, error, ...) log_unit_full_errno(unit, LOG_INFO, error, ##__VA_ARGS__)
#define log_unit_notice_errno(unit, error, ...) log_unit_full_errno(unit, LOG_NOTICE, error, ##__VA_ARGS__)
#define log_unit_warning_errno(unit, error, ...) log_unit_full_errno(unit, LOG_WARNING, error, ##__VA_ARGS__)
#define log_unit_error_errno(unit, error, ...) log_unit_full_errno(unit, LOG_ERR, error, ##__VA_ARGS__)
#define LOG_CONTEXT_PUSH_UNIT(unit) \
_LOG_CONTEXT_PUSH_UNIT(unit, UNIQ_T(u, UNIQ))
static void unit_status_info_clear(UnitStatusInfo *p) {
assert(p);
@@ -155,8 +136,10 @@ static int context_add_ntp_service(Context *c, const char *s, const char *source
if (!unit->name)
return -ENOMEM;
LOG_CONTEXT_PUSH_UNIT(unit);
LIST_APPEND(units, c->units, unit);
log_unit_debug(unit, "added from %s.", source);
log_debug("added from %s.", source);
TAKE_PTR(unit);
return 0;
@@ -423,6 +406,8 @@ static int context_update_ntp_status(Context *c, sd_bus *bus, sd_bus_message *m)
_cleanup_(sd_bus_error_free) sd_bus_error error = SD_BUS_ERROR_NULL;
_cleanup_free_ char *path = NULL;
LOG_CONTEXT_PUSH_UNIT(u);
unit_status_info_clear(u);
path = unit_dbus_path_from_name(u->name);
@@ -439,7 +424,7 @@ static int context_update_ntp_status(Context *c, sd_bus *bus, sd_bus_message *m)
NULL,
u);
if (r < 0)
return log_unit_error_errno(u, r, "Failed to get properties: %s", bus_error_message(&error, r));
return log_error_errno(r, "Failed to get properties: %s", bus_error_message(&error, r));
}
return 0;
@@ -493,6 +478,8 @@ static int unit_start_or_stop(UnitStatusInfo *u, sd_bus *bus, sd_bus_error *erro
assert(bus);
assert(error);
LOG_CONTEXT_PUSH_UNIT(u);
r = bus_call_method(
bus,
bus_systemd_mgr,
@@ -502,8 +489,8 @@ static int unit_start_or_stop(UnitStatusInfo *u, sd_bus *bus, sd_bus_error *erro
"ss",
u->name,
"replace");
log_unit_full_errno_zerook(u, r < 0 ? LOG_WARNING : LOG_DEBUG, r,
"%s unit: %m", start ? "Starting" : "Stopping");
log_full_errno_zerook(r < 0 ? LOG_WARNING : LOG_DEBUG, r,
"%s unit: %m", start ? "Starting" : "Stopping");
if (r < 0)
return r;
@@ -527,12 +514,14 @@ static int unit_enable_or_disable(UnitStatusInfo *u, sd_bus *bus, sd_bus_error *
/* Call context_update_ntp_status() to update UnitStatusInfo before calling this. */
LOG_CONTEXT_PUSH_UNIT(u);
if (streq(u->unit_file_state, "enabled") == enable) {
log_unit_debug(u, "already %sd.", enable_disable(enable));
log_debug("already %sd.", enable_disable(enable));
return 0;
}
log_unit_info(u, "%s unit.", enable ? "Enabling" : "Disabling");
log_info("%s unit.", enable ? "Enabling" : "Disabling");
if (enable)
r = bus_call_method(
@@ -998,6 +987,8 @@ static int method_set_ntp(sd_bus_message *m, void *userdata, sd_bus_error *error
if (!streq(u->load_state, "loaded"))
continue;
LOG_CONTEXT_PUSH_UNIT(u);
r = unit_enable_or_disable(u, bus, error, enable_this_one);
if (r < 0)
/* If enablement failed, don't start this unit. */
@@ -1005,9 +996,9 @@ static int method_set_ntp(sd_bus_message *m, void *userdata, sd_bus_error *error
r = unit_start_or_stop(u, bus, error, enable_this_one);
if (r < 0)
log_unit_warning_errno(u, r, "Failed to %s %sd NTP unit, ignoring: %m",
enable_this_one ? "start" : "stop",
enable_disable(enable_this_one));
log_warning_errno(r, "Failed to %s %sd NTP unit, ignoring: %m",
enable_this_one ? "start" : "stop",
enable_disable(enable_this_one));
if (enable_this_one)
selected = u;
}