diff options
| -rw-r--r-- | src/core/automount.c | 66 | ||||
| -rw-r--r-- | src/core/device.c | 8 | ||||
| -rw-r--r-- | src/core/job.c | 46 | ||||
| -rw-r--r-- | src/core/manager.c | 23 | ||||
| -rw-r--r-- | src/core/mount.c | 110 | ||||
| -rw-r--r-- | src/core/path.c | 3 | ||||
| -rw-r--r-- | src/core/service.c | 310 | ||||
| -rw-r--r-- | src/core/socket.c | 233 | ||||
| -rw-r--r-- | src/core/swap.c | 67 | ||||
| -rw-r--r-- | src/core/timer.c | 46 | ||||
| -rw-r--r-- | src/core/transaction.c | 88 |
11 files changed, 665 insertions, 335 deletions
diff --git a/src/core/automount.c b/src/core/automount.c index 74776646f6..4a98540d82 100644 --- a/src/core/automount.c +++ b/src/core/automount.c @@ -180,7 +180,7 @@ static int automount_verify(Automount *a) { return 0; if (path_equal(a->where, "/")) { - log_error("Cannot have an automount unit for the root directory. Refusing."); + log_error_unit(UNIT(a)->id, "Cannot have an automount unit for the root directory. Refusing."); return -EINVAL; } @@ -192,7 +192,7 @@ static int automount_verify(Automount *a) { free(e); if (!b) { - log_error("%s's Where setting doesn't match unit name. Refusing.", UNIT(a)->id); + log_error_unit(UNIT(a)->id, "%s's Where setting doesn't match unit name. Refusing.", UNIT(a)->id); return -EINVAL; } @@ -258,10 +258,11 @@ static void automount_set_state(Automount *a, AutomountState state) { unmount_autofs(a); if (state != old_state) - log_debug("%s changed %s -> %s", - UNIT(a)->id, - automount_state_to_string(old_state), - automount_state_to_string(state)); + log_debug_unit(UNIT(a)->id, + "%s changed %s -> %s", + UNIT(a)->id, + automount_state_to_string(old_state), + automount_state_to_string(state)); unit_notify(UNIT(a), state_translation_table[old_state], state_translation_table[state], true); } @@ -455,9 +456,9 @@ int automount_send_ready(Automount *a, int status) { } if (status) - log_debug("Sending failure: %s", strerror(-status)); + log_debug_unit(UNIT(a)->id, "Sending failure: %s", strerror(-status)); else - log_debug("Sending success."); + log_debug_unit(UNIT(a)->id, "Sending success."); r = 0; @@ -579,7 +580,8 @@ fail: if (mounted) repeat_unmout(a->where); - log_error("Failed to initialize automounter: %s", strerror(-r)); + log_error_unit(UNIT(a)->id, + "Failed to initialize automounter: %s", strerror(-r)); automount_enter_dead(a, AUTOMOUNT_FAILURE_RESOURCES); } @@ -596,7 +598,8 @@ static void automount_enter_runnning(Automount *a) { /* We don't take mount requests anymore if we are supposed to * shut down anyway */ if (unit_pending_inactive(UNIT(a))) { - log_debug("Suppressing automount request on %s since unit stop is scheduled.", UNIT(a)->id); + log_debug_unit(UNIT(a)->id, + "Suppressing automount request on %s since unit stop is scheduled.", UNIT(a)->id); automount_send_ready(a, -EHOSTDOWN); return; } @@ -605,14 +608,18 @@ static void automount_enter_runnning(Automount *a) { /* Before we do anything, let's see if somebody is playing games with us? */ if (lstat(a->where, &st) < 0) { - log_warning("%s failed to stat automount point: %m", UNIT(a)->id); + log_warning_unit(UNIT(a)->id, + "%s failed to stat automount point: %m", UNIT(a)->id); goto fail; } if (!S_ISDIR(st.st_mode) || st.st_dev != a->dev_id) - log_info("%s's automount point already active?", UNIT(a)->id); + log_info_unit(UNIT(a)->id, + "%s's automount point already active?", UNIT(a)->id); else if ((r = manager_add_job(UNIT(a)->manager, JOB_START, UNIT_DEREF(a->mount), JOB_REPLACE, true, &error, NULL)) < 0) { - log_warning("%s failed to queue mount startup job: %s", UNIT(a)->id, bus_error(&error, r)); + log_warning_unit(UNIT(a)->id, + "%s failed to queue mount startup job: %s", + UNIT(a)->id, bus_error(&error, r)); goto fail; } @@ -630,7 +637,9 @@ static int automount_start(Unit *u) { assert(a->state == AUTOMOUNT_DEAD || a->state == AUTOMOUNT_FAILED); if (path_is_mount_point(a->where, false)) { - log_error("Path %s is already a mount point, refusing start for %s", a->where, u->id); + log_error_unit(u->id, + "Path %s is already a mount point, refusing start for %s", + a->where, u->id); return -EEXIST; } @@ -693,7 +702,7 @@ static int automount_deserialize_item(Unit *u, const char *key, const char *valu state = automount_state_from_string(value); if (state < 0) - log_debug("Failed to parse state value %s", value); + log_debug_unit(u->id, "Failed to parse state value %s", value); else a->deserialized_state = state; } else if (streq(key, "result")) { @@ -701,7 +710,7 @@ static int automount_deserialize_item(Unit *u, const char *key, const char *valu f = automount_result_from_string(value); if (f < 0) - log_debug("Failed to parse result value %s", value); + log_debug_unit(u->id, "Failed to parse result value %s", value); else if (f != AUTOMOUNT_SUCCESS) a->result = f; @@ -709,14 +718,14 @@ static int automount_deserialize_item(Unit *u, const char *key, const char *valu unsigned d; if (safe_atou(value, &d) < 0) - log_debug("Failed to parse dev-id value %s", value); + log_debug_unit(u->id, "Failed to parse dev-id value %s", value); else a->dev_id = (unsigned) d; } else if (streq(key, "token")) { unsigned token; if (safe_atou(value, &token) < 0) - log_debug("Failed to parse token value %s", value); + log_debug_unit(u->id, "Failed to parse token value %s", value); else { if (!a->tokens) if (!(a->tokens = set_new(trivial_hash_func, trivial_compare_func))) @@ -730,7 +739,7 @@ static int automount_deserialize_item(Unit *u, const char *key, const char *valu int fd; if (safe_atoi(value, &fd) < 0 || fd < 0 || !fdset_contains(fds, fd)) - log_debug("Failed to parse pipe-fd value %s", value); + log_debug_unit(u->id, "Failed to parse pipe-fd value %s", value); else { if (a->pipe_fd >= 0) close_nointr_nofail(a->pipe_fd); @@ -738,7 +747,7 @@ static int automount_deserialize_item(Unit *u, const char *key, const char *valu a->pipe_fd = fdset_remove(fds, fd); } } else - log_debug("Unknown serialization key '%s'", key); + log_debug_unit(u->id, "Unknown serialization key '%s'", key); return 0; } @@ -776,13 +785,13 @@ static void automount_fd_event(Unit *u, int fd, uint32_t events, Watch *w) { assert(fd == a->pipe_fd); if (events != EPOLLIN) { - log_error("Got invalid poll event on pipe."); + log_error_unit(u->id, "Got invalid poll event on pipe."); goto fail; } l = loop_read(a->pipe_fd, &packet, sizeof(packet), true); if (l != sizeof(packet)) { - log_error("Invalid read from pipe: %s", l < 0 ? strerror(-l) : "short read"); + log_error_unit(u->id, "Invalid read from pipe: %s", l < 0 ? strerror(-l) : "short read"); goto fail; } @@ -794,20 +803,21 @@ static void automount_fd_event(Unit *u, int fd, uint32_t events, Watch *w) { _cleanup_free_ char *p = NULL; get_process_comm(packet.v5_packet.pid, &p); - log_debug("Got direct mount request on %s, triggered by %lu (%s)", - a->where, (unsigned long) packet.v5_packet.pid, strna(p)); + log_debug_unit(u->id, + "Got direct mount request on %s, triggered by %lu (%s)", + a->where, (unsigned long) packet.v5_packet.pid, strna(p)); } else - log_debug("Got direct mount request on %s", a->where); + log_debug_unit(u->id, "Got direct mount request on %s", a->where); r = set_ensure_allocated(&a->tokens, trivial_hash_func, trivial_compare_func); if (r < 0) { - log_error("Failed to allocate token set."); + log_error_unit(u->id, "Failed to allocate token set."); goto fail; } r = set_put(a->tokens, UINT_TO_PTR(packet.v5_packet.wait_queue_token)); if (r < 0) { - log_error("Failed to remember token: %s", strerror(-r)); + log_error_unit(u->id, "Failed to remember token: %s", strerror(-r)); goto fail; } @@ -815,7 +825,7 @@ static void automount_fd_event(Unit *u, int fd, uint32_t events, Watch *w) { break; default: - log_error("Received unknown automount request %i", packet.hdr.type); + log_error_unit(u->id, "Received unknown automount request %i", packet.hdr.type); break; } diff --git a/src/core/device.c b/src/core/device.c index be76cafaed..0b01718ad4 100644 --- a/src/core/device.c +++ b/src/core/device.c @@ -92,10 +92,10 @@ static void device_set_state(Device *d, DeviceState state) { d->state = state; if (state != old_state) - log_debug("%s changed %s -> %s", - UNIT(d)->id, - device_state_to_string(old_state), - device_state_to_string(state)); + log_debug_unit(UNIT(d)->id, + "%s changed %s -> %s", UNIT(d)->id, + device_state_to_string(old_state), + device_state_to_string(state)); unit_notify(UNIT(d), state_translation_table[old_state], state_translation_table[state], true); } diff --git a/src/core/job.c b/src/core/job.c index f08b8cbc7d..5ff95f5c90 100644 --- a/src/core/job.c +++ b/src/core/job.c @@ -187,8 +187,9 @@ Job* job_install(Job *j) { if (j->type == JOB_NOP || uj->state == JOB_WAITING || (job_type_allows_late_merge(j->type) && job_type_is_superset(uj->type, j->type))) { job_merge_into_installed(uj, j); - log_debug("Merged into installed job %s/%s as %u", - uj->unit->id, job_type_to_string(uj->type), (unsigned) uj->id); + log_debug_unit(uj->unit->id, + "Merged into installed job %s/%s as %u", + uj->unit->id, job_type_to_string(uj->type), (unsigned) uj->id); return uj; } else { /* already running and not safe to merge into */ @@ -196,8 +197,9 @@ Job* job_install(Job *j) { /* XXX It should be safer to queue j to run after uj finishes, but it is * not currently possible to have more than one installed job per unit. */ job_merge_into_installed(uj, j); - log_debug("Merged into running job, re-running: %s/%s as %u", - uj->unit->id, job_type_to_string(uj->type), (unsigned) uj->id); + log_debug_unit(uj->unit->id, + "Merged into running job, re-running: %s/%s as %u", + uj->unit->id, job_type_to_string(uj->type), (unsigned) uj->id); uj->state = JOB_WAITING; return uj; } @@ -208,7 +210,9 @@ Job* job_install(Job *j) { *pj = j; j->installed = true; j->manager->n_installed_jobs ++; - log_debug("Installed new job %s/%s as %u", j->unit->id, job_type_to_string(j->type), (unsigned) j->id); + log_debug_unit(j->unit->id, + "Installed new job %s/%s as %u", + j->unit->id, job_type_to_string(j->type), (unsigned) j->id); return j; } @@ -225,12 +229,16 @@ int job_install_deserialized(Job *j) { pj = (j->type == JOB_NOP) ? &j->unit->nop_job : &j->unit->job; if (*pj) { - log_debug("Unit %s already has a job installed. Not installing deserialized job.", j->unit->id); + log_debug_unit(j->unit->id, + "Unit %s already has a job installed. Not installing deserialized job.", + j->unit->id); return -EEXIST; } *pj = j; j->installed = true; - log_debug("Reinstalled deserialized job %s/%s as %u", j->unit->id, job_type_to_string(j->type), (unsigned) j->id); + log_debug_unit(j->unit->id, + "Reinstalled deserialized job %s/%s as %u", + j->unit->id, job_type_to_string(j->type), (unsigned) j->id); return 0; } @@ -457,9 +465,10 @@ bool job_is_runnable(Job *j) { } static void job_change_type(Job *j, JobType newtype) { - log_debug("Converting job %s/%s -> %s/%s", - j->unit->id, job_type_to_string(j->type), - j->unit->id, job_type_to_string(newtype)); + log_debug_unit(j->unit->id, + "Converting job %s/%s -> %s/%s", + j->unit->id, job_type_to_string(j->type), + j->unit->id, job_type_to_string(newtype)); j->type = newtype; } @@ -744,7 +753,8 @@ int job_finish_and_invalidate(Job *j, JobResult result, bool recursive) { j->result = result; - log_debug("Job %s/%s finished, result=%s", u->id, job_type_to_string(t), job_result_to_string(result)); + log_debug_unit(u->id, "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); @@ -804,14 +814,19 @@ int job_finish_and_invalidate(Job *j, JobResult result, bool recursive) { } /* Trigger OnFailure dependencies that are not generated by - * the unit itself. We don't tread JOB_CANCELED as failure in + * the unit itself. We don't treat JOB_CANCELED as failure in * this context. And JOB_FAILURE is already handled by the * unit itself. */ if (result == JOB_TIMEOUT || result == JOB_DEPENDENCY) { - log_notice("Job %s/%s failed with result '%s'.", + log_struct(LOG_NOTICE, + "UNIT=%s", u->id, + "JOB_TYPE=%s", job_type_to_string(t), + "JOB_RESULT=%s", job_result_to_string(t), + "Job %s/%s failed with result '%s'.", u->id, job_type_to_string(t), - job_result_to_string(result)); + job_result_to_string(result), + NULL); unit_trigger_on_failure(u); } @@ -918,7 +933,8 @@ void job_timer_event(Job *j, uint64_t n_elapsed, Watch *w) { assert(j); assert(w == &j->timer_watch); - log_warning("Job %s/%s timed out.", j->unit->id, job_type_to_string(j->type)); + log_warning_unit(j->unit->id, "Job %s/%s timed out.", + j->unit->id, job_type_to_string(j->type)); job_finish_and_invalidate(j, JOB_TIMEOUT, true); } diff --git a/src/core/manager.c b/src/core/manager.c index ec3541418d..3a4023f31a 100644 --- a/src/core/manager.c +++ b/src/core/manager.c @@ -487,7 +487,7 @@ static unsigned manager_dispatch_gc_queue(Manager *m) { if (u->gc_marker == gc_marker + GC_OFFSET_BAD || u->gc_marker == gc_marker + GC_OFFSET_UNSURE) { - log_debug("Collecting %s", u->id); + log_debug_unit(u->id, "Collecting %s", u->id); u->gc_marker = gc_marker + GC_OFFSET_BAD; unit_add_to_cleanup_queue(u); } @@ -749,7 +749,9 @@ int manager_add_job(Manager *m, JobType type, Unit *unit, JobMode mode, bool ove return -EPERM; } - log_debug("Trying to enqueue job %s/%s/%s", unit->id, job_type_to_string(type), job_mode_to_string(mode)); + log_debug_unit(unit->id, + "Trying to enqueue job %s/%s/%s", unit->id, + job_type_to_string(type), job_mode_to_string(mode)); job_type_collapse(&type, unit); @@ -773,7 +775,9 @@ int manager_add_job(Manager *m, JobType type, Unit *unit, JobMode mode, bool ove if (r < 0) goto tr_abort; - log_debug("Enqueued job %s/%s as %u", unit->id, job_type_to_string(type), (unsigned) tr->anchor_job->id); + log_debug_unit(unit->id, + "Enqueued job %s/%s as %u", unit->id, + job_type_to_string(type), (unsigned) tr->anchor_job->id); if (_ret) *_ret = tr->anchor_job; @@ -1070,7 +1074,7 @@ static int manager_process_notify_fd(Manager *m) { if (!tags) return log_oom(); - log_debug("Got notification message for unit %s", u->id); + log_debug_unit(u->id, "Got notification message for unit %s", u->id); if (UNIT_VTABLE(u)->notify_message) UNIT_VTABLE(u)->notify_message(u, ucred->pid, tags); @@ -1150,7 +1154,8 @@ static int manager_dispatch_sigchld(Manager *m) { if (!u) continue; - log_debug("Child %lu belongs to %s", (long unsigned) si.si_pid, u->id); + log_debug_unit(u->id, + "Child %lu belongs to %s", (long unsigned) si.si_pid, u->id); hashmap_remove(m->watch_pids, LONG_TO_PTR(si.si_pid)); UNIT_VTABLE(u)->sigchld_event(u, si.si_pid, si.si_code, si.si_status); @@ -1165,11 +1170,12 @@ static int manager_start_target(Manager *m, const char *name, JobMode mode) { dbus_error_init(&error); - log_debug("Activating special unit %s", name); + log_debug_unit(name, "Activating special unit %s", name); r = manager_add_job_by_name(m, JOB_START, name, mode, true, &error, NULL); if (r < 0) - log_error("Failed to enqueue %s job: %s", name, bus_error(&error, r)); + log_error_unit(name, + "Failed to enqueue %s job: %s", name, bus_error(&error, r)); dbus_error_free(&error); @@ -1677,7 +1683,8 @@ void manager_send_unit_audit(Manager *m, Unit *u, int type, bool success) { p = unit_name_to_prefix_and_instance(u->id); if (!p) { - log_error("Failed to allocate unit name for audit message: %s", strerror(ENOMEM)); + log_error_unit(u->id, + "Failed to allocate unit name for audit message: %s", strerror(ENOMEM)); return; } diff --git a/src/core/mount.c b/src/core/mount.c index 7cadd9fcb4..5d2b010013 100644 --- a/src/core/mount.c +++ b/src/core/mount.c @@ -387,7 +387,8 @@ static int mount_add_device_links(Mount *m) { r = manager_load_unit_prepare(UNIT(m)->manager, name, NULL, NULL, &fsck); if (r < 0) { - log_warning("Failed to prepare unit %s: %s", name, strerror(-r)); + log_warning_unit(name, + "Failed to prepare unit %s: %s", name, strerror(-r)); free(name); return r; } @@ -498,7 +499,9 @@ static int mount_fix_timeouts(Mount *m) { free(t); if (r < 0) { - log_warning("Failed to parse timeout for %s, ignoring: %s", m->where, timeout); + log_warning_unit(UNIT(m)->id, + "Failed to parse timeout for %s, ignoring: %s", + m->where, timeout); return r; } @@ -530,22 +533,29 @@ static int mount_verify(Mount *m) { free(e); if (!b) { - log_error("%s's Where setting doesn't match unit name. Refusing.", UNIT(m)->id); + log_error_unit(UNIT(m)->id, + "%s's Where setting doesn't match unit name. Refusing.", + UNIT(m)->id); return -EINVAL; } if (mount_point_is_api(m->where) || mount_point_ignore(m->where)) { - log_error("Cannot create mount unit for API file system %s. Refusing.", m->where); + log_error_unit(UNIT(m)->id, + "Cannot create mount unit for API file system %s. Refusing.", + m->where); return -EINVAL; } if (UNIT(m)->fragment_path && !m->parameters_fragment.what) { - log_error("%s's What setting is missing. Refusing.", UNIT(m)->id); + log_error_unit(UNIT(m)->id, + "%s's What setting is missing. Refusing.", UNIT(m)->id); return -EBADMSG; } if (m->exec_context.pam_name && m->kill_context.kill_mode != KILL_CONTROL_GROUP) { - log_error("%s has PAM enabled. Kill mode must be set to 'control-group'. Refusing.", UNIT(m)->id); + log_error_unit(UNIT(m)->id, + "%s has PAM enabled. Kill mode must be set to control-group'. Refusing.", + UNIT(m)->id); return -EINVAL; } @@ -712,10 +722,11 @@ static void mount_set_state(Mount *m, MountState state) { } if (state != old_state) - log_debug("%s changed %s -> %s", - UNIT(m)->id, - mount_state_to_string(old_state), - mount_state_to_string(state)); + log_debug_unit(UNIT(m)->id, + "%s changed %s -> %s", + UNIT(m)->id, + mount_state_to_string(old_state), + mount_state_to_string(state)); unit_notify(UNIT(m), state_translation_table[old_state], state_translation_table[state], m->reload_result == MOUNT_SUCCESS); m->reload_result = MOUNT_SUCCESS; @@ -882,7 +893,9 @@ static void mount_enter_signal(Mount *m, MountState state, MountResult f) { if (m->control_pid > 0) { if (kill_and_sigcont(m->control_pid, sig) < 0 && errno != ESRCH) - log_warning("Failed to kill control process %li: %m", (long) m->control_pid); + log_warning_unit(UNIT(m)->id, + "Failed to kill control process %li: %m", + (long) m->control_pid); else wait_for_exit = true; } @@ -902,7 +915,9 @@ static void mount_enter_signal(Mount *m, MountState state, MountResult f) { r = cgroup_bonding_kill_list(UNIT(m)->cgroup_bondings, sig, true, false, pid_set, NULL); if (r < 0) { if (r != -EAGAIN && r != -ESRCH && r != -ENOENT) - log_warning("Failed to kill control group: %s", strerror(-r)); + log_warning_unit(UNIT(m)->id, + "Failed to kill control group: %s", + strerror(-r)); } else if (r > 0) wait_for_exit = true; @@ -925,7 +940,8 @@ static void mount_enter_signal(Mount *m, MountState state, MountResult f) { return; fail: - log_warning("%s failed to kill processes: %s", UNIT(m)->id, strerror(-r)); + log_warning_unit(UNIT(m)->id, + "%s failed to kill processes: %s", UNIT(m)->id, strerror(-r)); if (state == MOUNT_REMOUNTING_SIGTERM || state == MOUNT_REMOUNTING_SIGKILL) mount_enter_mounted(m, MOUNT_FAILURE_RESOURCES); @@ -973,7 +989,9 @@ static void mount_enter_unmounting(Mount *m) { return; fail: - log_warning("%s failed to run 'umount' task: %s", UNIT(m)->id, strerror(-r)); + log_warning_unit(UNIT(m)->id, + "%s failed to run 'umount' task: %s", + UNIT(m)->id, strerror(-r)); mount_enter_mounted(m, MOUNT_FAILURE_RESOURCES); } @@ -1021,7 +1039,9 @@ static void mount_enter_mounting(Mount *m) { return; fail: - log_warning("%s failed to run 'mount' task: %s", UNIT(m)->id, strerror(-r)); + log_warning_unit(UNIT(m)->id, + "%s failed to run 'mount' task: %s", + UNIT(m)->id, strerror(-r)); mount_enter_dead(m, MOUNT_FAILURE_RESOURCES); } @@ -1079,7 +1099,9 @@ static void mount_enter_remounting(Mount *m) { return; fail: - log_warning("%s failed to run 'remount' task: %s", UNIT(m)->id, strerror(-r)); + log_warning_unit(UNIT(m)->id, + "%s failed to run 'remount' task: %s", + UNIT(m)->id, strerror(-r)); m->reload_result = MOUNT_FAILURE_RESOURCES; mount_enter_mounted(m, MOUNT_SUCCESS); } @@ -1181,7 +1203,7 @@ static int mount_deserialize_item(Unit *u, const char *key, const char *value, F MountState state; if ((state = mount_state_from_string(value)) < 0) - log_debug("Failed to parse state value %s", value); + log_debug_unit(u->id, "Failed to parse state value %s", value); else m->deserialized_state = state; } else if (streq(key, "result")) { @@ -1189,7 +1211,8 @@ static int mount_deserialize_item(Unit *u, const char *key, const char *value, F f = mount_result_from_string(value); if (f < 0) - log_debug("Failed to parse result value %s", value); + log_debug_unit(UNIT(m)->id, + "Failed to parse result value %s", value); else if (f != MOUNT_SUCCESS) m->result = f; @@ -1198,7 +1221,8 @@ static int mount_deserialize_item(Unit *u, const char *key, const char *value, F f = mount_result_from_string(value); if (f < 0) - log_debug("Failed to parse reload result value %s", value); + log_debug_unit(UNIT(m)->id, + "Failed to parse reload result value %s", value); else if (f != MOUNT_SUCCESS) m->reload_result = f; @@ -1206,21 +1230,24 @@ static int mount_deserialize_item(Unit *u, const char *key, const char *value, F pid_t pid; if (parse_pid(value, &pid) < 0) - log_debug("Failed to parse control-pid value %s", value); + log_debug_unit(UNIT(m)->id, + "Failed to parse control-pid value %s", value); else m->control_pid = pid; } else if (streq(key, "control-command")) { MountExecCommand id; if ((id = mount_exec_command_from_string(value)) < 0) - log_debug("Failed to parse exec-command value %s", value); + log_debug_unit(UNIT(m)->id, + "Failed to parse exec-command value %s", value); else { m->control_command_id = id; m->control_command = m->exec_command + id; } } else - log_debug("Unknown serialization key '%s'", key); + log_debug_unit(UNIT(m)->id, + "Unknown serialization key '%s'", key); return 0; } @@ -1278,8 +1305,9 @@ static void mount_sigchld_event(Unit *u, pid_t pid, int code, int status) { m->control_command_id = _MOUNT_EXEC_COMMAND_INVALID; } - log_full(f == MOUNT_SUCCESS ? LOG_DEBUG : LOG_NOTICE, - "%s mount process exited, code=%s status=%i", u->id, sigchld_code_to_string(code), status); + log_full_unit(f == MOUNT_SUCCESS ? LOG_DEBUG : LOG_NOTICE, u->id, + "%s mount process exited, code=%s status=%i", + u->id, sigchld_code_to_string(code), status); /* Note that mount(8) returning and the kernel sending us a * mount table change event might happen out-of-order. If an @@ -1346,27 +1374,33 @@ static void mount_timer_event(Unit *u, uint64_t elapsed, Watch *w) { case MOUNT_MOUNTING: case MOUNT_MOUNTING_DONE: - log_warning("%s mounting timed out. Stopping.", u->id); + log_warning_unit(u->id, + "%s mounting timed out. Stopping.", u->id); mount_enter_signal(m, MOUNT_MOUNTING_SIGTERM, MOUNT_FAILURE_TIMEOUT); break; case MOUNT_REMOUNTING: - log_warning("%s remounting timed out. Stopping.", u->id); + log_warning_unit(u->id, + "%s remounting timed out. Stopping.", u->id); m->reload_result = MOUNT_FAILURE_TIMEOUT; mount_enter_mounted(m, MOUNT_SUCCESS); break; case MOUNT_UNMOUNTING: - log_warning("%s unmounting timed out. Stopping.", u->id); + log_warning_unit(u->id, + "%s unmounting timed out. Stopping.", u->id); mount_enter_signal(m, MOUNT_UNMOUNTING_SIGTERM, MOUNT_FAILURE_TIMEOUT); break; case MOUNT_MOUNTING_SIGTERM: if (m->kill_context.send_sigkill) { - log_warning("%s mounting timed out. Killing.", u->id); + log_warning_unit(u->id, + "%s mounting timed out. Killing.", u->id); mount_enter_signal(m, MOUNT_MOUNTING_SIGKILL, MOUNT_FAILURE_TIMEOUT); } else { - log_warning("%s mounting timed out. Skipping SIGKILL. Ignoring.", u->id); + log_warning_unit(u->id, + "%s mounting timed out. Skipping SIGKILL. Ignoring.", + u->id); if (m->from_proc_self_mountinfo) mount_enter_mounted(m, MOUNT_FAILURE_TIMEOUT); @@ -1377,10 +1411,13 @@ static void mount_timer_event(Unit *u, uint64_t elapsed, Watch *w) { case MOUNT_REMOUNTING_SIGTERM: if (m->kill_context.send_sigkill) { - log_warning("%s remounting timed out. Killing.", u->id); + log_warning_unit(u->id, + "%s remounting timed out. Killing.", u->id); mount_enter_signal(m, MOUNT_REMOUNTING_SIGKILL, MOUNT_FAILURE_TIMEOUT); } else { - log_warning("%s remounting timed out. Skipping SIGKILL. Ignoring.", u->id); + log_warning_unit(u->id, + "%s remounting timed out. Skipping SIGKILL. Ignoring.", + u->id); if (m->from_proc_self_mountinfo) mount_enter_mounted(m, MOUNT_FAILURE_TIMEOUT); @@ -1391,10 +1428,13 @@ static void mount_timer_event(Unit *u, uint64_t elapsed, Watch *w) { case MOUNT_UNMOUNTING_SIGTERM: if (m->kill_context.send_sigkill) { - log_warning("%s unmounting timed out. Killing.", u->id); + log_warning_unit(u->id, + "%s unmounting timed out. Killing.", u->id); mount_enter_signal(m, MOUNT_UNMOUNTING_SIGKILL, MOUNT_FAILURE_TIMEOUT); } else { - log_warning("%s unmounting timed out. Skipping SIGKILL. Ignoring.", u->id); + log_warning_unit(u->id, + "%s unmounting timed out. Skipping SIGKILL. Ignoring.", + u->id); if (m->from_proc_self_mountinfo) mount_enter_mounted(m, MOUNT_FAILURE_TIMEOUT); @@ -1406,7 +1446,9 @@ static void mount_timer_event(Unit *u, uint64_t elapsed, Watch *w) { case MOUNT_MOUNTING_SIGKILL: case MOUNT_REMOUNTING_SIGKILL: case MOUNT_UNMOUNTING_SIGKILL: - log_warning("%s mount process still around after SIGKILL. Ignoring.", u->id); + log_warning_unit(u->id, + "%s mount process still around after SIGKILL. Ignoring.", + u->id); if (m->from_proc_self_mountinfo) mount_enter_mounted(m, MOUNT_FAILURE_TIMEOUT); diff --git a/src/core/path.c b/src/core/path.c index d65339771e..767620ba75 100644 --- a/src/core/path.c +++ b/src/core/path.c @@ -307,7 +307,8 @@ static int path_verify(Path *p) { return 0; if (!p->specs) { - log_error("%s lacks path setting. Refusing.", UNIT(p)->id); + log_error_unit(UNIT(p)->id, + "%s lacks path setting. Refusing.", UNIT(p)->id); return -EINVAL; } diff --git a/src/core/service.c b/src/core/service.c index 70b93e8446..2a4e691e78 100644 --- a/src/core/service.c +++ b/src/core/service.c @@ -169,7 +169,8 @@ static void service_unwatch_pid_file(Service *s) { if (!s->pid_file_pathspec) return; - log_debug("Stopping watch for %s's PID file %s", UNIT(s)->id, s->pid_file_pathspec->path); + log_debug_unit(UNIT(s)->id, "Stopping watch for %s's PID file %s", + UNIT(s)->id, s->pid_file_pathspec->path); path_spec_unwatch(s->pid_file_pathspec, UNIT(s)); path_spec_done(s->pid_file_pathspec); free(s->pid_file_pathspec); @@ -191,8 +192,9 @@ static int service_set_main_pid(Service *s, pid_t pid) { s->main_pid_known = true; if (get_parent_of_pid(pid, &ppid) >= 0 && ppid != getpid()) { - log_warning("%s: Supervising process %lu which is not our child. We'll most likely not notice when it exits.", - UNIT(s)->id, (unsigned long) pid); + log_warning_unit(UNIT(s)->id, + "%s: Supervising process %lu which is not our child. We'll most likely not notice when it exits.", + UNIT(s)->id, (unsigned long) pid); s->main_pid_alien = true; } else @@ -244,14 +246,16 @@ static void service_handle_watchdog(Service *s) { offset = now(CLOCK_MONOTONIC) - s->watchdog_timestamp.monotonic; if (offset >= s->watchdog_usec) { - log_error("%s watchdog timeout!", UNIT(s)->id); + log_error_unit(UNIT(s)->id, "%s watchdog timeout!", UNIT(s)->id); service_enter_dead(s, SERVICE_FAILURE_WATCHDOG, true); return; } r = unit_watch_timer(UNIT(s), CLOCK_MONOTONIC, true, s->watchdog_usec - offset, &s->watchdog_watch); if (r < 0) - log_warning("%s failed to install watchdog timer: %s", UNIT(s)->id, strerror(-r)); + log_warning_unit(UNIT(s)->id, + "%s failed to install watchdog timer: %s", + UNIT(s)->id, strerror(-r)); } static void service_reset_watchdog(Service *s) { @@ -581,7 +585,9 @@ static int service_load_sysv_path(Service *s, const char *path) { break; r = -errno; - log_error("Failed to read configuration file '%s': %s", path, strerror(-r)); + log_error_unit(u->id, + "Failed to read configuration file '%s': %s", + path, strerror(-r)); goto finish; } @@ -634,7 +640,9 @@ static int service_load_sysv_path(Service *s, const char *path) { runlevels, &start_priority) != 2) { - log_warning("[%s:%u] Failed to parse chkconfig line. Ignoring.", path, line); + log_warning_unit(u->id, + "[%s:%u] Failed to parse chkconfig line. Ignoring.", + path, line); continue; } @@ -642,7 +650,9 @@ static int service_load_sysv_path(Service *s, const char *path) { * symlink farms is preferred over the * data from the LSB header. */ if (start_priority < 0 || start_priority > 99) - log_warning("[%s:%u] Start priority out of range. Ignoring.", path, line); + log_warning_unit(u->id, + "[%s:%u] Start priority out of range. Ignoring.", + path, line); else s->sysv_start_priority = start_priority; @@ -691,7 +701,9 @@ static int service_load_sysv_path(Service *s, const char *path) { fn = strstrip(t+8); if (!path_is_absolute(fn)) { - log_warning("[%s:%u] PID file not absolute. Ignoring.", path, line); + log_warning_unit(u->id, + "[%s:%u] PID file not absolute. Ignoring.", + path, line); continue; } @@ -778,7 +790,9 @@ static int service_load_sysv_path(Service *s, const char *path) { r = unit_add_two_dependencies_by_name(u, UNIT_BEFORE, UNIT_WANTS, m, NULL, true); if (r < 0) - log_error("[%s:%u] Failed to add LSB Provides name %s, ignoring: %s", path, line, m, strerror(-r)); + log_error_unit(u->id, + "[%s:%u] Failed to add LSB Provides name %s, ignoring: %s", + path, line, m, strerror(-r)); free(m); } @@ -803,7 +817,9 @@ static int service_load_sysv_path(Service *s, const char *path) { r = sysv_translate_facility(n, path_get_file_name(path), &m); if (r < 0) { - log_error("[%s:%u] Failed to translate LSB dependency %s, ignoring: %s", path, line, n, strerror(-r)); + log_error_unit(u->id, + "[%s:%u] Failed to translate LSB dependency %s, ignoring: %s", + path, line, n, strerror(-r)); free(n); continue; } @@ -816,7 +832,8 @@ static int service_load_sysv_path(Service *s, const char *path) { r = unit_add_dependency_by_name(u, startswith_no_case(t, "X-Start-Before:") ? UNIT_BEFORE : UNIT_AFTER, m, NULL, true); if (r < 0) - log_error("[%s:%u] Failed to add dependency on %s, ignoring: %s", path, line, m, strerror(-r)); + log_error_unit(u->id, "[%s:%u] Failed to add dependency on %s, ignoring: %s", + path, line, m, strerror(-r)); free(m); } @@ -1105,26 +1122,31 @@ static int service_verify(Service *s) { return 0; if (!s->exec_command[SERVICE_EXEC_START]) { - log_error("%s lacks ExecStart setting. Refusing.", UNIT(s)->id); + log_error_unit(UNIT(s)->id, + "%s lacks ExecStart setting. Refusing.", UNIT(s)->id); return -EINVAL; } if (s->type != SERVICE_ONESHOT && s->exec_command[SERVICE_EXEC_START]->command_next) { - log_error("%s has more than one ExecStart setting, which is only allowed for Type=oneshot services. Refusing.", UNIT(s)->id); + log_error_unit(UNIT(s)->id, + "%s has more than one ExecStart setting, which is only allowed for Type=oneshot services. Refusing.", UNIT(s)->id); return -EINVAL; } if (s->type == SERVICE_DBUS && !s->bus_name) { - log_error("%s is of type D-Bus but no D-Bus service name has been specified. Refusing.", UNIT(s)->id); + log_error_unit(UNIT(s)->id, + "%s is of type D-Bus but no D-Bus service name has been specified. Refusing.", UNIT(s)->id); return -EINVAL; } if (s->bus_name && s->type != SERVICE_DBUS) - log_warning("%s has a D-Bus service name specified, but is not of type dbus. Ignoring.", UNIT(s)->id); + log_warning_unit(UNIT(s)->id, + "%s has a D-Bus service name specified, but is not of type dbus. Ignoring.", UNIT(s)->id); if (s->exec_context.pam_name && s->kill_context.kill_mode != KILL_CONTROL_GROUP) { - log_error("%s has PAM enabled. Kill mode must be set to 'control-group'. Refusing.", UNIT(s)->id); + log_error_unit(UNIT(s)->id, + "%s has PAM enabled. Kill mode must be set to 'control-group'. Refusing.", UNIT(s)->id); return -EINVAL; } @@ -1366,8 +1388,9 @@ static int service_load_pid_file(Service *s, bool may_warn) { if ((r = read_one_line_file(s->pid_file, &k)) < 0) { if (may_warn) - log_info("PID file %s not readable (yet?) after %s.", - s->pid_file, service_state_to_string(s->state)); + log_info_unit(UNIT(s)->id, + "PID file %s not readable (yet?) after %s.", + s->pid_file, service_state_to_string(s->state)); return r; } @@ -1379,8 +1402,9 @@ static int service_load_pid_file(Service *s, bool may_warn) { if (kill(pid, 0) < 0 && errno != EPERM) { if (may_warn) - log_info("PID %lu read from file %s does not exist.", - (unsigned long) pid, s->pid_file); + log_info_unit(UNIT(s)->id, + "PID %lu read from file %s does not exist.", + (unsigned long) pid, s->pid_file); return -ESRCH; } @@ -1388,12 +1412,14 @@ static int service_load_pid_file(Service *s, bool may_warn) { if (pid == s->main_pid) return 0; - log_debug("Main PID changing: %lu -> %lu", - (unsigned long) s->main_pid, (unsigned long) pid); + log_debug_unit(UNIT(s)->id, + "Main PID changing: %lu -> %lu", + (unsigned long) s->main_pid, (unsigned long) pid); service_unwatch_main_pid(s); s->main_pid_known = false; } else - log_debug("Main PID loaded: %lu", (unsigned long) pid); + log_debug_unit(UNIT(s)->id, + "Main PID loaded: %lu", (unsigned long) pid); if ((r = service_set_main_pid(s, pid)) < 0) return r; @@ -1424,7 +1450,8 @@ static int service_search_main_pid(Service *s) { if ((pid = cgroup_bonding_search_main_pid_list(UNIT(s)->cgroup_bondings)) <= 0) return -ENOENT; - log_debug("Main PID guessed: %lu", (unsigned long) pid); + log_debug_unit(UNIT(s)->id, + "Main PID guessed: %lu", (unsigned long) pid); if ((r = service_set_main_pid(s, pid)) < 0) return r; @@ -1540,12 +1567,10 @@ static void service_set_state(Service *s, ServiceState state) { cgroup_bonding_trim_list(UNIT(s)->cgroup_bondings, true); if (old_state != state) - log_struct(LOG_DEBUG, - "UNIT=%s", UNIT(s)->id, - "MESSAGE=%s changed %s -> %s", UNIT(s)->id, - service_state_to_string(old_state), - service_state_to_string(state), - NULL); + log_debug_unit(UNIT(s)->id, + "%s changed %s -> %s", UNIT(s)->id, + service_state_to_string(old_state), + service_state_to_string(state)); unit_notify(UNIT(s), table[old_state], table[state], s->reload_result == SERVICE_SUCCESS); s->reload_result = SERVICE_SUCCESS; @@ -1889,7 +1914,9 @@ static void service_enter_dead(Service *s, ServiceResult f, bool allow_restart) return; fail: - log_warning("%s failed to run install restart timer: %s", UNIT(s)->id, strerror(-r)); + log_warning_unit(UNIT(s)->id, + "%s failed to run install restart timer: %s", + UNIT(s)->id, strerror(-r)); service_enter_dead(s, SERVICE_FAILURE_RESOURCES, false); } @@ -1928,7 +1955,9 @@ static void service_enter_stop_post(Service *s, ServiceResult f) { return; fail: - log_warning("%s failed to run 'stop-post' task: %s", UNIT(s)->id, strerror(-r)); + log_warning_unit(UNIT(s)->id, + "%s failed to run 'stop-post' task: %s", + UNIT(s)->id, strerror(-r)); service_enter_signal(s, SERVICE_FINAL_SIGTERM, SERVICE_FAILURE_RESOURCES); } @@ -1947,14 +1976,16 @@ static void service_enter_signal(Service *s, ServiceState state, ServiceResult f if (s->main_pid > 0) { if (kill_and_sigcont(s->main_pid, sig) < 0 && errno != ESRCH) - log_warning("Failed to kill main process %li: %m", (long) s->main_pid); + log_warning_unit(UNIT(s)->id, + "Failed to kill main process %li: %m", (long) s->main_pid); else wait_for_exit = !s->main_pid_alien; } if (s->control_pid > 0) { if (kill_and_sigcont(s->control_pid, sig) < 0 && errno != ESRCH) - log_warning("Failed to kill control process %li: %m", (long) s->control_pid); + log_warning_unit(UNIT(s)->id, + "Failed to kill control process %li: %m", (long) s->control_pid); else wait_for_exit = true; } @@ -1979,7 +2010,8 @@ static void service_enter_signal(Service *s, ServiceState state, ServiceResult f r = cgroup_bonding_kill_list(UNIT(s)->cgroup_bondings, sig, true, false, pid_set, NULL); if (r < 0) { if (r != -EAGAIN && r != -ESRCH && r != -ENOENT) - log_warning("Failed to kill control group: %s", strerror(-r)); + log_warning_unit(UNIT(s)->id, + "Failed to kill control group: %s", strerror(-r)); } else if (r > 0) wait_for_exit = true; @@ -2004,7 +2036,8 @@ static void service_enter_signal(Service *s, ServiceState state, ServiceResult f return; fail: - log_warning("%s failed to kill processes: %s", UNIT(s)->id, strerror(-r)); + log_warning_unit(UNIT(s)->id, + "%s failed to kill processes: %s", UNIT(s)->id, strerror(-r)); if (state == SERVICE_STOP_SIGTERM || state == SERVICE_STOP_SIGKILL) service_enter_stop_post(s, SERVICE_FAILURE_RESOURCES); @@ -2048,7 +2081,8 @@ static void service_enter_stop(Service *s, ServiceResult f) { return; fail: - log_warning("%s failed to run 'stop' task: %s", UNIT(s)->id, strerror(-r)); + log_warning_unit(UNIT(s)->id, + "%s failed to run 'stop' task: %s", UNIT(s)->id, strerror(-r)); service_enter_signal(s, SERVICE_STOP_SIGTERM, SERVICE_FAILURE_RESOURCES); } @@ -2103,7 +2137,8 @@ static void service_enter_start_post(Service *s) { return; fail: - log_warning("%s failed to run 'start-post' task: %s", UNIT(s)->id, strerror(-r)); + log_warning_unit(UNIT(s)->id, + "%s failed to run 'start-post' task: %s", UNIT(s)->id, strerror(-r)); service_enter_stop(s, SERVICE_FAILURE_RESOURCES); } @@ -2186,7 +2221,8 @@ static void service_enter_start(Service *s) { return; fail: - log_warning("%s failed to run 'start' task: %s", UNIT(s)->id, strerror(-r)); + log_warning_unit(UNIT(s)->id, + "%s failed to run 'start' task: %s", UNIT(s)->id, strerror(-r)); service_enter_signal(s, SERVICE_FINAL_SIGTERM, SERVICE_FAILURE_RESOURCES); } @@ -2225,7 +2261,8 @@ static void service_enter_start_pre(Service *s) { return; fail: - log_warning("%s failed to run 'start-pre' task: %s", UNIT(s)->id, strerror(-r)); + log_warning_unit(UNIT(s)->id, + "%s failed to run 'start-pre' task: %s", UNIT(s)->id, strerror(-r)); service_enter_dead(s, SERVICE_FAILURE_RESOURCES, true); } @@ -2238,7 +2275,8 @@ static void service_enter_restart(Service *s) { if (UNIT(s)->job && UNIT(s)->job->type == JOB_STOP) { /* Don't restart things if we are going down anyway */ - log_info("Stop job pending for unit, delaying automatic restart."); + log_info_unit(UNIT(s)->id, + "Stop job pending for unit, delaying automatic restart."); r = unit_watch_timer(UNIT(s), CLOCK_MONOTONIC, true, s->restart_usec, &s->timer_watch); if (r < 0) @@ -2259,11 +2297,14 @@ static void service_enter_restart(Service *s) { * it will be canceled as part of the service_stop() call that * is executed as part of JOB_RESTART. */ - log_debug("%s scheduled restart job.", UNIT(s)->id); + log_debug_unit(UNIT(s)->id, + "%s scheduled restart job.", UNIT(s)->id); return; fail: - log_warning("%s failed to schedule restart job: %s", UNIT(s)->id, bus_error(&error, -r)); + log_warning_unit(UNIT(s)->id, + "%s failed to schedule restart job: %s", + UNIT(s)->id, bus_error(&error, -r)); service_enter_dead(s, SERVICE_FAILURE_RESOURCES, false); dbus_error_free(&error); @@ -2299,7 +2340,9 @@ static void service_enter_reload(Service *s) { return; fail: - log_warning("%s failed to run 'reload' task: %s", UNIT(s)->id, strerror(-r)); + log_warning_unit(UNIT(s)->id, + "%s failed to run 'reload' task: %s", + UNIT(s)->id, strerror(-r)); s->reload_result = SERVICE_FAILURE_RESOURCES; service_enter_running(s, SERVICE_SUCCESS); } @@ -2333,7 +2376,9 @@ static void service_run_next_control(Service *s) { return; fail: - log_warning("%s failed to run next control task: %s", UNIT(s)->id, strerror(-r)); + log_warning_unit(UNIT(s)->id, + "%s failed to run next control task: %s", + UNIT(s)->id, strerror(-r)); if (s->state == SERVICE_START_PRE) service_enter_signal(s, SERVICE_FINAL_SIGTERM, SERVICE_FAILURE_RESOURCES); @@ -2378,7 +2423,8 @@ static void service_run_next_main(Service *s) { return; fail: - log_warning("%s failed to run next main task: %s", UNIT(s)->id, strerror(-r)); + log_warning_unit(UNIT(s)->id, + "%s failed to run next main task: %s", UNIT(s)->id, strerror(-r)); service_enter_stop(s, SERVICE_FAILURE_RESOURCES); } @@ -2391,7 +2437,9 @@ static int service_start_limit_test(Service *s) { switch (s->start_limit_action) { case SERVICE_START_LIMIT_NONE: - log_warning("%s start request repeated too quickly, refusing to start.", UNIT(s)->id); + log_warning_unit(UNIT(s)->id, + "%s start request repeated too quickly, refusing to start.", + UNIT(s)->id); break; case SERVICE_START_LIMIT_REBOOT: { @@ -2400,11 +2448,13 @@ static int service_start_limit_test(Service *s) { dbus_error_init(&error); - log_warning("%s start request repeated too quickly, rebooting.", UNIT(s)->id); + log_warning_unit(UNIT(s)->id, + "%s start request repeated too quickly, rebooting.", UNIT(s)->id); r = manager_add_job_by_name(UNIT(s)->manager, JOB_START, SPECIAL_REBOOT_TARGET, JOB_REPLACE, true, &error, NULL); if (r < 0) { - log_error("Failed to reboot: %s.", bus_error(&error, r)); + log_error_unit(UNIT(s)->id, + "Failed to reboot: %s.", bus_error(&error, r)); dbus_error_free(&error); } @@ -2412,18 +2462,21 @@ static int service_start_limit_test(Service *s) { } case SERVICE_START_LIMIT_REBOOT_FORCE: - log_warning("%s start request repeated too quickly, forcibly rebooting.", UNIT(s)->id); + log_warning_unit(UNIT(s)->id, + "%s start request repeated too quickly, forcibly rebooting.", UNIT(s)->id); UNIT(s)->manager->exit_code = MANAGER_REBOOT; break; case SERVICE_START_LIMIT_REBOOT_IMMEDIATE: - log_warning("%s start request repeated too quickly, rebooting immediately.", UNIT(s)->id); + log_warning_unit(UNIT(s)->id, + "%s start request repeated too quickly, rebooting immediately.", UNIT(s)->id); sync(); reboot(RB_AUTOBOOT); break; default: - log_error("start limit action=%i", s->start_limit_action); + log_error_unit(UNIT(s)->id, + "start limit action=%i", s->start_limit_action); assert_not_reached("Unknown StartLimitAction."); } @@ -2605,7 +2658,7 @@ static int service_deserialize_item(Unit *u, const char *key, const char *value, ServiceState state; if ((state = service_state_from_string(value)) < 0) - log_debug("Failed to parse state value %s", value); + log_debug_unit(u->id, "Failed to parse state value %s", value); else s->deserialized_state = state; } else if (streq(key, "result")) { @@ -2613,7 +2666,7 @@ static int service_deserialize_item(Unit *u, const char *key, const char *value, f = service_result_from_string(value); if (f < 0) - log_debug("Failed to parse result value %s", value); + log_debug_unit(u->id, "Failed to parse result value %s", value); else if (f != SERVICE_SUCCESS) s->result = f; @@ -2622,7 +2675,7 @@ static int service_deserialize_item(Unit *u, const char *key, const char *value, f = service_result_from_string(value); if (f < 0) - log_debug("Failed to parse reload result value %s", value); + log_debug_unit(u->id, "Failed to parse reload result value %s", value); else if (f != SERVICE_SUCCESS) s->reload_result = f; @@ -2630,21 +2683,21 @@ static int service_deserialize_item(Unit *u, const char *key, const char *value, pid_t pid; if (parse_pid(value, &pid) < 0) - log_debug("Failed to parse control-pid value %s", value); + log_debug_unit(u->id, "Failed to parse control-pid value %s", value); else s->control_pid = pid; } else if (streq(key, "main-pid")) { pid_t pid; if (parse_pid(value, &pid) < 0) - log_debug("Failed to parse main-pid value %s", value); + log_debug_unit(u->id, "Failed to parse main-pid value %s", value); else service_set_main_pid(s, (pid_t) pid); } else if (streq(key, "main-pid-known")) { int b; if ((b = parse_boolean(value)) < 0) - log_debug("Failed to parse main-pid-known value %s", value); + log_debug_unit(u->id, "Failed to parse main-pid-known value %s", value); else s->main_pid_known = b; } else if (streq(key, "status-text")) { @@ -2659,7 +2712,7 @@ static int service_deserialize_item(Unit *u, const char *key, const char *value, ServiceExecCommand id; if ((id = service_exec_command_from_string(value)) < 0) - log_debug("Failed to parse exec-command value %s", value); + log_debug_unit(u->id, "Failed to parse exec-command value %s", value); else { s->control_command_id = id; s->control_command = s->exec_command[id]; @@ -2668,7 +2721,7 @@ static int service_deserialize_item(Unit *u, const char *key, const char *value, int fd; if (safe_atoi(value, &fd) < 0 || fd < 0 || !fdset_contains(fds, fd)) - log_debug("Failed to parse socket-fd value %s", value); + log_debug_unit(u->id, "Failed to parse socket-fd value %s", value); else { if (s->socket_fd >= 0) @@ -2679,21 +2732,21 @@ static int service_deserialize_item(Unit *u, const char *key, const char *value, pid_t pid; if (parse_pid(value, &pid) < 0) - log_debug("Failed to parse main-exec-status-pid value %s", value); + log_debug_unit(u->id, "Failed to parse main-exec-status-pid value %s", value); else s->main_exec_status.pid = pid; } else if (streq(key, "main-exec-status-code")) { int i; if (safe_atoi(value, &i) < 0) - log_debug("Failed to parse main-exec-status-code value %s", value); + log_debug_unit(u->id, "Failed to parse main-exec-status-code value %s", value); else s->main_exec_status.code = i; } else if (streq(key, "main-exec-status-status")) { int i; if (safe_atoi(value, &i) < 0) - log_debug("Failed to parse main-exec-status-status value %s", value); + log_debug_unit(u->id, "Failed to parse main-exec-status-status value %s", value); else s->main_exec_status.status = i; } else if (streq(key, "main-exec-status-start")) @@ -2703,7 +2756,7 @@ static int service_deserialize_item(Unit *u, const char *key, const char *value, else if (streq(key, "watchdog-timestamp")) dual_timestamp_deserialize(value, &s->watchdog_timestamp); else - log_debug("Unknown serialization key '%s'", key); + log_debug_unit(u->id, "Unknown serialization key '%s'", key); return 0; } @@ -2771,7 +2824,9 @@ static int service_retry_pid_file(Service *s) { static int service_watch_pid_file(Service *s) { int r; - log_debug("Setting watch for %s's PID file %s", UNIT(s)->id, s->pid_file_pathspec->path); + log_debug_unit(UNIT(s)->id, + "Setting watch for %s's PID file %s", + UNIT(s)->id, s->pid_file_pathspec->path); r = path_spec_watch(s->pid_file_pathspec, UNIT(s)); if (r < 0) goto fail; @@ -2781,8 +2836,9 @@ static int service_watch_pid_file(Service *s) { return 0; fail: - log_error("Failed to set a watch for %s's PID file %s: %s", - UNIT(s)->id, s->pid_file_pathspec->path, strerror(-r)); + log_error_unit(UNIT(s)->id, + "Failed to set a watch for %s's PID file %s: %s", + UNIT(s)->id, s->pid_file_pathspec->path, strerror(-r)); service_unwatch_pid_file(s); return r; } @@ -2824,7 +2880,7 @@ static void service_fd_event(Unit *u, int fd, uint32_t events, Watch *w) { assert(s->pid_file_pathspec); assert(path_spec_owns_inotify_fd(s->pid_file_pathspec, fd)); - log_debug("inotify event for %s", u->id); + log_debug_unit(u->id, "inotify event for %s", u->id); if (path_spec_fd_event(s->pid_file_pathspec, events) < 0) goto fail; @@ -2902,7 +2958,9 @@ static void service_sigchld_event(Unit *u, pid_t pid, int code, int status) { /* There is another command to * * execute, so let's do that. */ - log_debug("%s running next main command for state %s", u->id, service_state_to_string(s->state)); + log_debug_unit(u->id, + "%s running next main command for state %s", + u->id, service_state_to_string(s->state)); service_run_next_main(s); } else { @@ -2961,8 +3019,9 @@ static void service_sigchld_event(Unit *u, pid_t pid, int code, int status) { f = SERVICE_SUCCESS; } - log_full(f == SERVICE_SUCCESS ? LOG_DEBUG : LOG_NOTICE, - "%s: control process exited, code=%s status=%i", u->id, sigchld_code_to_string(code), status); + log_full_unit(f == SERVICE_SUCCESS ? LOG_DEBUG : LOG_NOTICE, u->id, + "%s: control process exited, code=%s status=%i", + u->id, sigchld_code_to_string(code), status); if (f != SERVICE_SUCCESS) s->result = f; @@ -2979,7 +3038,9 @@ static void service_sigchld_event(Unit *u, pid_t pid, int code, int status) { /* There is another command to * * execute, so let's do that. */ - log_debug("%s running next control command for state %s", u->id, service_state_to_string(s->state)); + log_debug_unit(u->id, + "%s running next control command for state %s", + u->id, service_state_to_string(s->state)); service_run_next_control(s); } else { @@ -2989,7 +3050,9 @@ static void service_sigchld_event(Unit *u, pid_t pid, int code, int status) { s->control_command = NULL; s->control_command_id = _SERVICE_EXEC_COMMAND_INVALID; - log_debug("%s got final SIGCHLD for state %s", u->id, service_state_to_string(s->state)); + log_debug_unit(u->id, + "%s got final SIGCHLD for state %s", + u->id, service_state_to_string(s->state)); switch (s->state) { @@ -3111,32 +3174,38 @@ static void service_timer_event(Unit *u, uint64_t elapsed, Watch* w) { case SERVICE_START_PRE: case SERVICE_START: - log_warning("%s operation timed out. Terminating.", u->id); + log_warning_unit(u->id, + "%s operation timed out. Terminating.", u->id); service_enter_signal(s, SERVICE_FINAL_SIGTERM, SERVICE_FAILURE_TIMEOUT); break; case SERVICE_START_POST: - log_warning("%s operation timed out. Stopping.", u->id); + log_warning_unit(u->id, + "%s operation timed out. Stopping.", u->id); service_enter_stop(s, SERVICE_FAILURE_TIMEOUT); break; case SERVICE_RELOAD: - log_warning("%s operation timed out. Stopping.", u->id); + log_warning_unit(u->id, + "%s operation timed out. Stopping.", u->id); s->reload_result = SERVICE_FAILURE_TIMEOUT; service_enter_running(s, SERVICE_SUCCESS); break; case SERVICE_STOP: - log_warning("%s stopping timed out. Terminating.", u->id); + log_warning_unit(u->id, + "%s stopping timed out. Terminating.", u->id); service_enter_signal(s, SERVICE_STOP_SIGTERM, SERVICE_FAILURE_TIMEOUT); break; case SERVICE_STOP_SIGTERM: if (s->kill_context.send_sigkill) { - log_warning("%s stopping timed out. Killing.", u->id); + log_warning_unit(u->id, + "%s stopping timed out. Killing.", u->id); service_enter_signal(s, SERVICE_STOP_SIGKILL, SERVICE_FAILURE_TIMEOUT); } else { - log_warning("%s stopping timed out. Skipping SIGKILL.", u->id); + log_warning_unit(u->id, + "%s stopping timed out. Skipping SIGKILL.", u->id); service_enter_stop_post(s, SERVICE_FAILURE_TIMEOUT); } @@ -3147,33 +3216,40 @@ static void service_timer_event(Unit *u, uint64_t elapsed, Watch* w) { * Must be something we cannot kill, so let's just be * weirded out and continue */ - log_warning("%s still around after SIGKILL. Ignoring.", u->id); + log_warning_unit(u->id, + "%s still around after SIGKILL. Ignoring.", u->id); service_enter_stop_post(s, SERVICE_FAILURE_TIMEOUT); break; case SERVICE_STOP_POST: - log_warning("%s stopping timed out (2). Terminating.", u->id); + log_warning_unit(u->id, + "%s stopping timed out (2). Terminating.", u->id); service_enter_signal(s, SERVICE_FINAL_SIGTERM, SERVICE_FAILURE_TIMEOUT); break; case SERVICE_FINAL_SIGTERM: if (s->kill_context.send_sigkill) { - log_warning("%s stopping timed out (2). Killing.", u->id); + log_warning_unit(u->id, + "%s stopping timed out (2). Killing.", u->id); service_enter_signal(s, SERVICE_FINAL_SIGKILL, SERVICE_FAILURE_TIMEOUT); } else { - log_warning("%s stopping timed out (2). Skipping SIGKILL. Entering failed mode.", u->id); + log_warning_unit(u->id, + "%s stopping timed out (2). Skipping SIGKILL. Entering failed mode.", + u->id); service_enter_dead(s, SERVICE_FAILURE_TIMEOUT, false); } break; case SERVICE_FINAL_SIGKILL: - log_warning("%s still around after SIGKILL (2). Entering failed mode.", u->id); + log_warning_unit(u->id, + "%s still around after SIGKILL (2). Entering failed mode.", u->id); service_enter_dead(s, SERVICE_FAILURE_TIMEOUT, true); break; case SERVICE_AUTO_RESTART: - log_info("%s holdoff time over, scheduling restart.", u->id); + log_info_unit(u->id, + "%s holdoff time over, scheduling restart.", u->id); service_enter_restart(s); break; @@ -3187,7 +3263,8 @@ static void service_cgroup_notify_event(Unit *u) { assert(u); - log_debug("%s: cgroup is empty", u->id); + log_debug_unit(u->id, + "%s: cgroup is empty", u->id); switch (s->state) { @@ -3202,7 +3279,8 @@ static void service_cgroup_notify_event(Unit *u) { /* If we were hoping for the daemon to write its PID file, * we can give up now. */ if (s->pid_file_pathspec) { - log_warning("%s never wrote its PID file. Failing.", UNIT(s)->id); + log_warning_unit(u->id, + "%s never wrote its PID file. Failing.", UNIT(s)->id); service_unwatch_pid_file(s); if (s->state == SERVICE_START) service_enter_signal(s, SERVICE_FINAL_SIGTERM, SERVICE_FAILURE_RESOURCES); @@ -3243,18 +3321,21 @@ static void service_notify_message(Unit *u, pid_t pid, char **tags) { assert(u); if (s->notify_access == NOTIFY_NONE) { - log_warning("%s: Got notification message from PID %lu, but reception is disabled.", - u->id, (unsigned long) pid); + log_warning_unit(u->id, + "%s: Got notification message from PID %lu, but reception is disabled.", + u->id, (unsigned long) pid); return; } if (s->notify_access == NOTIFY_MAIN && pid != s->main_pid) { - log_warning("%s: Got notification message from PID %lu, but reception only permitted for PID %lu", - u->id, (unsigned long) pid, (unsigned long) s->main_pid); + log_warning_unit(u->id, + "%s: Got notification message from PID %lu, but reception only permitted for PID %lu", + u->id, (unsigned long) pid, (unsigned long) s->main_pid); return; } - log_debug("%s: Got message", u->id); + log_debug_unit(u->id, + "%s: Got message", u->id); /* Interpret MAINPID= */ if ((e = strv_find_prefix(tags, "MAINPID=")) && @@ -3264,9 +3345,11 @@ static void service_notify_message(Unit *u, pid_t pid, char **tags) { s->state == SERVICE_RELOAD)) { if (parse_pid(e + 8, &pid) < 0) - log_warning("Failed to parse notification message %s", e); + log_warning_unit(u->id, + "Failed to parse notification message %s", e); else { - log_debug("%s: got %s", u->id, e); + log_debug_unit(u->id, + "%s: got %s", u->id, e); service_set_main_pid(s, pid); } } @@ -3275,7 +3358,8 @@ static void service_notify_message(Unit *u, pid_t pid, char **tags) { if (s->type == SERVICE_NOTIFY && s->state == SERVICE_START && strv_find(tags, "READY=1")) { - log_debug("%s: got READY=1", u->id); + log_debug_unit(u->id, + "%s: got READY=1", u->id); service_enter_start_post(s); } @@ -3288,17 +3372,20 @@ static void service_notify_message(Unit *u, pid_t pid, char **tags) { if (e[7]) { if (!utf8_is_valid(e+7)) { - log_warning("Status message in notification is not UTF-8 clean."); + log_warning_unit(u->id, + "Status message in notification is not UTF-8 clean."); return; } t = strdup(e+7); if (!t) { - log_error("Failed to allocate string."); + log_error_unit(u->id, + "Failed to allocate string."); return; } - log_debug("%s: got %s", u->id, e); + log_debug_unit(u->id, + "%s: got %s", u->id, e); free(s->status_text); s->status_text = t; @@ -3309,7 +3396,8 @@ static void service_notify_message(Unit *u, pid_t pid, char **tags) { } if (strv_find(tags, "WATCHDOG=1")) { - log_debug("%s: got WATCHDOG=1", u->id); + log_debug_unit(u->id, + "%s: got WATCHDOG=1", u->id); service_reset_watchdog(s); } @@ -3396,7 +3484,8 @@ static int service_enumerate(Manager *m) { goto finish; } - if ((r = manager_load_unit_prepare(m, name, NULL, NULL, &service)) < 0) { + r = manager_load_unit_prepare(m, name, NULL, NULL, &service); + if (r < 0) { log_warning("Failed to prepare unit %s: %s", name, strerror(-r)); continue; } @@ -3495,11 +3584,17 @@ static void service_bus_name_owner_change( assert(old_owner || new_owner); if (old_owner && new_owner) - log_debug("%s's D-Bus name %s changed owner from %s to %s", u->id, name, old_owner, new_owner); + log_debug_unit(u->id, + "%s's D-Bus name %s changed owner from %s to %s", + u->id, name, old_owner, new_owner); else if (old_owner) - log_debug("%s's D-Bus name %s no longer registered by %s", u->id, name, old_owner); + log_debug_unit(u->id, + "%s's D-Bus name %s no longer registered by %s", + u->id, name, old_owner); else - log_debug("%s's D-Bus name %s now registered by %s", u->id, name, new_owner); + log_debug_unit(u->id, + "%s's D-Bus name %s now registered by %s", + u->id, name, new_owner); s->bus_name_good = !!new_owner; @@ -3520,7 +3615,8 @@ static void service_bus_name_owner_change( s->state == SERVICE_RELOAD)) { /* Try to acquire PID from bus service */ - log_debug("Trying to acquire PID from D-Bus name..."); + log_debug_unit(u->id, + "Trying to acquire PID from D-Bus name..."); bus_query_pid(u->manager, name); } @@ -3536,7 +3632,9 @@ static void service_bus_query_pid_done( assert(s); assert(name); - log_debug("%s's D-Bus name %s is now owned by process %u", u->id, name, (unsigned) pid); + log_debug_unit(u->id, + "%s's D-Bus name %s is now owned by process %u", + u->id, name, (unsigned) pid); if (s->main_pid <= 0 && (s->state == SERVICE_START || diff --git a/src/core/socket.c b/src/core/socket.c index 324ec1e34b..fcbcdbe192 100644 --- a/src/core/socket.c +++ b/src/core/socket.c @@ -213,27 +213,35 @@ static int socket_verify(Socket *s) { return 0; if (!s->ports) { - log_error("%s lacks Listen setting. Refusing.", UNIT(s)->id); + log_error_unit(UNIT(s)->id, + "%s lacks Listen setting. Refusing.", UNIT(s)->id); return -EINVAL; } if (s->accept && have_non_accept_socket(s)) { - log_error("%s configured for accepting sockets, but sockets are non-accepting. Refusing.", UNIT(s)->id); + log_error_unit(UNIT(s)->id, + "%s configured for accepting sockets, but sockets are non-accepting. Refusing.", + UNIT(s)->id); return -EINVAL; } if (s->accept && s->max_connections <= 0) { - log_error("%s's MaxConnection setting too small. Refusing.", UNIT(s)->id); + log_error_unit(UNIT(s)->id, + "%s's MaxConnection setting too small. Refusing.", UNIT(s)->id); return -EINVAL; } if (s->accept && UNIT_DEREF(s->service)) { - log_error("Explicit service configuration for accepting sockets not supported on %s. Refusing.", UNIT(s)->id); + log_error_unit(UNIT(s)->id, + "Explicit service configuration for accepting sockets not supported on %s. Refusing.", + UNIT(s)->id); return -EINVAL; } if (s->exec_context.pam_name && s->kill_context.kill_mode != KILL_CONTROL_GROUP) { - log_error("%s has PAM enabled. Kill mode must be set to 'control-group'. Refusing.", UNIT(s)->id); + log_error_unit(UNIT(s)->id, + "%s has PAM enabled. Kill mode must be set to 'control-group'. Refusing.", + UNIT(s)->id); return -EINVAL; } @@ -700,30 +708,30 @@ static void socket_apply_socket_options(Socket *s, int fd) { if (s->keep_alive) { int b = s->keep_alive; if (setsockopt(fd, SOL_SOCKET, SO_KEEPALIVE, &b, sizeof(b)) < 0) - log_warning("SO_KEEPALIVE failed: %m"); + log_warning_unit(UNIT(s)->id, "SO_KEEPALIVE failed: %m"); } if (s->broadcast) { int one = 1; if (setsockopt(fd, SOL_SOCKET, SO_BROADCAST, &one, sizeof(one)) < 0) - log_warning("SO_BROADCAST failed: %m"); + log_warning_unit(UNIT(s)->id, "SO_BROADCAST failed: %m"); } if (s->pass_cred) { int one = 1; if (setsockopt(fd, SOL_SOCKET, SO_PASSCRED, &one, sizeof(one)) < 0) - log_warning("SO_PASSCRED failed: %m"); + log_warning_unit(UNIT(s)->id, "SO_PASSCRED failed: %m"); } if (s->pass_sec) { int one = 1; if (setsockopt(fd, SOL_SOCKET, SO_PASSSEC, &one, sizeof(one)) < 0) - log_warning("SO_PASSSEC failed: %m"); + log_warning_unit(UNIT(s)->id, "SO_PASSSEC failed: %m"); } if (s->priority >= 0) if (setsockopt(fd, SOL_SOCKET, SO_PRIORITY, &s->priority, sizeof(s->priority)) < 0) - log_warning("SO_PRIORITY failed: %m"); + log_warning_unit(UNIT(s)->id, "SO_PRIORITY failed: %m"); if (s->receive_buffer > 0) { int value = (int) s->receive_buffer; @@ -732,23 +740,23 @@ static void socket_apply_socket_options(Socket *s, int fd) { if (setsockopt(fd, SOL_SOCKET, SO_RCVBUFFORCE, &value, sizeof(value)) < 0) if (setsockopt(fd, SOL_SOCKET, SO_RCVBUF, &value, sizeof(value)) < 0) - log_warning("SO_RCVBUF failed: %m"); + log_warning_unit(UNIT(s)->id, "SO_RCVBUF failed: %m"); } if (s->send_buffer > 0) { int value = (int) s->send_buffer; if (setsockopt(fd, SOL_SOCKET, SO_SNDBUFFORCE, &value, sizeof(value)) < 0) if (setsockopt(fd, SOL_SOCKET, SO_SNDBUF, &value, sizeof(value)) < 0) - log_warning("SO_SNDBUF failed: %m"); + log_warning_unit(UNIT(s)->id, "SO_SNDBUF failed: %m"); } if (s->mark >= 0) if (setsockopt(fd, SOL_SOCKET, SO_MARK, &s->mark, sizeof(s->mark)) < 0) - log_warning("SO_MARK failed: %m"); + log_warning_unit(UNIT(s)->id, "SO_MARK failed: %m"); if (s->ip_tos >= 0) if (setsockopt(fd, IPPROTO_IP, IP_TOS, &s->ip_tos, sizeof(s->ip_tos)) < 0) - log_warning("IP_TOS failed: %m"); + log_warning_unit(UNIT(s)->id, "IP_TOS failed: %m"); if (s->ip_ttl >= 0) { int r, x; @@ -763,21 +771,24 @@ static void socket_apply_socket_options(Socket *s, int fd) { } if (r < 0 && x < 0) - log_warning("IP_TTL/IPV6_UNICAST_HOPS failed: %m"); + log_warning_unit(UNIT(s)->id, + "IP_TTL/IPV6_UNICAST_HOPS failed: %m"); } if (s->tcp_congestion) if (setsockopt(fd, SOL_TCP, TCP_CONGESTION, s->tcp_congestion, strlen(s->tcp_congestion)+1) < 0) - log_warning("TCP_CONGESTION failed: %m"); + log_warning_unit(UNIT(s)->id, "TCP_CONGESTION failed: %m"); #ifdef HAVE_ATTR_XATTR_H if (s->smack_ip_in) if (fsetxattr(fd, "security.SMACK64IPIN", s->smack_ip_in, strlen(s->smack_ip_in), 0) < 0) - log_error("fsetxattr(\"security.SMACK64IPIN\"): %m"); + log_error_unit(UNIT(s)->id, + "fsetxattr(\"security.SMACK64IPIN\"): %m"); if (s->smack_ip_out) if (fsetxattr(fd, "security.SMACK64IPOUT", s->smack_ip_out, strlen(s->smack_ip_out), 0) < 0) - log_error("fsetxattr(\"security.SMACK64IPOUT\"): %m"); + log_error_unit(UNIT(s)->id, + "fsetxattr(\"security.SMACK64IPOUT\"): %m"); #endif } @@ -787,12 +798,14 @@ static void socket_apply_fifo_options(Socket *s, int fd) { if (s->pipe_size > 0) if (fcntl(fd, F_SETPIPE_SZ, s->pipe_size) < 0) - log_warning("F_SETPIPE_SZ: %m"); + log_warning_unit(UNIT(s)->id, + "F_SETPIPE_SZ: %m"); #ifdef HAVE_ATTR_XATTR_H if (s->smack) if (fsetxattr(fd, "security.SMACK64", s->smack, strlen(s->smack), 0) < 0) - log_error("fsetxattr(\"security.SMACK64\"): %m"); + log_error_unit(UNIT(s)->id, + "fsetxattr(\"security.SMACK64\"): %m"); #endif } @@ -1117,10 +1130,10 @@ static void socket_set_state(Socket *s, SocketState state) { socket_close_fds(s); if (state != old_state) - log_debug("%s changed %s -> %s", - UNIT(s)->id, - socket_state_to_string(old_state), - socket_state_to_string(state)); + log_debug_unit(UNIT(s)->id, + "%s changed %s -> %s", UNIT(s)->id, + socket_state_to_string(old_state), + socket_state_to_string(state)); unit_notify(UNIT(s), state_translation_table[old_state], state_translation_table[state], true); } @@ -1260,7 +1273,9 @@ static void socket_enter_stop_post(Socket *s, SocketResult f) { return; fail: - log_warning("%s failed to run 'stop-post' task: %s", UNIT(s)->id, strerror(-r)); + log_warning_unit(UNIT(s)->id, + "%s failed to run 'stop-post' task: %s", + UNIT(s)->id, strerror(-r)); socket_enter_signal(s, SOCKET_FINAL_SIGTERM, SOCKET_FAILURE_RESOURCES); } @@ -1280,7 +1295,9 @@ static void socket_enter_signal(Socket *s, SocketState state, SocketResult f) { if (s->control_pid > 0) { if (kill_and_sigcont(s->control_pid, sig) < 0 && errno != ESRCH) - log_warning("Failed to kill control process %li: %m", (long) s->control_pid); + log_warning_unit(UNIT(s)->id, + "Failed to kill control process %li: %m", + (long) s->control_pid); else wait_for_exit = true; } @@ -1300,7 +1317,9 @@ static void socket_enter_signal(Socket *s, SocketState state, SocketResult f) { r = cgroup_bonding_kill_list(UNIT(s)->cgroup_bondings, sig, true, false, pid_set, NULL); if (r < 0) { if (r != -EAGAIN && r != -ESRCH && r != -ENOENT) - log_warning("Failed to kill control group: %s", strerror(-r)); + log_warning_unit(UNIT(s)->id, + "Failed to kill control group: %s", + strerror(-r)); } else if (r > 0) wait_for_exit = true; @@ -1323,7 +1342,9 @@ static void socket_enter_signal(Socket *s, SocketState state, SocketResult f) { return; fail: - log_warning("%s failed to kill processes: %s", UNIT(s)->id, strerror(-r)); + log_warning_unit(UNIT(s)->id, + "%s failed to kill processes: %s", + UNIT(s)->id, strerror(-r)); if (state == SOCKET_STOP_PRE_SIGTERM || state == SOCKET_STOP_PRE_SIGKILL) socket_enter_stop_post(s, SOCKET_FAILURE_RESOURCES); @@ -1356,7 +1377,9 @@ static void socket_enter_stop_pre(Socket *s, SocketResult f) { return; fail: - log_warning("%s failed to run 'stop-pre' task: %s", UNIT(s)->id, strerror(-r)); + log_warning_unit(UNIT(s)->id, + "%s failed to run 'stop-pre' task: %s", + UNIT(s)->id, strerror(-r)); socket_enter_stop_post(s, SOCKET_FAILURE_RESOURCES); } @@ -1366,7 +1389,9 @@ static void socket_enter_listening(Socket *s) { r = socket_watch_fds(s); if (r < 0) { - log_warning("%s failed to watch sockets: %s", UNIT(s)->id, strerror(-r)); + log_warning_unit(UNIT(s)->id, + "%s failed to watch sockets: %s", + UNIT(s)->id, strerror(-r)); goto fail; } @@ -1383,7 +1408,9 @@ static void socket_enter_start_post(Socket *s) { r = socket_open_fds(s); if (r < 0) { - log_warning("%s failed to listen on sockets: %s", UNIT(s)->id, strerror(-r)); + log_warning_unit(UNIT(s)->id, + "%s failed to listen on sockets: %s", + UNIT(s)->id, strerror(-r)); goto fail; } @@ -1394,7 +1421,9 @@ static void socket_enter_start_post(Socket *s) { if ((s->control_command = s->exec_command[SOCKET_EXEC_START_POST])) { r = socket_spawn(s, s->control_command, &s->control_pid); if (r < 0) { - log_warning("%s failed to run 'start-post' task: %s", UNIT(s)->id, strerror(-r)); + log_warning_unit(UNIT(s)->id, + "%s failed to run 'start-post' task: %s", + UNIT(s)->id, strerror(-r)); goto fail; } @@ -1427,7 +1456,9 @@ static void socket_enter_start_pre(Socket *s) { return; fail: - log_warning("%s failed to run 'start-pre' task: %s", UNIT(s)->id, strerror(-r)); + log_warning_unit(UNIT(s)->id, + "%s failed to run 'start-pre' task: %s", + UNIT(s)->id, strerror(-r)); socket_enter_dead(s, SOCKET_FAILURE_RESOURCES); } @@ -1441,7 +1472,9 @@ static void socket_enter_running(Socket *s, int cfd) { /* We don't take connections anymore if we are supposed to * shut down anyway */ if (unit_pending_inactive(UNIT(s))) { - log_debug("Suppressing connection request on %s since unit stop is scheduled.", UNIT(s)->id); + log_debug_unit(UNIT(s)->id, + "Suppressing connection request on %s since unit stop is scheduled.", + UNIT(s)->id); if (cfd >= 0) close_nointr_nofail(cfd); @@ -1451,7 +1484,9 @@ static void socket_enter_running(Socket *s, int cfd) { r = socket_watch_fds(s); if (r < 0) { - log_warning("%s failed to watch sockets: %s", UNIT(s)->id, strerror(-r)); + log_warning_unit(UNIT(s)->id, + "%s failed to watch sockets: %s", + UNIT(s)->id, strerror(-r)); socket_enter_stop_pre(s, SOCKET_FAILURE_RESOURCES); } } @@ -1484,7 +1519,9 @@ static void socket_enter_running(Socket *s, int cfd) { Service *service; if (s->n_connections >= s->max_connections) { - log_warning("%s: Too many incoming connections (%u)", UNIT(s)->id, s->n_connections); + log_warning_unit(UNIT(s)->id, + "%s: Too many incoming connections (%u)", + UNIT(s)->id, s->n_connections); close_nointr_nofail(cfd); return; } @@ -1553,7 +1590,11 @@ static void socket_enter_running(Socket *s, int cfd) { return; fail: - log_warning("%s failed to queue service startup job (Maybe the service file is missing or not a %s unit?): %s", UNIT(s)->id, cfd >= 0 ? "template" : "non-template", bus_error(&error, r)); + log_warning_unit(UNIT(s)->id, + "%s failed to queue service startup job (Maybe the service file is missing or not a %s unit?): %s", + UNIT(s)->id, + cfd >= 0 ? "template" : "non-template", + bus_error(&error, r)); socket_enter_stop_pre(s, SOCKET_FAILURE_RESOURCES); if (cfd >= 0) @@ -1579,7 +1620,9 @@ static void socket_run_next(Socket *s) { return; fail: - log_warning("%s failed to run next task: %s", UNIT(s)->id, strerror(-r)); + log_warning_unit(UNIT(s)->id, + "%s failed to run next task: %s", + UNIT(s)->id, strerror(-r)); if (s->state == SOCKET_START_POST) socket_enter_stop_pre(s, SOCKET_FAILURE_RESOURCES); @@ -1615,7 +1658,9 @@ static int socket_start(Unit *u) { service = SERVICE(UNIT_DEREF(s->service)); if (UNIT(service)->load_state != UNIT_LOADED) { - log_error("Socket service %s not loaded, refusing.", UNIT(service)->id); + log_error_unit(UNIT(service)->id, + "Socket service %s not loaded, refusing.", + UNIT(service)->id); return -ENOENT; } @@ -1624,13 +1669,16 @@ static int socket_start(Unit *u) { if (service->state != SERVICE_DEAD && service->state != SERVICE_FAILED && service->state != SERVICE_AUTO_RESTART) { - log_error("Socket service %s already active, refusing.", UNIT(service)->id); + log_error_unit(UNIT(service)->id, + "Socket service %s already active, refusing.", + UNIT(service)->id); return -EBUSY; } #ifdef HAVE_SYSV_COMPAT if (service->is_sysv) { - log_error("Using SysV services for socket activation is not supported. Refusing."); + log_error_unit(UNIT(s)->id, + "Using SysV services for socket activation is not supported. Refusing."); return -ENOENT; } #endif @@ -1737,7 +1785,8 @@ static int socket_deserialize_item(Unit *u, const char *key, const char *value, state = socket_state_from_string(value); if (state < 0) - log_debug("Failed to parse state value %s", value); + log_debug_unit(u->id, + "Failed to parse state value %s", value); else s->deserialized_state = state; } else if (streq(key, "result")) { @@ -1745,7 +1794,8 @@ static int socket_deserialize_item(Unit *u, const char *key, const char *value, f = socket_result_from_string(value); if (f < 0) - log_debug("Failed to parse result value %s", value); + log_debug_unit(u->id, + "Failed to parse result value %s", value); else if (f != SOCKET_SUCCESS) s->result = f; @@ -1753,21 +1803,25 @@ static int socket_deserialize_item(Unit *u, const char *key, const char *value, unsigned k; if (safe_atou(value, &k) < 0) - log_debug("Failed to parse n-accepted value %s", value); + log_debug_unit(u->id, + "Failed to parse n-accepted value %s", value); else s->n_accepted += k; } else if (streq(key, "control-pid")) { pid_t pid; if (parse_pid(value, &pid) < 0) - log_debug("Failed to parse control-pid value %s", value); + log_debug_unit(u->id, + "Failed to parse control-pid value %s", value); else s->control_pid = pid; } else if (streq(key, "control-command")) { SocketExecCommand id; - if ((id = socket_exec_command_from_string(value)) < 0) - log_debug("Failed to parse exec-command value %s", value); + id = socket_exec_command_from_string(value); + if (id < 0) + log_debug_unit(u->id, + "Failed to parse exec-command value %s", value); else { s->control_command_id = id; s->control_command = s->exec_command[id]; @@ -1777,7 +1831,8 @@ static int socket_deserialize_item(Unit *u, const char *key, const char *value, SocketPort *p; if (sscanf(value, "%i %n", &fd, &skip) < 1 || fd < 0 || !fdset_contains(fds, fd)) - log_debug("Failed to parse fifo value %s", value); + log_debug_unit(u->id, + "Failed to parse fifo value %s", value); else { LIST_FOREACH(port, p, s->ports) @@ -1797,7 +1852,8 @@ static int socket_deserialize_item(Unit *u, const char *key, const char *value, SocketPort *p; if (sscanf(value, "%i %n", &fd, &skip) < 1 || fd < 0 || !fdset_contains(fds, fd)) - log_debug("Failed to parse special value %s", value); + log_debug_unit(u->id, + "Failed to parse special value %s", value); else { LIST_FOREACH(port, p, s->ports) @@ -1817,7 +1873,8 @@ static int socket_deserialize_item(Unit *u, const char *key, const char *value, SocketPort *p; if (sscanf(value, "%i %n", &fd, &skip) < 1 || fd < 0 || !fdset_contains(fds, fd)) - log_debug("Failed to parse mqueue value %s", value); + log_debug_unit(u->id, + "Failed to parse mqueue value %s", value); else { LIST_FOREACH(port, p, s->ports) @@ -1837,7 +1894,8 @@ static int socket_deserialize_item(Unit *u, const char *key, const char *value, SocketPort *p; if (sscanf(value, "%i %i %n", &fd, &type, &skip) < 2 || fd < 0 || type < 0 || !fdset_contains(fds, fd)) - log_debug("Failed to parse socket value %s", value); + log_debug_unit(u->id, + "Failed to parse socket value %s", value); else { LIST_FOREACH(port, p, s->ports) @@ -1856,7 +1914,8 @@ static int socket_deserialize_item(Unit *u, const char *key, const char *value, SocketPort *p; if (sscanf(value, "%i %n", &fd, &skip) < 1 || fd < 0 || !fdset_contains(fds, fd)) - log_debug("Failed to parse socket value %s", value); + log_debug_unit(u->id, + "Failed to parse socket value %s", value); else { LIST_FOREACH(port, p, s->ports) @@ -1871,7 +1930,8 @@ static int socket_deserialize_item(Unit *u, const char *key, const char *value, } } else - log_debug("Unknown serialization key '%s'", key); + log_debug_unit(UNIT(s)->id, + "Unknown serialization key '%s'", key); return 0; } @@ -1934,14 +1994,18 @@ static void socket_fd_event(Unit *u, int fd, uint32_t events, Watch *w) { if (s->state != SOCKET_LISTENING) return; - log_debug("Incoming traffic on %s", u->id); + log_debug_unit(u->id, "Incoming traffic on %s", u->id); if (events != EPOLLIN) { if (events & EPOLLHUP) - log_error("%s: Got POLLHUP on a listening socket. The service probably invoked shutdown() on it, and should better not do that.", u->id); + log_error_unit(u->id, + "%s: Got POLLHUP on a listening socket. The service probably invoked shutdown() on it, and should better not do that.", + u->id); else - log_error("%s: Got unexpected poll event (0x%x) on socket.", u->id, events); + log_error_unit(u->id, + "%s: Got unexpected poll event (0x%x) on socket.", + u->id, events); goto fail; } @@ -1955,7 +2019,8 @@ static void socket_fd_event(Unit *u, int fd, uint32_t events, Watch *w) { if (errno == EINTR) continue; - log_error("Failed to accept socket: %m"); + log_error_unit(u->id, + "Failed to accept socket: %m"); goto fail; } @@ -2002,8 +2067,10 @@ static void socket_sigchld_event(Unit *u, pid_t pid, int code, int status) { f = SOCKET_SUCCESS; } - log_full(f == SOCKET_SUCCESS ? LOG_DEBUG : LOG_NOTICE, - "%s control process exited, code=%s status=%i", u->id, sigchld_code_to_string(code), status); + log_full_unit(f == SOCKET_SUCCESS ? LOG_DEBUG : LOG_NOTICE, + u->id, + "%s control process exited, code=%s status=%i", + u->id, sigchld_code_to_string(code), status); if (f != SOCKET_SUCCESS) s->result = f; @@ -2012,7 +2079,9 @@ static void socket_sigchld_event(Unit *u, pid_t pid, int code, int status) { s->control_command->command_next && f == SOCKET_SUCCESS) { - log_debug("%s running next command for state %s", u->id, socket_state_to_string(s->state)); + log_debug_unit(u->id, + "%s running next command for state %s", + u->id, socket_state_to_string(s->state)); socket_run_next(s); } else { s->control_command = NULL; @@ -2021,7 +2090,9 @@ static void socket_sigchld_event(Unit *u, pid_t pid, int code, int status) { /* No further commands for this step, so let's figure * out what to do next */ - log_debug("%s got final SIGCHLD for state %s", u->id, socket_state_to_string(s->state)); + log_debug_unit(u->id, + "%s got final SIGCHLD for state %s", + u->id, socket_state_to_string(s->state)); switch (s->state) { @@ -2070,52 +2141,65 @@ static void socket_timer_event(Unit *u, uint64_t elapsed, Watch *w) { switch (s->state) { case SOCKET_START_PRE: - log_warning("%s starting timed out. Terminating.", u->id); + log_warning_unit(u->id, + "%s starting timed out. Terminating.", u->id); socket_enter_signal(s, SOCKET_FINAL_SIGTERM, SOCKET_FAILURE_TIMEOUT); break; case SOCKET_START_POST: - log_warning("%s starting timed out. Stopping.", u->id); + log_warning_unit(u->id, + "%s starting timed out. Stopping.", u->id); socket_enter_stop_pre(s, SOCKET_FAILURE_TIMEOUT); break; case SOCKET_STOP_PRE: - log_warning("%s stopping timed out. Terminating.", u->id); + log_warning_unit(u->id, + "%s stopping timed out. Terminating.", u->id); socket_enter_signal(s, SOCKET_STOP_PRE_SIGTERM, SOCKET_FAILURE_TIMEOUT); break; case SOCKET_STOP_PRE_SIGTERM: if (s->kill_context.send_sigkill) { - log_warning("%s stopping timed out. Killing.", u->id); + log_warning_unit(u->id, + "%s stopping timed out. Killing.", u->id); socket_enter_signal(s, SOCKET_STOP_PRE_SIGKILL, SOCKET_FAILURE_TIMEOUT); } else { - log_warning("%s stopping timed out. Skipping SIGKILL. Ignoring.", u->id); + log_warning_unit(u->id, + "%s stopping timed out. Skipping SIGKILL. Ignoring.", + u->id); socket_enter_stop_post(s, SOCKET_FAILURE_TIMEOUT); } break; case SOCKET_STOP_PRE_SIGKILL: - log_warning("%s still around after SIGKILL. Ignoring.", u->id); + log_warning_unit(u->id, + "%s still around after SIGKILL. Ignoring.", u->id); socket_enter_stop_post(s, SOCKET_FAILURE_TIMEOUT); break; case SOCKET_STOP_POST: - log_warning("%s stopping timed out (2). Terminating.", u->id); + log_warning_unit(u->id, + "%s stopping timed out (2). Terminating.", u->id); socket_enter_signal(s, SOCKET_FINAL_SIGTERM, SOCKET_FAILURE_TIMEOUT); break; case SOCKET_FINAL_SIGTERM: if (s->kill_context.send_sigkill) { - log_warning("%s stopping timed out (2). Killing.", u->id); + log_warning_unit(u->id, + "%s stopping timed out (2). Killing.", u->id); socket_enter_signal(s, SOCKET_FINAL_SIGKILL, SOCKET_FAILURE_TIMEOUT); } else { - log_warning("%s stopping timed out (2). Skipping SIGKILL. Ignoring.", u->id); + log_warning_unit(u->id, + "%s stopping timed out (2). Skipping SIGKILL. Ignoring.", + u->id); socket_enter_dead(s, SOCKET_FAILURE_TIMEOUT); } break; case SOCKET_FINAL_SIGKILL: - log_warning("%s still around after SIGKILL (2). Entering failed mode.", u->id); + log_warning_unit(u->id, + "%s still around after SIGKILL (2). Entering failed mode.", + u->id); socket_enter_dead(s, SOCKET_FAILURE_TIMEOUT); break; @@ -2171,7 +2255,9 @@ void socket_notify_service_dead(Socket *s, bool failed_permanent) { * services. */ if (s->state == SOCKET_RUNNING) { - log_debug("%s got notified about service death (failed permanently: %s)", UNIT(s)->id, yes_no(failed_permanent)); + log_debug_unit(UNIT(s)->id, + "%s got notified about service death (failed permanently: %s)", + UNIT(s)->id, yes_no(failed_permanent)); if (failed_permanent) socket_enter_stop_pre(s, SOCKET_FAILURE_SERVICE_FAILED_PERMANENT); else @@ -2190,7 +2276,8 @@ void socket_connection_unref(Socket *s) { assert(s->n_connections > 0); s->n_connections--; - log_debug("%s: One connection closed, %u left.", UNIT(s)->id, s->n_connections); + log_debug_unit(UNIT(s)->id, + "%s: One connection closed, %u left.", UNIT(s)->id, s->n_connections); } static void socket_reset_failed(Unit *u) { diff --git a/src/core/swap.c b/src/core/swap.c index bd40516c99..c8e25d0665 100644 --- a/src/core/swap.c +++ b/src/core/swap.c @@ -225,12 +225,16 @@ static int swap_verify(Swap *s) { b = unit_has_name(UNIT(s), e); if (!b) { - log_error("%s: Value of \"What\" and unit name do not match, not loading.", UNIT(s)->id); + log_error_unit(UNIT(s)->id, + "%s: Value of \"What\" and unit name do not match, not loading.", + UNIT(s)->id); return -EINVAL; } if (s->exec_context.pam_name && s->kill_context.kill_mode != KILL_CONTROL_GROUP) { - log_error("%s has PAM enabled. Kill mode must be set to 'control-group'. Refusing to load.", UNIT(s)->id); + log_error_unit(UNIT(s)->id, + "%s has PAM enabled. Kill mode must be set to 'control-group'. Refusing to load.", + UNIT(s)->id); return -EINVAL; } @@ -398,7 +402,7 @@ static int swap_add_one( return 0; fail: - log_warning("Failed to load swap unit: %s", strerror(-r)); + log_warning_unit(e, "Failed to load swap unit: %s", strerror(-r)); free(wp); @@ -483,10 +487,11 @@ static void swap_set_state(Swap *s, SwapState state) { } if (state != old_state) - log_debug("%s changed %s -> %s", - UNIT(s)->id, - swap_state_to_string(old_state), - swap_state_to_string(state)); + log_debug_unit(UNIT(s)->id, + "%s changed %s -> %s", + UNIT(s)->id, + swap_state_to_string(old_state), + swap_state_to_string(state)); unit_notify(UNIT(s), state_translation_table[old_state], state_translation_table[state], true); @@ -656,7 +661,9 @@ static void swap_enter_signal(Swap *s, SwapState state, SwapResult f) { if (s->control_pid > 0) { if (kill_and_sigcont(s->control_pid, sig) < 0 && errno != ESRCH) - log_warning("Failed to kill control process %li: %m", (long) s->control_pid); + log_warning_unit(UNIT(s)->id, + "Failed to kill control process %li: %m", + (long) s->control_pid); else wait_for_exit = true; } @@ -679,7 +686,8 @@ static void swap_enter_signal(Swap *s, SwapState state, SwapResult f) { r = cgroup_bonding_kill_list(UNIT(s)->cgroup_bondings, sig, true, false, pid_set, NULL); if (r < 0) { if (r != -EAGAIN && r != -ESRCH && r != -ENOENT) - log_warning("Failed to kill control group: %s", strerror(-r)); + log_warning_unit(UNIT(s)->id, + "Failed to kill control group: %s", strerror(-r)); } else if (r > 0) wait_for_exit = true; @@ -700,7 +708,8 @@ static void swap_enter_signal(Swap *s, SwapState state, SwapResult f) { return; fail: - log_warning("%s failed to kill processes: %s", UNIT(s)->id, strerror(-r)); + log_warning_unit(UNIT(s)->id, + "%s failed to kill processes: %s", UNIT(s)->id, strerror(-r)); swap_enter_dead(s, SWAP_FAILURE_RESOURCES); @@ -755,7 +764,9 @@ static void swap_enter_activating(Swap *s) { return; fail: - log_warning("%s failed to run 'swapon' task: %s", UNIT(s)->id, strerror(-r)); + log_warning_unit(UNIT(s)->id, + "%s failed to run 'swapon' task: %s", + UNIT(s)->id, strerror(-r)); swap_enter_dead(s, SWAP_FAILURE_RESOURCES); } @@ -785,7 +796,9 @@ static void swap_enter_deactivating(Swap *s) { return; fail: - log_warning("%s failed to run 'swapoff' task: %s", UNIT(s)->id, strerror(-r)); + log_warning_unit(UNIT(s)->id, + "%s failed to run 'swapoff' task: %s", + UNIT(s)->id, strerror(-r)); swap_enter_active(s, SWAP_FAILURE_RESOURCES); } @@ -869,7 +882,7 @@ static int swap_deserialize_item(Unit *u, const char *key, const char *value, FD state = swap_state_from_string(value); if (state < 0) - log_debug("Failed to parse state value %s", value); + log_debug_unit(u->id, "Failed to parse state value %s", value); else s->deserialized_state = state; } else if (streq(key, "result")) { @@ -877,14 +890,14 @@ static int swap_deserialize_item(Unit *u, const char *key, const char *value, FD f = swap_result_from_string(value); if (f < 0) - log_debug("Failed to parse result value %s", value); + log_debug_unit(u->id, "Failed to parse result value %s", value); else if (f != SWAP_SUCCESS) s->result = f; } else if (streq(key, "control-pid")) { pid_t pid; if (parse_pid(value, &pid) < 0) - log_debug("Failed to parse control-pid value %s", value); + log_debug_unit(u->id, "Failed to parse control-pid value %s", value); else s->control_pid = pid; @@ -893,14 +906,14 @@ static int swap_deserialize_item(Unit *u, const char *key, const char *value, FD id = swap_exec_command_from_string(value); if (id < 0) - log_debug("Failed to parse exec-command value %s", value); + log_debug_unit(u->id, "Failed to parse exec-command value %s", value); else { s->control_command_id = id; s->control_command = s->exec_command + id; } } else - log_debug("Unknown serialization key '%s'", key); + log_debug_unit(u->id, "Unknown serialization key '%s'", key); return 0; } @@ -958,8 +971,10 @@ static void swap_sigchld_event(Unit *u, pid_t pid, int code, int status) { s->control_command_id = _SWAP_EXEC_COMMAND_INVALID; } - log_full(f == SWAP_SUCCESS ? LOG_DEBUG : LOG_NOTICE, - "%s swap process exited, code=%s status=%i", u->id, sigchld_code_to_string(code), status); + log_full_unit(f == SWAP_SUCCESS ? LOG_DEBUG : LOG_NOTICE, + u->id, + "%s swap process exited, code=%s status=%i", + u->id, sigchld_code_to_string(code), status); switch (s->state) { @@ -1005,38 +1020,38 @@ static void swap_timer_event(Unit *u, uint64_t elapsed, Watch *w) { switch (s->state) { case SWAP_ACTIVATING: - log_warning("%s activation timed out. Stopping.", u->id); + log_warning_unit(u->id, "%s activation timed out. Stopping.", u->id); swap_enter_signal(s, SWAP_ACTIVATING_SIGTERM, SWAP_FAILURE_TIMEOUT); break; case SWAP_DEACTIVATING: - log_warning("%s deactivation timed out. Stopping.", u->id); + log_warning_unit(u->id, "%s deactivation timed out. Stopping.", u->id); swap_enter_signal(s, SWAP_DEACTIVATING_SIGTERM, SWAP_FAILURE_TIMEOUT); break; case SWAP_ACTIVATING_SIGTERM: if (s->kill_context.send_sigkill) { - log_warning("%s activation timed out. Killing.", u->id); + log_warning_unit(u->id, "%s activation timed out. Killing.", u->id); swap_enter_signal(s, SWAP_ACTIVATING_SIGKILL, SWAP_FAILURE_TIMEOUT); } else { - log_warning("%s activation timed out. Skipping SIGKILL. Ignoring.", u->id); + log_warning_unit(u->id, "%s activation timed out. Skipping SIGKILL. Ignoring.", u->id); swap_enter_dead(s, SWAP_FAILURE_TIMEOUT); } break; case SWAP_DEACTIVATING_SIGTERM: if (s->kill_context.send_sigkill) { - log_warning("%s deactivation timed out. Killing.", u->id); + log_warning_unit(u->id, "%s deactivation timed out. Killing.", u->id); swap_enter_signal(s, SWAP_DEACTIVATING_SIGKILL, SWAP_FAILURE_TIMEOUT); } else { - log_warning("%s deactivation timed out. Skipping SIGKILL. Ignoring.", u->id); + log_warning_unit(u->id, "%s deactivation timed out. Skipping SIGKILL. Ignoring.", u->id); swap_enter_dead(s, SWAP_FAILURE_TIMEOUT); } break; case SWAP_ACTIVATING_SIGKILL: case SWAP_DEACTIVATING_SIGKILL: - log_warning("%s swap process still around after SIGKILL. Ignoring.", u->id); + log_warning_unit(u->id, "%s swap process still around after SIGKILL. Ignoring.", u->id); swap_enter_dead(s, SWAP_FAILURE_TIMEOUT); break; diff --git a/src/core/timer.c b/src/core/timer.c index bd27970449..31ef176e7e 100644 --- a/src/core/timer.c +++ b/src/core/timer.c @@ -76,7 +76,8 @@ static int timer_verify(Timer *t) { return 0; if (!t->values) { - log_error("%s lacks value setting. Refusing.", UNIT(t)->id); + log_error_unit(UNIT(t)->id, + "%s lacks value setting. Refusing.", UNIT(t)->id); return -EINVAL; } @@ -187,10 +188,10 @@ static void timer_set_state(Timer *t, TimerState state) { } if (state != old_state) - log_debug("%s changed %s -> %s", - UNIT(t)->id, - timer_state_to_string(old_state), - timer_state_to_string(state)); + log_debug_unit(UNIT(t)->id, + "%s changed %s -> %s", UNIT(t)->id, + timer_state_to_string(old_state), + timer_state_to_string(state)); unit_notify(UNIT(t), state_translation_table[old_state], state_translation_table[state], true); } @@ -312,14 +313,17 @@ static void timer_enter_waiting(Timer *t, bool initial) { } if (!found_monotonic && !found_realtime) { - log_debug("%s: Timer is elapsed.", UNIT(t)->id); + log_debug_unit(UNIT(t)->id, "%s: Timer is elapsed.", UNIT(t)->id); timer_set_state(t, TIMER_ELAPSED); return; } if (found_monotonic) { char buf[FORMAT_TIMESPAN_MAX]; - log_debug("%s: Monotonic timer elapses in %s the next time.", UNIT(t)->id, format_timespan(buf, sizeof(buf), t->next_elapse_monotonic - ts.monotonic)); + log_debug_unit(UNIT(t)->id, + "%s: Monotonic timer elapses in %s the next time.", + UNIT(t)->id, + format_timespan(buf, sizeof(buf), t->next_elapse_monotonic - ts.monotonic)); r = unit_watch_timer(UNIT(t), CLOCK_MONOTONIC, false, t->next_elapse_monotonic, &t->monotonic_watch); if (r < 0) @@ -329,7 +333,10 @@ static void timer_enter_waiting(Timer *t, bool initial) { if (found_realtime) { char buf[FORMAT_TIMESTAMP_MAX]; - log_debug("%s: Realtime timer elapses at %s the next time.", UNIT(t)->id, format_timestamp(buf, sizeof(buf), t->next_elapse_realtime)); + log_debug_unit(UNIT(t)->id, + "%s: Realtime timer elapses at %s the next time.", + UNIT(t)->id, + format_timestamp(buf, sizeof(buf), t->next_elapse_realtime)); r = unit_watch_timer(UNIT(t), CLOCK_REALTIME, false, t->next_elapse_realtime, &t->realtime_watch); if (r < 0) @@ -341,7 +348,9 @@ static void timer_enter_waiting(Timer *t, bool initial) { return; fail: - log_warning("%s failed to enter waiting state: %s", UNIT(t)->id, strerror(-r)); + log_warning_unit(UNIT(t)->id, + "%s failed to enter waiting state: %s", + UNIT(t)->id, strerror(-r)); timer_enter_dead(t, TIMER_FAILURE_RESOURCES); } @@ -364,7 +373,9 @@ static void timer_enter_running(Timer *t) { return; fail: - log_warning("%s failed to queue unit startup job: %s", UNIT(t)->id, bus_error(&error, r)); + log_warning_unit(UNIT(t)->id, + "%s failed to queue unit startup job: %s", + UNIT(t)->id, bus_error(&error, r)); timer_enter_dead(t, TIMER_FAILURE_RESOURCES); dbus_error_free(&error); @@ -420,7 +431,7 @@ static int timer_deserialize_item(Unit *u, const char *key, const char *value, F state = timer_state_from_string(value); if (state < 0) - log_debug("Failed to parse state value %s", value); + log_debug_unit(u->id, "Failed to parse state value %s", value); else t->deserialized_state = state; } else if (streq(key, "result")) { @@ -428,12 +439,12 @@ static int timer_deserialize_item(Unit *u, const char *key, const char *value, F f = timer_result_from_string(value); if (f < 0) - log_debug("Failed to parse result value %s", value); + log_debug_unit(u->id, "Failed to parse result value %s", value); else if (f != TIMER_SUCCESS) t->result = f; } else - log_debug("Unknown serialization key '%s'", key); + log_debug_unit(u->id, "Unknown serialization key '%s'", key); return 0; } @@ -459,7 +470,7 @@ static void timer_timer_event(Unit *u, uint64_t elapsed, Watch *w) { if (t->state != TIMER_WAITING) return; - log_debug("Timer elapsed on %s", u->id); + log_debug_unit(u->id, "Timer elapsed on %s", u->id); timer_enter_running(t); } @@ -500,7 +511,9 @@ void timer_unit_notify(Unit *u, UnitActiveState new_state) { case TIMER_RUNNING: if (UNIT_IS_INACTIVE_OR_FAILED(new_state)) { - log_debug("%s got notified about unit deactivation.", UNIT(t)->id); + log_debug_unit(UNIT(t)->id, + "%s got notified about unit deactivation.", + UNIT(t)->id); timer_enter_waiting(t, false); } @@ -535,7 +548,8 @@ static void timer_time_change(Unit *u) { if (t->state != TIMER_WAITING) return; - log_info("%s: time change, recalculating next elapse.", u->id); + log_info_unit(u->id, + "%s: time change, recalculating next elapse.", u->id); timer_enter_waiting(t, false); } diff --git a/src/core/transaction.c b/src/core/transaction.c index ee6992a81a..1854047afd 100644 --- a/src/core/transaction.c +++ b/src/core/transaction.c @@ -186,8 +186,14 @@ static int delete_one_unmergeable_job(Transaction *tr, Job *j) { * another unit in which case we * rather remove the start. */ - log_debug("Looking at job %s/%s conflicted_by=%s", j->unit->id, job_type_to_string(j->type), yes_no(j->type == JOB_STOP && job_is_conflicted_by(j))); - log_debug("Looking at job %s/%s conflicted_by=%s", k->unit->id, job_type_to_string(k->type), yes_no(k->type == JOB_STOP && job_is_conflicted_by(k))); + log_debug_unit(j->unit->id, + "Looking at job %s/%s conflicted_by=%s", + j->unit->id, job_type_to_string(j->type), + yes_no(j->type == JOB_STOP && job_is_conflicted_by(j))); + log_debug_unit(k->unit->id, + "Looking at job %s/%s conflicted_by=%s", + k->unit->id, job_type_to_string(k->type), + yes_no(k->type == JOB_STOP && job_is_conflicted_by(k))); if (j->type == JOB_STOP) { @@ -213,7 +219,9 @@ static int delete_one_unmergeable_job(Transaction *tr, Job *j) { return -ENOEXEC; /* Ok, we can drop one, so let's do so. */ - log_debug("Fixing conflicting jobs by deleting job %s/%s", d->unit->id, job_type_to_string(d->type)); + log_debug_unit(d->unit->id, + "Fixing conflicting jobs by deleting job %s/%s", + d->unit->id, job_type_to_string(d->type)); transaction_delete_job(tr, d, true); return 0; } @@ -352,12 +360,17 @@ static int transaction_verify_order_one(Transaction *tr, Job *j, Job *from, unsi * job to remove. We use the marker to find our way * back, since smart how we are we stored our way back * in there. */ - log_warning("Found ordering cycle on %s/%s", j->unit->id, job_type_to_string(j->type)); + log_warning_unit(j->unit->id, + "Found ordering cycle on %s/%s", + j->unit->id, job_type_to_string(j->type)); delete = NULL; for (k = from; k; k = ((k->generation == generation && k->marker != k) ? k->marker : NULL)) { - log_info("Walked on cycle path to %s/%s", k->unit->id, job_type_to_string(k->type)); + /* logging for j not k here here to provide consistent narrative */ + log_info_unit(j->unit->id, + "Walked on cycle path to %s/%s", + k->unit->id, job_type_to_string(k->type)); if (!delete && !unit_matters_to_anchor(k->unit, k)) { @@ -374,15 +387,24 @@ static int transaction_verify_order_one(Transaction *tr, Job *j, Job *from, unsi if (delete) { - log_error("Breaking ordering cycle by deleting job %s/%s", delete->unit->id, job_type_to_string(delete->type)); - status_printf(ANSI_HIGHLIGHT_RED_ON " SKIP " ANSI_HIGHLIGHT_OFF, true, "Ordering cycle found, skip %s", unit_description(delete->unit)); + /* logging for j not k here here to provide consistent narrative */ + log_warning_unit(j->unit->id, + "Breaking ordering cycle by deleting job %s/%s", + delete->unit->id, job_type_to_string(delete->type)); + log_error_unit(delete->unit->id, + "Job %s/%s deleted to break ordering cycle starting with %s/%s", + delete->unit->id, job_type_to_string(delete->type), + j->unit->id, job_type_to_string(j->type)); + status_printf(ANSI_HIGHLIGHT_RED_ON " SKIP " ANSI_HIGHLIGHT_OFF, true, + "Ordering cycle found, skipping %s", unit_description(delete->unit)); transaction_delete_unit(tr, delete->unit); return -EAGAIN; } log_error("Unable to break cycle"); - dbus_set_error(e, BUS_ERROR_TRANSACTION_ORDER_IS_CYCLIC, "Transaction order is cyclic. See system logs for details."); + dbus_set_error(e, BUS_ERROR_TRANSACTION_ORDER_IS_CYCLIC, + "Transaction order is cyclic. See system logs for details."); return -ENOEXEC; } @@ -525,13 +547,19 @@ rescan: continue; if (stops_running_service) - log_debug("%s/%s would stop a running service.", j->unit->id, job_type_to_string(j->type)); + log_debug_unit(j->unit->id, + "%s/%s would stop a running service.", + j->unit->id, job_type_to_string(j->type)); if (changes_existing_job) - log_debug("%s/%s would change existing job.", j->unit->id, job_type_to_string(j->type)); + log_debug_unit(j->unit->id, + "%s/%s would change existing job.", + j->unit->id, job_type_to_string(j->type)); /* Ok, let's get rid of this */ - log_debug("Deleting %s/%s to minimize impact.", j->unit->id, job_type_to_string(j->type)); + log_debug_unit(j->unit->id, + "Deleting %s/%s to minimize impact.", + j->unit->id, job_type_to_string(j->type)); transaction_delete_job(tr, j, true); goto rescan; @@ -783,9 +811,10 @@ static void transaction_unlink_job(Transaction *tr, Job *j, bool delete_dependen job_dependency_free(j->object_list); if (other && delete_dependencies) { - log_debug("Deleting job %s/%s as dependency of job %s/%s", - other->unit->id, job_type_to_string(other->type), - j->unit->id, job_type_to_string(j->type)); + log_debug_unit(other->unit->id, + "Deleting job %s/%s as dependency of job %s/%s", + other->unit->id, job_type_to_string(other->type), + j->unit->id, job_type_to_string(j->type)); transaction_delete_job(tr, other, delete_dependencies); } } @@ -871,7 +900,9 @@ int transaction_add_job_and_dependencies( SET_FOREACH(dep, following, i) { r = transaction_add_job_and_dependencies(tr, type, dep, ret, false, override, false, false, ignore_order, e); if (r < 0) { - log_warning("Cannot add dependency job for unit %s, ignoring: %s", dep->id, bus_error(e, r)); + log_warning_unit(dep->id, + "Cannot add dependency job for unit %s, ignoring: %s", + dep->id, bus_error(e, r)); if (e) dbus_error_free(e); @@ -908,8 +939,9 @@ int transaction_add_job_and_dependencies( SET_FOREACH(dep, ret->unit->dependencies[UNIT_REQUIRES_OVERRIDABLE], i) { r = transaction_add_job_and_dependencies(tr, JOB_START, dep, ret, !override, override, false, false, ignore_order, e); if (r < 0) { - log_full(r == -EADDRNOTAVAIL ? LOG_DEBUG : LOG_WARNING, - "Cannot add dependency job for unit %s, ignoring: %s", dep->id, bus_error(e, r)); + log_full_unit(r == -EADDRNOTAVAIL ? LOG_DEBUG : LOG_WARNING, dep->id, + "Cannot add dependency job for unit %s, ignoring: %s", + dep->id, bus_error(e, r)); if (e) dbus_error_free(e); @@ -919,8 +951,9 @@ int transaction_add_job_and_dependencies( SET_FOREACH(dep, ret->unit->dependencies[UNIT_WANTS], i) { r = transaction_add_job_and_dependencies(tr, JOB_START, dep, ret, false, false, false, false, ignore_order, e); if (r < 0) { - log_full(r == -EADDRNOTAVAIL ? LOG_DEBUG : LOG_WARNING, - "Cannot add dependency job for unit %s, ignoring: %s", dep->id, bus_error(e, r)); + log_full_unit(r == -EADDRNOTAVAIL ? LOG_DEBUG : LOG_WARNING, dep->id, + "Cannot add dependency job for unit %s, ignoring: %s", + dep->id, bus_error(e, r)); if (e) dbus_error_free(e); @@ -941,8 +974,9 @@ int transaction_add_job_and_dependencies( SET_FOREACH(dep, ret->unit->dependencies[UNIT_REQUISITE_OVERRIDABLE], i) { r = transaction_add_job_and_dependencies(tr, JOB_VERIFY_ACTIVE, dep, ret, !override, override, false, false, ignore_order, e); if (r < 0) { - log_full(r == -EADDRNOTAVAIL ? LOG_DEBUG : LOG_WARNING, - "Cannot add dependency job for unit %s, ignoring: %s", dep->id, bus_error(e, r)); + log_full_unit(r == -EADDRNOTAVAIL ? LOG_DEBUG : LOG_WARNING, dep->id, + "Cannot add dependency job for unit %s, ignoring: %s", + dep->id, bus_error(e, r)); if (e) dbus_error_free(e); @@ -963,7 +997,9 @@ int transaction_add_job_and_dependencies( SET_FOREACH(dep, ret->unit->dependencies[UNIT_CONFLICTED_BY], i) { r = transaction_add_job_and_dependencies(tr, JOB_STOP, dep, ret, false, override, false, false, ignore_order, e); if (r < 0) { - log_warning("Cannot add dependency job for unit %s, ignoring: %s", dep->id, bus_error(e, r)); + log_warning_unit(dep->id, + "Cannot add dependency job for unit %s, ignoring: %s", + dep->id, bus_error(e, r)); if (e) dbus_error_free(e); @@ -1014,7 +1050,9 @@ int transaction_add_job_and_dependencies( SET_FOREACH(dep, ret->unit->dependencies[UNIT_PROPAGATES_RELOAD_TO], i) { r = transaction_add_job_and_dependencies(tr, JOB_RELOAD, dep, ret, false, override, false, false, ignore_order, e); if (r < 0) { - log_warning("Cannot add dependency reload job for unit %s, ignoring: %s", dep->id, bus_error(e, r)); + log_warning_unit(dep->id, + "Cannot add dependency reload job for unit %s, ignoring: %s", + dep->id, bus_error(e, r)); if (e) dbus_error_free(e); @@ -1059,7 +1097,9 @@ int transaction_add_isolate_jobs(Transaction *tr, Manager *m) { r = transaction_add_job_and_dependencies(tr, JOB_STOP, u, tr->anchor_job, true, false, false, false, false, NULL); if (r < 0) - log_warning("Cannot add isolate job for unit %s, ignoring: %s", u->id, strerror(-r)); + log_warning_unit(u->id, + "Cannot add isolate job for unit %s, ignoring: %s", + u->id, strerror(-r)); } return 0; |