From d1a34ae9c20f1c02aab17884919eccef572b1d21 Mon Sep 17 00:00:00 2001 From: Michal Schmidt Date: Thu, 16 Jul 2015 20:08:30 +0200 Subject: core: fix confusing logging of instantaneous jobs For instantaneous jobs (e.g. starting of targets, sockets, slices, or Type=simple services) the log shows the job completion before starting: systemd[1]: Created slice -.slice. systemd[1]: Starting -.slice. systemd[1]: Created slice System Slice. systemd[1]: Starting System Slice. systemd[1]: Listening on Journal Audit Socket. systemd[1]: Starting Journal Audit Socket. systemd[1]: Reached target Timers. systemd[1]: Starting Timers. ... The reason is that the job completes before the ->start() method returns and only then does unit_start() print the "Starting ..." message. The same thing happens when stopping units. Rather than fixing the order of the messages, let's just not emit the Starting/Stopping message at all when the job completes instantaneously. The job completion message is sufficient in this case. --- src/core/job.c | 65 +++++++++++++++++++++++++++++++++++++++------------------ src/core/unit.c | 36 +++++++++++--------------------- src/core/unit.h | 1 + 3 files changed, 58 insertions(+), 44 deletions(-) (limited to 'src') diff --git a/src/core/job.c b/src/core/job.c index 1448e5b69a..670a70bbb8 100644 --- a/src/core/job.c +++ b/src/core/job.c @@ -495,10 +495,48 @@ static void job_change_type(Job *j, JobType newtype) { j->type = newtype; } +static int job_perform_on_unit(Job **j) { + /* While we execute this operation the job might go away (for + * example: because it finishes immediately or is replaced by a new, + * conflicting job.) To make sure we don't access a freed job later on + * we store the id here, so that we can verify the job is still + * valid. */ + Manager *m = (*j)->manager; + Unit *u = (*j)->unit; + JobType t = (*j)->type; + uint32_t id = (*j)->id; + int r; + + switch (t) { + case JOB_START: + r = unit_start(u); + break; + + case JOB_RESTART: + t = JOB_STOP; + case JOB_STOP: + r = unit_stop(u); + break; + + case JOB_RELOAD: + r = unit_reload(u); + break; + + default: + assert_not_reached("Invalid job type"); + } + + /* Log if the job still exists and the start/stop/reload function + * actually did something. */ + *j = manager_get_job(m, id); + if (*j && r > 0) + unit_status_emit_starting_stopping_reloading(u, t); + + return r; +} + int job_run_and_invalidate(Job *j) { int r; - uint32_t id; - Manager *m = j->manager; assert(j); assert(j->installed); @@ -517,23 +555,9 @@ int job_run_and_invalidate(Job *j) { job_set_state(j, JOB_RUNNING); job_add_to_dbus_queue(j); - /* While we execute this operation the job might go away (for - * example: because it is replaced by a new, conflicting - * job.) To make sure we don't access a freed job later on we - * store the id here, so that we can verify the job is still - * valid. */ - id = j->id; switch (j->type) { - case JOB_START: - r = unit_start(j->unit); - - /* If this unit cannot be started, then simply wait */ - if (r == -EBADR) - r = 0; - break; - case JOB_VERIFY_ACTIVE: { UnitActiveState t = unit_active_state(j->unit); if (UNIT_IS_ACTIVE_OR_RELOADING(t)) @@ -545,17 +569,19 @@ int job_run_and_invalidate(Job *j) { break; } + case JOB_START: case JOB_STOP: case JOB_RESTART: - r = unit_stop(j->unit); + r = job_perform_on_unit(&j); - /* If this unit cannot stopped, then simply wait. */ + /* If the unit type does not support starting/stopping, + * then simply wait. */ if (r == -EBADR) r = 0; break; case JOB_RELOAD: - r = unit_reload(j->unit); + r = job_perform_on_unit(&j); break; case JOB_NOP: @@ -566,7 +592,6 @@ int job_run_and_invalidate(Job *j) { assert_not_reached("Unknown job type"); } - j = manager_get_job(m, id); if (j) { if (r == -EALREADY) r = job_finish_and_invalidate(j, JOB_DONE, true); diff --git a/src/core/unit.c b/src/core/unit.c index fac017c57d..4f5132586c 100644 --- a/src/core/unit.c +++ b/src/core/unit.c @@ -1413,6 +1413,15 @@ static void unit_status_log_starting_stopping_reloading(Unit *u, JobType t) { NULL); } +void unit_status_emit_starting_stopping_reloading(Unit *u, JobType t) { + + unit_status_log_starting_stopping_reloading(u, t); + + /* Reload status messages have traditionally not been printed to console. */ + if (t != JOB_RELOAD) + unit_status_print_starting_stopping(u, t); +} + /* Errors: * -EBADR: This unit type does not support starting. * -EALREADY: Unit is already started. @@ -1423,7 +1432,6 @@ static void unit_status_log_starting_stopping_reloading(Unit *u, JobType t) { int unit_start(Unit *u) { UnitActiveState state; Unit *following; - int r; assert(u); @@ -1477,14 +1485,7 @@ int unit_start(Unit *u) { unit_add_to_dbus_queue(u); - r = UNIT_VTABLE(u)->start(u); - if (r <= 0) - return r; - - /* Log if the start function actually did something */ - unit_status_log_starting_stopping_reloading(u, JOB_START); - unit_status_print_starting_stopping(u, JOB_START); - return r; + return UNIT_VTABLE(u)->start(u); } bool unit_can_start(Unit *u) { @@ -1508,7 +1509,6 @@ bool unit_can_isolate(Unit *u) { int unit_stop(Unit *u) { UnitActiveState state; Unit *following; - int r; assert(u); @@ -1527,13 +1527,7 @@ int unit_stop(Unit *u) { unit_add_to_dbus_queue(u); - r = UNIT_VTABLE(u)->stop(u); - if (r <= 0) - return r; - - unit_status_log_starting_stopping_reloading(u, JOB_STOP); - unit_status_print_starting_stopping(u, JOB_STOP); - return r; + return UNIT_VTABLE(u)->stop(u); } /* Errors: @@ -1544,7 +1538,6 @@ int unit_stop(Unit *u) { int unit_reload(Unit *u) { UnitActiveState state; Unit *following; - int r; assert(u); @@ -1571,12 +1564,7 @@ int unit_reload(Unit *u) { unit_add_to_dbus_queue(u); - r = UNIT_VTABLE(u)->reload(u); - if (r <= 0) - return r; - - unit_status_log_starting_stopping_reloading(u, JOB_RELOAD); - return r; + return UNIT_VTABLE(u)->reload(u); } bool unit_can_reload(Unit *u) { diff --git a/src/core/unit.h b/src/core/unit.h index 9491ef64f9..e60168267f 100644 --- a/src/core/unit.h +++ b/src/core/unit.h @@ -544,6 +544,7 @@ int unit_add_node_link(Unit *u, const char *what, bool wants); int unit_coldplug(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); -- cgit v1.2.3-54-g00ecf From 2d018ae23b838f050516d06859f50ecb9733d44b Mon Sep 17 00:00:00 2001 From: Michal Schmidt Date: Thu, 16 Jul 2015 21:39:56 +0200 Subject: core: correct return value from reload methods Return 1 from *_reload() methods to signify "we did something", just like in *_start(). This causes "Reloading foo..." messages to be logged. "Reloaded foo." messages are already logged. --- src/core/mount.c | 2 +- src/core/service.c | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) (limited to 'src') diff --git a/src/core/mount.c b/src/core/mount.c index 851b41351e..a4fdf2b798 100644 --- a/src/core/mount.c +++ b/src/core/mount.c @@ -1025,7 +1025,7 @@ static int mount_reload(Unit *u) { assert(m->state == MOUNT_MOUNTED); mount_enter_remounting(m); - return 0; + return 1; } static int mount_serialize(Unit *u, FILE *f, FDSet *fds) { diff --git a/src/core/service.c b/src/core/service.c index d72ff54daa..78c8838f7c 100644 --- a/src/core/service.c +++ b/src/core/service.c @@ -1974,7 +1974,7 @@ static int service_reload(Unit *u) { assert(s->state == SERVICE_RUNNING || s->state == SERVICE_EXITED); service_enter_reload(s); - return 0; + return 1; } _pure_ static bool service_can_reload(Unit *u) { -- cgit v1.2.3-54-g00ecf From a85ca902c9f7f5aa8f2f3e3299147733802cf09d Mon Sep 17 00:00:00 2001 From: Michal Schmidt Date: Mon, 20 Jul 2015 17:18:13 +0200 Subject: core: always try harder to get unit status message format string The starting/stopping messages are printed to the console only if the corresponding format string is defined in the unit's vtable. To avoid excessive messages on the console, the unit types whose start/stop jobs are instantaneous had the format strings intentionally undefined. When logging the same event to the journal, a fallback to generic Starting/Stopping/Reloading messages is used. The problem of excessive console messages with instantaneous jobs is already resolved in a nicer way ("core: fix confusing logging of instantaneous jobs"), so there's no longer a need to have two ways of getting the format strings. Let's fold them into one function with the fallback to generic message strings. --- src/core/unit.c | 34 ++++++++++------------------------ 1 file changed, 10 insertions(+), 24 deletions(-) (limited to 'src') diff --git a/src/core/unit.c b/src/core/unit.c index 4f5132586c..c0b5d02d35 100644 --- a/src/core/unit.c +++ b/src/core/unit.c @@ -1318,32 +1318,21 @@ static bool unit_assert_test(Unit *u) { } _pure_ static const char* unit_get_status_message_format(Unit *u, JobType t) { - const UnitStatusMessageFormats *format_table; - - assert(u); - assert(t >= 0); - assert(t < _JOB_TYPE_MAX); - - if (t != JOB_START && t != JOB_STOP) - return NULL; - - format_table = &UNIT_VTABLE(u)->status_message_formats; - if (!format_table) - return NULL; - - return format_table->starting_stopping[t == JOB_STOP]; -} - -_pure_ static const char *unit_get_status_message_format_try_harder(Unit *u, JobType t) { const char *format; + const UnitStatusMessageFormats *format_table; assert(u); assert(t >= 0); assert(t < _JOB_TYPE_MAX); - format = unit_get_status_message_format(u, t); - if (format) - return format; + if (t == JOB_START || t == 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) @@ -1361,9 +1350,6 @@ static void unit_status_print_starting_stopping(Unit *u, JobType t) { assert(u); - /* We only print status messages for selected units on - * selected operations. */ - format = unit_get_status_message_format(u, t); if (!format) return; @@ -1388,7 +1374,7 @@ static void unit_status_log_starting_stopping_reloading(Unit *u, JobType t) { /* We log status messages for all units and all operations. */ - format = unit_get_status_message_format_try_harder(u, t); + format = unit_get_status_message_format(u, t); if (!format) return; -- cgit v1.2.3-54-g00ecf From b5bf308ba50ab0bac0f0caec2d8e4d5c75c107d0 Mon Sep 17 00:00:00 2001 From: Michal Schmidt Date: Mon, 20 Jul 2015 18:36:12 +0200 Subject: core: unit_get_status_message_format() never returns NULL unit_get_status_message_format() is used only with one of JOB_START, JOB_STOP, JOB_RELOAD, all of which have fallback message strings defined, so the function may never return NULL. --- src/core/unit.c | 13 +++---------- 1 file changed, 3 insertions(+), 10 deletions(-) (limited to 'src') diff --git a/src/core/unit.c b/src/core/unit.c index c0b5d02d35..dd5e801285 100644 --- a/src/core/unit.c +++ b/src/core/unit.c @@ -1322,10 +1322,9 @@ _pure_ static const char* unit_get_status_message_format(Unit *u, JobType t) { const UnitStatusMessageFormats *format_table; assert(u); - assert(t >= 0); - assert(t < _JOB_TYPE_MAX); + assert(t == JOB_START || t == JOB_STOP || t == JOB_RELOAD); - if (t == JOB_START || t == JOB_STOP) { + if (t != JOB_RELOAD) { format_table = &UNIT_VTABLE(u)->status_message_formats; if (format_table) { format = format_table->starting_stopping[t == JOB_STOP]; @@ -1339,10 +1338,8 @@ _pure_ static const char* unit_get_status_message_format(Unit *u, JobType t) { return "Starting %s."; else if (t == JOB_STOP) return "Stopping %s."; - else if (t == JOB_RELOAD) + else return "Reloading %s."; - - return NULL; } static void unit_status_print_starting_stopping(Unit *u, JobType t) { @@ -1351,8 +1348,6 @@ static void unit_status_print_starting_stopping(Unit *u, JobType t) { assert(u); format = unit_get_status_message_format(u, t); - if (!format) - return; DISABLE_WARNING_FORMAT_NONLITERAL; unit_status_printf(u, "", format); @@ -1375,8 +1370,6 @@ static void unit_status_log_starting_stopping_reloading(Unit *u, JobType t) { /* We log status messages for all units and all operations. */ format = unit_get_status_message_format(u, t); - if (!format) - return; DISABLE_WARNING_FORMAT_NONLITERAL; snprintf(buf, sizeof(buf), format, unit_description(u)); -- cgit v1.2.3-54-g00ecf From aa49ab5f22c0fdc7a5381d4e452f40705f3d7bf8 Mon Sep 17 00:00:00 2001 From: Michal Schmidt Date: Tue, 21 Jul 2015 14:54:24 +0200 Subject: core: try harder to get job completion messages too This is similar to "core: always try harder to get unit status message format string", but for job completion status messages. It makes generic status messages applicable for printing to the console. And it rewrites the functions in a more table-based style. --- src/core/job.c | 192 ++++++++++++++++++++------------------------------------- 1 file changed, 68 insertions(+), 124 deletions(-) (limited to 'src') diff --git a/src/core/job.c b/src/core/job.c index 670a70bbb8..e2e9d876bb 100644 --- a/src/core/job.c +++ b/src/core/job.c @@ -613,156 +613,100 @@ int job_run_and_invalidate(Job *j) { } _pure_ static const char *job_get_status_message_format(Unit *u, JobType t, JobResult result) { + const char *format; const UnitStatusMessageFormats *format_table; + static const char *const generic_finished_start_job[_JOB_RESULT_MAX] = { + [JOB_DONE] = "Started %s.", + [JOB_TIMEOUT] = "Timed out starting %s.", + [JOB_FAILED] = "Failed to start %s.", + [JOB_DEPENDENCY] = "Dependency failed for %s.", + [JOB_ASSERT] = "Assertion failed for %s.", + [JOB_UNSUPPORTED] = "Starting of %s not supported.", + }; + static const char *const generic_finished_stop_job[_JOB_RESULT_MAX] = { + [JOB_DONE] = "Stopped %s.", + [JOB_FAILED] = "Stopped (with error) %s.", + [JOB_TIMEOUT] = "Timed out stoppping %s.", + }; + static const char *const generic_finished_reload_job[_JOB_RESULT_MAX] = { + [JOB_DONE] = "Reloaded %s.", + [JOB_FAILED] = "Reload failed for %s.", + [JOB_TIMEOUT] = "Timed out reloading %s.", + }; + /* When verify-active detects the unit is inactive, report it. + * Most likely a DEPEND warning from a requisiting unit will + * occur next and it's nice to see what was requisited. */ + static const char *const generic_finished_verify_active_job[_JOB_RESULT_MAX] = { + [JOB_SKIPPED] = "%s is not active.", + }; assert(u); assert(t >= 0); assert(t < _JOB_TYPE_MAX); - format_table = &UNIT_VTABLE(u)->status_message_formats; - if (!format_table) - return NULL; + if (t == JOB_START || t == JOB_STOP || t == 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; + } + } + /* Return generic strings */ if (t == JOB_START) - return format_table->finished_start_job[result]; + return generic_finished_start_job[result]; else if (t == JOB_STOP || t == JOB_RESTART) - return format_table->finished_stop_job[result]; - - return NULL; -} - -_pure_ static const char *job_get_status_message_format_try_harder(Unit *u, JobType t, JobResult result) { - const char *format; - - assert(u); - assert(t >= 0); - assert(t < _JOB_TYPE_MAX); - - format = job_get_status_message_format(u, t, result); - if (format) - return format; - - /* Return generic strings */ - if (t == JOB_START) { - if (result == JOB_DONE) - return "Started %s."; - else if (result == JOB_TIMEOUT) - return "Timed out starting %s."; - else if (result == JOB_FAILED) - return "Failed to start %s."; - else if (result == JOB_DEPENDENCY) - return "Dependency failed for %s."; - else if (result == JOB_ASSERT) - return "Assertion failed for %s."; - else if (result == JOB_UNSUPPORTED) - return "Starting of %s not supported."; - } else if (t == JOB_STOP || t == JOB_RESTART) { - if (result == JOB_DONE) - return "Stopped %s."; - else if (result == JOB_FAILED) - return "Stopped (with error) %s."; - else if (result == JOB_TIMEOUT) - return "Timed out stoppping %s."; - } else if (t == JOB_RELOAD) { - if (result == JOB_DONE) - return "Reloaded %s."; - else if (result == JOB_FAILED) - return "Reload failed for %s."; - else if (result == JOB_TIMEOUT) - return "Timed out reloading %s."; - } + return generic_finished_stop_job[result]; + else if (t == JOB_RELOAD) + return generic_finished_reload_job[result]; + else if (t == JOB_VERIFY_ACTIVE) + return generic_finished_verify_active_job[result]; return NULL; } static void job_print_status_message(Unit *u, JobType t, JobResult result) { const char *format; + static const char* const job_result_status_table[_JOB_RESULT_MAX] = { + [JOB_DONE] = ANSI_GREEN_ON " OK " ANSI_HIGHLIGHT_OFF, + [JOB_TIMEOUT] = ANSI_HIGHLIGHT_RED_ON " TIME " ANSI_HIGHLIGHT_OFF, + [JOB_FAILED] = ANSI_HIGHLIGHT_RED_ON "FAILED" ANSI_HIGHLIGHT_OFF, + [JOB_DEPENDENCY] = ANSI_HIGHLIGHT_YELLOW_ON "DEPEND" ANSI_HIGHLIGHT_OFF, + [JOB_SKIPPED] = ANSI_HIGHLIGHT_ON " INFO " ANSI_HIGHLIGHT_OFF, + [JOB_ASSERT] = ANSI_HIGHLIGHT_YELLOW_ON "ASSERT" ANSI_HIGHLIGHT_OFF, + [JOB_UNSUPPORTED] = ANSI_HIGHLIGHT_YELLOW_ON "UNSUPP" ANSI_HIGHLIGHT_OFF, + }; assert(u); assert(t >= 0); assert(t < _JOB_TYPE_MAX); - DISABLE_WARNING_FORMAT_NONLITERAL; - - if (t == JOB_START) { - format = job_get_status_message_format(u, t, result); - if (!format) - return; - - switch (result) { - - case JOB_DONE: - if (u->condition_result) - unit_status_printf(u, ANSI_GREEN_ON " OK " ANSI_HIGHLIGHT_OFF, format); - break; - - case JOB_TIMEOUT: - manager_flip_auto_status(u->manager, true); - unit_status_printf(u, ANSI_HIGHLIGHT_RED_ON " TIME " ANSI_HIGHLIGHT_OFF, format); - break; - - case JOB_FAILED: { - _cleanup_free_ char *quoted = NULL; - - quoted = shell_maybe_quote(u->id); - - manager_flip_auto_status(u->manager, true); - unit_status_printf(u, ANSI_HIGHLIGHT_RED_ON "FAILED" ANSI_HIGHLIGHT_OFF, format); - manager_status_printf(u->manager, STATUS_TYPE_NORMAL, NULL, "See 'systemctl status %s' for details.", strna(quoted)); - break; - } - - case JOB_DEPENDENCY: - manager_flip_auto_status(u->manager, true); - unit_status_printf(u, ANSI_HIGHLIGHT_YELLOW_ON "DEPEND" ANSI_HIGHLIGHT_OFF, format); - break; - - case JOB_ASSERT: - manager_flip_auto_status(u->manager, true); - unit_status_printf(u, ANSI_HIGHLIGHT_YELLOW_ON "ASSERT" ANSI_HIGHLIGHT_OFF, format); - break; - - case JOB_UNSUPPORTED: - manager_flip_auto_status(u->manager, true); - unit_status_printf(u, ANSI_HIGHLIGHT_YELLOW_ON "UNSUPP" ANSI_HIGHLIGHT_OFF, format); - break; - - default: - ; - } - - } else if (t == JOB_STOP || t == JOB_RESTART) { - - format = job_get_status_message_format(u, t, result); - if (!format) - return; + /* Reload status messages have traditionally not been printed to console. */ + if (t == JOB_RELOAD) + return; - switch (result) { + if (t == JOB_START && result == JOB_DONE && !u->condition_result) + return; - case JOB_TIMEOUT: - manager_flip_auto_status(u->manager, true); - unit_status_printf(u, ANSI_HIGHLIGHT_RED_ON " TIME " ANSI_HIGHLIGHT_OFF, format); - break; + format = job_get_status_message_format(u, t, result); + if (!format) + return; - case JOB_DONE: - case JOB_FAILED: - unit_status_printf(u, ANSI_GREEN_ON " OK " ANSI_HIGHLIGHT_OFF, format); - break; + if (result != JOB_DONE) + manager_flip_auto_status(u->manager, true); - default: - ; - } + DISABLE_WARNING_FORMAT_NONLITERAL; + unit_status_printf(u, job_result_status_table[result], format); + REENABLE_WARNING; - } else if (t == JOB_VERIFY_ACTIVE) { + if (t == JOB_START && result == JOB_FAILED) { + _cleanup_free_ char *quoted = shell_maybe_quote(u->id); - /* When verify-active detects the unit is inactive, report it. - * Most likely a DEPEND warning from a requisiting unit will - * occur next and it's nice to see what was requisited. */ - if (result == JOB_SKIPPED) - unit_status_printf(u, ANSI_HIGHLIGHT_ON " INFO " ANSI_HIGHLIGHT_OFF, "%s is not active."); + manager_status_printf(u->manager, STATUS_TYPE_NORMAL, NULL, + "See 'systemctl status %s' for details.", strna(quoted)); } - - REENABLE_WARNING; } static void job_log_status_message(Unit *u, JobType t, JobResult result) { @@ -779,7 +723,7 @@ static void job_log_status_message(Unit *u, JobType t, JobResult result) { if (log_on_console()) return; - format = job_get_status_message_format_try_harder(u, t, result); + format = job_get_status_message_format(u, t, result); if (!format) return; -- cgit v1.2.3-54-g00ecf From c382d69e3d39daedebcedb2da882beeb147a3cda Mon Sep 17 00:00:00 2001 From: Michal Schmidt Date: Tue, 21 Jul 2015 15:51:16 +0200 Subject: core: remove generic job completion messages from unit vtables These units' message format strings are identical to the generic strings. Since we can always rely on the fallback, these are now redundant. --- src/core/automount.c | 1 - src/core/busname.c | 3 --- src/core/mount.c | 1 - src/core/service.c | 3 --- src/core/slice.c | 1 - src/core/socket.c | 1 - src/core/swap.c | 1 - src/core/target.c | 1 - 8 files changed, 12 deletions(-) (limited to 'src') diff --git a/src/core/automount.c b/src/core/automount.c index d847dc1629..90b331f70e 100644 --- a/src/core/automount.c +++ b/src/core/automount.c @@ -1066,7 +1066,6 @@ const UnitVTable automount_vtable = { .finished_start_job = { [JOB_DONE] = "Set up automount %s.", [JOB_FAILED] = "Failed to set up automount %s.", - [JOB_DEPENDENCY] = "Dependency failed for %s.", }, .finished_stop_job = { [JOB_DONE] = "Unset automount %s.", diff --git a/src/core/busname.c b/src/core/busname.c index 2085721546..9530a87311 100644 --- a/src/core/busname.c +++ b/src/core/busname.c @@ -1065,13 +1065,10 @@ const UnitVTable busname_vtable = { .finished_start_job = { [JOB_DONE] = "Listening on %s.", [JOB_FAILED] = "Failed to listen on %s.", - [JOB_DEPENDENCY] = "Dependency failed for %s.", - [JOB_TIMEOUT] = "Timed out starting %s.", }, .finished_stop_job = { [JOB_DONE] = "Closed %s.", [JOB_FAILED] = "Failed stopping %s.", - [JOB_TIMEOUT] = "Timed out stopping %s.", }, }, }; diff --git a/src/core/mount.c b/src/core/mount.c index a4fdf2b798..bf8e52bf0e 100644 --- a/src/core/mount.c +++ b/src/core/mount.c @@ -1897,7 +1897,6 @@ const UnitVTable mount_vtable = { .finished_start_job = { [JOB_DONE] = "Mounted %s.", [JOB_FAILED] = "Failed to mount %s.", - [JOB_DEPENDENCY] = "Dependency failed for %s.", [JOB_TIMEOUT] = "Timed out mounting %s.", }, .finished_stop_job = { diff --git a/src/core/service.c b/src/core/service.c index 78c8838f7c..39a2507b6f 100644 --- a/src/core/service.c +++ b/src/core/service.c @@ -3229,13 +3229,10 @@ const UnitVTable service_vtable = { .finished_start_job = { [JOB_DONE] = "Started %s.", [JOB_FAILED] = "Failed to start %s.", - [JOB_DEPENDENCY] = "Dependency failed for %s.", - [JOB_TIMEOUT] = "Timed out starting %s.", }, .finished_stop_job = { [JOB_DONE] = "Stopped %s.", [JOB_FAILED] = "Stopped (with error) %s.", - [JOB_TIMEOUT] = "Timed out stopping %s.", }, }, }; diff --git a/src/core/slice.c b/src/core/slice.c index e52bf71515..064eb5d933 100644 --- a/src/core/slice.c +++ b/src/core/slice.c @@ -297,7 +297,6 @@ const UnitVTable slice_vtable = { .status_message_formats = { .finished_start_job = { [JOB_DONE] = "Created slice %s.", - [JOB_DEPENDENCY] = "Dependency failed for %s.", }, .finished_stop_job = { [JOB_DONE] = "Removed slice %s.", diff --git a/src/core/socket.c b/src/core/socket.c index 693cbc6080..87631f8753 100644 --- a/src/core/socket.c +++ b/src/core/socket.c @@ -2722,7 +2722,6 @@ const UnitVTable socket_vtable = { .finished_start_job = { [JOB_DONE] = "Listening on %s.", [JOB_FAILED] = "Failed to listen on %s.", - [JOB_DEPENDENCY] = "Dependency failed for %s.", [JOB_TIMEOUT] = "Timed out starting %s.", }, .finished_stop_job = { diff --git a/src/core/swap.c b/src/core/swap.c index 193c8c3767..0bc3827ff0 100644 --- a/src/core/swap.c +++ b/src/core/swap.c @@ -1505,7 +1505,6 @@ const UnitVTable swap_vtable = { .finished_start_job = { [JOB_DONE] = "Activated swap %s.", [JOB_FAILED] = "Failed to activate swap %s.", - [JOB_DEPENDENCY] = "Dependency failed for %s.", [JOB_TIMEOUT] = "Timed out activating swap %s.", }, .finished_stop_job = { diff --git a/src/core/target.c b/src/core/target.c index 8817ef21c4..b492a7c4c7 100644 --- a/src/core/target.c +++ b/src/core/target.c @@ -227,7 +227,6 @@ const UnitVTable target_vtable = { .status_message_formats = { .finished_start_job = { [JOB_DONE] = "Reached target %s.", - [JOB_DEPENDENCY] = "Dependency failed for %s.", }, .finished_stop_job = { [JOB_DONE] = "Stopped target %s.", -- cgit v1.2.3-54-g00ecf From 30961fa300cad21b50fe47baee523beeadb5d0bc Mon Sep 17 00:00:00 2001 From: Michal Schmidt Date: Tue, 21 Jul 2015 16:15:19 +0200 Subject: core: do not log done failed-condition jobs as if unit started It is misleading to see "Started foo." in the log when the unit's condition was false. --- src/core/job.c | 23 ++++++++++++++--------- 1 file changed, 14 insertions(+), 9 deletions(-) (limited to 'src') diff --git a/src/core/job.c b/src/core/job.c index e2e9d876bb..e3ad1ddc73 100644 --- a/src/core/job.c +++ b/src/core/job.c @@ -683,13 +683,6 @@ static void job_print_status_message(Unit *u, JobType t, JobResult result) { assert(t >= 0); assert(t < _JOB_TYPE_MAX); - /* Reload status messages have traditionally not been printed to console. */ - if (t == JOB_RELOAD) - return; - - if (t == JOB_START && result == JOB_DONE && !u->condition_result) - return; - format = job_get_status_message_format(u, t, result); if (!format) return; @@ -759,6 +752,19 @@ static void job_log_status_message(Unit *u, JobType t, JobResult result) { NULL); } +static void job_emit_status_message(Unit *u, JobType t, JobResult result) { + + /* 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); + + /* Reload status messages have traditionally not been printed to console. */ + if (t != JOB_RELOAD) + job_print_status_message(u, t, result); +} + static void job_fail_dependencies(Unit *u, UnitDependency d) { Unit *other; Iterator i; @@ -794,8 +800,7 @@ int job_finish_and_invalidate(Job *j, JobResult result, bool recursive) { log_unit_debug(u, "Job %s/%s finished, result=%s", u->id, job_type_to_string(t), job_result_to_string(result)); - job_print_status_message(u, t, result); - job_log_status_message(u, t, result); + job_emit_status_message(u, t, result); job_add_to_dbus_queue(j); -- cgit v1.2.3-54-g00ecf From 4f29c6fea6a6c5c2c9406ad091cd6f56da21e2cb Mon Sep 17 00:00:00 2001 From: Michal Schmidt Date: Tue, 21 Jul 2015 16:20:18 +0200 Subject: core: log completion of remaining job types JOB_RESTART and failed JOB_VERIFY_ACTIVE completions were printed to console but not to the log. --- src/core/job.c | 8 +++++++- 1 file changed, 7 insertions(+), 1 deletion(-) (limited to 'src') diff --git a/src/core/job.c b/src/core/job.c index e3ad1ddc73..0f0fe1994a 100644 --- a/src/core/job.c +++ b/src/core/job.c @@ -735,7 +735,7 @@ static void job_log_status_message(Unit *u, JobType t, JobResult result) { "RESULT=%s", job_result_to_string(result), NULL); - } else if (t == JOB_STOP) + } else if (t == JOB_STOP || t == JOB_RESTART) log_struct(result == JOB_DONE ? LOG_INFO : LOG_ERR, LOG_MESSAGE_ID(SD_MESSAGE_UNIT_STOPPED), LOG_UNIT_ID(u), @@ -750,6 +750,12 @@ static void job_log_status_message(Unit *u, JobType t, JobResult result) { LOG_MESSAGE("%s", buf), "RESULT=%s", job_result_to_string(result), NULL); + else + log_struct(result == JOB_DONE ? LOG_INFO : LOG_ERR, + LOG_UNIT_ID(u), + LOG_MESSAGE("%s", buf), + "RESULT=%s", job_result_to_string(result), + NULL); } static void job_emit_status_message(Unit *u, JobType t, JobResult result) { -- cgit v1.2.3-54-g00ecf From b81bbe5355b97d0d7dbe8796afd39bf284696063 Mon Sep 17 00:00:00 2001 From: Michal Schmidt Date: Tue, 21 Jul 2015 17:26:28 +0200 Subject: core: small refactor of job completion logging Joins three log_struct() calls into one. --- src/core/job.c | 40 +++++++++++++++------------------------- 1 file changed, 15 insertions(+), 25 deletions(-) (limited to 'src') diff --git a/src/core/job.c b/src/core/job.c index 0f0fe1994a..03ef1d5891 100644 --- a/src/core/job.c +++ b/src/core/job.c @@ -705,6 +705,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) { const char *format; char buf[LINE_MAX]; + sd_id128_t mid; assert(u); assert(t >= 0); @@ -724,38 +725,27 @@ static void job_log_status_message(Unit *u, JobType t, JobResult result) { snprintf(buf, sizeof(buf), format, unit_description(u)); REENABLE_WARNING; - if (t == JOB_START) { - sd_id128_t mid; - + if (t == JOB_START) mid = result == JOB_DONE ? SD_MESSAGE_UNIT_STARTED : SD_MESSAGE_UNIT_FAILED; - log_struct(result == JOB_DONE ? LOG_INFO : LOG_ERR, - LOG_MESSAGE_ID(mid), - LOG_UNIT_ID(u), - LOG_MESSAGE("%s", buf), - "RESULT=%s", job_result_to_string(result), - NULL); - - } else if (t == JOB_STOP || t == JOB_RESTART) - log_struct(result == JOB_DONE ? LOG_INFO : LOG_ERR, - LOG_MESSAGE_ID(SD_MESSAGE_UNIT_STOPPED), - LOG_UNIT_ID(u), - LOG_MESSAGE("%s", buf), - "RESULT=%s", job_result_to_string(result), - NULL); - + else if (t == JOB_STOP || t == JOB_RESTART) + mid = SD_MESSAGE_UNIT_STOPPED; else if (t == JOB_RELOAD) - log_struct(result == JOB_DONE ? LOG_INFO : LOG_ERR, - LOG_MESSAGE_ID(SD_MESSAGE_UNIT_RELOADED), - LOG_UNIT_ID(u), - LOG_MESSAGE("%s", buf), - "RESULT=%s", job_result_to_string(result), - NULL); - else + mid = SD_MESSAGE_UNIT_RELOADED; + else { log_struct(result == JOB_DONE ? LOG_INFO : LOG_ERR, LOG_UNIT_ID(u), LOG_MESSAGE("%s", buf), "RESULT=%s", job_result_to_string(result), NULL); + return; + } + + log_struct(result == JOB_DONE ? LOG_INFO : LOG_ERR, + LOG_MESSAGE_ID(mid), + LOG_UNIT_ID(u), + LOG_MESSAGE("%s", buf), + "RESULT=%s", job_result_to_string(result), + NULL); } static void job_emit_status_message(Unit *u, JobType t, JobResult result) { -- cgit v1.2.3-54-g00ecf From 64f575d2ab9a6743d3c7172b7591c88ba243cf1b Mon Sep 17 00:00:00 2001 From: Michal Schmidt Date: Tue, 21 Jul 2015 19:07:24 +0200 Subject: core: adjust job completion message log levels We do not print all non-OK job completion status messages to the console in red, because not all of them are plain errors. We do however log the same messages as LOG_ERR. Differentiate the log levels by deducing them from the job result in a way that more or less matches the color of the console message. --- src/core/job.c | 15 +++++++++++++-- 1 file changed, 13 insertions(+), 2 deletions(-) (limited to 'src') diff --git a/src/core/job.c b/src/core/job.c index 03ef1d5891..15f5cc0cc9 100644 --- a/src/core/job.c +++ b/src/core/job.c @@ -706,6 +706,17 @@ static void job_log_status_message(Unit *u, JobType t, JobResult result) { const char *format; char buf[LINE_MAX]; sd_id128_t mid; + static const int job_result_log_level[_JOB_RESULT_MAX] = { + [JOB_DONE] = LOG_INFO, + [JOB_CANCELED] = LOG_INFO, + [JOB_TIMEOUT] = LOG_ERR, + [JOB_FAILED] = LOG_ERR, + [JOB_DEPENDENCY] = LOG_WARNING, + [JOB_SKIPPED] = LOG_NOTICE, + [JOB_INVALID] = LOG_INFO, + [JOB_ASSERT] = LOG_WARNING, + [JOB_UNSUPPORTED] = LOG_WARNING, + }; assert(u); assert(t >= 0); @@ -732,7 +743,7 @@ static void job_log_status_message(Unit *u, JobType t, JobResult result) { else if (t == JOB_RELOAD) mid = SD_MESSAGE_UNIT_RELOADED; else { - log_struct(result == JOB_DONE ? LOG_INFO : LOG_ERR, + log_struct(job_result_log_level[result], LOG_UNIT_ID(u), LOG_MESSAGE("%s", buf), "RESULT=%s", job_result_to_string(result), @@ -740,7 +751,7 @@ static void job_log_status_message(Unit *u, JobType t, JobResult result) { return; } - log_struct(result == JOB_DONE ? LOG_INFO : LOG_ERR, + log_struct(job_result_log_level[result], LOG_MESSAGE_ID(mid), LOG_UNIT_ID(u), LOG_MESSAGE("%s", buf), -- cgit v1.2.3-54-g00ecf