From 481f24d1f6ffb2535bce6531c2c67b7fdffdff56 Mon Sep 17 00:00:00 2001 From: Yu Watanabe Date: Tue, 8 Dec 2020 21:49:34 +0900 Subject: [PATCH 1/4] udev: drop meaningless size optimization These objects are not allocated multiple times simultaneously per single process. --- src/udev/udev-ctrl.c | 8 ++++---- src/udev/udev-event.h | 16 ++++++++-------- src/udev/udevd.c | 4 ++-- 3 files changed, 14 insertions(+), 14 deletions(-) diff --git a/src/udev/udev-ctrl.c b/src/udev/udev-ctrl.c index 48355aa50c..64051d0aa8 100644 --- a/src/udev/udev-ctrl.c +++ b/src/udev/udev-ctrl.c @@ -44,10 +44,10 @@ struct udev_ctrl { int sock_connect; union sockaddr_union saddr; socklen_t addrlen; - bool bound:1; - bool cleanup_socket:1; - bool connected:1; - bool maybe_disconnected:1; + bool bound; + bool cleanup_socket; + bool connected; + bool maybe_disconnected; sd_event *event; sd_event_source *event_source; sd_event_source *event_source_connect; diff --git a/src/udev/udev-event.h b/src/udev/udev-event.h index 864782822c..a34b85176d 100644 --- a/src/udev/udev-event.h +++ b/src/udev/udev-event.h @@ -34,14 +34,14 @@ typedef struct UdevEvent { unsigned builtin_run; unsigned builtin_ret; UdevRuleEscapeType esc:8; - bool inotify_watch:1; - bool inotify_watch_final:1; - bool group_final:1; - bool owner_final:1; - bool mode_final:1; - bool name_final:1; - bool devlink_final:1; - bool run_final:1; + bool inotify_watch; + bool inotify_watch_final; + bool group_final; + bool owner_final; + bool mode_final; + bool name_final; + bool devlink_final; + bool run_final; } UdevEvent; UdevEvent *udev_event_new(sd_device *dev, usec_t exec_delay_usec, sd_netlink *rtnl); diff --git a/src/udev/udevd.c b/src/udev/udevd.c index 19e4951a6e..e65916cb1c 100644 --- a/src/udev/udevd.c +++ b/src/udev/udevd.c @@ -100,8 +100,8 @@ typedef struct Manager { usec_t last_usec; - bool stop_exec_queue:1; - bool exit:1; + bool stop_exec_queue; + bool exit; } Manager; enum event_state { From b2d9e58f789fd691483e364d8a9fa5ee0c415c45 Mon Sep 17 00:00:00 2001 From: Yu Watanabe Date: Tue, 8 Dec 2020 22:36:42 +0900 Subject: [PATCH 2/4] udev: introduce log_device_uevent() helper function And this drops duplicated check for seqnum and device action. --- src/shared/udev-util.c | 14 ++++++++++++++ src/shared/udev-util.h | 2 ++ src/udev/udevd.c | 34 ++++------------------------------ 3 files changed, 20 insertions(+), 30 deletions(-) diff --git a/src/shared/udev-util.c b/src/shared/udev-util.c index 030922eca9..411b1f704b 100644 --- a/src/shared/udev-util.c +++ b/src/shared/udev-util.c @@ -324,6 +324,20 @@ bool device_for_action(sd_device *dev, DeviceAction action) { return a == action; } +void log_device_uevent(sd_device *device, const char *str) { + DeviceAction action = _DEVICE_ACTION_INVALID; + uint64_t seqnum = 0; + + if (!DEBUG_LOGGING) + return; + + (void) device_get_seqnum(device, &seqnum); + (void) device_get_action(device, &action); + log_device_debug(device, "%s%s(SEQNUM=%"PRIu64", ACTION=%s)", + strempty(str), isempty(str) ? "" : " ", + seqnum, strna(device_action_to_string(action))); +} + int udev_rule_parse_value(char *str, char **ret_value, char **ret_endpos) { char *i, *j; int r; diff --git a/src/shared/udev-util.h b/src/shared/udev-util.h index 270861e55e..4e512cf754 100644 --- a/src/shared/udev-util.h +++ b/src/shared/udev-util.h @@ -33,4 +33,6 @@ int device_wait_for_devlink(const char *path, const char *subsystem, usec_t dead int device_is_renaming(sd_device *dev); bool device_for_action(sd_device *dev, DeviceAction action); +void log_device_uevent(sd_device *device, const char *str); + int udev_rule_parse_value(char *str, char **ret_value, char **ret_endpos); diff --git a/src/udev/udevd.c b/src/udev/udevd.c index e65916cb1c..3961e76305 100644 --- a/src/udev/udevd.c +++ b/src/udev/udevd.c @@ -436,23 +436,12 @@ static int worker_mark_block_device_read_only(sd_device *dev) { static int worker_process_device(Manager *manager, sd_device *dev) { _cleanup_(udev_event_freep) UdevEvent *udev_event = NULL; _cleanup_close_ int fd_lock = -1; - DeviceAction action; - uint64_t seqnum; int r; assert(manager); assert(dev); - r = device_get_seqnum(dev, &seqnum); - if (r < 0) - return log_device_debug_errno(dev, r, "Failed to get SEQNUM: %m"); - - r = device_get_action(dev, &action); - if (r < 0) - return log_device_debug_errno(dev, r, "Failed to get ACTION: %m"); - - log_device_debug(dev, "Processing device (SEQNUM=%"PRIu64", ACTION=%s)", - seqnum, device_action_to_string(action)); + log_device_uevent(dev, "Processing device"); udev_event = udev_event_new(dev, arg_exec_delay_usec, manager->rtnl); if (!udev_event) @@ -521,9 +510,7 @@ static int worker_process_device(Manager *manager, sd_device *dev) { } else (void) udev_watch_end(dev); - log_device_debug(dev, "Device (SEQNUM=%"PRIu64", ACTION=%s) processed", - seqnum, device_action_to_string(action)); - + log_device_uevent(dev, "Device processed"); return 0; } @@ -655,13 +642,7 @@ static void event_run(Manager *manager, struct event *event) { assert(manager); assert(event); - if (DEBUG_LOGGING) { - DeviceAction action; - - r = device_get_action(event->dev, &action); - log_device_debug(event->dev, "Device (SEQNUM=%"PRIu64", ACTION=%s) ready for processing", - event->seqnum, r >= 0 ? device_action_to_string(action) : ""); - } + log_device_uevent(event->dev, "Device ready for processing"); HASHMAP_FOREACH(worker, manager->workers) { if (worker->state != WORKER_IDLE) @@ -704,7 +685,6 @@ static void event_run(Manager *manager, struct event *event) { static int event_queue_insert(Manager *manager, sd_device *dev) { _cleanup_(sd_device_unrefp) sd_device *clone = NULL; struct event *event; - DeviceAction action; uint64_t seqnum; int r; @@ -719,11 +699,6 @@ static int event_queue_insert(Manager *manager, sd_device *dev) { if (r < 0) return r; - /* Refuse devices do not have ACTION property. */ - r = device_get_action(dev, &action); - if (r < 0) - return r; - /* Save original device to restore the state on failures. */ r = device_shallow_clone(dev, &clone); if (r < 0) @@ -753,8 +728,7 @@ static int event_queue_insert(Manager *manager, sd_device *dev) { LIST_APPEND(event, manager->events, event); - log_device_debug(dev, "Device (SEQNUM=%"PRIu64", ACTION=%s) is queued", - seqnum, device_action_to_string(action)); + log_device_uevent(dev, "Device is queued"); return 0; } From 1a0bd01529d42bc4fed71d94c914b590b8c6ff7e Mon Sep 17 00:00:00 2001 From: Yu Watanabe Date: Tue, 8 Dec 2020 22:37:12 +0900 Subject: [PATCH 3/4] udev: introduce new OPTIONS="log_level=" udev rule --- src/test/test-udev.c | 2 +- src/udev/udev-event.c | 4 +++- src/udev/udev-event.h | 4 +++- src/udev/udev-rules.c | 29 +++++++++++++++++++++++++++++ src/udev/udevadm-test.c | 2 +- src/udev/udevd.c | 9 ++++++++- 6 files changed, 45 insertions(+), 5 deletions(-) diff --git a/src/test/test-udev.c b/src/test/test-udev.c index 8acf86da37..488b965c82 100644 --- a/src/test/test-udev.c +++ b/src/test/test-udev.c @@ -102,7 +102,7 @@ static int run(int argc, char *argv[]) { if (r < 0) return log_debug_errno(r, "Failed to open device '%s'", devpath); - assert_se(event = udev_event_new(dev, 0, NULL)); + assert_se(event = udev_event_new(dev, 0, NULL, log_get_max_level())); assert_se(sigprocmask_many(SIG_BLOCK, NULL, SIGTERM, SIGINT, SIGHUP, SIGCHLD, -1) >= 0); diff --git a/src/udev/udev-event.c b/src/udev/udev-event.c index 5159d19a38..307f949fde 100644 --- a/src/udev/udev-event.c +++ b/src/udev/udev-event.c @@ -51,7 +51,7 @@ typedef struct Spawn { size_t result_len; } Spawn; -UdevEvent *udev_event_new(sd_device *dev, usec_t exec_delay_usec, sd_netlink *rtnl) { +UdevEvent *udev_event_new(sd_device *dev, usec_t exec_delay_usec, sd_netlink *rtnl, int log_level) { UdevEvent *event; assert(dev); @@ -68,6 +68,8 @@ UdevEvent *udev_event_new(sd_device *dev, usec_t exec_delay_usec, sd_netlink *rt .uid = UID_INVALID, .gid = GID_INVALID, .mode = MODE_INVALID, + .log_level_was_debug = log_level == LOG_DEBUG, + .default_log_level = log_level, }; return event; diff --git a/src/udev/udev-event.h b/src/udev/udev-event.h index a34b85176d..27bf8f9372 100644 --- a/src/udev/udev-event.h +++ b/src/udev/udev-event.h @@ -42,9 +42,11 @@ typedef struct UdevEvent { bool name_final; bool devlink_final; bool run_final; + bool log_level_was_debug; + int default_log_level; } UdevEvent; -UdevEvent *udev_event_new(sd_device *dev, usec_t exec_delay_usec, sd_netlink *rtnl); +UdevEvent *udev_event_new(sd_device *dev, usec_t exec_delay_usec, sd_netlink *rtnl, int log_level); UdevEvent *udev_event_free(UdevEvent *event); DEFINE_TRIVIAL_CLEANUP_FUNC(UdevEvent*, udev_event_free); diff --git a/src/udev/udev-rules.c b/src/udev/udev-rules.c index ef6a0c112c..48fd33fded 100644 --- a/src/udev/udev-rules.c +++ b/src/udev/udev-rules.c @@ -25,6 +25,7 @@ #include "strv.h" #include "strxcpyx.h" #include "sysctl-util.h" +#include "syslog-util.h" #include "udev-builtin.h" #include "udev-event.h" #include "udev-rules.h" @@ -104,6 +105,7 @@ typedef enum { TK_A_OPTIONS_DB_PERSIST, /* no argument */ TK_A_OPTIONS_INOTIFY_WATCH, /* boolean */ TK_A_OPTIONS_DEVLINK_PRIORITY, /* int */ + TK_A_OPTIONS_LOG_LEVEL, /* string of log level or "reset" */ TK_A_OWNER, /* user name */ TK_A_GROUP, /* group name */ TK_A_MODE, /* mode string */ @@ -834,6 +836,17 @@ static int parse_token(UdevRules *rules, const char *key, char *attr, UdevRuleOp if (r < 0) return log_token_error_errno(rules, r, "Failed to parse link priority '%s': %m", tmp); r = rule_line_add_token(rule_line, TK_A_OPTIONS_DEVLINK_PRIORITY, op, NULL, INT_TO_PTR(prio)); + } else if ((tmp = startswith(value, "log_level="))) { + int level; + + if (streq(tmp, "reset")) + level = -1; + else { + level = log_level_from_string(tmp); + if (level < 0) + return log_token_error_errno(rules, level, "Failed to parse log level '%s': %m", tmp); + } + r = rule_line_add_token(rule_line, TK_A_OPTIONS_LOG_LEVEL, op, NULL, INT_TO_PTR(level)); } else { log_token_warning(rules, "Invalid value for OPTIONS key, ignoring: '%s'", value); return 0; @@ -1858,6 +1871,22 @@ static int udev_rule_apply_token_to_event( case TK_A_OPTIONS_DEVLINK_PRIORITY: device_set_devlink_priority(dev, PTR_TO_INT(token->data)); break; + case TK_A_OPTIONS_LOG_LEVEL: { + int level = PTR_TO_INT(token->data); + + if (level < 0) + level = event->default_log_level; + + log_set_max_level_all_realms(level); + + if (level == LOG_DEBUG && !event->log_level_was_debug) { + /* The log level becomes LOG_DEBUG at first time. Let's log basic information. */ + log_device_uevent(dev, "The log level is changed to 'debug' while processing device"); + event->log_level_was_debug = true; + } + + break; + } case TK_A_OWNER: { char owner[UTIL_NAME_SIZE]; const char *ow = owner; diff --git a/src/udev/udevadm-test.c b/src/udev/udevadm-test.c index a029622af9..747047dac8 100644 --- a/src/udev/udevadm-test.c +++ b/src/udev/udevadm-test.c @@ -138,7 +138,7 @@ int test_main(int argc, char *argv[], void *userdata) { /* don't read info from the db */ device_seal(dev); - event = udev_event_new(dev, 0, NULL); + event = udev_event_new(dev, 0, NULL, LOG_DEBUG); assert_se(sigfillset(&mask) >= 0); assert_se(sigprocmask(SIG_SETMASK, &mask, &sigmask_orig) >= 0); diff --git a/src/udev/udevd.c b/src/udev/udevd.c index 3961e76305..5d02a9d27c 100644 --- a/src/udev/udevd.c +++ b/src/udev/udevd.c @@ -84,6 +84,7 @@ typedef struct Manager { LIST_HEAD(struct event, events); const char *cgroup; pid_t pid; /* the process that originally allocated the manager object */ + int log_level; UdevRules *rules; Hashmap *properties; @@ -443,7 +444,7 @@ static int worker_process_device(Manager *manager, sd_device *dev) { log_device_uevent(dev, "Processing device"); - udev_event = udev_event_new(dev, arg_exec_delay_usec, manager->rtnl); + udev_event = udev_event_new(dev, arg_exec_delay_usec, manager->rtnl, manager->log_level); if (!udev_event) return -ENOMEM; @@ -540,6 +541,9 @@ static int worker_device_monitor_handler(sd_device_monitor *monitor, sd_device * if (r < 0) log_device_warning_errno(dev, r, "Failed to send signal to main daemon, ignoring: %m"); + /* Reset the log level, as it might be changed by "OPTIONS=log_level=". */ + log_set_max_level_all_realms(manager->log_level); + return 1; } @@ -1064,6 +1068,7 @@ static int on_ctrl_msg(struct udev_ctrl *uctrl, enum udev_ctrl_msg_type type, co case UDEV_CTRL_SET_LOG_LEVEL: log_debug("Received udev control message (SET_LOG_LEVEL), setting log_level=%i", value->intval); log_set_max_level_all_realms(value->intval); + manager->log_level = value->intval; manager_kill_workers(manager); break; case UDEV_CTRL_STOP_EXEC_QUEUE: @@ -1708,6 +1713,8 @@ static int manager_new(Manager **ret, int fd_ctrl, int fd_uevent, const char *cg if (r < 0) return log_error_errno(r, "Failed to bind netlink socket: %m"); + manager->log_level = log_get_max_level(); + *ret = TAKE_PTR(manager); return 0; From 563a94d0808566507714dfd053fa3f36bfc95e9a Mon Sep 17 00:00:00 2001 From: Yu Watanabe Date: Tue, 8 Dec 2020 23:11:03 +0900 Subject: [PATCH 4/4] man: mention new OPTIONS=log_level= udev rule --- man/udev.xml | 18 ++++++++++++++++++ 1 file changed, 18 insertions(+) diff --git a/man/udev.xml b/man/udev.xml index 14e4c21aae..c3168b0864 100644 --- a/man/udev.xml +++ b/man/udev.xml @@ -647,6 +647,24 @@ on the transition from initramfs. + + + + Takes a log level name like debug or + info, or a special value reset. When a log + level name is specified, the maximum log level is changed to that level. When + reset is set, then the previously specified log level is + revoked. Defaults to the log level of the main process of + systemd-udevd. + This may be useful when debugging events for certain devices. Note that the + log level is applied when the line including this rule is processed. So, for + debugging, it is recommended that this is specified at earlier place, e.g., the + first line of 00-debug.rules. + Example for debugging uevent processing for network interfaces. + # /etc/udev/rules.d/00-debug-net.rules +SUBSYSTEM=="net", OPTIONS="log_level=debug" + +