diff --git a/src/udev/udev-event.c b/src/udev/udev-event.c index 0aa43d3a2..a0a1060d5 100644 --- a/src/udev/udev-event.c +++ b/src/udev/udev-event.c @@ -542,6 +542,7 @@ out: static int spawn_wait(struct udev_event *event, usec_t timeout_usec, + usec_t timeout_warn_usec, const char *cmd, pid_t pid) { struct pollfd pfd[1]; int err = 0; @@ -551,6 +552,7 @@ static int spawn_wait(struct udev_event *event, while (pid > 0) { int timeout; + int timeout_warn = 0; int fdcount; if (timeout_usec > 0) { @@ -559,13 +561,17 @@ static int spawn_wait(struct udev_event *event, age_usec = now(CLOCK_MONOTONIC) - event->birth_usec; if (age_usec >= timeout_usec) timeout = 1000; - else - timeout = ((timeout_usec - age_usec) / USEC_PER_MSEC) + MSEC_PER_SEC; + else { + if (timeout_warn_usec > 0) + timeout_warn = ((timeout_warn_usec - age_usec) / USEC_PER_MSEC) + MSEC_PER_SEC; + + timeout = ((timeout_usec - timeout_warn_usec - age_usec) / USEC_PER_MSEC) + MSEC_PER_SEC; + } } else { timeout = -1; } - fdcount = poll(pfd, 1, timeout); + fdcount = poll(pfd, 1, timeout_warn); if (fdcount < 0) { if (errno == EINTR) continue; @@ -574,8 +580,20 @@ static int spawn_wait(struct udev_event *event, goto out; } if (fdcount == 0) { - log_error("timeout: killing '%s' [%u]", cmd, pid); - kill(pid, SIGKILL); + log_warning("slow: '%s' [%u]", cmd, pid); + + fdcount = poll(pfd, 1, timeout); + if (fdcount < 0) { + if (errno == EINTR) + continue; + err = -errno; + log_error("failed to poll: %m"); + goto out; + } + if (fdcount == 0) { + log_error("timeout: killing '%s' [%u]", cmd, pid); + kill(pid, SIGKILL); + } } if (pfd[0].revents & POLLIN) { @@ -655,6 +673,7 @@ out: int udev_event_spawn(struct udev_event *event, usec_t timeout_usec, + usec_t timeout_warn_usec, const char *cmd, char **envp, const sigset_t *sigmask, char *result, size_t ressize) { struct udev *udev = event->udev; @@ -737,7 +756,7 @@ int udev_event_spawn(struct udev_event *event, outpipe[READ_END], errpipe[READ_END], result, ressize); - err = spawn_wait(event, timeout_usec, cmd, pid); + err = spawn_wait(event, timeout_usec, timeout_warn_usec, cmd, pid); } out: @@ -829,6 +848,7 @@ static int rename_netif(struct udev_event *event) { void udev_event_execute_rules(struct udev_event *event, usec_t timeout_usec, + usec_t timeout_warn_usec, struct udev_rules *rules, const sigset_t *sigmask) { struct udev_device *dev = event->dev; @@ -843,7 +863,7 @@ void udev_event_execute_rules(struct udev_event *event, if (major(udev_device_get_devnum(dev)) != 0) udev_watch_end(event->udev, dev); - udev_rules_apply_to_event(rules, event, timeout_usec, sigmask); + udev_rules_apply_to_event(rules, event, timeout_usec, timeout_warn_usec, sigmask); if (major(udev_device_get_devnum(dev)) != 0) udev_node_remove(dev); @@ -876,7 +896,7 @@ void udev_event_execute_rules(struct udev_event *event, } } - udev_rules_apply_to_event(rules, event, timeout_usec, sigmask); + udev_rules_apply_to_event(rules, event, timeout_usec, timeout_warn_usec, sigmask); /* rename a new network interface, if needed */ @@ -1018,7 +1038,7 @@ void udev_event_execute_rules(struct udev_event *event, } } -void udev_event_execute_run(struct udev_event *event, usec_t timeout_usec, const sigset_t *sigmask) { +void udev_event_execute_run(struct udev_event *event, usec_t timeout_usec, usec_t timeout_warn_usec, const sigset_t *sigmask) { struct udev_list_entry *list_entry; udev_list_entry_foreach(list_entry, udev_list_get_entry(&event->run_list)) { @@ -1041,7 +1061,7 @@ void udev_event_execute_run(struct udev_event *event, usec_t timeout_usec, const udev_event_apply_format(event, cmd, program, sizeof(program)); envp = udev_device_get_properties_envp(event->dev); - udev_event_spawn(event, timeout_usec, program, envp, sigmask, NULL, 0); + udev_event_spawn(event, timeout_usec, timeout_warn_usec, program, envp, sigmask, NULL, 0); } } } diff --git a/src/udev/udev-rules.c b/src/udev/udev-rules.c index a5348b84c..0dcd41734 100644 --- a/src/udev/udev-rules.c +++ b/src/udev/udev-rules.c @@ -620,6 +620,7 @@ static int import_file_into_properties(struct udev_device *dev, const char *file static int import_program_into_properties(struct udev_event *event, usec_t timeout_usec, + usec_t timeout_warn_usec, const char *program, const sigset_t *sigmask) { struct udev_device *dev = event->dev; char **envp; @@ -628,7 +629,7 @@ static int import_program_into_properties(struct udev_event *event, int err; envp = udev_device_get_properties_envp(dev); - err = udev_event_spawn(event, timeout_usec, program, envp, sigmask, result, sizeof(result)); + err = udev_event_spawn(event, timeout_usec, timeout_warn_usec, program, envp, sigmask, result, sizeof(result)); if (err < 0) return err; @@ -1931,6 +1932,7 @@ int udev_rules_assigning_name_to(struct udev_rules *rules, const char *match_nam int udev_rules_apply_to_event(struct udev_rules *rules, struct udev_event *event, usec_t timeout_usec, + usec_t timeout_warn_usec, const sigset_t *sigmask) { struct token *cur; struct token *rule; @@ -2139,7 +2141,7 @@ int udev_rules_apply_to_event(struct udev_rules *rules, rules_str(rules, rule->rule.filename_off), rule->rule.filename_line); - if (udev_event_spawn(event, timeout_usec, program, envp, sigmask, result, sizeof(result)) < 0) { + if (udev_event_spawn(event, timeout_usec, timeout_warn_usec, program, envp, sigmask, result, sizeof(result)) < 0) { if (cur->key.op != OP_NOMATCH) goto nomatch; } else { @@ -2175,7 +2177,7 @@ int udev_rules_apply_to_event(struct udev_rules *rules, rules_str(rules, rule->rule.filename_off), rule->rule.filename_line); - if (import_program_into_properties(event, timeout_usec, import, sigmask) != 0) + if (import_program_into_properties(event, timeout_usec, timeout_warn_usec, import, sigmask) != 0) if (cur->key.op != OP_NOMATCH) goto nomatch; break; diff --git a/src/udev/udev.h b/src/udev/udev.h index 64a098329..5a1f5488c 100644 --- a/src/udev/udev.h +++ b/src/udev/udev.h @@ -71,7 +71,8 @@ struct udev_rules; struct udev_rules *udev_rules_new(struct udev *udev, int resolve_names); struct udev_rules *udev_rules_unref(struct udev_rules *rules); bool udev_rules_check_timestamp(struct udev_rules *rules); -int udev_rules_apply_to_event(struct udev_rules *rules, struct udev_event *event, usec_t timeout_usec, const sigset_t *sigmask); +int udev_rules_apply_to_event(struct udev_rules *rules, struct udev_event *event, usec_t timeout_usec, usec_t timeout_warn_usec, + const sigset_t *sigmask); int udev_rules_apply_static_dev_perms(struct udev_rules *rules); /* udev-event.c */ @@ -82,10 +83,12 @@ int udev_event_apply_subsys_kernel(struct udev_event *event, const char *string, char *result, size_t maxsize, int read_value); int udev_event_spawn(struct udev_event *event, usec_t timeout_usec, + usec_t timeout_warn_usec, const char *cmd, char **envp, const sigset_t *sigmask, char *result, size_t ressize); -void udev_event_execute_rules(struct udev_event *event, usec_t timeout_usec, struct udev_rules *rules, const sigset_t *sigset); -void udev_event_execute_run(struct udev_event *event, usec_t timeout_usec, const sigset_t *sigset); +void udev_event_execute_rules(struct udev_event *event, usec_t timeout_usec, usec_t timeout_warn_usec, + struct udev_rules *rules, const sigset_t *sigset); +void udev_event_execute_run(struct udev_event *event, usec_t timeout_usec, usec_t timeout_warn_usec, const sigset_t *sigset); int udev_build_argv(struct udev *udev, char *cmd, int *argc, char *argv[]); /* udev-watch.c */ diff --git a/src/udev/udevadm-test.c b/src/udev/udevadm-test.c index 809adb6d9..4738b611c 100644 --- a/src/udev/udevadm-test.c +++ b/src/udev/udevadm-test.c @@ -136,7 +136,7 @@ static int adm_test(struct udev *udev, int argc, char *argv[]) { goto out; } - udev_event_execute_rules(event, 60 * USEC_PER_SEC, rules, &sigmask_orig); + udev_event_execute_rules(event, 60 * USEC_PER_SEC, 20 * USEC_PER_SEC, rules, &sigmask_orig); udev_list_entry_foreach(entry, udev_device_get_properties_list_entry(dev)) printf("%s=%s\n", udev_list_entry_get_name(entry), udev_list_entry_get_value(entry)); diff --git a/src/udev/udevd.c b/src/udev/udevd.c index 68fd34bfd..171bf83d0 100644 --- a/src/udev/udevd.c +++ b/src/udev/udevd.c @@ -74,6 +74,7 @@ static int children; static int children_max; static int exec_delay; static usec_t event_timeout_usec = 180 * USEC_PER_SEC; +static usec_t event_timeout_warn_usec = 180 * USEC_PER_SEC / 3; static sigset_t sigmask_orig; static UDEV_LIST(event_list); static UDEV_LIST(worker_list); @@ -124,6 +125,7 @@ struct worker { enum worker_state state; struct event *event; usec_t event_start_usec; + bool event_warned; }; /* passed from worker to main process */ @@ -302,9 +304,9 @@ static void worker_new(struct event *event) { } /* apply rules, create node, symlinks */ - udev_event_execute_rules(udev_event, event_timeout_usec, rules, &sigmask_orig); + udev_event_execute_rules(udev_event, event_timeout_usec, event_timeout_warn_usec, rules, &sigmask_orig); - udev_event_execute_run(udev_event, event_timeout_usec, &sigmask_orig); + udev_event_execute_run(udev_event, event_timeout_usec, event_timeout_warn_usec, &sigmask_orig); /* apply/restore inotify watch */ if (udev_event->inotify_watch) { @@ -395,6 +397,7 @@ out: worker->pid = pid; worker->state = WORKER_RUNNING; worker->event_start_usec = now(CLOCK_MONOTONIC); + worker->event_warned = false; worker->event = event; event->state = EVENT_RUNNING; udev_list_node_append(&worker->node, &worker_list); @@ -425,6 +428,7 @@ static void event_run(struct event *event) { worker->event = event; worker->state = WORKER_RUNNING; worker->event_start_usec = now(CLOCK_MONOTONIC); + worker->event_warned = false; event->state = EVENT_RUNNING; return; } @@ -1013,6 +1017,7 @@ static void kernel_cmdline_options(struct udev *udev) { exec_delay = strtoul(opt + 16, NULL, 0); } else if (startswith(opt, "udev.event-timeout=")) { event_timeout_usec = strtoul(opt + 16, NULL, 0) * USEC_PER_SEC; + event_timeout_warn_usec = (event_timeout_usec / 3) ? : 1; } free(s); @@ -1074,6 +1079,7 @@ int main(int argc, char *argv[]) { break; case 't': event_timeout_usec = strtoul(optarg, NULL, 0) * USEC_PER_SEC; + event_timeout_warn_usec = (event_timeout_usec / 3) ? : 1; break; case 'D': debug = true; @@ -1402,21 +1408,29 @@ int main(int argc, char *argv[]) { /* check for hanging events */ udev_list_node_foreach(loop, &worker_list) { struct worker *worker = node_to_worker(loop); + usec_t ts; if (worker->state != WORKER_RUNNING) continue; - if ((now(CLOCK_MONOTONIC) - worker->event_start_usec) > event_timeout_usec) { - log_error("worker [%u] %s timeout; kill it", worker->pid, worker->event->devpath); - kill(worker->pid, SIGKILL); - worker->state = WORKER_KILLED; + ts = now(CLOCK_MONOTONIC); - /* drop reference taken for state 'running' */ - worker_unref(worker); - log_error("seq %llu '%s' killed", udev_device_get_seqnum(worker->event->dev), worker->event->devpath); - worker->event->exitcode = -64; - event_queue_delete(worker->event); - worker->event = NULL; + if ((ts - worker->event_start_usec) > event_timeout_warn_usec) { + if ((ts - worker->event_start_usec) > event_timeout_usec) { + log_error("worker [%u] %s timeout; kill it", worker->pid, worker->event->devpath); + kill(worker->pid, SIGKILL); + worker->state = WORKER_KILLED; + + /* drop reference taken for state 'running' */ + worker_unref(worker); + log_error("seq %llu '%s' killed", udev_device_get_seqnum(worker->event->dev), worker->event->devpath); + worker->event->exitcode = -64; + event_queue_delete(worker->event); + worker->event = NULL; + } else if (!worker->event_warned) { + log_warning("worker [%u] %s is taking a long time", worker->pid, worker->event->devpath); + worker->event_warned = true; + } } } diff --git a/test/test-udev.c b/test/test-udev.c index cafe329c4..0d0407854 100644 --- a/test/test-udev.c +++ b/test/test-udev.c @@ -164,8 +164,8 @@ int main(int argc, char *argv[]) { } } - udev_event_execute_rules(event, USEC_PER_SEC, rules, &sigmask_orig); - udev_event_execute_run(event, USEC_PER_SEC, NULL); + udev_event_execute_rules(event, 3 * USEC_PER_SEC, USEC_PER_SEC, rules, &sigmask_orig); + udev_event_execute_run(event, 3 * USEC_PER_SEC, USEC_PER_SEC, NULL); out: if (event != NULL && event->fd_signal >= 0) close(event->fd_signal);