udev: timeout - warn after a third of the timeout before killing

Signed-off-by: Anthony G. Basile <blueness@gentoo.org>

6 files changed, 71 insertions, 32 deletions

diff --git a/src/udev/udev-event.c b/src/udev/udev-event.c
index 0aa43d3a2b..a0a1060d57 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 a5348b84c7..0dcd41734b 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 64a0983299..5a1f5488cb 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 809adb6d9a..4738b611c3 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 68fd34bfdf..171bf83d05 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;
-
-                                        /* 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;
+                                ts = now(CLOCK_MONOTONIC);
+
+                                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 cafe329c43..0d04078542 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);