Merge pull request #17903 from yuwata/udev-options-log-level

udev: introduce OPTIONS="log_level=xxx" rule
This commit is contained in:
Lennart Poettering 2020-12-10 20:45:32 +01:00 committed by GitHub
commit 4add63c79e
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
10 changed files with 97 additions and 49 deletions

View File

@ -647,6 +647,24 @@
on the transition from initramfs.</para>
</listitem>
</varlistentry>
<varlistentry>
<term><option>log_level=<replaceable>level</replaceable></option></term>
<listitem>
<para>Takes a log level name like <literal>debug</literal> or
<literal>info</literal>, or a special value <literal>reset</literal>. When a log
level name is specified, the maximum log level is changed to that level. When
<literal>reset</literal> is set, then the previously specified log level is
revoked. Defaults to the log level of the main process of
<command>systemd-udevd</command>.</para>
<para>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 <filename>00-debug.rules</filename>.</para>
<para>Example for debugging uevent processing for network interfaces.
<programlisting># /etc/udev/rules.d/00-debug-net.rules
SUBSYSTEM=="net", OPTIONS="log_level=debug"</programlisting></para>
</listitem>
</varlistentry>
</variablelist>
</listitem>
</varlistentry>

View File

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

View File

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

View File

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

View File

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

View File

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

View File

@ -34,17 +34,19 @@ 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;
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);

View File

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

View File

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

View File

@ -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;
@ -100,8 +101,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 {
@ -436,25 +437,14 @@ 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");
log_device_uevent(dev, "Processing device");
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));
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;
@ -521,9 +511,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;
}
@ -553,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;
}
@ -655,13 +646,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) : "<unknown>");
}
log_device_uevent(event->dev, "Device ready for processing");
HASHMAP_FOREACH(worker, manager->workers) {
if (worker->state != WORKER_IDLE)
@ -704,7 +689,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 +703,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 +732,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;
}
@ -1090,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:
@ -1734,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;