picnoir/Systemd
1
0
Fork 0
Code Issues Pull requests Projects Releases Wiki Activity

Merge pull request #647 from michich/job-logging

Browse source 
Job logging fixes and improvements
This commit is contained in:
Tom Gundersen 2015-07-22 14:17:12 +02:00
parent 75cb22f1bf 64f575d2ab
commit bd37a92297
11 changed files with 180 additions and 243 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

1
src/core/automount.c
View file

@ -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.",

3
src/core/busname.c
View file

@ -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.",
},
},
};

325
src/core/job.c
View file

@ -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);
@ -588,161 +613,110 @@ int job_run_and_invalidate(Job *j) {
}
_pure_ static const char *job_get_status_message_format(Unit *u, JobType t, JobResult result) {
const UnitStatusMessageFormats *format_table;
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)
return format_table->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;
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 = job_get_status_message_format(u, t, result);
if (format)
return format;
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) {
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.";
}
if (t == JOB_START)
return generic_finished_start_job[result];
else if (t == JOB_STOP || t == JOB_RESTART)
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);
format = job_get_status_message_format(u, t, result);
if (!format)
return;
if (result != JOB_DONE)
manager_flip_auto_status(u->manager, true);
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;
switch (result) {
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_DONE:
case JOB_FAILED:
unit_status_printf(u, ANSI_GREEN_ON " OK " ANSI_HIGHLIGHT_OFF, format);
break;
default:
;
}
} else if (t == JOB_VERIFY_ACTIVE) {
/* 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.");
}
unit_status_printf(u, job_result_status_table[result], format);
REENABLE_WARNING;
if (t == JOB_START && result == JOB_FAILED) {
_cleanup_free_ char *quoted = shell_maybe_quote(u->id);
manager_status_printf(u->manager, STATUS_TYPE_NORMAL, NULL,
"See 'systemctl status %s' for details.", strna(quoted));
}
}
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);
@ -754,7 +728,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;
@ -762,32 +736,40 @@ 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)
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),
mid = SD_MESSAGE_UNIT_RELOADED;
else {
log_struct(job_result_log_level[result],
LOG_UNIT_ID(u),
LOG_MESSAGE("%s", buf),
"RESULT=%s", job_result_to_string(result),
NULL);
return;
}
log_struct(job_result_log_level[result],
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) {
/* 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) {
@ -825,8 +807,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);

3
src/core/mount.c
View file

@ -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) {
@ -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 = {

5
src/core/service.c
View file

@ -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) {
@ -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.",
},
},
};

1
src/core/slice.c
View file

@ -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.",

1
src/core/socket.c
View file

@ -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 = {

1
src/core/swap.c
View file

@ -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 = {

1
src/core/target.c
View file

@ -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.",

81
src/core/unit.c
View file

@ -1318,42 +1318,28 @@ static bool unit_assert_test(Unit *u) {
}
_pure_ static const char* unit_get_status_message_format(Unit *u, JobType t) {
const char *format;
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)
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;
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_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 if (t == JOB_RELOAD)
else
return "Reloading %s.";
return NULL;
}
static void unit_status_print_starting_stopping(Unit *u, JobType t) {
@ -1361,12 +1347,7 @@ 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;
DISABLE_WARNING_FORMAT_NONLITERAL;
unit_status_printf(u, "", format);
@ -1388,9 +1369,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);
if (!format)
return;
format = unit_get_status_message_format(u, t);
DISABLE_WARNING_FORMAT_NONLITERAL;
snprintf(buf, sizeof(buf), format, unit_description(u));
@ -1413,6 +1392,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 +1411,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 +1464,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 +1488,6 @@ bool unit_can_isolate(Unit *u) {
int unit_stop(Unit *u) {
UnitActiveState state;
Unit *following;
int r;
assert(u);
@ -1527,13 +1506,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 +1517,6 @@ int unit_stop(Unit *u) {
int unit_reload(Unit *u) {
UnitActiveState state;
Unit *following;
int r;
assert(u);
@ -1571,12 +1543,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) {

1
src/core/unit.h
View file

@ -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);