core,network: major per-object logging rework

This changes log_unit_info() (and friends) to take a real Unit* object
insted of just a unit name as parameter. The call will now prefix all
logged messages with the unit name, thus allowing the unit name to be
dropped from the various passed romat strings, simplifying invocations
drastically, and unifying log output across messages. Also, UNIT= vs.
USER_UNIT= is now derived from the Manager object attached to the Unit
object, instead of getpid(). This has the benefit of correcting the
field for --test runs.

Also contains a couple of other logging improvements:

- Drops a couple of strerror() invocations in favour of using %m.

- Not only .mount units now warn if a symlinks exist for the mount
  point already, .automount units do that too, now.

- A few invocations of log_struct() that didn't actually pass any
  additional structured data have been replaced by simpler invocations
  of log_unit_info() and friends.

- For structured data a new LOG_UNIT_MESSAGE() macro has been added,
  that works like LOG_MESSAGE() but prefixes the message with the unit
  name. Similar, there's now LOG_LINK_MESSAGE() and
  LOG_NETDEV_MESSAGE().

- For structured data new LOG_UNIT_ID(), LOG_LINK_INTERFACE(),
  LOG_NETDEV_INTERFACE() macros have been added that generate the
  necessary per object fields. The old log_unit_struct() call has been
  removed in favour of these new macros used in raw log_struct()
  invocations. In addition to removing one more function call this
  allows generated structured log messages that contain two object
  fields, as necessary for example for network interfaces that are
  joined into another network interface, and whose messages shall be
  indexed by both.

- The LOG_ERRNO() macro has been removed, in favour of
  log_struct_errno(). The latter has the benefit of ensuring that %m in
  format strings is properly resolved to the specified error number.

- A number of logging messages have been converted to use
  log_unit_info() instead of log_info()

- The client code in sysv-generator no longer #includes core code from
  src/core/.

- log_unit_full_errno() has been removed, log_unit_full() instead takes
  an errno now, too.

- log_unit_info(), log_link_info(), log_netdev_info() and friends, now
  avoid double evaluation of their parameters

1 files changed, 30 insertions, 36 deletions

diff --git a/src/core/busname.c b/src/core/busname.c
index 3dc6e87e55..2010ec0985 100644
--- a/src/core/busname.c
+++ b/src/core/busname.c
@@ -208,13 +208,13 @@ static int busname_verify(BusName *n) {
                 return 0;
 
         if (!service_name_is_valid(n->name)) {
-                log_unit_error(UNIT(n)->id, "%s's Name= setting is not a valid service name Refusing.", UNIT(n)->id);
+                log_unit_error(UNIT(n), "Name= setting is not a valid service name Refusing.");
                 return -EINVAL;
         }
 
         e = strjoina(n->name, ".busname");
         if (!unit_has_name(UNIT(n), e)) {
-                log_unit_error(UNIT(n)->id, "%s's Name= setting doesn't match unit name. Refusing.", UNIT(n)->id);
+                log_unit_error(UNIT(n), "Name= setting doesn't match unit name. Refusing.");
                 return -EINVAL;
         }
 
@@ -276,7 +276,7 @@ static void busname_unwatch_fd(BusName *n) {
 
         r = sd_event_source_set_enabled(n->starter_event_source, SD_EVENT_OFF);
         if (r < 0)
-                log_unit_debug(UNIT(n)->id, "Failed to disable event source.");
+                log_unit_debug_errno(UNIT(n), r, "Failed to disable event source: %m");
 }
 
 static int busname_watch_fd(BusName *n) {
@@ -293,7 +293,7 @@ static int busname_watch_fd(BusName *n) {
                 r = sd_event_add_io(UNIT(n)->manager->event, &n->starter_event_source, n->starter_fd, EPOLLIN, busname_dispatch_io, n);
 
         if (r < 0) {
-                log_unit_warning_errno(UNIT(n)->id, r, "Failed to watch starter fd: %m");
+                log_unit_warning_errno(UNIT(n), r, "Failed to watch starter fd: %m");
                 busname_unwatch_fd(n);
                 return r;
         }
@@ -315,7 +315,7 @@ static int busname_open_fd(BusName *n) {
         mode = UNIT(n)->manager->running_as == SYSTEMD_SYSTEM ? "system" : "user";
         n->starter_fd = bus_kernel_open_bus_fd(mode, &path);
         if (n->starter_fd < 0)
-                return log_unit_warning_errno(UNIT(n)->id, n->starter_fd, "Failed to open %s: %m", path ?: "kdbus");
+                return log_unit_warning_errno(UNIT(n), n->starter_fd, "Failed to open %s: %m", path ?: "kdbus");
 
         return 0;
 }
@@ -339,8 +339,7 @@ static void busname_set_state(BusName *n, BusNameState state) {
                 busname_close_fd(n);
 
         if (state != old_state)
-                log_unit_debug(UNIT(n)->id, "%s changed %s -> %s",
-                               UNIT(n)->id, busname_state_to_string(old_state), busname_state_to_string(state));
+                log_unit_debug(UNIT(n), "Changed %s -> %s", busname_state_to_string(old_state), busname_state_to_string(state));
 
         unit_notify(UNIT(n), state_translation_table[old_state], state_translation_table[state], true);
 }
@@ -462,14 +461,14 @@ static void busname_enter_signal(BusName *n, BusNameState state, BusNameResult f
                               n->control_pid,
                               false);
         if (r < 0) {
-                log_unit_warning_errno(UNIT(n)->id, r, "%s failed to kill control process: %m", UNIT(n)->id);
+                log_unit_warning_errno(UNIT(n), r, "Failed to kill control process: %m");
                 goto fail;
         }
 
         if (r > 0) {
                 r = busname_arm_timer(n);
                 if (r < 0) {
-                        log_unit_warning_errno(UNIT(n)->id, r, "%s failed to arm timer: %m", UNIT(n)->id);
+                        log_unit_warning_errno(UNIT(n), r, "Failed to arm timer: %m");
                         goto fail;
                 }
 
@@ -493,7 +492,7 @@ static void busname_enter_listening(BusName *n) {
         if (n->activating) {
                 r = busname_watch_fd(n);
                 if (r < 0) {
-                        log_unit_warning_errno(UNIT(n)->id, r, "%s failed to watch names: %m", UNIT(n)->id);
+                        log_unit_warning_errno(UNIT(n), r, "Failed to watch names: %m");
                         goto fail;
                 }
 
@@ -524,7 +523,7 @@ static void busname_enter_making(BusName *n) {
 
                 r = busname_make_starter(n, &n->control_pid);
                 if (r < 0) {
-                        log_unit_warning_errno(UNIT(n)->id, r, "%s failed to fork 'making' task: %m", UNIT(n)->id);
+                        log_unit_warning_errno(UNIT(n), r, "Failed to fork 'making' task: %m");
                         goto fail;
                 }
 
@@ -535,7 +534,7 @@ static void busname_enter_making(BusName *n) {
 
                 r = bus_kernel_make_starter(n->starter_fd, n->name, n->activating, n->accept_fd, NULL, n->policy_world);
                 if (r < 0) {
-                        log_unit_warning_errno(UNIT(n)->id, r, "%s failed to make starter: %m", UNIT(n)->id);
+                        log_unit_warning_errno(UNIT(n), r, "Failed to make starter: %m");
                         goto fail;
                 }
 
@@ -564,7 +563,7 @@ static void busname_enter_running(BusName *n) {
          * shut down anyway */
 
         if (unit_stop_pending(UNIT(n))) {
-                log_unit_debug(UNIT(n)->id, "Suppressing activation request on %s since unit stop is scheduled.", UNIT(n)->id);
+                log_unit_debug(UNIT(n), "Suppressing activation request since unit stop is scheduled.");
 
                 /* Flush all queued activation reqeuest by closing and reopening the connection */
                 bus_kernel_drop_one(n->starter_fd);
@@ -591,7 +590,7 @@ static void busname_enter_running(BusName *n) {
         return;
 
 fail:
-        log_unit_warning(UNIT(n)->id, "%s failed to queue service startup job: %s", UNIT(n)->id, bus_error_message(&error, r));
+        log_unit_warning(UNIT(n), "Failed to queue service startup job: %s", bus_error_message(&error, r));
         busname_enter_dead(n, BUSNAME_FAILURE_RESOURCES);
 }
 
@@ -615,7 +614,7 @@ static int busname_start(Unit *u) {
                 service = SERVICE(UNIT_DEREF(n->service));
 
                 if (UNIT(service)->load_state != UNIT_LOADED) {
-                        log_unit_error(u->id, "Bus service %s not loaded, refusing.", UNIT(service)->id);
+                        log_unit_error(u, "Bus service %s not loaded, refusing.", UNIT(service)->id);
                         return -ENOENT;
                 }
         }
@@ -689,7 +688,7 @@ static int busname_deserialize_item(Unit *u, const char *key, const char *value,
 
                 state = busname_state_from_string(value);
                 if (state < 0)
-                        log_unit_debug(u->id, "Failed to parse state value %s", value);
+                        log_unit_debug(u, "Failed to parse state value: %s", value);
                 else
                         n->deserialized_state = state;
 
@@ -698,7 +697,7 @@ static int busname_deserialize_item(Unit *u, const char *key, const char *value,
 
                 f = busname_result_from_string(value);
                 if (f < 0)
-                        log_unit_debug(u->id, "Failed to parse result value %s", value);
+                        log_unit_debug(u, "Failed to parse result value: %s", value);
                 else if (f != BUSNAME_SUCCESS)
                         n->result = f;
 
@@ -706,20 +705,20 @@ static int busname_deserialize_item(Unit *u, const char *key, const char *value,
                 pid_t pid;
 
                 if (parse_pid(value, &pid) < 0)
-                        log_unit_debug(u->id, "Failed to parse control-pid value %s", value);
+                        log_unit_debug(u, "Failed to parse control-pid value: %s", value);
                 else
                         n->control_pid = pid;
         } else if (streq(key, "starter-fd")) {
                 int fd;
 
                 if (safe_atoi(value, &fd) < 0 || fd < 0 || !fdset_contains(fds, fd))
-                        log_unit_debug(u->id, "Failed to parse starter fd value %s", value);
+                        log_unit_debug(u, "Failed to parse starter fd value: %s", value);
                 else {
                         safe_close(n->starter_fd);
                         n->starter_fd = fdset_remove(fds, fd);
                 }
         } else
-                log_unit_debug(u->id, "Unknown serialization key '%s'", key);
+                log_unit_debug(u, "Unknown serialization key: %s", key);
 
         return 0;
 }
@@ -769,8 +768,7 @@ static int busname_peek_message(BusName *n) {
                 if (errno == EINTR || errno == EAGAIN)
                         return 0;
 
-                log_unit_error(UNIT(n)->id, "%s: Failed to query activation message: %m", UNIT(n)->id);
-                return -errno;
+                return log_unit_error_errno(UNIT(n), errno, "Failed to query activation message: %m");
         }
 
         /* We map as late as possible, and unmap imemdiately after
@@ -786,8 +784,7 @@ static int busname_peek_message(BusName *n) {
 
         p = mmap(NULL, sz, PROT_READ, MAP_SHARED, n->starter_fd, start);
         if (p == MAP_FAILED) {
-                log_unit_error(UNIT(n)->id, "%s: Failed to map activation message: %m", UNIT(n)->id);
-                r = -errno;
+                r = log_unit_error_errno(UNIT(n), errno, "Failed to map activation message: %m");
                 goto finish;
         }
 
@@ -806,7 +803,7 @@ static int busname_peek_message(BusName *n) {
         }
 
         if (pid > 0)
-                log_unit_debug(UNIT(n)->id, "%s: Activation triggered by process " PID_FMT " (%s)", UNIT(n)->id, pid, strna(comm));
+                log_unit_debug(UNIT(n), "Activation triggered by process " PID_FMT " (%s)", pid, strna(comm));
 
         r = 0;
 
@@ -816,7 +813,7 @@ finish:
 
         cmd_free.offset = cmd_recv.msg.offset;
         if (ioctl(n->starter_fd, KDBUS_CMD_FREE, &cmd_free) < 0)
-                log_unit_warning(UNIT(n)->id, "Failed to free peeked message, ignoring: %m");
+                log_unit_warning(UNIT(n), "Failed to free peeked message, ignoring: %m");
 
         return r;
 }
@@ -830,11 +827,10 @@ static int busname_dispatch_io(sd_event_source *source, int fd, uint32_t revents
         if (n->state != BUSNAME_LISTENING)
                 return 0;
 
-        log_unit_debug(UNIT(n)->id, "Activation request on %s", UNIT(n)->id);
+        log_unit_debug(UNIT(n), "Activation request");
 
         if (revents != EPOLLIN) {
-                log_unit_error(UNIT(n)->id, "%s: Got unexpected poll event (0x%x) on starter fd.",
-                               UNIT(n)->id, revents);
+                log_unit_error(UNIT(n), "Got unexpected poll event (0x%x) on starter fd.", revents);
                 goto fail;
         }
 
@@ -870,10 +866,8 @@ static void busname_sigchld_event(Unit *u, pid_t pid, int code, int status) {
         else
                 assert_not_reached("Unknown sigchld code");
 
-        log_unit_full(u->id,
-                      f == BUSNAME_SUCCESS ? LOG_DEBUG : LOG_NOTICE,
-                      "%s control process exited, code=%s status=%i",
-                      u->id, sigchld_code_to_string(code), status);
+        log_unit_full(u, f == BUSNAME_SUCCESS ? LOG_DEBUG : LOG_NOTICE, 0,
+                      "Control process exited, code=%s status=%i", sigchld_code_to_string(code), status);
 
         if (f != BUSNAME_SUCCESS)
                 n->result = f;
@@ -909,17 +903,17 @@ static int busname_dispatch_timer(sd_event_source *source, usec_t usec, void *us
         switch (n->state) {
 
         case BUSNAME_MAKING:
-                log_unit_warning(UNIT(n)->id, "%s making timed out. Terminating.", UNIT(n)->id);
+                log_unit_warning(UNIT(n), "Making timed out. Terminating.");
                 busname_enter_signal(n, BUSNAME_SIGTERM, BUSNAME_FAILURE_TIMEOUT);
                 break;
 
         case BUSNAME_SIGTERM:
-                log_unit_warning(UNIT(n)->id, "%s stopping timed out. Killing.", UNIT(n)->id);
+                log_unit_warning(UNIT(n), "Stopping timed out. Killing.");
                 busname_enter_signal(n, BUSNAME_SIGKILL, BUSNAME_FAILURE_TIMEOUT);
                 break;
 
         case BUSNAME_SIGKILL:
-                log_unit_warning(UNIT(n)->id, "%s still around after SIGKILL. Ignoring.", UNIT(n)->id);
+                log_unit_warning(UNIT(n), "Processes still around after SIGKILL. Ignoring.");
                 busname_enter_dead(n, BUSNAME_FAILURE_TIMEOUT);
                 break;