From 1cd81629e16d13ec1fd11c6588a2b4957bba4374 Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Tue, 13 Nov 2018 19:28:54 +0100 Subject: [PATCH 01/16] job: include JOB_ID field in log message about jobs --- src/core/job.c | 12 +++++++----- 1 file changed, 7 insertions(+), 5 deletions(-) diff --git a/src/core/job.c b/src/core/job.c index 2dc520389b..07846ca202 100644 --- a/src/core/job.c +++ b/src/core/job.c @@ -754,7 +754,7 @@ static void job_print_status_message(Unit *u, JobType t, JobResult result) { } } -static void job_log_status_message(Unit *u, JobType t, JobResult result) { +static void job_log_status_message(Unit *u, uint32_t job_id, JobType t, JobResult result) { const char *format, *mid; char buf[LINE_MAX]; static const int job_result_log_level[_JOB_RESULT_MAX] = { @@ -813,6 +813,7 @@ static void job_log_status_message(Unit *u, JobType t, JobResult result) { default: log_struct(job_result_log_level[result], LOG_MESSAGE("%s", buf), + "JOB_ID=%" PRIu32, job_id, "JOB_TYPE=%s", job_type_to_string(t), "JOB_RESULT=%s", job_result_to_string(result), LOG_UNIT_ID(u), @@ -822,6 +823,7 @@ static void job_log_status_message(Unit *u, JobType t, JobResult result) { log_struct(job_result_log_level[result], LOG_MESSAGE("%s", buf), + "JOB_ID=%" PRIu32, job_id, "JOB_TYPE=%s", job_type_to_string(t), "JOB_RESULT=%s", job_result_to_string(result), LOG_UNIT_ID(u), @@ -829,14 +831,14 @@ static void job_log_status_message(Unit *u, JobType t, JobResult result) { mid); } -static void job_emit_status_message(Unit *u, JobType t, JobResult result) { +static void job_emit_status_message(Unit *u, uint32_t job_id, JobType t, JobResult result) { assert(u); /* No message if the job did not actually do anything due to failed condition. */ if (t == JOB_START && result == JOB_DONE && !u->condition_result) return; - job_log_status_message(u, t, result); + job_log_status_message(u, job_id, t, result); job_print_status_message(u, t, result); } @@ -888,11 +890,11 @@ int job_finish_and_invalidate(Job *j, JobResult result, bool recursive, bool alr j->result = result; - log_unit_debug(u, "Job %s/%s finished, result=%s", u->id, job_type_to_string(t), job_result_to_string(result)); + log_unit_debug(u, "Job %" PRIu32 " %s/%s finished, result=%s", j->id, u->id, job_type_to_string(t), job_result_to_string(result)); /* If this job did nothing to respective unit we don't log the status message */ if (!already) - job_emit_status_message(u, t, result); + job_emit_status_message(u, j->id, t, result); /* Patch restart jobs so that they become normal start jobs */ if (result == JOB_DONE && t == JOB_RESTART) { From ea2c0e4526dbb520d55936e781f4493357a9866e Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Tue, 13 Nov 2018 19:34:30 +0100 Subject: [PATCH 02/16] job: minor coding style tweaks --- src/core/job.c | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/src/core/job.c b/src/core/job.c index 07846ca202..372d5360d5 100644 --- a/src/core/job.c +++ b/src/core/job.c @@ -583,7 +583,9 @@ int job_run_and_invalidate(Job *j) { switch (j->type) { case JOB_VERIFY_ACTIVE: { - UnitActiveState t = unit_active_state(j->unit); + UnitActiveState t; + + t = unit_active_state(j->unit); if (UNIT_IS_ACTIVE_OR_RELOADING(t)) r = -EALREADY; else if (t == UNIT_ACTIVATING) @@ -598,8 +600,7 @@ int job_run_and_invalidate(Job *j) { case JOB_RESTART: r = job_perform_on_unit(&j); - /* If the unit type does not support starting/stopping, - * then simply wait. */ + /* If the unit type does not support starting/stopping, then simply wait. */ if (r == -EBADR) r = 0; break; From 8ebd9175dba671aa5bf52130d48f0563a20b4efd Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Tue, 13 Nov 2018 19:39:04 +0100 Subject: [PATCH 03/16] job: add comment for EAGAIN job run case --- src/core/job.c | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/core/job.c b/src/core/job.c index 372d5360d5..6c4bd928a7 100644 --- a/src/core/job.c +++ b/src/core/job.c @@ -618,7 +618,9 @@ int job_run_and_invalidate(Job *j) { } if (j) { - if (r == -EALREADY) + if (r == -EAGAIN) + job_set_state(j, JOB_WAITING); /* Hmm, not ready after all, let's return to JOB_WAITING state */ + else if (r == -EALREADY) r = job_finish_and_invalidate(j, JOB_DONE, true, true); else if (r == -EBADR) r = job_finish_and_invalidate(j, JOB_SKIPPED, true, false); @@ -632,8 +634,6 @@ int job_run_and_invalidate(Job *j) { r = job_finish_and_invalidate(j, JOB_DEPENDENCY, true, false); else if (r == -ESTALE) r = job_finish_and_invalidate(j, JOB_ONCE, true, false); - else if (r == -EAGAIN) - job_set_state(j, JOB_WAITING); else if (r < 0) r = job_finish_and_invalidate(j, JOB_FAILED, true, false); } From f8c34706f51f5c66d33d6265b4d939d22cf90154 Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Tue, 13 Nov 2018 19:40:02 +0100 Subject: [PATCH 04/16] job: add log message when we can't enable the job run event source --- src/core/job.c | 9 +++++++-- 1 file changed, 7 insertions(+), 2 deletions(-) diff --git a/src/core/job.c b/src/core/job.c index 6c4bd928a7..1a4781dc8c 100644 --- a/src/core/job.c +++ b/src/core/job.c @@ -1036,14 +1036,19 @@ int job_start_timer(Job *j, bool job_running) { } void job_add_to_run_queue(Job *j) { + int r; + assert(j); assert(j->installed); if (j->in_run_queue) return; - if (!j->manager->run_queue) - sd_event_source_set_enabled(j->manager->run_queue_event_source, SD_EVENT_ONESHOT); + if (!j->manager->run_queue) { + r = sd_event_source_set_enabled(j->manager->run_queue_event_source, SD_EVENT_ONESHOT); + if (r < 0) + log_warning_errno(r, "Failed to enable job run queue event source, ignoring: %m"); + } LIST_PREPEND(run_queue, j->manager->run_queue, j); j->in_run_queue = true; From 33a3fdd9781329379f74e11a7a2707816aad8c61 Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Tue, 13 Nov 2018 19:57:43 +0100 Subject: [PATCH 05/16] core: move unit_status_emit_starting_stopping_reloading() and related calls to job.c MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit This call is only used by job.c and very specific to job handling. Moreover the very similar logic of job_emit_status_message() is already in job.c. Hence, let's clean this up, and move both sets of functions to job.c, and rename them a bit so that they express precisely what they do: 1. unit_status_emit_starting_stopping_reloading() → job_emit_begin_status_message() 2. job_emit_status_message() → job_emit_done_status_message() The first call is after all what we call when we begin with the execution of a job, and the second call what we call when we are done wiht it. Just some moving and renaming, not other changes, and hence no change in behaviour. --- src/core/job.c | 119 +++++++++++++++++++++++++++++++++++++++++------- src/core/unit.c | 86 ---------------------------------- src/core/unit.h | 1 - 3 files changed, 103 insertions(+), 103 deletions(-) diff --git a/src/core/job.c b/src/core/job.c index 1a4781dc8c..42474ce59d 100644 --- a/src/core/job.c +++ b/src/core/job.c @@ -509,6 +509,93 @@ static void job_change_type(Job *j, JobType newtype) { j->type = newtype; } +_pure_ static const char* job_get_begin_status_message_format(Unit *u, JobType t) { + const char *format; + const UnitStatusMessageFormats *format_table; + + assert(u); + assert(IN_SET(t, JOB_START, JOB_STOP, JOB_RELOAD)); + + if (t != JOB_RELOAD) { + format_table = &UNIT_VTABLE(u)->status_message_formats; + if (format_table) { + format = format_table->starting_stopping[t == JOB_STOP]; + if (format) + return format; + } + } + + /* Return generic strings */ + if (t == JOB_START) + return "Starting %s."; + else if (t == JOB_STOP) + return "Stopping %s."; + else + return "Reloading %s."; +} + +static void job_print_begin_status_message(Unit *u, JobType t) { + const char *format; + + assert(u); + + /* Reload status messages have traditionally not been printed to console. */ + if (!IN_SET(t, JOB_START, JOB_STOP)) + return; + + format = job_get_begin_status_message_format(u, t); + + DISABLE_WARNING_FORMAT_NONLITERAL; + unit_status_printf(u, "", format); + REENABLE_WARNING; +} + +static void job_log_begin_status_message(Unit *u, JobType t) { + const char *format, *mid; + char buf[LINE_MAX]; + + assert(u); + + if (!IN_SET(t, JOB_START, JOB_STOP, JOB_RELOAD)) + return; + + if (log_on_console()) + return; + + /* We log status messages for all units and all operations. */ + + format = job_get_begin_status_message_format(u, t); + + DISABLE_WARNING_FORMAT_NONLITERAL; + (void) snprintf(buf, sizeof buf, format, unit_description(u)); + REENABLE_WARNING; + + mid = t == JOB_START ? "MESSAGE_ID=" SD_MESSAGE_UNIT_STARTING_STR : + t == JOB_STOP ? "MESSAGE_ID=" SD_MESSAGE_UNIT_STOPPING_STR : + "MESSAGE_ID=" SD_MESSAGE_UNIT_RELOADING_STR; + + /* Note that we deliberately use LOG_MESSAGE() instead of + * LOG_UNIT_MESSAGE() here, since this is supposed to mimic + * closely what is written to screen using the status output, + * which is supposed the highest level, friendliest output + * possible, which means we should avoid the low-level unit + * name. */ + log_struct(LOG_INFO, + LOG_MESSAGE("%s", buf), + LOG_UNIT_ID(u), + LOG_UNIT_INVOCATION_ID(u), + mid); +} + +static void job_emit_begin_status_message(Unit *u, JobType t) { + assert(u); + assert(t >= 0); + assert(t < _JOB_TYPE_MAX); + + job_log_begin_status_message(u, t); + job_print_begin_status_message(u, t); +} + static int job_perform_on_unit(Job **j) { uint32_t id; Manager *m; @@ -554,7 +641,7 @@ static int job_perform_on_unit(Job **j) { * actually did something. */ *j = manager_get_job(m, id); if (*j && r > 0) - unit_status_emit_starting_stopping_reloading(u, t); + job_emit_begin_status_message(u, t); return r; } @@ -641,7 +728,7 @@ int job_run_and_invalidate(Job *j) { return r; } -_pure_ static const char *job_get_status_message_format(Unit *u, JobType t, JobResult result) { +_pure_ static const char *job_get_done_status_message_format(Unit *u, JobType t, JobResult result) { static const char *const generic_finished_start_job[_JOB_RESULT_MAX] = { [JOB_DONE] = "Started %s.", @@ -702,7 +789,7 @@ _pure_ static const char *job_get_status_message_format(Unit *u, JobType t, JobR static const struct { const char *color, *word; -} job_print_status_messages [_JOB_RESULT_MAX] = { +} job_print_done_status_messages[_JOB_RESULT_MAX] = { [JOB_DONE] = { ANSI_OK_COLOR, " OK " }, [JOB_TIMEOUT] = { ANSI_HIGHLIGHT_RED, " TIME " }, [JOB_FAILED] = { ANSI_HIGHLIGHT_RED, "FAILED" }, @@ -714,7 +801,7 @@ static const struct { [JOB_ONCE] = { ANSI_HIGHLIGHT_RED, " ONCE " }, }; -static void job_print_status_message(Unit *u, JobType t, JobResult result) { +static void job_print_done_status_message(Unit *u, JobType t, JobResult result) { const char *format; const char *status; @@ -726,19 +813,19 @@ static void job_print_status_message(Unit *u, JobType t, JobResult result) { if (t == JOB_RELOAD) return; - if (!job_print_status_messages[result].word) + if (!job_print_done_status_messages[result].word) return; - format = job_get_status_message_format(u, t, result); + format = job_get_done_status_message_format(u, t, result); if (!format) return; if (log_get_show_color()) - status = strjoina(job_print_status_messages[result].color, - job_print_status_messages[result].word, + status = strjoina(job_print_done_status_messages[result].color, + job_print_done_status_messages[result].word, ANSI_NORMAL); else - status = job_print_status_messages[result].word; + status = job_print_done_status_messages[result].word; if (result != JOB_DONE) manager_flip_auto_status(u->manager, true); @@ -755,7 +842,7 @@ static void job_print_status_message(Unit *u, JobType t, JobResult result) { } } -static void job_log_status_message(Unit *u, uint32_t job_id, JobType t, JobResult result) { +static void job_log_done_status_message(Unit *u, uint32_t job_id, JobType t, JobResult result) { const char *format, *mid; char buf[LINE_MAX]; static const int job_result_log_level[_JOB_RESULT_MAX] = { @@ -778,10 +865,10 @@ static void job_log_status_message(Unit *u, uint32_t job_id, JobType t, JobResul /* Skip printing if output goes to the console, and job_print_status_message() will actually print something to the console. */ - if (log_on_console() && job_print_status_messages[result].word) + if (log_on_console() && job_print_done_status_messages[result].word) return; - format = job_get_status_message_format(u, t, result); + format = job_get_done_status_message_format(u, t, result); if (!format) return; @@ -832,15 +919,15 @@ static void job_log_status_message(Unit *u, uint32_t job_id, JobType t, JobResul mid); } -static void job_emit_status_message(Unit *u, uint32_t job_id, JobType t, JobResult result) { +static void job_emit_done_status_message(Unit *u, uint32_t job_id, JobType t, JobResult result) { assert(u); /* No message if the job did not actually do anything due to failed condition. */ if (t == JOB_START && result == JOB_DONE && !u->condition_result) return; - job_log_status_message(u, job_id, t, result); - job_print_status_message(u, t, result); + job_log_done_status_message(u, job_id, t, result); + job_print_done_status_message(u, t, result); } static void job_fail_dependencies(Unit *u, UnitDependency d) { @@ -895,7 +982,7 @@ int job_finish_and_invalidate(Job *j, JobResult result, bool recursive, bool alr /* If this job did nothing to respective unit we don't log the status message */ if (!already) - job_emit_status_message(u, j->id, t, result); + job_emit_done_status_message(u, j->id, t, result); /* Patch restart jobs so that they become normal start jobs */ if (result == JOB_DONE && t == JOB_RESTART) { diff --git a/src/core/unit.c b/src/core/unit.c index c4a0b49edb..1dc62768a2 100644 --- a/src/core/unit.c +++ b/src/core/unit.c @@ -1627,92 +1627,6 @@ void unit_status_printf(Unit *u, const char *status, const char *unit_status_msg REENABLE_WARNING; } -_pure_ static const char* unit_get_status_message_format(Unit *u, JobType t) { - const char *format; - const UnitStatusMessageFormats *format_table; - - assert(u); - assert(IN_SET(t, JOB_START, JOB_STOP, JOB_RELOAD)); - - if (t != JOB_RELOAD) { - format_table = &UNIT_VTABLE(u)->status_message_formats; - if (format_table) { - format = format_table->starting_stopping[t == JOB_STOP]; - if (format) - return format; - } - } - - /* Return generic strings */ - if (t == JOB_START) - return "Starting %s."; - else if (t == JOB_STOP) - return "Stopping %s."; - else - return "Reloading %s."; -} - -static void unit_status_print_starting_stopping(Unit *u, JobType t) { - const char *format; - - assert(u); - - /* Reload status messages have traditionally not been printed to console. */ - if (!IN_SET(t, JOB_START, JOB_STOP)) - return; - - format = unit_get_status_message_format(u, t); - - DISABLE_WARNING_FORMAT_NONLITERAL; - unit_status_printf(u, "", format); - REENABLE_WARNING; -} - -static void unit_status_log_starting_stopping_reloading(Unit *u, JobType t) { - const char *format, *mid; - char buf[LINE_MAX]; - - assert(u); - - if (!IN_SET(t, JOB_START, JOB_STOP, JOB_RELOAD)) - return; - - if (log_on_console()) - return; - - /* We log status messages for all units and all operations. */ - - format = unit_get_status_message_format(u, t); - - DISABLE_WARNING_FORMAT_NONLITERAL; - (void) snprintf(buf, sizeof buf, format, unit_description(u)); - REENABLE_WARNING; - - mid = t == JOB_START ? "MESSAGE_ID=" SD_MESSAGE_UNIT_STARTING_STR : - t == JOB_STOP ? "MESSAGE_ID=" SD_MESSAGE_UNIT_STOPPING_STR : - "MESSAGE_ID=" SD_MESSAGE_UNIT_RELOADING_STR; - - /* Note that we deliberately use LOG_MESSAGE() instead of - * LOG_UNIT_MESSAGE() here, since this is supposed to mimic - * closely what is written to screen using the status output, - * which is supposed the highest level, friendliest output - * possible, which means we should avoid the low-level unit - * name. */ - log_struct(LOG_INFO, - LOG_MESSAGE("%s", buf), - LOG_UNIT_ID(u), - LOG_UNIT_INVOCATION_ID(u), - mid); -} - -void unit_status_emit_starting_stopping_reloading(Unit *u, JobType t) { - assert(u); - assert(t >= 0); - assert(t < _JOB_TYPE_MAX); - - unit_status_log_starting_stopping_reloading(u, t); - unit_status_print_starting_stopping(u, t); -} int unit_start_limit_test(Unit *u) { const char *reason; diff --git a/src/core/unit.h b/src/core/unit.h index c6ee1dfc3b..eb8f1f5653 100644 --- a/src/core/unit.h +++ b/src/core/unit.h @@ -701,7 +701,6 @@ int unit_coldplug(Unit *u); void unit_catchup(Unit *u); void unit_status_printf(Unit *u, const char *status, const char *unit_status_msg_format) _printf_(3, 0); -void unit_status_emit_starting_stopping_reloading(Unit *u, JobType t); bool unit_need_daemon_reload(Unit *u); From b344b363ce26c13fcd27df5dc5ecf45e426329a0 Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Tue, 13 Nov 2018 20:16:45 +0100 Subject: [PATCH 06/16] job: also include job ID in log messages when we begin with a job --- src/core/job.c | 12 ++++++++---- 1 file changed, 8 insertions(+), 4 deletions(-) diff --git a/src/core/job.c b/src/core/job.c index 42474ce59d..bf3db5a887 100644 --- a/src/core/job.c +++ b/src/core/job.c @@ -550,11 +550,13 @@ static void job_print_begin_status_message(Unit *u, JobType t) { REENABLE_WARNING; } -static void job_log_begin_status_message(Unit *u, JobType t) { +static void job_log_begin_status_message(Unit *u, uint32_t job_id, JobType t) { const char *format, *mid; char buf[LINE_MAX]; assert(u); + assert(t >= 0); + assert(t < _JOB_TYPE_MAX); if (!IN_SET(t, JOB_START, JOB_STOP, JOB_RELOAD)) return; @@ -582,17 +584,19 @@ static void job_log_begin_status_message(Unit *u, JobType t) { * name. */ log_struct(LOG_INFO, LOG_MESSAGE("%s", buf), + "JOB_ID=%" PRIu32, job_id, + "JOB_TYPE=%s", job_type_to_string(t), LOG_UNIT_ID(u), LOG_UNIT_INVOCATION_ID(u), mid); } -static void job_emit_begin_status_message(Unit *u, JobType t) { +static void job_emit_begin_status_message(Unit *u, uint32_t job_id, JobType t) { assert(u); assert(t >= 0); assert(t < _JOB_TYPE_MAX); - job_log_begin_status_message(u, t); + job_log_begin_status_message(u, job_id, t); job_print_begin_status_message(u, t); } @@ -641,7 +645,7 @@ static int job_perform_on_unit(Job **j) { * actually did something. */ *j = manager_get_job(m, id); if (*j && r > 0) - job_emit_begin_status_message(u, t); + job_emit_begin_status_message(u, id, t); return r; } From 0b999d34b15303da9ee349ddba258a63ff35eca8 Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Tue, 13 Nov 2018 20:36:51 +0100 Subject: [PATCH 07/16] catalog: update job begin/done messages These texts have been slightly misleading previously, as they talked about units, not jobs, but are actually generated for jobs, not units. This difference matters as units can change state without a job requesting that. Also, the message be02cf6855d2428ba40df7e9d022f03d was particularly wrong, as it claimed the unit failed, while it actually is the start job that failed, which is a major difference, as jobs can fail without the unit actually being placed in a failed state. Let's move this message a bit up, closed to 39f53479d3a045ac8e11786248231fbf (i.e. the message seen when a start job finished successfully). --- catalog/systemd.catalog.in | 62 +++++++++++++++++++++----------------- 1 file changed, 35 insertions(+), 27 deletions(-) diff --git a/catalog/systemd.catalog.in b/catalog/systemd.catalog.in index 49a45890f6..2136c93d02 100644 --- a/catalog/systemd.catalog.in +++ b/catalog/systemd.catalog.in @@ -189,59 +189,67 @@ System shutdown has been initiated. The shutdown has now begun and all system services are terminated and all file systems unmounted. -- 7d4958e842da4a758f6c1cdc7b36dcc5 -Subject: Unit @UNIT@ has begun start-up +Subject: A start job for unit @UNIT@ has begun execution Defined-By: systemd Support: %SUPPORT_URL% -Unit @UNIT@ has begun starting up. +A start job for unit @UNIT@ has begun execution. + +The job identifier is @JOB_ID@. -- 39f53479d3a045ac8e11786248231fbf -Subject: Unit @UNIT@ has finished start-up +Subject: A start job for unit @UNIT@ has finished successfully Defined-By: systemd Support: %SUPPORT_URL% -Unit @UNIT@ has finished starting up. +A start job for unit @UNIT@ has finished successfully. -The start-up result is @JOB_RESULT@. - --- de5b426a63be47a7b6ac3eaac82e2f6f -Subject: Unit @UNIT@ has begun shutting down -Defined-By: systemd -Support: %SUPPORT_URL% - -Unit @UNIT@ has begun shutting down. - --- 9d1aaa27d60140bd96365438aad20286 -Subject: Unit @UNIT@ has finished shutting down -Defined-By: systemd -Support: %SUPPORT_URL% - -Unit @UNIT@ has finished shutting down. +The job identifier is @JOB_ID@. -- be02cf6855d2428ba40df7e9d022f03d -Subject: Unit @UNIT@ has failed +Subject: A start job for unit @UNIT@ has failed Defined-By: systemd Support: %SUPPORT_URL% -Unit @UNIT@ has failed. +A start job for unit @UNIT@ has finished with a failure. -The result is @JOB_RESULT@. +The job identifier is @JOB_ID@ and the job result is @JOB_RESULT@. + +-- de5b426a63be47a7b6ac3eaac82e2f6f +Subject: A stop job for unit @UNIT@ has begun execution +Defined-By: systemd +Support: %SUPPORT_URL% + +A stop job for unit @UNIT@ has begun execution. + +The job identifier is @JOB_ID@. + +-- 9d1aaa27d60140bd96365438aad20286 +Subject: A stop job for unit @UNIT@ has finished +Defined-By: systemd +Support: %SUPPORT_URL% + +A stop job for unit @UNIT@ has finished. + +The job identifier is @JOB_ID@ and the job result is @JOB_RESULT@. -- d34d037fff1847e6ae669a370e694725 -Subject: Unit @UNIT@ has begun reloading its configuration +Subject: A reload job for unit @UNIT@ has begun execution Defined-By: systemd Support: %SUPPORT_URL% -Unit @UNIT@ has begun reloading its configuration +A reload job for unit @UNIT@ has begun execution. + +The job identifier is @JOB_ID@. -- 7b05ebc668384222baa8881179cfda54 -Subject: Unit @UNIT@ has finished reloading its configuration +Subject: A reload job for unit @UNIT@ has finished Defined-By: systemd Support: %SUPPORT_URL% -Unit @UNIT@ has finished reloading its configuration +A reload job for unit @UNIT@ has finished. -The result is @JOB_RESULT@. +The job identifier is @JOB_ID@ and the job result is @JOB_RESULT@. -- 641257651c1b4ec9a8624d7a40a9e1e7 Subject: Process @EXECUTABLE@ could not be executed From 295f31b0b73052b1347e64466f897f71dbfe0b4d Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Tue, 13 Nov 2018 20:40:38 +0100 Subject: [PATCH 08/16] sd-messages: add comment and reorder a bit The message SD_MESSAGE_UNIT_FAILED is closely related to SD_MESSAGE_UNIT_STARTED as it is generated when a start job failed instead of completed successfully, Hence they should be placed together. Otherwise one might get the impression that the message was about failing units, which it really is not. --- src/systemd/sd-messages.h | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/src/systemd/sd-messages.h b/src/systemd/sd-messages.h index ba6c6b1cf8..749038aed7 100644 --- a/src/systemd/sd-messages.h +++ b/src/systemd/sd-messages.h @@ -81,16 +81,19 @@ _SD_BEGIN_DECLARATIONS; #define SD_MESSAGE_SHUTDOWN SD_ID128_MAKE(98,26,88,66,d1,d5,4a,49,9c,4e,98,92,1d,93,bc,40) #define SD_MESSAGE_SHUTDOWN_STR SD_ID128_MAKE_STR(98,26,88,66,d1,d5,4a,49,9c,4e,98,92,1d,93,bc,40) +/* The messages below are actually about jobs, not really about units, the macros are misleadingly named. Moreover + * SD_MESSAGE_UNIT_FAILED is not actually about a failing unit but about a failed start job. A job either finishes with + * SD_MESSAGE_UNIT_STARTED or with SD_MESSAGE_UNIT_FAILED hence. */ #define SD_MESSAGE_UNIT_STARTING SD_ID128_MAKE(7d,49,58,e8,42,da,4a,75,8f,6c,1c,dc,7b,36,dc,c5) #define SD_MESSAGE_UNIT_STARTING_STR SD_ID128_MAKE_STR(7d,49,58,e8,42,da,4a,75,8f,6c,1c,dc,7b,36,dc,c5) #define SD_MESSAGE_UNIT_STARTED SD_ID128_MAKE(39,f5,34,79,d3,a0,45,ac,8e,11,78,62,48,23,1f,bf) #define SD_MESSAGE_UNIT_STARTED_STR SD_ID128_MAKE_STR(39,f5,34,79,d3,a0,45,ac,8e,11,78,62,48,23,1f,bf) +#define SD_MESSAGE_UNIT_FAILED SD_ID128_MAKE(be,02,cf,68,55,d2,42,8b,a4,0d,f7,e9,d0,22,f0,3d) +#define SD_MESSAGE_UNIT_FAILED_STR SD_ID128_MAKE_STR(be,02,cf,68,55,d2,42,8b,a4,0d,f7,e9,d0,22,f0,3d) #define SD_MESSAGE_UNIT_STOPPING SD_ID128_MAKE(de,5b,42,6a,63,be,47,a7,b6,ac,3e,aa,c8,2e,2f,6f) #define SD_MESSAGE_UNIT_STOPPING_STR SD_ID128_MAKE_STR(de,5b,42,6a,63,be,47,a7,b6,ac,3e,aa,c8,2e,2f,6f) #define SD_MESSAGE_UNIT_STOPPED SD_ID128_MAKE(9d,1a,aa,27,d6,01,40,bd,96,36,54,38,aa,d2,02,86) #define SD_MESSAGE_UNIT_STOPPED_STR SD_ID128_MAKE_STR(9d,1a,aa,27,d6,01,40,bd,96,36,54,38,aa,d2,02,86) -#define SD_MESSAGE_UNIT_FAILED SD_ID128_MAKE(be,02,cf,68,55,d2,42,8b,a4,0d,f7,e9,d0,22,f0,3d) -#define SD_MESSAGE_UNIT_FAILED_STR SD_ID128_MAKE_STR(be,02,cf,68,55,d2,42,8b,a4,0d,f7,e9,d0,22,f0,3d) #define SD_MESSAGE_UNIT_RELOADING SD_ID128_MAKE(d3,4d,03,7f,ff,18,47,e6,ae,66,9a,37,0e,69,47,25) #define SD_MESSAGE_UNIT_RELOADING_STR SD_ID128_MAKE_STR(d3,4d,03,7f,ff,18,47,e6,ae,66,9a,37,0e,69,47,25) #define SD_MESSAGE_UNIT_RELOADED SD_ID128_MAKE(7b,05,eb,c6,68,38,42,22,ba,a8,88,11,79,cf,da,54) From 7c047d7443347c109daf67023a01c118b5f361eb Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Tue, 13 Nov 2018 21:25:22 +0100 Subject: [PATCH 09/16] core: make log messages about units entering a 'failed' state recognizable Let's make this recognizable, and carry result information in a structure fashion. --- catalog/systemd.catalog.in | 7 +++++++ src/core/automount.c | 2 +- src/core/mount.c | 2 +- src/core/path.c | 2 +- src/core/scope.c | 2 +- src/core/service.c | 2 +- src/core/socket.c | 2 +- src/core/swap.c | 2 +- src/core/timer.c | 2 +- src/core/unit.c | 12 ++++++++++++ src/core/unit.h | 2 ++ src/systemd/sd-messages.h | 4 ++++ 12 files changed, 33 insertions(+), 8 deletions(-) diff --git a/catalog/systemd.catalog.in b/catalog/systemd.catalog.in index 2136c93d02..1e64209e9c 100644 --- a/catalog/systemd.catalog.in +++ b/catalog/systemd.catalog.in @@ -352,6 +352,13 @@ Support: %SUPPORT_URL% The unit @UNIT@ completed and consumed the indicated resources. +-- d9b373ed55a64feb8242e02dbe79a49c +Subject: Unit failed +Defined-By: systemd +Support: %SUPPORT_URL% + +The unit @UNIT@ has entered the 'failed' state with result '@UNIT_RESULT@'. + -- 50876a9db00f4c40bde1a2ad381c3a1b Subject: The system is configured in a way that might cause problems Defined-By: systemd diff --git a/src/core/automount.c b/src/core/automount.c index eaacf5e8b9..57e6a985fd 100644 --- a/src/core/automount.c +++ b/src/core/automount.c @@ -316,7 +316,7 @@ static void automount_enter_dead(Automount *a, AutomountResult f) { a->result = f; if (a->result != AUTOMOUNT_SUCCESS) - log_unit_warning(UNIT(a), "Failed with result '%s'.", automount_result_to_string(a->result)); + unit_log_failure(UNIT(a), automount_result_to_string(a->result)); automount_set_state(a, a->result != AUTOMOUNT_SUCCESS ? AUTOMOUNT_FAILED : AUTOMOUNT_DEAD); } diff --git a/src/core/mount.c b/src/core/mount.c index 5e1ef1e6ac..e13b07d33b 100644 --- a/src/core/mount.c +++ b/src/core/mount.c @@ -800,7 +800,7 @@ static void mount_enter_dead(Mount *m, MountResult f) { m->result = f; if (m->result != MOUNT_SUCCESS) - log_unit_warning(UNIT(m), "Failed with result '%s'.", mount_result_to_string(m->result)); + unit_log_failure(UNIT(m), mount_result_to_string(m->result)); mount_set_state(m, m->result != MOUNT_SUCCESS ? MOUNT_FAILED : MOUNT_DEAD); diff --git a/src/core/path.c b/src/core/path.c index 258e3a00cb..a134fc288c 100644 --- a/src/core/path.c +++ b/src/core/path.c @@ -450,7 +450,7 @@ static void path_enter_dead(Path *p, PathResult f) { p->result = f; if (p->result != PATH_SUCCESS) - log_unit_warning(UNIT(p), "Failed with result '%s'.", path_result_to_string(p->result)); + unit_log_failure(UNIT(p), path_result_to_string(p->result)); path_set_state(p, p->result != PATH_SUCCESS ? PATH_FAILED : PATH_DEAD); } diff --git a/src/core/scope.c b/src/core/scope.c index 7883d19325..9ff082df3a 100644 --- a/src/core/scope.c +++ b/src/core/scope.c @@ -241,7 +241,7 @@ static void scope_enter_dead(Scope *s, ScopeResult f) { s->result = f; if (s->result != SCOPE_SUCCESS) - log_unit_warning(UNIT(s), "Failed with result '%s'.", scope_result_to_string(s->result)); + unit_log_failure(UNIT(s), scope_result_to_string(s->result)); scope_set_state(s, s->result != SCOPE_SUCCESS ? SCOPE_FAILED : SCOPE_DEAD); } diff --git a/src/core/service.c b/src/core/service.c index 50ceda7ac6..c008062411 100644 --- a/src/core/service.c +++ b/src/core/service.c @@ -1700,7 +1700,7 @@ static void service_enter_dead(Service *s, ServiceResult f, bool allow_restart) s->result = f; if (s->result != SERVICE_SUCCESS) - log_unit_warning(UNIT(s), "Failed with result '%s'.", service_result_to_string(s->result)); + unit_log_failure(UNIT(s), service_result_to_string(s->result)); if (allow_restart && service_shall_restart(s)) s->will_auto_restart = true; diff --git a/src/core/socket.c b/src/core/socket.c index 407ad1352c..5d44ce3fb1 100644 --- a/src/core/socket.c +++ b/src/core/socket.c @@ -1986,7 +1986,7 @@ static void socket_enter_dead(Socket *s, SocketResult f) { s->result = f; if (s->result != SOCKET_SUCCESS) - log_unit_warning(UNIT(s), "Failed with result '%s'.", socket_result_to_string(s->result)); + unit_log_failure(UNIT(s), socket_result_to_string(s->result)); socket_set_state(s, s->result != SOCKET_SUCCESS ? SOCKET_FAILED : SOCKET_DEAD); diff --git a/src/core/swap.c b/src/core/swap.c index ff1412879f..d3d0e40e2d 100644 --- a/src/core/swap.c +++ b/src/core/swap.c @@ -654,7 +654,7 @@ static void swap_enter_dead(Swap *s, SwapResult f) { s->result = f; if (s->result != SWAP_SUCCESS) - log_unit_warning(UNIT(s), "Failed with result '%s'.", swap_result_to_string(s->result)); + unit_log_failure(UNIT(s), swap_result_to_string(s->result)); swap_set_state(s, s->result != SWAP_SUCCESS ? SWAP_FAILED : SWAP_DEAD); diff --git a/src/core/timer.c b/src/core/timer.c index bd119cabd3..98ba868bb1 100644 --- a/src/core/timer.c +++ b/src/core/timer.c @@ -289,7 +289,7 @@ static void timer_enter_dead(Timer *t, TimerResult f) { t->result = f; if (t->result != TIMER_SUCCESS) - log_unit_warning(UNIT(t), "Failed with result '%s'.", timer_result_to_string(t->result)); + unit_log_failure(UNIT(t), timer_result_to_string(t->result)); timer_set_state(t, t->result != TIMER_SUCCESS ? TIMER_FAILED : TIMER_DEAD); } diff --git a/src/core/unit.c b/src/core/unit.c index 1dc62768a2..88d20a1b9f 100644 --- a/src/core/unit.c +++ b/src/core/unit.c @@ -5444,6 +5444,18 @@ int unit_pid_attachable(Unit *u, pid_t pid, sd_bus_error *error) { return 0; } +void unit_log_failure(Unit *u, const char *result) { + assert(u); + assert(result); + + log_struct(LOG_WARNING, + "MESSAGE_ID=" SD_MESSAGE_UNIT_FAILURE_RESULT_STR, + LOG_UNIT_ID(u), + LOG_UNIT_INVOCATION_ID(u), + LOG_UNIT_MESSAGE(u, "Failed with result '%s'.", result), + "UNIT_RESULT=%s", result); +} + static const char* const collect_mode_table[_COLLECT_MODE_MAX] = { [COLLECT_INACTIVE] = "inactive", [COLLECT_INACTIVE_OR_FAILED] = "inactive-or-failed", diff --git a/src/core/unit.h b/src/core/unit.h index eb8f1f5653..e3f859d5ef 100644 --- a/src/core/unit.h +++ b/src/core/unit.h @@ -806,6 +806,8 @@ const char *unit_label_path(Unit *u); int unit_pid_attachable(Unit *unit, pid_t pid, sd_bus_error *error); +void unit_log_failure(Unit *u, const char *result); + /* Macros which append UNIT= or USER_UNIT= to the message */ #define log_unit_full(unit, level, error, ...) \ diff --git a/src/systemd/sd-messages.h b/src/systemd/sd-messages.h index 749038aed7..1ea79fc661 100644 --- a/src/systemd/sd-messages.h +++ b/src/systemd/sd-messages.h @@ -106,6 +106,10 @@ _SD_BEGIN_DECLARATIONS; #define SD_MESSAGE_UNIT_RESOURCES SD_ID128_MAKE(ae,8f,7b,86,6b,03,47,b9,af,31,fe,1c,80,b1,27,c0) #define SD_MESSAGE_UNIT_RESOURCES_STR SD_ID128_MAKE_STR(ae,8f,7b,86,6b,03,47,b9,af,31,fe,1c,80,b1,27,c0) +#define SD_MESSAGE_UNIT_FAILURE_RESULT SD_ID128_MAKE(d9,b3,73,ed,55,a6,4f,eb,82,42,e0,2d,be,79,a4,9c) +#define SD_MESSAGE_UNIT_FAILURE_RESULT_STR \ + SD_ID128_MAKE_STR(d9,b3,73,ed,55,a6,4f,eb,82,42,e0,2d,be,79,a4,9c) + #define SD_MESSAGE_SPAWN_FAILED SD_ID128_MAKE(64,12,57,65,1c,1b,4e,c9,a8,62,4d,7a,40,a9,e1,e7) #define SD_MESSAGE_SPAWN_FAILED_STR SD_ID128_MAKE_STR(64,12,57,65,1c,1b,4e,c9,a8,62,4d,7a,40,a9,e1,e7) From 91bbd9b796ec9a2926660fd0e1c9a1b326a1a98a Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Tue, 13 Nov 2018 22:10:38 +0100 Subject: [PATCH 10/16] core: make log messages about unit processes exiting recognizable --- catalog/systemd.catalog.in | 9 +++++++++ src/core/mount.c | 7 +++++-- src/core/service.c | 30 ++++++++++++------------------ src/core/socket.c | 8 +++++--- src/core/swap.c | 7 +++++-- src/core/unit.c | 29 +++++++++++++++++++++++++++++ src/core/unit.h | 1 + src/systemd/sd-messages.h | 3 +++ 8 files changed, 69 insertions(+), 25 deletions(-) diff --git a/catalog/systemd.catalog.in b/catalog/systemd.catalog.in index 1e64209e9c..c99da0a634 100644 --- a/catalog/systemd.catalog.in +++ b/catalog/systemd.catalog.in @@ -359,6 +359,15 @@ Support: %SUPPORT_URL% The unit @UNIT@ has entered the 'failed' state with result '@UNIT_RESULT@'. +-- 98e322203f7a4ed290d09fe03c09fe15 +Subject: Unit process exited +Defined-By: systemd +Support: %SUPPORT_URL% + +An @COMMAND@= process belonging to unit @UNIT@ has exited. + +The process' exit code is '@EXIT_CODE@' and its exit status is @EXIT_STATUS@. + -- 50876a9db00f4c40bde1a2ad381c3a1b Subject: The system is configured in a way that might cause problems Defined-By: systemd diff --git a/src/core/mount.c b/src/core/mount.c index e13b07d33b..002127bf10 100644 --- a/src/core/mount.c +++ b/src/core/mount.c @@ -1270,8 +1270,11 @@ static void mount_sigchld_event(Unit *u, pid_t pid, int code, int status) { m->control_command_id = _MOUNT_EXEC_COMMAND_INVALID; } - log_unit_full(u, f == MOUNT_SUCCESS ? LOG_DEBUG : LOG_NOTICE, 0, - "Mount process exited, code=%s status=%i", sigchld_code_to_string(code), status); + unit_log_process_exit( + u, f == MOUNT_SUCCESS ? LOG_DEBUG : LOG_NOTICE, + "Mount process", + mount_exec_command_to_string(m->control_command_id), + code, status); /* Note that due to the io event priority logic, we can be sure the new mountinfo is loaded * before we process the SIGCHLD for the mount command. */ diff --git a/src/core/service.c b/src/core/service.c index c008062411..49a1131c38 100644 --- a/src/core/service.c +++ b/src/core/service.c @@ -3233,21 +3233,13 @@ static void service_sigchld_event(Unit *u, pid_t pid, int code, int status) { /* When this is a successful exit, let's log about the exit code on DEBUG level. If this is a failure * and the process exited on its own via exit(), then let's make this a NOTICE, under the assumption - * that the service already logged the reason at a higher log level on its own. However, if the service - * died due to a signal, then it most likely didn't say anything about any reason, hence let's raise - * our log level to WARNING then. */ - - log_struct(f == SERVICE_SUCCESS ? LOG_DEBUG : - (code == CLD_EXITED ? LOG_NOTICE : LOG_WARNING), - LOG_UNIT_MESSAGE(u, "Main process exited, code=%s, status=%i/%s", - sigchld_code_to_string(code), status, - strna(code == CLD_EXITED - ? exit_status_to_string(status, EXIT_STATUS_FULL) - : signal_to_string(status))), - "EXIT_CODE=%s", sigchld_code_to_string(code), - "EXIT_STATUS=%i", status, - LOG_UNIT_ID(u), - LOG_UNIT_INVOCATION_ID(u)); + * that the service already logged the reason at a higher log level on its own. (Internally, + * unit_log_process_exit() will possibly bump this to WARNING if the service died due to a signal.) */ + unit_log_process_exit( + u, f == SERVICE_SUCCESS ? LOG_DEBUG : LOG_NOTICE, + "Main process", + service_exec_command_to_string(SERVICE_EXEC_START), + code, status); if (s->result == SERVICE_SUCCESS) s->result = f; @@ -3336,9 +3328,11 @@ static void service_sigchld_event(Unit *u, pid_t pid, int code, int status) { f = SERVICE_SUCCESS; } - log_unit_full(u, f == SERVICE_SUCCESS ? LOG_DEBUG : LOG_NOTICE, 0, - "Control process exited, code=%s status=%i", - sigchld_code_to_string(code), status); + unit_log_process_exit( + u, f == SERVICE_SUCCESS ? LOG_DEBUG : LOG_NOTICE, + "Control process", + service_exec_command_to_string(s->control_command_id), + code, status); if (s->result == SERVICE_SUCCESS) s->result = f; diff --git a/src/core/socket.c b/src/core/socket.c index 5d44ce3fb1..de1a558023 100644 --- a/src/core/socket.c +++ b/src/core/socket.c @@ -2968,9 +2968,11 @@ static void socket_sigchld_event(Unit *u, pid_t pid, int code, int status) { f = SOCKET_SUCCESS; } - log_unit_full(u, f == SOCKET_SUCCESS ? LOG_DEBUG : LOG_NOTICE, 0, - "Control process exited, code=%s status=%i", - sigchld_code_to_string(code), status); + unit_log_process_exit( + u, f == SOCKET_SUCCESS ? LOG_DEBUG : LOG_NOTICE, + "Control process", + socket_exec_command_to_string(s->control_command_id), + code, status); if (s->result == SOCKET_SUCCESS) s->result = f; diff --git a/src/core/swap.c b/src/core/swap.c index d3d0e40e2d..40517f2aad 100644 --- a/src/core/swap.c +++ b/src/core/swap.c @@ -1011,8 +1011,11 @@ static void swap_sigchld_event(Unit *u, pid_t pid, int code, int status) { s->control_command_id = _SWAP_EXEC_COMMAND_INVALID; } - log_unit_full(u, f == SWAP_SUCCESS ? LOG_DEBUG : LOG_NOTICE, 0, - "Swap process exited, code=%s status=%i", sigchld_code_to_string(code), status); + unit_log_process_exit( + u, f == SWAP_SUCCESS ? LOG_DEBUG : LOG_NOTICE, + "Swap process", + swap_exec_command_to_string(s->control_command_id), + code, status); switch (s->state) { diff --git a/src/core/unit.c b/src/core/unit.c index 88d20a1b9f..54a1bd963c 100644 --- a/src/core/unit.c +++ b/src/core/unit.c @@ -5456,6 +5456,35 @@ void unit_log_failure(Unit *u, const char *result) { "UNIT_RESULT=%s", result); } +void unit_log_process_exit( + Unit *u, + int level, + const char *kind, + const char *command, + int code, + int status) { + + assert(u); + assert(kind); + + if (code != CLD_EXITED) + level = LOG_WARNING; + + log_struct(level, + "MESSAGE_ID=" SD_MESSAGE_UNIT_PROCESS_EXIT_STR, + LOG_UNIT_MESSAGE(u, "%s exited, code=%s, status=%i/%s", + kind, + sigchld_code_to_string(code), status, + strna(code == CLD_EXITED + ? exit_status_to_string(status, EXIT_STATUS_FULL) + : signal_to_string(status))), + "EXIT_CODE=%s", sigchld_code_to_string(code), + "EXIT_STATUS=%i", status, + "COMMAND=%s", strna(command), + LOG_UNIT_ID(u), + LOG_UNIT_INVOCATION_ID(u)); +} + static const char* const collect_mode_table[_COLLECT_MODE_MAX] = { [COLLECT_INACTIVE] = "inactive", [COLLECT_INACTIVE_OR_FAILED] = "inactive-or-failed", diff --git a/src/core/unit.h b/src/core/unit.h index e3f859d5ef..da48438519 100644 --- a/src/core/unit.h +++ b/src/core/unit.h @@ -807,6 +807,7 @@ const char *unit_label_path(Unit *u); int unit_pid_attachable(Unit *unit, pid_t pid, sd_bus_error *error); void unit_log_failure(Unit *u, const char *result); +void unit_log_process_exit(Unit *u, int level, const char *kind, const char *command, int code, int status); /* Macros which append UNIT= or USER_UNIT= to the message */ diff --git a/src/systemd/sd-messages.h b/src/systemd/sd-messages.h index 1ea79fc661..9ac263c89f 100644 --- a/src/systemd/sd-messages.h +++ b/src/systemd/sd-messages.h @@ -113,6 +113,9 @@ _SD_BEGIN_DECLARATIONS; #define SD_MESSAGE_SPAWN_FAILED SD_ID128_MAKE(64,12,57,65,1c,1b,4e,c9,a8,62,4d,7a,40,a9,e1,e7) #define SD_MESSAGE_SPAWN_FAILED_STR SD_ID128_MAKE_STR(64,12,57,65,1c,1b,4e,c9,a8,62,4d,7a,40,a9,e1,e7) +#define SD_MESSAGE_UNIT_PROCESS_EXIT SD_ID128_MAKE(98,e3,22,20,3f,7a,4e,d2,90,d0,9f,e0,3c,09,fe,15) +#define SD_MESSAGE_UNIT_PROCESS_EXIT_STR SD_ID128_MAKE_STR(98,e3,22,20,3f,7a,4e,d2,90,d0,9f,e0,3c,09,fe,15) + #define SD_MESSAGE_FORWARD_SYSLOG_MISSED SD_ID128_MAKE(00,27,22,9c,a0,64,41,81,a7,6c,4e,92,45,8a,fa,2e) #define SD_MESSAGE_FORWARD_SYSLOG_MISSED_STR \ SD_ID128_MAKE_STR(00,27,22,9c,a0,64,41,81,a7,6c,4e,92,45,8a,fa,2e) From 523ee2d41471bfb738f52d59de9b469301842644 Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Tue, 13 Nov 2018 23:28:09 +0100 Subject: [PATCH 11/16] core: log a recognizable message when a unit succeeds, too We already are doing it on failure, let's do it on success, too. Fixes: #10265 --- catalog/systemd.catalog.in | 7 +++++++ src/core/automount.c | 4 +++- src/core/mount.c | 4 +++- src/core/path.c | 4 +++- src/core/scope.c | 4 +++- src/core/service.c | 4 +++- src/core/socket.c | 4 +++- src/core/swap.c | 4 +++- src/core/timer.c | 4 +++- src/core/unit.c | 10 ++++++++++ src/core/unit.h | 1 + src/systemd/sd-messages.h | 2 ++ 12 files changed, 44 insertions(+), 8 deletions(-) diff --git a/catalog/systemd.catalog.in b/catalog/systemd.catalog.in index c99da0a634..5c6799ee5d 100644 --- a/catalog/systemd.catalog.in +++ b/catalog/systemd.catalog.in @@ -352,6 +352,13 @@ Support: %SUPPORT_URL% The unit @UNIT@ completed and consumed the indicated resources. +-- 7ad2d189f7e94e70a38c781354912448 +Subject: Unit succeeded +Defined-By: systemd +Support: %SUPPORT_URL% + +The unit @UNIT@ has successfully entered the 'dead' state. + -- d9b373ed55a64feb8242e02dbe79a49c Subject: Unit failed Defined-By: systemd diff --git a/src/core/automount.c b/src/core/automount.c index 57e6a985fd..9da3f87fca 100644 --- a/src/core/automount.c +++ b/src/core/automount.c @@ -315,7 +315,9 @@ static void automount_enter_dead(Automount *a, AutomountResult f) { if (a->result == AUTOMOUNT_SUCCESS) a->result = f; - if (a->result != AUTOMOUNT_SUCCESS) + if (a->result == AUTOMOUNT_SUCCESS) + unit_log_success(UNIT(a)); + else unit_log_failure(UNIT(a), automount_result_to_string(a->result)); automount_set_state(a, a->result != AUTOMOUNT_SUCCESS ? AUTOMOUNT_FAILED : AUTOMOUNT_DEAD); diff --git a/src/core/mount.c b/src/core/mount.c index 002127bf10..8035a73184 100644 --- a/src/core/mount.c +++ b/src/core/mount.c @@ -799,7 +799,9 @@ static void mount_enter_dead(Mount *m, MountResult f) { if (m->result == MOUNT_SUCCESS) m->result = f; - if (m->result != MOUNT_SUCCESS) + if (m->result == MOUNT_SUCCESS) + unit_log_success(UNIT(m)); + else unit_log_failure(UNIT(m), mount_result_to_string(m->result)); mount_set_state(m, m->result != MOUNT_SUCCESS ? MOUNT_FAILED : MOUNT_DEAD); diff --git a/src/core/path.c b/src/core/path.c index a134fc288c..7523bf54f7 100644 --- a/src/core/path.c +++ b/src/core/path.c @@ -449,7 +449,9 @@ static void path_enter_dead(Path *p, PathResult f) { if (p->result == PATH_SUCCESS) p->result = f; - if (p->result != PATH_SUCCESS) + if (p->result == PATH_SUCCESS) + unit_log_success(UNIT(p)); + else unit_log_failure(UNIT(p), path_result_to_string(p->result)); path_set_state(p, p->result != PATH_SUCCESS ? PATH_FAILED : PATH_DEAD); diff --git a/src/core/scope.c b/src/core/scope.c index 9ff082df3a..6d8d4af56d 100644 --- a/src/core/scope.c +++ b/src/core/scope.c @@ -240,7 +240,9 @@ static void scope_enter_dead(Scope *s, ScopeResult f) { if (s->result == SCOPE_SUCCESS) s->result = f; - if (s->result != SCOPE_SUCCESS) + if (s->result == SCOPE_SUCCESS) + unit_log_success(UNIT(s)); + else unit_log_failure(UNIT(s), scope_result_to_string(s->result)); scope_set_state(s, s->result != SCOPE_SUCCESS ? SCOPE_FAILED : SCOPE_DEAD); diff --git a/src/core/service.c b/src/core/service.c index 49a1131c38..a90711213c 100644 --- a/src/core/service.c +++ b/src/core/service.c @@ -1699,7 +1699,9 @@ static void service_enter_dead(Service *s, ServiceResult f, bool allow_restart) if (s->result == SERVICE_SUCCESS) s->result = f; - if (s->result != SERVICE_SUCCESS) + if (s->result == SERVICE_SUCCESS) + unit_log_success(UNIT(s)); + else unit_log_failure(UNIT(s), service_result_to_string(s->result)); if (allow_restart && service_shall_restart(s)) diff --git a/src/core/socket.c b/src/core/socket.c index de1a558023..f725c9eb00 100644 --- a/src/core/socket.c +++ b/src/core/socket.c @@ -1985,7 +1985,9 @@ static void socket_enter_dead(Socket *s, SocketResult f) { if (s->result == SOCKET_SUCCESS) s->result = f; - if (s->result != SOCKET_SUCCESS) + if (s->result == SOCKET_SUCCESS) + unit_log_success(UNIT(s)); + else unit_log_failure(UNIT(s), socket_result_to_string(s->result)); socket_set_state(s, s->result != SOCKET_SUCCESS ? SOCKET_FAILED : SOCKET_DEAD); diff --git a/src/core/swap.c b/src/core/swap.c index 40517f2aad..e2b888ec9e 100644 --- a/src/core/swap.c +++ b/src/core/swap.c @@ -653,7 +653,9 @@ static void swap_enter_dead(Swap *s, SwapResult f) { if (s->result == SWAP_SUCCESS) s->result = f; - if (s->result != SWAP_SUCCESS) + if (s->result == SWAP_SUCCESS) + unit_log_success(UNIT(s)); + else unit_log_failure(UNIT(s), swap_result_to_string(s->result)); swap_set_state(s, s->result != SWAP_SUCCESS ? SWAP_FAILED : SWAP_DEAD); diff --git a/src/core/timer.c b/src/core/timer.c index 98ba868bb1..c7f769dbe1 100644 --- a/src/core/timer.c +++ b/src/core/timer.c @@ -288,7 +288,9 @@ static void timer_enter_dead(Timer *t, TimerResult f) { if (t->result == TIMER_SUCCESS) t->result = f; - if (t->result != TIMER_SUCCESS) + if (t->result == TIMER_SUCCESS) + unit_log_success(UNIT(t)); + else unit_log_failure(UNIT(t), timer_result_to_string(t->result)); timer_set_state(t, t->result != TIMER_SUCCESS ? TIMER_FAILED : TIMER_DEAD); diff --git a/src/core/unit.c b/src/core/unit.c index 54a1bd963c..c4d55dc2d3 100644 --- a/src/core/unit.c +++ b/src/core/unit.c @@ -5444,6 +5444,16 @@ int unit_pid_attachable(Unit *u, pid_t pid, sd_bus_error *error) { return 0; } +void unit_log_success(Unit *u) { + assert(u); + + log_struct(LOG_INFO, + "MESSAGE_ID=" SD_MESSAGE_UNIT_SUCCESS_STR, + LOG_UNIT_ID(u), + LOG_UNIT_INVOCATION_ID(u), + LOG_UNIT_MESSAGE(u, "Succeeded.")); +} + void unit_log_failure(Unit *u, const char *result) { assert(u); assert(result); diff --git a/src/core/unit.h b/src/core/unit.h index da48438519..3931684a56 100644 --- a/src/core/unit.h +++ b/src/core/unit.h @@ -806,6 +806,7 @@ const char *unit_label_path(Unit *u); int unit_pid_attachable(Unit *unit, pid_t pid, sd_bus_error *error); +void unit_log_success(Unit *u); void unit_log_failure(Unit *u, const char *result); void unit_log_process_exit(Unit *u, int level, const char *kind, const char *command, int code, int status); diff --git a/src/systemd/sd-messages.h b/src/systemd/sd-messages.h index 9ac263c89f..293db8e8e1 100644 --- a/src/systemd/sd-messages.h +++ b/src/systemd/sd-messages.h @@ -106,6 +106,8 @@ _SD_BEGIN_DECLARATIONS; #define SD_MESSAGE_UNIT_RESOURCES SD_ID128_MAKE(ae,8f,7b,86,6b,03,47,b9,af,31,fe,1c,80,b1,27,c0) #define SD_MESSAGE_UNIT_RESOURCES_STR SD_ID128_MAKE_STR(ae,8f,7b,86,6b,03,47,b9,af,31,fe,1c,80,b1,27,c0) +#define SD_MESSAGE_UNIT_SUCCESS SD_ID128_MAKE(7a,d2,d1,89,f7,e9,4e,70,a3,8c,78,13,54,91,24,48) +#define SD_MESSAGE_UNIT_SUCCESS_STR SD_ID128_MAKE_STR(7a,d2,d1,89,f7,e9,4e,70,a3,8c,78,13,54,91,24,48) #define SD_MESSAGE_UNIT_FAILURE_RESULT SD_ID128_MAKE(d9,b3,73,ed,55,a6,4f,eb,82,42,e0,2d,be,79,a4,9c) #define SD_MESSAGE_UNIT_FAILURE_RESULT_STR \ SD_ID128_MAKE_STR(d9,b3,73,ed,55,a6,4f,eb,82,42,e0,2d,be,79,a4,9c) From a69b3872acc279f30528ee2a941bda13dcc1170b Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Wed, 14 Nov 2018 11:01:14 +0100 Subject: [PATCH 12/16] job: let's remove one comparison and reduce indentation level by one --- src/core/job.c | 26 ++++++++++++++------------ 1 file changed, 14 insertions(+), 12 deletions(-) diff --git a/src/core/job.c b/src/core/job.c index bf3db5a887..3826fb354f 100644 --- a/src/core/job.c +++ b/src/core/job.c @@ -510,28 +510,30 @@ static void job_change_type(Job *j, JobType newtype) { } _pure_ static const char* job_get_begin_status_message_format(Unit *u, JobType t) { - const char *format; const UnitStatusMessageFormats *format_table; + const char *format; assert(u); - assert(IN_SET(t, JOB_START, JOB_STOP, JOB_RELOAD)); - if (t != JOB_RELOAD) { - format_table = &UNIT_VTABLE(u)->status_message_formats; - if (format_table) { - format = format_table->starting_stopping[t == JOB_STOP]; - if (format) - return format; - } + if (t == JOB_RELOAD) + return "Reloading %s."; + + assert(IN_SET(t, JOB_START, JOB_STOP)); + + format_table = &UNIT_VTABLE(u)->status_message_formats; + if (format_table) { + format = format_table->starting_stopping[t == JOB_STOP]; + if (format) + return format; } /* Return generic strings */ if (t == JOB_START) return "Starting %s."; - else if (t == JOB_STOP) + else { + assert(t == JOB_STOP); return "Stopping %s."; - else - return "Reloading %s."; + } } static void job_print_begin_status_message(Unit *u, JobType t) { From 0e2b4a822e53be021899fb1def11bf9fd6cb6d67 Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Wed, 14 Nov 2018 11:01:28 +0100 Subject: [PATCH 13/16] job: add two explanatory comments --- src/core/job.c | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/src/core/job.c b/src/core/job.c index 3826fb354f..48d60af82b 100644 --- a/src/core/job.c +++ b/src/core/job.c @@ -563,7 +563,7 @@ 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 (log_on_console()) + if (log_on_console()) /* Skip this if it would only go on the console anyway */ return; /* We log status messages for all units and all operations. */ @@ -643,8 +643,9 @@ static int job_perform_on_unit(Job **j) { assert_not_reached("Invalid job type"); } - /* Log if the job still exists and the start/stop/reload function - * actually did something. */ + /* Log if the job still exists and the start/stop/reload function actually did something. Note that this means + * for units for which there's no 'activating' phase (i.e. because we transition directly from 'inactive' to + * 'active') we'll possibly skip the "Starting..." message. */ *j = manager_get_job(m, id); if (*j && r > 0) job_emit_begin_status_message(u, id, t); From 6e64994d690ccc0359a4a9d20fbead2dbfe23836 Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Wed, 14 Nov 2018 11:38:51 +0100 Subject: [PATCH 14/16] core: make unit_start() return a distinguishable error code in case conditions didn't hold Ideally we'd even propagate this all the way to the client, by having a separate JobType enum value for this. But it's hard to add this without breaking compat, hence for now let's at least internally propagate this case differently from the case "already on it". This is then used to call job_finish_and_invalidate() slightly differently, with the already= parameter false, as in the failed condition case no message was likely produced so far. --- src/core/job.c | 4 +++- src/core/manager.c | 2 +- src/core/unit.c | 2 +- 3 files changed, 5 insertions(+), 3 deletions(-) diff --git a/src/core/job.c b/src/core/job.c index 48d60af82b..fc3d8d8308 100644 --- a/src/core/job.c +++ b/src/core/job.c @@ -714,8 +714,10 @@ int job_run_and_invalidate(Job *j) { if (j) { if (r == -EAGAIN) job_set_state(j, JOB_WAITING); /* Hmm, not ready after all, let's return to JOB_WAITING state */ - else if (r == -EALREADY) + else if (r == -EALREADY) /* already being executed */ r = job_finish_and_invalidate(j, JOB_DONE, true, true); + else if (r == -ECOMM) /* condition failed, but all is good */ + r = job_finish_and_invalidate(j, JOB_DONE, true, false); else if (r == -EBADR) r = job_finish_and_invalidate(j, JOB_SKIPPED, true, false); else if (r == -ENOEXEC) diff --git a/src/core/manager.c b/src/core/manager.c index 3150740e05..11c353076c 100644 --- a/src/core/manager.c +++ b/src/core/manager.c @@ -2138,7 +2138,7 @@ static int manager_dispatch_run_queue(sd_event_source *source, void *userdata) { assert(j->installed); assert(j->in_run_queue); - job_run_and_invalidate(j); + (void) job_run_and_invalidate(j); } if (m->n_running_jobs > 0) diff --git a/src/core/unit.c b/src/core/unit.c index c4d55dc2d3..ab057ada87 100644 --- a/src/core/unit.c +++ b/src/core/unit.c @@ -1726,7 +1726,7 @@ int unit_start(Unit *u) { if (state != UNIT_ACTIVATING && !unit_condition_test(u)) { log_unit_debug(u, "Starting requested but condition failed. Not starting unit."); - return -EALREADY; + return -ECOMM; } /* If the asserts failed, fail the entire job */ From 9a80f2f4533883d272e6a436512aa7e88cedc549 Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Wed, 14 Nov 2018 11:08:16 +0100 Subject: [PATCH 15/16] job: when a job was skipped due to a failed condition, log about it Previously we'd neither show console status output nor log output. Let's fix that, and still log something. --- src/core/job.c | 22 ++++++++++++++++++---- 1 file changed, 18 insertions(+), 4 deletions(-) diff --git a/src/core/job.c b/src/core/job.c index fc3d8d8308..ec1113f2dd 100644 --- a/src/core/job.c +++ b/src/core/job.c @@ -822,6 +822,10 @@ static void job_print_done_status_message(Unit *u, JobType t, JobResult result) if (t == JOB_RELOAD) return; + /* No message if the job did not actually do anything due to failed condition. */ + if (t == JOB_START && result == JOB_DONE && !u->condition_result) + return; + if (!job_print_done_status_messages[result].word) return; @@ -877,6 +881,20 @@ static void job_log_done_status_message(Unit *u, uint32_t job_id, JobType t, Job if (log_on_console() && job_print_done_status_messages[result].word) return; + /* Show condition check message if the job did not actually do anything due to failed condition. */ + if (t == JOB_START && result == JOB_DONE && !u->condition_result) { + log_struct(LOG_INFO, + "MESSAGE=Condition check resulted in %s being skipped.", unit_description(u), + "JOB_ID=%" PRIu32, job_id, + "JOB_TYPE=%s", job_type_to_string(t), + "JOB_RESULT=%s", job_result_to_string(result), + LOG_UNIT_ID(u), + LOG_UNIT_INVOCATION_ID(u), + "MESSAGE_ID=" SD_MESSAGE_UNIT_STARTED_STR); + + return; + } + format = job_get_done_status_message_format(u, t, result); if (!format) return; @@ -931,10 +949,6 @@ static void job_log_done_status_message(Unit *u, uint32_t job_id, JobType t, Job static void job_emit_done_status_message(Unit *u, uint32_t job_id, JobType t, JobResult result) { assert(u); - /* No message if the job did not actually do anything due to failed condition. */ - if (t == JOB_START && result == JOB_DONE && !u->condition_result) - return; - job_log_done_status_message(u, job_id, t, result); job_print_done_status_message(u, t, result); } From ff30a86bd41c02da3f2a527f882989bdf4534641 Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Fri, 16 Nov 2018 15:28:26 +0100 Subject: [PATCH 16/16] job: simplify status message extraction As @keszybz points out these fields are always here, there's no point in checking if they are NULL or not. --- src/core/job.c | 23 ++++++++--------------- 1 file changed, 8 insertions(+), 15 deletions(-) diff --git a/src/core/job.c b/src/core/job.c index ec1113f2dd..8f36e02eb9 100644 --- a/src/core/job.c +++ b/src/core/job.c @@ -510,7 +510,6 @@ static void job_change_type(Job *j, JobType newtype) { } _pure_ static const char* job_get_begin_status_message_format(Unit *u, JobType t) { - const UnitStatusMessageFormats *format_table; const char *format; assert(u); @@ -520,12 +519,9 @@ _pure_ static const char* job_get_begin_status_message_format(Unit *u, JobType t assert(IN_SET(t, JOB_START, JOB_STOP)); - format_table = &UNIT_VTABLE(u)->status_message_formats; - if (format_table) { - format = format_table->starting_stopping[t == JOB_STOP]; - if (format) - return format; - } + format = UNIT_VTABLE(u)->status_message_formats.starting_stopping[t == JOB_STOP]; + if (format) + return format; /* Return generic strings */ if (t == JOB_START) @@ -766,7 +762,6 @@ _pure_ static const char *job_get_done_status_message_format(Unit *u, JobType t, [JOB_SKIPPED] = "%s is not active.", }; - const UnitStatusMessageFormats *format_table; const char *format; assert(u); @@ -774,13 +769,11 @@ _pure_ static const char *job_get_done_status_message_format(Unit *u, JobType t, assert(t < _JOB_TYPE_MAX); if (IN_SET(t, JOB_START, JOB_STOP, JOB_RESTART)) { - format_table = &UNIT_VTABLE(u)->status_message_formats; - if (format_table) { - format = t == JOB_START ? format_table->finished_start_job[result] : - format_table->finished_stop_job[result]; - if (format) - return format; - } + format = t == JOB_START ? + UNIT_VTABLE(u)->status_message_formats.finished_start_job[result] : + UNIT_VTABLE(u)->status_message_formats.finished_stop_job[result]; + if (format) + return format; } /* Return generic strings */