From 38d1555d7c32c52506a456635453c536bf0ec724 Mon Sep 17 00:00:00 2001 From: Yu Watanabe Date: Thu, 1 Nov 2018 16:12:46 +0900 Subject: [PATCH 1/8] sd-device: drop subsystem from log_device_*() The sd_device object always has syspath and sysname, but subsytem may not. Also, it may take some costs to get subsystem. So, let's drop subsystem from logs. --- src/libsystemd/sd-device/device-util.h | 8 +++----- 1 file changed, 3 insertions(+), 5 deletions(-) diff --git a/src/libsystemd/sd-device/device-util.h b/src/libsystemd/sd-device/device-util.h index e25350edc59..94f6174bff9 100644 --- a/src/libsystemd/sd-device/device-util.h +++ b/src/libsystemd/sd-device/device-util.h @@ -33,17 +33,15 @@ #define log_device_full(device, level, error, ...) \ ({ \ - const char *_sysname = NULL, *_subsystem = NULL; \ + const char *_sysname = NULL; \ sd_device *_d = (device); \ int _level = (level), _error = (error); \ \ - if (_d && _unlikely_(log_get_max_level() >= _level)) { \ + if (_d && _unlikely_(log_get_max_level() >= _level)) \ (void) sd_device_get_sysname(_d, &_sysname); \ - (void) sd_device_get_subsystem(_d, &_subsystem); \ - } \ log_object_internal(_level, _error, __FILE__, __LINE__, __func__, \ _sysname ? "DEVICE=" : NULL, _sysname, \ - _subsystem ? "SUBSYSTEM=" : NULL, _subsystem, ##__VA_ARGS__); \ + NULL, NULL, ##__VA_ARGS__); \ }) #define log_device_debug(device, ...) log_device_full(device, LOG_DEBUG, 0, ##__VA_ARGS__) From c7d54daef939602001bebabe087e73e3c48cea48 Mon Sep 17 00:00:00 2001 From: Yu Watanabe Date: Thu, 1 Nov 2018 16:15:50 +0900 Subject: [PATCH 2/8] sd-device: normalize debug messages --- src/libsystemd/sd-device/device-enumerator.c | 27 +++++----- src/libsystemd/sd-device/device-monitor.c | 52 ++++++++++---------- src/libsystemd/sd-device/device-private.c | 52 ++++++++++---------- src/libsystemd/sd-device/sd-device.c | 38 +++++++------- 4 files changed, 84 insertions(+), 85 deletions(-) diff --git a/src/libsystemd/sd-device/device-enumerator.c b/src/libsystemd/sd-device/device-enumerator.c index 8329a3f909a..20529aafd36 100644 --- a/src/libsystemd/sd-device/device-enumerator.c +++ b/src/libsystemd/sd-device/device-enumerator.c @@ -554,7 +554,7 @@ static int enumerator_scan_dir(sd_device_enumerator *enumerator, const char *bas if (!dir) return -errno; - log_debug(" device-enumerator: scanning %s", path); + log_debug("sd-device-enumerator: Scanning %s", path); FOREACH_DIRENT_ALL(dent, dir, return -errno) { int k; @@ -586,10 +586,9 @@ static int enumerator_scan_devices_tag(sd_device_enumerator *enumerator, const c dir = opendir(path); if (!dir) { - if (errno == ENOENT) - return 0; - else - return log_error_errno(errno, "sd-device-enumerator: could not open tags directory %s: %m", path); + if (errno != ENOENT) + return log_debug_errno(errno, "sd-device-enumerator: Failed to open tags directory %s: %m", path); + return 0; } /* TODO: filter away subsystems? */ @@ -714,7 +713,7 @@ static int parent_crawl_children(sd_device_enumerator *enumerator, const char *p dir = opendir(path); if (!dir) - return log_debug_errno(errno, "sd-device-enumerate: could not open parent directory %s: %m", path); + return log_debug_errno(errno, "sd-device-enumerator: Failed to open parent directory %s: %m", path); FOREACH_DIRENT_ALL(dent, dir, return -errno) { _cleanup_free_ char *child = NULL; @@ -737,7 +736,7 @@ static int parent_crawl_children(sd_device_enumerator *enumerator, const char *p if (maxdepth > 0) parent_crawl_children(enumerator, child, maxdepth - 1); else - log_debug("device-enumerate: max depth reached, %s: ignoring devices", child); + log_debug("sd-device-enumerator: Max depth reached, %s: ignoring devices", child); } return r; @@ -765,25 +764,25 @@ static int enumerator_scan_devices_children(sd_device_enumerator *enumerator) { static int enumerator_scan_devices_all(sd_device_enumerator *enumerator) { int r = 0; - log_debug("device-enumerator: scan all dirs"); + log_debug("sd-device-enumerator: Scan all dirs"); if (access("/sys/subsystem", F_OK) >= 0) { /* we have /subsystem/, forget all the old stuff */ r = enumerator_scan_dir(enumerator, "subsystem", "devices", NULL); if (r < 0) - return log_debug_errno(r, "device-enumerator: failed to scan /sys/subsystem: %m"); + return log_debug_errno(r, "sd-device-enumerator: Failed to scan /sys/subsystem: %m"); } else { int k; k = enumerator_scan_dir(enumerator, "bus", "devices", NULL); if (k < 0) { - log_debug_errno(k, "device-enumerator: failed to scan /sys/bus: %m"); + log_debug_errno(k, "sd-device-enumerator: Failed to scan /sys/bus: %m"); r = k; } k = enumerator_scan_dir(enumerator, "class", NULL, NULL); if (k < 0) { - log_debug_errno(k, "device-enumerator: failed to scan /sys/class: %m"); + log_debug_errno(k, "sd-device-enumerator: Failed to scan /sys/class: %m"); r = k; } } @@ -904,7 +903,7 @@ int device_enumerator_scan_subsystems(sd_device_enumerator *enumerator) { if (match_subsystem(enumerator, "module")) { k = enumerator_scan_dir_and_add_devices(enumerator, "module", NULL, NULL); if (k < 0) { - log_debug_errno(k, "device-enumerator: failed to scan modules: %m"); + log_debug_errno(k, "sd-device-enumerator: Failed to scan modules: %m"); r = k; } } @@ -918,7 +917,7 @@ int device_enumerator_scan_subsystems(sd_device_enumerator *enumerator) { if (match_subsystem(enumerator, "subsystem")) { k = enumerator_scan_dir_and_add_devices(enumerator, subsysdir, NULL, NULL); if (k < 0) { - log_debug_errno(k, "device-enumerator: failed to scan subsystems: %m"); + log_debug_errno(k, "sd-device-enumerator: Failed to scan subsystems: %m"); r = k; } } @@ -927,7 +926,7 @@ int device_enumerator_scan_subsystems(sd_device_enumerator *enumerator) { if (match_subsystem(enumerator, "drivers")) { k = enumerator_scan_dir(enumerator, subsysdir, "drivers", "drivers"); if (k < 0) { - log_debug_errno(k, "device-enumerator: failed to scan drivers: %m"); + log_debug_errno(k, "sd-device-enumerator: Failed to scan drivers: %m"); r = k; } } diff --git a/src/libsystemd/sd-device/device-monitor.c b/src/libsystemd/sd-device/device-monitor.c index f79a8497bae..ea8231aa638 100644 --- a/src/libsystemd/sd-device/device-monitor.c +++ b/src/libsystemd/sd-device/device-monitor.c @@ -140,14 +140,14 @@ int device_monitor_new_full(sd_device_monitor **ret, MonitorNetlinkGroup group, * will not receive any messages. */ - log_debug("The udev service seems not to be active, disabling the monitor"); + log_debug("sd-device-monitor: The udev service seems not to be active, disabling the monitor"); group = MONITOR_GROUP_NONE; } if (fd < 0) { sock = socket(PF_NETLINK, SOCK_RAW|SOCK_CLOEXEC|SOCK_NONBLOCK, NETLINK_KOBJECT_UEVENT); if (sock < 0) - return log_debug_errno(errno, "Failed to create socket: %m"); + return log_debug_errno(errno, "sd-device-monitor: Failed to create socket: %m"); } m = new(sd_device_monitor, 1); @@ -165,7 +165,7 @@ int device_monitor_new_full(sd_device_monitor **ret, MonitorNetlinkGroup group, if (fd >= 0) { r = monitor_set_nl_address(m); if (r < 0) - return log_debug_errno(r, "Failed to set netlink address: %m"); + return log_debug_errno(r, "sd-device-monitor: Failed to set netlink address: %m"); } *ret = TAKE_PTR(m); @@ -280,24 +280,24 @@ int device_monitor_enable_receiving(sd_device_monitor *m) { if (!m->filter_uptodate) { r = sd_device_monitor_filter_update(m); if (r < 0) - return log_debug_errno(r, "Failed to update filter: %m"); + return log_debug_errno(r, "sd-device-monitor: Failed to update filter: %m"); } if (!m->bound) { if (bind(m->sock, &m->snl.sa, sizeof(struct sockaddr_nl)) < 0) - return log_debug_errno(errno, "Failed to bind monitoring socket to event source: %m"); + return log_debug_errno(errno, "sd-device-monitor: Failed to bind monitoring socket to event source: %m"); m->bound = true; } r = monitor_set_nl_address(m); if (r < 0) - return log_debug_errno(r, "Failed to set address: %m"); + return log_debug_errno(r, "sd-device-monitor: Failed to set address: %m"); /* enable receiving of sender credentials */ r = setsockopt_int(m->sock, SOL_SOCKET, SO_PASSCRED, true); if (r < 0) - return log_debug_errno(r, "Failed to set socket option SO_PASSCRED: %m"); + return log_debug_errno(r, "sd-device-monitor: Failed to set socket option SO_PASSCRED: %m"); return 0; } @@ -392,40 +392,40 @@ int device_monitor_receive_device(sd_device_monitor *m, sd_device **ret) { buflen = recvmsg(m->sock, &smsg, 0); if (buflen < 0) { if (errno != EINTR) - log_debug_errno(errno, "Failed to receive message: %m"); + log_debug_errno(errno, "sd-device-monitor: Failed to receive message: %m"); return -errno; } if (buflen < 32 || (smsg.msg_flags & MSG_TRUNC)) - return log_debug_errno(EINVAL, "Invalid message length."); + return log_debug_errno(EINVAL, "sd-device-monitor: Invalid message length."); if (snl.nl.nl_groups == MONITOR_GROUP_NONE) { /* unicast message, check if we trust the sender */ if (m->snl_trusted_sender.nl.nl_pid == 0 || snl.nl.nl_pid != m->snl_trusted_sender.nl.nl_pid) - return log_debug_errno(EAGAIN, "Unicast netlink message ignored."); + return log_debug_errno(EAGAIN, "sd-device-monitor: Unicast netlink message ignored."); } else if (snl.nl.nl_groups == MONITOR_GROUP_KERNEL) { if (snl.nl.nl_pid > 0) - return log_debug_errno(EAGAIN, "Multicast kernel netlink message from PID %"PRIu32" ignored.", snl.nl.nl_pid); + return log_debug_errno(EAGAIN, "sd-device-monitor: Multicast kernel netlink message from PID %"PRIu32" ignored.", snl.nl.nl_pid); } cmsg = CMSG_FIRSTHDR(&smsg); if (!cmsg || cmsg->cmsg_type != SCM_CREDENTIALS) - return log_debug_errno(EAGAIN, "No sender credentials received, message ignored."); + return log_debug_errno(EAGAIN, "sd-device-monitor: No sender credentials received, message ignored."); cred = (struct ucred*) CMSG_DATA(cmsg); if (cred->uid != 0) - return log_debug_errno(EAGAIN, "Sender uid="UID_FMT", message ignored.", cred->uid); + return log_debug_errno(EAGAIN, "sd-device-monitor: Sender uid="UID_FMT", message ignored.", cred->uid); if (streq(buf.raw, "libudev")) { /* udev message needs proper version magic */ if (buf.nlh.magic != htobe32(UDEV_MONITOR_MAGIC)) - return log_debug_errno(EAGAIN, "Invalid message signature (%x != %x)", + return log_debug_errno(EAGAIN, "sd-device-monitor: Invalid message signature (%x != %x)", buf.nlh.magic, htobe32(UDEV_MONITOR_MAGIC)); if (buf.nlh.properties_off+32 > (size_t) buflen) - return log_debug_errno(EAGAIN, "Invalid message length (%u > %zd)", + return log_debug_errno(EAGAIN, "sd-device-monitor: Invalid message length (%u > %zd)", buf.nlh.properties_off+32, buflen); bufpos = buf.nlh.properties_off; @@ -437,16 +437,16 @@ int device_monitor_receive_device(sd_device_monitor *m, sd_device **ret) { /* kernel message with header */ bufpos = strlen(buf.raw) + 1; if ((size_t) bufpos < sizeof("a@/d") || bufpos >= buflen) - return log_debug_errno(EAGAIN, "Invalid message length"); + return log_debug_errno(EAGAIN, "sd-device-monitor: Invalid message length"); /* check message header */ if (!strstr(buf.raw, "@/")) - return log_debug_errno(EAGAIN, "Invalid message header"); + return log_debug_errno(EAGAIN, "sd-device-monitor: Invalid message header"); } r = device_new_from_nulstr(&device, (uint8_t*) &buf.raw[bufpos], buflen - bufpos); if (r < 0) - return log_debug_errno(r, "Failed to create device: %m"); + return log_debug_errno(r, "sd-device-monitor: Failed to create device from received message: %m"); if (is_initialized) device_set_is_initialized(device); @@ -454,9 +454,9 @@ int device_monitor_receive_device(sd_device_monitor *m, sd_device **ret) { /* Skip device, if it does not pass the current filter */ r = passes_filter(m, device); if (r < 0) - return log_device_debug_errno(device, r, "Failed to check received device passing filter: %m"); + return log_device_debug_errno(device, r, "sd-device-monitor: Failed to check received device passing filter: %m"); if (r == 0) - log_device_debug(device, "Received device does not pass filter, ignoring"); + log_device_debug(device, "sd-device-monitor: Received device does not pass filter, ignoring"); else *ret = TAKE_PTR(device); @@ -512,16 +512,16 @@ int device_monitor_send_device( r = device_get_properties_nulstr(device, (const uint8_t **) &buf, &blen); if (r < 0) - return log_debug_errno(r, "Failed to get device properties: %m"); + return log_device_debug_errno(device, r, "sd-device-monitor: Failed to get device properties: %m"); if (blen < 32) { - log_debug("Device buffer is too small to contain a valid device"); + log_device_debug(device, "sd-device-monitor: Length of device property nulstr is too small to contain valid device information"); return -EINVAL; } /* fill in versioned header */ r = sd_device_get_subsystem(device, &val); if (r < 0) - return log_device_debug_errno(device, r, "Failed to get device subsystem: %m"); + return log_device_debug_errno(device, r, "sd-device-monitor: Failed to get device subsystem: %m"); nlh.filter_subsystem_hash = htobe32(string_hash32(val)); if (sd_device_get_devtype(device, &val) >= 0) @@ -556,13 +556,13 @@ int device_monitor_send_device( count = sendmsg(m->sock, &smsg, 0); if (count < 0) { if (!destination && errno == ECONNREFUSED) { - log_device_debug(device, "Passed to netlink monitor"); + log_device_debug(device, "sd-device-monitor: Passed to netlink monitor"); return 0; } else - return log_device_debug_errno(device, errno, "Failed to send device to netlink monitor: %m"); + return log_device_debug_errno(device, errno, "sd-device-monitor: Failed to send device to netlink monitor: %m"); } - log_device_debug(device, "Passed %zi byte to netlink monitor", count); + log_device_debug(device, "sd-device-monitor: Passed %zi byte to netlink monitor", count); return count; } diff --git a/src/libsystemd/sd-device/device-private.c b/src/libsystemd/sd-device/device-private.c index 0bd31216bf7..fa0829885aa 100644 --- a/src/libsystemd/sd-device/device-private.c +++ b/src/libsystemd/sd-device/device-private.c @@ -115,7 +115,7 @@ static int handle_db_line(sd_device *device, char key, const char *value) { break; default: - log_debug("device db: unknown key '%c'", key); + log_device_debug(device, "sd-device: Unknown key '%c' in device db, ignoring", key); } return 0; @@ -189,7 +189,7 @@ static int device_read_db(sd_device *device) { if (r == -ENOENT) return 0; else - return log_debug_errno(r, "sd-device: failed to read db '%s': %m", path); + return log_device_debug_errno(device, r, "sd-device: Failed to read db '%s': %m", path); } /* devices with a database entry are initialized */ @@ -207,7 +207,7 @@ static int device_read_db(sd_device *device) { break; case KEY: if (db[i] != ':') { - log_debug("sd-device: ignoring invalid db entry with key '%c'", key); + log_device_debug(device, "sd-device: Invalid db entry with key '%c', ignoring", key); state = INVALID_LINE; } else { @@ -233,14 +233,14 @@ static int device_read_db(sd_device *device) { db[i] = '\0'; r = handle_db_line(device, key, value); if (r < 0) - log_debug_errno(r, "sd-device: failed to handle db entry '%c:%s': %m", key, value); + log_device_debug_errno(device, r, "sd-device: Failed to handle db entry '%c:%s', ignoring: %m", key, value); state = PRE_KEY; } break; default: - assert_not_reached("invalid state when parsing db"); + assert_not_reached("Invalid state when parsing db"); } } @@ -376,43 +376,43 @@ static int device_amend(sd_device *device, const char *key, const char *value) { /* the caller must verify or trust this data (e.g., if it comes from the kernel) */ r = device_set_syspath(device, path, false); if (r < 0) - return log_debug_errno(r, "sd-device: could not set syspath to '%s': %m", path); + return log_device_debug_errno(device, r, "sd-device: Failed to set syspath to '%s': %m", path); } else if (streq(key, "SUBSYSTEM")) { r = device_set_subsystem(device, value); if (r < 0) - return log_debug_errno(r, "sd-device: could not set subsystem to '%s': %m", value); + return log_device_debug_errno(device, r, "sd-device: Failed to set subsystem to '%s': %m", value); } else if (streq(key, "DEVTYPE")) { r = device_set_devtype(device, value); if (r < 0) - return log_debug_errno(r, "sd-device: could not set devtype to '%s': %m", value); + return log_device_debug_errno(device, r, "sd-device: Failed to set devtype to '%s': %m", value); } else if (streq(key, "DEVNAME")) { r = device_set_devname(device, value); if (r < 0) - return log_debug_errno(r, "sd-device: could not set devname to '%s': %m", value); + return log_device_debug_errno(device, r, "sd-device: Failed to set devname to '%s': %m", value); } else if (streq(key, "USEC_INITIALIZED")) { r = device_set_usec_initialized(device, value); if (r < 0) - return log_debug_errno(r, "sd-device: could not set usec-initialized to '%s': %m", value); + return log_device_debug_errno(device, r, "sd-device: Failed to set usec-initialized to '%s': %m", value); } else if (streq(key, "DRIVER")) { r = device_set_driver(device, value); if (r < 0) - return log_debug_errno(r, "sd-device: could not set driver to '%s': %m", value); + return log_device_debug_errno(device, r, "sd-device: Failed to set driver to '%s': %m", value); } else if (streq(key, "IFINDEX")) { r = device_set_ifindex(device, value); if (r < 0) - return log_debug_errno(r, "sd-device: could not set ifindex to '%s': %m", value); + return log_device_debug_errno(device, r, "sd-device: Failed to set ifindex to '%s': %m", value); } else if (streq(key, "DEVMODE")) { r = device_set_devmode(device, value); if (r < 0) - return log_debug_errno(r, "sd-device: could not set devmode to '%s': %m", value); + return log_device_debug_errno(device, r, "sd-device: Failed to set devmode to '%s': %m", value); } else if (streq(key, "DEVUID")) { r = device_set_devuid(device, value); if (r < 0) - return log_debug_errno(r, "sd-device: could not set devuid to '%s': %m", value); + return log_device_debug_errno(device, r, "sd-device: Failed to set devuid to '%s': %m", value); } else if (streq(key, "DEVGID")) { r = device_set_devgid(device, value); if (r < 0) - return log_debug_errno(r, "sd-device: could not set devgid to '%s': %m", value); + return log_device_debug_errno(device, r, "sd-device: Failed to set devgid to '%s': %m", value); } else if (streq(key, "DEVLINKS")) { const char *word, *state; size_t l; @@ -425,7 +425,7 @@ static int device_amend(sd_device *device, const char *key, const char *value) { r = device_add_devlink(device, devlink); if (r < 0) - return log_debug_errno(r, "sd-device: could not add devlink '%s': %m", devlink); + return log_device_debug_errno(device, r, "sd-device: Failed to add devlink '%s': %m", devlink); } } else if (streq(key, "TAGS")) { const char *word, *state; @@ -439,12 +439,12 @@ static int device_amend(sd_device *device, const char *key, const char *value) { r = device_add_tag(device, tag); if (r < 0) - return log_debug_errno(r, "sd-device: could not add tag '%s': %m", tag); + return log_device_debug_errno(device, r, "sd-device: Failed to add tag '%s': %m", tag); } } else { r = device_add_property_internal(device, key, value); if (r < 0) - return log_debug_errno(r, "sd-device: could not add property '%s=%s': %m", key, value); + return log_device_debug_errno(device, r, "sd-device: Failed to add property '%s=%s': %m", key, value); } return 0; @@ -480,7 +480,7 @@ static int device_append(sd_device *device, char *key, const char **_major, cons value = strchr(key, '='); if (!value) { - log_debug("sd-device: not a key-value pair: '%s'", key); + log_device_debug(device, "sd-device: Not a key-value pair: '%s'", key); return -EINVAL; } @@ -536,7 +536,7 @@ static int device_verify(sd_device *device, DeviceAction action, uint64_t seqnum assert(device); if (!device->devpath || !device->subsystem || action == _DEVICE_ACTION_INVALID || seqnum == 0) { - log_debug("sd-device: device created from strv lacks devpath, subsystem, action or seqnum"); + log_device_debug(device, "sd-device: Device created from strv or nulstr lacks devpath, subsystem, action or seqnum."); return -EINVAL; } @@ -569,7 +569,7 @@ int device_new_from_strv(sd_device **ret, char **strv) { if (major) { r = device_set_devnum(device, major, minor); if (r < 0) - return log_debug_errno(r, "sd-device: could not set devnum %s:%s: %m", major, minor); + return log_device_debug_errno(device, r, "sd-device: Failed to set devnum %s:%s: %m", major, minor); } r = device_verify(device, action, seqnum); @@ -604,7 +604,7 @@ int device_new_from_nulstr(sd_device **ret, uint8_t *nulstr, size_t len) { key = (char*)&nulstr[i]; end = memchr(key, '\0', len - i); if (!end) { - log_debug("sd-device: failed to parse nulstr"); + log_device_debug(device, "sd-device: Failed to parse nulstr"); return -EINVAL; } i += end - key + 1; @@ -617,7 +617,7 @@ int device_new_from_nulstr(sd_device **ret, uint8_t *nulstr, size_t len) { if (major) { r = device_set_devnum(device, major, minor); if (r < 0) - return log_debug_errno(r, "sd-device: could not set devnum %s:%s: %m", major, minor); + return log_device_debug_errno(device, r, "sd-device: Failed to set devnum %s:%s: %m", major, minor); } r = device_verify(device, action, seqnum); @@ -1083,8 +1083,8 @@ int device_update_db(sd_device *device) { goto fail; } - log_debug("created %s file '%s' for '%s'", has_info ? "db" : "empty", - path, device->devpath); + log_device_debug(device, "sd-device: Created %s file '%s' for '%s'", has_info ? "db" : "empty", + path, device->devpath); return 0; @@ -1092,7 +1092,7 @@ fail: (void) unlink(path); (void) unlink(path_tmp); - return log_error_errno(r, "failed to create %s file '%s' for '%s'", has_info ? "db" : "empty", path, device->devpath); + return log_device_debug_errno(device, r, "sd-device: Failed to create %s file '%s' for '%s'", has_info ? "db" : "empty", path, device->devpath); } int device_delete_db(sd_device *device) { diff --git a/src/libsystemd/sd-device/sd-device.c b/src/libsystemd/sd-device/sd-device.c index d0f5e1efcf5..480754edaec 100644 --- a/src/libsystemd/sd-device/sd-device.c +++ b/src/libsystemd/sd-device/sd-device.c @@ -138,7 +138,7 @@ int device_set_syspath(sd_device *device, const char *_syspath, bool verify) { /* must be a subdirectory of /sys */ if (!path_startswith(_syspath, "/sys/")) { - log_debug("sd-device: syspath '%s' is not a subdirectory of /sys", _syspath); + log_debug("sd-device: Syspath '%s' is not a subdirectory of /sys", _syspath); return -EINVAL; } @@ -147,7 +147,7 @@ int device_set_syspath(sd_device *device, const char *_syspath, bool verify) { if (r == -ENOENT) return -ENODEV; /* the device does not exist (any more?) */ if (r < 0) - return log_debug_errno(r, "sd-device: could not get target of '%s': %m", _syspath); + return log_debug_errno(r, "sd-device: Failed to get target of '%s': %m", _syspath); if (!path_startswith(syspath, "/sys")) { _cleanup_free_ char *real_sys = NULL, *new_syspath = NULL; @@ -156,17 +156,17 @@ int device_set_syspath(sd_device *device, const char *_syspath, bool verify) { /* /sys is a symlink to somewhere sysfs is mounted on? In that case, we convert the path to real sysfs to "/sys". */ r = chase_symlinks("/sys", NULL, 0, &real_sys); if (r < 0) - return log_debug_errno(r, "sd-device: could not chase symlink /sys: %m"); + return log_debug_errno(r, "sd-device: Failed to chase symlink /sys: %m"); p = path_startswith(syspath, real_sys); if (!p) { - log_debug("sd-device: canonicalized path '%s' does not starts with sysfs mount point '%s'", syspath, real_sys); + log_debug("sd-device: Canonicalized path '%s' does not starts with sysfs mount point '%s'", syspath, real_sys); return -ENODEV; } new_syspath = strjoin("/sys/", p); if (!new_syspath) - return log_oom(); + return -ENOMEM; free_and_replace(syspath, new_syspath); path_simplify(syspath, false); @@ -513,7 +513,7 @@ int device_read_uevent_file(sd_device *device) { /* some devices may not have uevent files, see set_syspath() */ return 0; else if (r < 0) - return log_debug_errno(r, "sd-device: failed to read uevent file '%s': %m", path); + return log_device_debug_errno(device, r, "sd-device: Failed to read uevent file '%s': %m", path); for (i = 0; i < uevent_len; i++) switch (state) { @@ -532,7 +532,7 @@ int device_read_uevent_file(sd_device *device) { state = PRE_VALUE; } else if (strchr(NEWLINE, uevent[i])) { uevent[i] = '\0'; - log_debug("sd-device: ignoring invalid uevent line '%s'", key); + log_device_debug(device, "sd-device: Invalid uevent line '%s', ignoring", key); state = PRE_KEY; } @@ -549,20 +549,20 @@ int device_read_uevent_file(sd_device *device) { r = handle_uevent_line(device, key, value, &major, &minor); if (r < 0) - log_debug_errno(r, "sd-device: failed to handle uevent entry '%s=%s': %m", key, value); + log_device_debug_errno(device, r, "sd-device: Failed to handle uevent entry '%s=%s', ignoring: %m", key, value); state = PRE_KEY; } break; default: - assert_not_reached("invalid state when parsing uevent file"); + assert_not_reached("Invalid state when parsing uevent file"); } if (major) { r = device_set_devnum(device, major, minor); if (r < 0) - log_debug_errno(r, "sd-device: could not set 'MAJOR=%s' or 'MINOR=%s' from '%s': %m", major, minor, path); + log_device_debug_errno(device, r, "sd-device: Failed to set 'MAJOR=%s' or 'MINOR=%s' from '%s', ignoring: %m", major, minor, path); } return 0; @@ -798,7 +798,7 @@ _public_ int sd_device_get_subsystem(sd_device *device, const char **ret) { path_startswith(device->devpath, "/bus/"))) r = device_set_subsystem(device, "subsystem"); if (r < 0 && r != -ENOENT) - return log_debug_errno(r, "sd-device: could not set subsystem for %s: %m", device->devpath); + return log_device_debug_errno(device, r, "sd-device: Failed to set subsystem for %s: %m", device->devpath); device->subsystem_set = true; } else if (!device->driver_subsystem_set) @@ -821,7 +821,7 @@ _public_ int sd_device_get_subsystem(sd_device *device, const char **ret) { r = device_set_drivers_subsystem(device, subsys + 1); } if (r < 0 && r != -ENOENT) - return log_debug_errno(r, "sd-device: could not set subsystem for driver %s: %m", device->devpath); + return log_device_debug_errno(device, r, "sd-device: Failed to set subsystem for driver %s: %m", device->devpath); } device->driver_subsystem_set = true; @@ -944,11 +944,11 @@ _public_ int sd_device_get_driver(sd_device *device, const char **ret) { if (r >= 0) { r = device_set_driver(device, driver); if (r < 0) - return log_debug_errno(r, "sd-device: could not set driver for %s: %m", device->devpath); + return log_device_debug_errno(device, r, "sd-device: Failed to set driver for %s: %m", device->devpath); } else if (r == -ENOENT) device->driver_set = true; else - return log_debug_errno(r, "sd-device: could not set driver for %s: %m", device->devpath); + return log_device_debug_errno(device, r, "sd-device: Failed to set driver for %s: %m", device->devpath); } if (!device->driver) @@ -1211,7 +1211,7 @@ static int handle_db_line(sd_device *device, char key, const char *value) { break; default: - log_debug("device db: unknown key '%c'", key); + log_device_debug(device, "sd-device: Unknown key '%c' in device db, ignoring", key); } return 0; @@ -1312,7 +1312,7 @@ int device_read_db_aux(sd_device *device, bool force) { if (r == -ENOENT) return 0; else - return log_debug_errno(r, "sd-device: failed to read db '%s': %m", path); + return log_device_debug_errno(device, r, "sd-device: Failed to read db '%s': %m", path); } /* devices with a database entry are initialized */ @@ -1330,7 +1330,7 @@ int device_read_db_aux(sd_device *device, bool force) { break; case KEY: if (db[i] != ':') { - log_debug("sd-device: ignoring invalid db entry with key '%c'", key); + log_device_debug(device, "sd-device: Invalid db entry with key '%c', ignoring", key); state = INVALID_LINE; } else { @@ -1356,14 +1356,14 @@ int device_read_db_aux(sd_device *device, bool force) { db[i] = '\0'; r = handle_db_line(device, key, value); if (r < 0) - log_debug_errno(r, "sd-device: failed to handle db entry '%c:%s': %m", key, value); + log_device_debug_errno(device, r, "sd-device: Failed to handle db entry '%c:%s', ignoring: %m", key, value); state = PRE_KEY; } break; default: - assert_not_reached("invalid state when parsing db"); + assert_not_reached("Invalid state when parsing db"); } } From ecbe9873a9c36aa7ad7dbcb60f44a2c796854cac Mon Sep 17 00:00:00 2001 From: Yu Watanabe Date: Wed, 31 Oct 2018 10:01:11 +0900 Subject: [PATCH 3/8] test: show name of testing functions in test-sd-device --- src/libsystemd/sd-device/test-sd-device.c | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/src/libsystemd/sd-device/test-sd-device.c b/src/libsystemd/sd-device/test-sd-device.c index 25ed3ecfea3..2e933cfed40 100644 --- a/src/libsystemd/sd-device/test-sd-device.c +++ b/src/libsystemd/sd-device/test-sd-device.c @@ -12,6 +12,8 @@ static void test_sd_device_basic(void) { _cleanup_(sd_device_enumerator_unrefp) sd_device_enumerator *e = NULL; sd_device *d; + log_info("/* %s */", __func__); + assert_se(sd_device_enumerator_new(&e) >= 0); assert_se(sd_device_enumerator_allow_uninitialized(e) >= 0); FOREACH_DEVICE(e, d) { @@ -91,6 +93,8 @@ static void test_sd_device_enumerator_filter_subsystem(void) { Hashmap *h; char *s; + log_info("/* %s */", __func__); + assert_se(subsystems = hashmap_new(&string_hash_ops)); assert_se(sd_device_enumerator_new(&e) >= 0); From 754d6c26b46d4960e37afb2413af63707b7ae87a Mon Sep 17 00:00:00 2001 From: Yu Watanabe Date: Wed, 31 Oct 2018 10:01:45 +0900 Subject: [PATCH 4/8] test: show is_initialized flag in log message of test-sd-device And drop devpath, as it is redundant for most cases. --- src/libsystemd/sd-device/test-sd-device.c | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/src/libsystemd/sd-device/test-sd-device.c b/src/libsystemd/sd-device/test-sd-device.c index 2e933cfed40..e523206b61a 100644 --- a/src/libsystemd/sd-device/test-sd-device.c +++ b/src/libsystemd/sd-device/test-sd-device.c @@ -17,7 +17,7 @@ static void test_sd_device_basic(void) { assert_se(sd_device_enumerator_new(&e) >= 0); assert_se(sd_device_enumerator_allow_uninitialized(e) >= 0); FOREACH_DEVICE(e, d) { - const char *syspath, *devpath, *subsystem, *val; + const char *syspath, *subsystem, *val; dev_t devnum; usec_t usec; int i, r; @@ -39,7 +39,7 @@ static void test_sd_device_basic(void) { r = sd_device_get_driver(d, &val); assert_se(r >= 0 || r == -ENOENT); - assert_se(sd_device_get_devpath(d, &devpath) >= 0); + assert_se(sd_device_get_devpath(d, &val) >= 0); r = sd_device_get_devname(d, &val); assert_se(r >= 0 || r == -ENOENT); @@ -49,9 +49,9 @@ static void test_sd_device_basic(void) { r = sd_device_get_sysnum(d, &val); assert_se(r >= 0 || r == -ENOENT); - r = sd_device_get_is_initialized(d); - assert_se(r >= 0); - if (r > 0) { + i = sd_device_get_is_initialized(d); + assert_se(i >= 0); + if (i > 0) { r = sd_device_get_usec_since_initialized(d, &usec); assert_se(r >= 0 || r == -ENODATA); } @@ -62,7 +62,7 @@ static void test_sd_device_basic(void) { r = sd_device_get_property_value(d, "ID_NET_DRIVER", &val); assert_se(r >= 0 || r == -ENOENT); - log_debug("syspath:%s devpath:%s subsystem:%s", syspath, devpath, strempty(subsystem)); + log_debug("subsystem:%s syspath:%s initialized:%s", strna(subsystem), syspath, yes_no(i)); } } From a5db6debcdc4de4381a878bd832a57041d86c41e Mon Sep 17 00:00:00 2001 From: Yu Watanabe Date: Wed, 31 Oct 2018 14:47:50 +0900 Subject: [PATCH 5/8] test: check returned value of sd_device_get_usec_since_initialized() --- src/libsystemd/sd-device/test-sd-device.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/libsystemd/sd-device/test-sd-device.c b/src/libsystemd/sd-device/test-sd-device.c index e523206b61a..1dda6625d20 100644 --- a/src/libsystemd/sd-device/test-sd-device.c +++ b/src/libsystemd/sd-device/test-sd-device.c @@ -53,7 +53,7 @@ static void test_sd_device_basic(void) { assert_se(i >= 0); if (i > 0) { r = sd_device_get_usec_since_initialized(d, &usec); - assert_se(r >= 0 || r == -ENODATA); + assert_se((r >= 0 && usec > 0) || r == -ENODATA); } r = sd_device_get_sysattr_value(d, "name_assign_type", &val); From 6174a243f919ea82ee5118bf5fe9613cf29056f7 Mon Sep 17 00:00:00 2001 From: Yu Watanabe Date: Fri, 26 Oct 2018 09:45:35 +0900 Subject: [PATCH 6/8] udev: setting the same log level to SYSTEMD realm Otherwise, many debug logs from libsystemd are dropped. --- src/udev/udevadm-hwdb.c | 2 -- src/udev/udevadm.c | 1 + src/udev/udevd.c | 2 ++ 3 files changed, 3 insertions(+), 2 deletions(-) diff --git a/src/udev/udevadm-hwdb.c b/src/udev/udevadm-hwdb.c index 4eb2897b219..e9a1af65fcd 100644 --- a/src/udev/udevadm-hwdb.c +++ b/src/udev/udevadm-hwdb.c @@ -80,8 +80,6 @@ static int parse_argv(int argc, char *argv[]) { int hwdb_main(int argc, char *argv[], void *userdata) { int r; - log_set_max_level_realm(LOG_REALM_SYSTEMD, log_get_max_level()); - r = parse_argv(argc, argv); if (r <= 0) return r; diff --git a/src/udev/udevadm.c b/src/udev/udevadm.c index e627c50ff95..8ed679698aa 100644 --- a/src/udev/udevadm.c +++ b/src/udev/udevadm.c @@ -112,6 +112,7 @@ int main(int argc, char *argv[]) { udev_parse_config(); log_parse_environment(); log_open(); + log_set_max_level_realm(LOG_REALM_SYSTEMD, log_get_max_level()); mac_selinux_init(); r = parse_argv(argc, argv); diff --git a/src/udev/udevd.c b/src/udev/udevd.c index 7ec30b92c37..49f178ef08b 100644 --- a/src/udev/udevd.c +++ b/src/udev/udevd.c @@ -1702,6 +1702,8 @@ int main(int argc, char *argv[]) { log_set_max_level(LOG_DEBUG); } + log_set_max_level_realm(LOG_REALM_SYSTEMD, log_get_max_level()); + r = must_be_root(); if (r < 0) goto exit; From a126a38a9fbb4b1b004ca7c061ac2bc55c18f5d8 Mon Sep 17 00:00:00 2001 From: Yu Watanabe Date: Tue, 30 Oct 2018 13:24:57 +0900 Subject: [PATCH 7/8] udev-node: drop redundant log message As node_symlink() logs almost same message. --- src/udev/udev-node.c | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/src/udev/udev-node.c b/src/udev/udev-node.c index 46445eda6a5..f02f71367d9 100644 --- a/src/udev/udev-node.c +++ b/src/udev/udev-node.c @@ -211,10 +211,8 @@ static int link_update(sd_device *dev, const char *slink, bool add) { log_device_debug(dev, "No reference left, removing '%s'", slink); if (unlink(slink) == 0) (void) rmdir_parents(slink, "/"); - } else { - log_device_debug(dev, "Creating link '%s' to '%s'", slink, target); + } else (void) node_symlink(dev, target, slink); - } if (add) do { From 6bee20659133b32260f9a2206ba4d7e21e59a351 Mon Sep 17 00:00:00 2001 From: Yu Watanabe Date: Tue, 30 Oct 2018 13:29:44 +0900 Subject: [PATCH 8/8] udev-node: add one more debug log when failed to create symlink --- src/udev/udev-node.c | 2 ++ 1 file changed, 2 insertions(+) diff --git a/src/udev/udev-node.c b/src/udev/udev-node.c index f02f71367d9..94bebd69c74 100644 --- a/src/udev/udev-node.c +++ b/src/udev/udev-node.c @@ -73,6 +73,8 @@ static int node_symlink(sd_device *dev, const char *node, const char *slink) { } while (r == -ENOENT); if (r == 0) return 0; + if (r < 0) + log_device_debug_errno(dev, r, "Failed to create symlink '%s' to '%s', trying to replace '%s': %m", slink, target, slink); } log_device_debug(dev, "Atomically replace '%s'", slink);