core: apply LogLevelMax to messages about units #19050

rhendric · 2021-03-19T06:35:14Z

This commit applies the filtering imposed by LogLevelMax on a unit's
processes to messages logged by PID1 about the unit as well.

The target use case for this feature is a service that runs on a timer
many times an hour, where the system administrator decides that writing
a generic success message to the journal every few minutes or seconds
adds no diagnostic value and isn't worth the clutter or disk I/O.

Feature design based on #14279 (comment). Closes #4919. The functionality added here is rather under-tested, but covering every possible case where filtering could happen is probably overboard? Let me know if there are other tests you think should be present.

poettering · 2021-04-28T08:35:25Z

src/core/unit.h

@@ -879,6 +879,11 @@ static inline bool unit_has_job_type(Unit *u, JobType type) {
        return u && u->job && u->job->type == type;
 }

+static inline bool unit_filters_log_level(const Unit *u, int level) {
+        ExecContext *ec = unit_get_exec_context((Unit *)u);


casting the const away looks wrong. Please move that to unit_get_exec_context()

poettering

looks pretty good, but please move the testing of the log level into some log_unit_struct() macro, i.e. move it into the log concept, so that we don't accidentally forget it.

poettering · 2021-04-28T08:36:35Z

src/core/cgroup.c

@@ -2785,7 +2785,7 @@ int unit_check_oomd_kill(Unit *u) {
        if (!increased)
                return 0;

-        if (n > 0)
+        if (n > 0 && !unit_filters_log_level(u, LOG_NOTICE))
                log_struct(LOG_NOTICE,


hmm, please instead add log_unit_struct() or so, that adds LOG_UNIT_ID(u) and so on implicitly, and does this check internally, too

LOG_UNIT_ID(u) (etc.) doesn't appear in exactly the same place in every such call. There's a pattern I can abstract that covers the majority of the cases; should I abstract that and leave the remainder as a combination of unit_log_level_test and log_struct, or have log_unit_struct not include LOG_UNIT_ID(u) at all?

the order of the fields doesn't matter, journald might reorder anyway

Ah, I see, thanks!

poettering · 2021-04-28T08:37:04Z

src/core/execute.c

-                                                          command->path),
-                                         "EXECUTABLE=%s", command->path);
+                        if (!unit_filters_log_level(unit, LOG_INFO))
+                                log_struct_errno(LOG_INFO, r,


ditto, please add log_unit_struct_errno(), wich encapsulates this internally

poettering · 2021-04-28T08:38:25Z

src/core/unit.h

+static inline bool unit_filters_log_level(const Unit *u, int level) {
+        ExecContext *ec = unit_get_exec_context((Unit *)u);
+        return ec && ec->log_level_max >= 0 && ec->log_level_max < LOG_PRI(level);
+}


i'd invert the function result btw. i.e. i'd always focus on the positive case, i.e. letting the logging go though. i.e. invert and rename unit_log_level_test(…) or so?

rhendric · 2021-04-29T18:44:42Z

src/core/job.c

+                if (!unit_log_level_test(u, LOG_NOTICE))
+                        log_struct(LOG_NOTICE,
+                                   "JOB_TYPE=%s", job_type_to_string(t),
+                                   "JOB_RESULT=%s", job_result_to_string(result),
+                                   LOG_UNIT_ID(u),
+                                   LOG_UNIT_MESSAGE(u, "Job %s/%s failed with result '%s'.",
+                                                    u->id,
+                                                    job_type_to_string(t),
+                                                    job_result_to_string(result)));


@poettering This looks like it should be a log_unit_struct call as well; the reason it isn't is that, unlike all the other calls to log_struct that I modified, this one doesn't contain a LOG_UNIT_INVOCATION_ID field. I don't know if that was an oversight (and thus that this should be a log_unit_struct call like the others) or if there's a reason to exclude that field from this call; and if the latter, is this an acceptable solution, or should I remove LOG_UNIT_INVOCATION_ID from log_unit_struct and restore it to all the other call sites?

the invocation ID only makes sense when we log about units that are currently active (or at least were just active). but a job can can be enqueued/failed long before a unit is started, i.e. long bevor the invocation ID is assigned to it... Hence, we don't add it here, becuse the job is not directly associated to a specific invocation of a unit, it's usually preparation for a state change, and that's quite often to start something which will then, but only then result in an invocatin ID allocation.
hence, I'd suggest LOG_UNIT_INVOCATION_ID() is something that should be passed manually to log_unit_strruct(), even if we'll pass it in 90% of the cases

This commit applies the filtering imposed by LogLevelMax on a unit's processes to messages logged by PID1 about the unit as well. The target use case for this feature is a service that runs on a timer many times an hour, where the system administrator decides that writing a generic success message to the journal every few minutes or seconds adds no diagnostic value and isn't worth the clutter or disk I/O.

poettering

Looks really good. The log_unit_struct() changes is a big improvement, even beyond the log level cutoff.

THe man page should get some update too, saying this also applies about the logging from PID 1 about the unit now.

poettering · 2021-04-30T09:20:44Z

src/core/job.c

@@ -557,6 +557,9 @@ static void job_log_begin_status_message(Unit *u, uint32_t job_id, JobType t) {
        if (!IN_SET(t, JOB_START, JOB_STOP, JOB_RELOAD))
                return;

+        if (!unit_log_level_test(u, LOG_INFO))
+                return;
+


the log_struct() call in this function further down should also use log_unit_struct(), i.e please port all calls over systematically, including those where you add an early check like above

poettering · 2021-04-30T09:23:47Z

src/core/unit.c

@@ -2220,7 +2223,7 @@ static int unit_log_resources(Unit *u) {
        t = strjoina(u->manager->invocation_log_field, u->invocation_id_string);
        iovec[n_iovec + 3] = IOVEC_MAKE_STRING(t);

-        log_struct_iovec(log_level, iovec, n_iovec + 4);
+        log_unit_struct_iovec(u, log_level, iovec, n_iovec + 4);


given this whole function is relatively expensive, it might make sense to add an early-exit here too if the log level would suppress the output anyway

poettering · 2021-04-30T09:24:18Z

src/core/unit.c

@@ -4492,6 +4495,9 @@ void unit_warn_if_dir_nonempty(Unit *u, const char* where) {
        assert(u);
        assert(where);

+        if (!unit_log_level_test(u, LOG_NOTICE))
+                return;


here, too, please change the log_struct() call below to use log_unit_struct(), too

poettering · 2021-04-30T09:26:04Z

src/core/unit.h

@@ -957,6 +962,22 @@ int unit_thaw_vtable_common(Unit *u);
 #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_unit_struct_errno(unit, level, error, ...)                  \
+        ({                                                              \
+                const Unit *_u = (unit);                                \


can you add local variables like this for level + error here too? You use both twice here, and we'd rather avoid double evaluation. adding local variables and only assigning them once means we avoid the double eval

error appears in multiple places in these macros but is only eval'd once. You're right about level, though.

poettering · 2021-04-30T09:26:12Z

src/core/unit.h

+#define log_unit_struct_iovec_errno(unit, level, error, iovec, n_iovec) \
+        (unit_log_level_test(unit, level) ?                             \
+                log_struct_iovec_errno(level, error, iovec, n_iovec) :  \
+                -ERRNO_VALUE(error))


similar here

poettering · 2021-05-03T14:58:53Z

look excellent! thanks!

lgtm

- instead of noisy systemd timer (systemd/systemd#4919) (fixed a year ago with systemd/systemd#19050) - also lives at https://github.com/eMPee584/night-mode-daemon now - milestone: my first full python app : D

eMPee584 · 2023-02-28T09:21:20Z

.. is this supposed to work with user units? because it doesn't seem to.. a user service with SyslogLevel=6 and LogLevelMax=0 still spams the journal.

rhendric · 2023-02-28T09:52:47Z

Works for me. Are you sure you've written the unit file correctly?

poettering · 2023-02-28T18:02:51Z

.. is this supposed to work with user units? because it doesn't seem to.. a user service with SyslogLevel=6 and LogLevelMax=0 still spams the journal.

doesn't work with old kernels since unpriv userspace cannot set xattrs on cgroups there, which we need for this to work.

eMPee584 · 2023-02-28T20:33:14Z

Thanks to both of you for replying.. kernel is 6.0.12-1~bpo11+1, systemd 252.5-2~bpo11+1 .. that should be current enough I'd guess?
The /usr/lib/systemd/user/appimagelauncherd.service file looks somewhat unsuspicious, too:

[Unit]
Description=AppImageLauncher daemon

[Service]
ExecStart=/usr/bin/appimagelauncherd
Restart=on-failure
RestartSec=10

[Install]
WantedBy=default.target

I will have a sterner look at this at some later point.

poettering mentioned this pull request Apr 28, 2021

[WIP] core: add Unit.SilentOnSuccess config item #14279

Closed

poettering reviewed Apr 28, 2021

View reviewed changes

poettering requested changes Apr 28, 2021

View reviewed changes

poettering added pid1 reviewed/needs-rework 🔨 PR has been reviewed and needs another round of reworks labels Apr 28, 2021

rhendric commented Apr 29, 2021

View reviewed changes

rhendric requested a review from poettering April 30, 2021 02:04

poettering requested changes Apr 30, 2021

View reviewed changes

rhendric requested a review from poettering May 1, 2021 00:07

poettering added good-to-merge/waiting-for-ci 👍 PR is good to merge, but CI hasn't passed at time of review. Please merge if you see CI has passed and removed reviewed/needs-rework 🔨 PR has been reviewed and needs another round of reworks labels May 3, 2021

poettering merged commit c2503e3 into systemd:main May 3, 2021

rhendric deleted the feature/log-level-max-affects-pid1 branch May 3, 2021 17:11

dhewg mentioned this pull request Sep 20, 2021

Reduce log spam with LogLevelMax systemd-cron/systemd-cron#76

Closed

This was referenced Dec 27, 2022

Impossible to suppress start/stop log output for timers? #9328

Closed

Frequent "Starting../Started.." status messages for frequent timer units #4919

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

core: apply LogLevelMax to messages about units #19050

core: apply LogLevelMax to messages about units #19050

rhendric commented Mar 19, 2021

poettering Apr 28, 2021

poettering left a comment

poettering Apr 28, 2021

rhendric Apr 29, 2021

poettering Apr 29, 2021

rhendric Apr 29, 2021

poettering Apr 28, 2021

poettering Apr 28, 2021

rhendric Apr 29, 2021

poettering Apr 29, 2021

poettering left a comment

poettering Apr 30, 2021

poettering Apr 30, 2021

poettering Apr 30, 2021

poettering Apr 30, 2021

rhendric Apr 30, 2021

poettering Apr 30, 2021

poettering commented May 3, 2021

eMPee584 commented Feb 28, 2023

rhendric commented Feb 28, 2023

poettering commented Feb 28, 2023

eMPee584 commented Feb 28, 2023

core: apply LogLevelMax to messages about units #19050

core: apply LogLevelMax to messages about units #19050

Conversation

rhendric commented Mar 19, 2021

Choose a reason for hiding this comment

poettering left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

poettering left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

poettering commented May 3, 2021

eMPee584 commented Feb 28, 2023

rhendric commented Feb 28, 2023

poettering commented Feb 28, 2023

eMPee584 commented Feb 28, 2023