chiark / gitweb /
udev: drop duplicate logging
[elogind.git] / src / udev / udevd.c
index be0acc3177138e95dac40f79c539b0ed3569ca56..8922ff9f8e3bcf134bb32a8a5214cadf09489910 100644 (file)
@@ -54,8 +54,6 @@
 #include "dev-setup.h"
 #include "fileio.h"
 
-static bool debug;
-
 void udev_main_log(struct udev *udev, int priority,
                    const char *file, int line, const char *fn,
                    const char *format, va_list args) {
@@ -72,9 +70,13 @@ static int fd_inotify = -1;
 static bool stop_exec_queue;
 static bool reload;
 static int children;
-static int children_max;
-static int exec_delay;
-static usec_t event_timeout_usec = 60 * USEC_PER_SEC;
+static bool arg_debug = false;
+static int arg_daemonize = false;
+static int arg_resolve_names = 1;
+static int arg_children_max;
+static int arg_exec_delay;
+static usec_t arg_event_timeout_usec = 180 * USEC_PER_SEC;
+static usec_t arg_event_timeout_warn_usec = 180 * USEC_PER_SEC / 3;
 static sigset_t sigmask_orig;
 static UDEV_LIST(event_list);
 static UDEV_LIST(worker_list);
@@ -125,6 +127,7 @@ struct worker {
         enum worker_state state;
         struct event *event;
         usec_t event_start_usec;
+        bool event_warned;
 };
 
 /* passed from worker to main process */
@@ -272,8 +275,8 @@ static void worker_new(struct event *event) {
                         /* needed for SIGCHLD/SIGTERM in spawn() */
                         udev_event->fd_signal = fd_signal;
 
-                        if (exec_delay > 0)
-                                udev_event->exec_delay = exec_delay;
+                        if (arg_exec_delay > 0)
+                                udev_event->exec_delay = arg_exec_delay;
 
                         /*
                          * Take a shared lock on the device node; this establishes
@@ -307,9 +310,9 @@ static void worker_new(struct event *event) {
                         udev_event->rtnl = rtnl;
 
                         /* apply rules, create node, symlinks */
-                        udev_event_execute_rules(udev_event, event_timeout_usec, rules, &sigmask_orig);
+                        udev_event_execute_rules(udev_event, arg_event_timeout_usec, arg_event_timeout_warn_usec, rules, &sigmask_orig);
 
-                        udev_event_execute_run(udev_event, event_timeout_usec, &sigmask_orig);
+                        udev_event_execute_run(udev_event, arg_event_timeout_usec, arg_event_timeout_warn_usec, &sigmask_orig);
 
                         /* in case rtnl was initialized */
                         rtnl = sd_rtnl_ref(udev_event->rtnl);
@@ -403,6 +406,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);
@@ -433,12 +437,13 @@ 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;
         }
 
-        if (children >= children_max) {
-                if (children_max > 1)
+        if (children >= arg_children_max) {
+                if (arg_children_max > 1)
                         log_debug("maximum number (%i) of children reached", children);
                 return;
         }
@@ -688,7 +693,7 @@ static struct udev_ctrl_connection *handle_ctrl_msg(struct udev_ctrl *uctrl) {
         i = udev_ctrl_get_set_children_max(ctrl_msg);
         if (i >= 0) {
                 log_debug("udevd message (SET_MAX_CHILDREN) received, children_max=%i", i);
-                children_max = i;
+                arg_children_max = i;
         }
 
         if (udev_ctrl_get_ping(ctrl_msg) > 0)
@@ -981,116 +986,135 @@ static void kernel_cmdline_options(struct udev *udev) {
                         log_set_max_level(prio);
                         udev_set_log_priority(udev, prio);
                 } else if (startswith(opt, "udev.children-max=")) {
-                        children_max = strtoul(opt + 18, NULL, 0);
+                        arg_children_max = strtoul(opt + 18, NULL, 0);
                 } else if (startswith(opt, "udev.exec-delay=")) {
-                        exec_delay = strtoul(opt + 16, NULL, 0);
+                        arg_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;
+                        arg_event_timeout_usec = strtoul(opt + 16, NULL, 0) * USEC_PER_SEC;
+                        arg_event_timeout_warn_usec = (arg_event_timeout_usec / 3) ? : 1;
                 }
 
                 free(s);
         }
 }
 
-int main(int argc, char *argv[]) {
-        struct udev *udev;
-        sigset_t mask;
-        int daemonize = false;
-        int resolve_names = 1;
+static void help(void) {
+        printf("%s [OPTIONS...]\n\n"
+               "Manages devices.\n\n"
+               "  --daemon\n"
+               "  --debug\n"
+               "  --children-max=<maximum number of workers>\n"
+               "  --exec-delay=<seconds to wait before executing RUN=>\n"
+               "  --event-timeout=<seconds to wait before terminating an event>\n"
+               "  --resolve-names=early|late|never\n"
+               "  --version\n"
+               "  --help\n"
+               , program_invocation_short_name);
+}
+
+static int parse_argv(int argc, char *argv[]) {
         static const struct option options[] = {
-                { "daemon", no_argument, NULL, 'd' },
-                { "debug", no_argument, NULL, 'D' },
-                { "children-max", required_argument, NULL, 'c' },
-                { "exec-delay", required_argument, NULL, 'e' },
-                { "event-timeout", required_argument, NULL, 't' },
-                { "resolve-names", required_argument, NULL, 'N' },
-                { "help", no_argument, NULL, 'h' },
-                { "version", no_argument, NULL, 'V' },
+                { "daemon",             no_argument,            NULL, 'd' },
+                { "debug",              no_argument,            NULL, 'D' },
+                { "children-max",       required_argument,      NULL, 'c' },
+                { "exec-delay",         required_argument,      NULL, 'e' },
+                { "event-timeout",      required_argument,      NULL, 't' },
+                { "resolve-names",      required_argument,      NULL, 'N' },
+                { "help",               no_argument,            NULL, 'h' },
+                { "version",            no_argument,            NULL, 'V' },
                 {}
         };
-        int fd_ctrl = -1;
-        int fd_netlink = -1;
-        int fd_worker = -1;
-        struct epoll_event ep_ctrl, ep_inotify, ep_signal, ep_netlink, ep_worker;
-        struct udev_ctrl_connection *ctrl_conn = NULL;
-        int rc = 1;
-
-        udev = udev_new();
-        if (udev == NULL)
-                goto exit;
-
-        log_set_target(LOG_TARGET_AUTO);
-        log_parse_environment();
-        log_open();
 
-        udev_set_log_fn(udev, udev_main_log);
-        log_set_max_level(udev_get_log_priority(udev));
+        int c;
 
-        log_debug("version %s", VERSION);
-        label_init("/dev");
+        assert(argc >= 0);
+        assert(argv);
 
-        for (;;) {
-                int option;
+        while ((c = getopt_long(argc, argv, "c:de:DtN:hV", options, NULL)) >= 0) {
 
-                option = getopt_long(argc, argv, "c:de:DtN:hV", options, NULL);
-                if (option == -1)
-                        break;
+                switch (c) {
 
-                switch (option) {
                 case 'd':
-                        daemonize = true;
+                        arg_daemonize = true;
                         break;
                 case 'c':
-                        children_max = strtoul(optarg, NULL, 0);
+                        arg_children_max = strtoul(optarg, NULL, 0);
                         break;
                 case 'e':
-                        exec_delay = strtoul(optarg, NULL, 0);
+                        arg_exec_delay = strtoul(optarg, NULL, 0);
                         break;
                 case 't':
-                        event_timeout_usec = strtoul(optarg, NULL, 0) * USEC_PER_SEC;
+                        arg_event_timeout_usec = strtoul(optarg, NULL, 0) * USEC_PER_SEC;
+                        arg_event_timeout_warn_usec = (arg_event_timeout_usec / 3) ? : 1;
                         break;
                 case 'D':
-                        debug = true;
-                        log_set_max_level(LOG_DEBUG);
-                        udev_set_log_priority(udev, LOG_DEBUG);
+                        arg_debug = true;
                         break;
                 case 'N':
                         if (streq(optarg, "early")) {
-                                resolve_names = 1;
+                                arg_resolve_names = 1;
                         } else if (streq(optarg, "late")) {
-                                resolve_names = 0;
+                                arg_resolve_names = 0;
                         } else if (streq(optarg, "never")) {
-                                resolve_names = -1;
+                                arg_resolve_names = -1;
                         } else {
-                                fprintf(stderr, "resolve-names must be early, late or never\n");
                                 log_error("resolve-names must be early, late or never");
-                                goto exit;
+                                return 0;
                         }
                         break;
                 case 'h':
-                        printf("Usage: udevd OPTIONS\n"
-                               "  --daemon\n"
-                               "  --debug\n"
-                               "  --children-max=<maximum number of workers>\n"
-                               "  --exec-delay=<seconds to wait before executing RUN=>\n"
-                               "  --event-timeout=<seconds to wait before terminating an event>\n"
-                               "  --resolve-names=early|late|never\n"
-                               "  --version\n"
-                               "  --help\n"
-                               "\n");
-                        goto exit;
+                        help();
+                        return 0;
                 case 'V':
                         printf("%s\n", VERSION);
-                        goto exit;
+                        return 0;
+                case '?':
+                        return -EINVAL;
                 default:
-                        goto exit;
+                        assert_not_reached("Unhandled option");
+
                 }
         }
 
+        return 1;
+}
+
+int main(int argc, char *argv[]) {
+        struct udev *udev;
+        sigset_t mask;
+        int fd_ctrl = -1;
+        int fd_netlink = -1;
+        int fd_worker = -1;
+        struct epoll_event ep_ctrl, ep_inotify, ep_signal, ep_netlink, ep_worker;
+        struct udev_ctrl_connection *ctrl_conn = NULL;
+        int rc = 1, r;
+
+        udev = udev_new();
+        if (udev == NULL)
+                goto exit;
+
+        log_set_target(LOG_TARGET_AUTO);
+        log_parse_environment();
+        log_open();
+
+        udev_set_log_fn(udev, udev_main_log);
+        log_set_max_level(udev_get_log_priority(udev));
+
+        log_debug("version %s", VERSION);
+        label_init("/dev");
+
+        r = parse_argv(argc, argv);
+        if (r <= 0)
+                goto exit;
+
         kernel_cmdline_options(udev);
 
+        if (arg_debug) {
+                log_set_max_level(LOG_DEBUG);
+                udev_set_log_priority(udev, LOG_DEBUG);
+        }
+
         if (getuid() != 0) {
-                fprintf(stderr, "root privileges required\n");
                 log_error("root privileges required");
                 goto exit;
         }
@@ -1104,7 +1128,7 @@ int main(int argc, char *argv[]) {
         dev_setup(NULL);
 
         /* before opening new files, make sure std{in,out,err} fds are in a sane state */
-        if (daemonize) {
+        if (arg_daemonize) {
                 int fd;
 
                 fd = open("/dev/null", O_RDWR);
@@ -1116,7 +1140,6 @@ int main(int argc, char *argv[]) {
                         if (fd > STDERR_FILENO)
                                 close(fd);
                 } else {
-                        fprintf(stderr, "cannot open /dev/null\n");
                         log_error("cannot open /dev/null");
                 }
         }
@@ -1144,7 +1167,6 @@ int main(int argc, char *argv[]) {
                 /* open control and netlink socket */
                 udev_ctrl = udev_ctrl_new(udev);
                 if (udev_ctrl == NULL) {
-                        fprintf(stderr, "error initializing udev control socket");
                         log_error("error initializing udev control socket");
                         rc = 1;
                         goto exit;
@@ -1153,7 +1175,6 @@ int main(int argc, char *argv[]) {
 
                 monitor = udev_monitor_new_from_netlink(udev, "kernel");
                 if (monitor == NULL) {
-                        fprintf(stderr, "error initializing netlink socket\n");
                         log_error("error initializing netlink socket");
                         rc = 3;
                         goto exit;
@@ -1162,14 +1183,12 @@ int main(int argc, char *argv[]) {
         }
 
         if (udev_monitor_enable_receiving(monitor) < 0) {
-                fprintf(stderr, "error binding netlink socket\n");
                 log_error("error binding netlink socket");
                 rc = 3;
                 goto exit;
         }
 
         if (udev_ctrl_enable_receiving(udev_ctrl) < 0) {
-                fprintf(stderr, "error binding udev control socket\n");
                 log_error("error binding udev control socket");
                 rc = 1;
                 goto exit;
@@ -1177,7 +1196,7 @@ int main(int argc, char *argv[]) {
 
         udev_monitor_set_receive_buffer_size(monitor, 128 * 1024 * 1024);
 
-        if (daemonize) {
+        if (arg_daemonize) {
                 pid_t pid;
 
                 pid = fork();
@@ -1200,9 +1219,9 @@ int main(int argc, char *argv[]) {
                 sd_notify(1, "READY=1");
         }
 
-        print_kmsg("starting version " VERSION "\n");
+        log_info("starting version " VERSION "\n");
 
-        if (!debug) {
+        if (!arg_debug) {
                 int fd;
 
                 fd = open("/dev/null", O_RDWR);
@@ -1216,7 +1235,6 @@ int main(int argc, char *argv[]) {
 
         fd_inotify = udev_watch_init(udev);
         if (fd_inotify < 0) {
-                fprintf(stderr, "error initializing inotify\n");
                 log_error("error initializing inotify");
                 rc = 4;
                 goto exit;
@@ -1228,7 +1246,6 @@ int main(int argc, char *argv[]) {
         sigprocmask(SIG_SETMASK, &mask, &sigmask_orig);
         fd_signal = signalfd(-1, &mask, SFD_NONBLOCK|SFD_CLOEXEC);
         if (fd_signal < 0) {
-                fprintf(stderr, "error creating signalfd\n");
                 log_error("error creating signalfd");
                 rc = 5;
                 goto exit;
@@ -1236,7 +1253,6 @@ int main(int argc, char *argv[]) {
 
         /* unnamed socket from workers to the main daemon */
         if (socketpair(AF_LOCAL, SOCK_DGRAM|SOCK_CLOEXEC, 0, worker_watch) < 0) {
-                fprintf(stderr, "error creating socketpair\n");
                 log_error("error creating socketpair");
                 rc = 6;
                 goto exit;
@@ -1245,7 +1261,7 @@ int main(int argc, char *argv[]) {
 
         udev_builtin_init(udev);
 
-        rules = udev_rules_new(udev, resolve_names);
+        rules = udev_rules_new(udev, arg_resolve_names);
         if (rules == NULL) {
                 log_error("error reading rules");
                 goto exit;
@@ -1285,16 +1301,16 @@ int main(int argc, char *argv[]) {
                 goto exit;
         }
 
-        if (children_max <= 0) {
+        if (arg_children_max <= 0) {
                 cpu_set_t cpu_set;
 
-                children_max = 8;
+                arg_children_max = 8;
 
                 if (sched_getaffinity(0, sizeof (cpu_set), &cpu_set) == 0) {
-                        children_max +=  CPU_COUNT(&cpu_set) * 2;
+                        arg_children_max +=  CPU_COUNT(&cpu_set) * 2;
                 }
         }
-        log_debug("set children_max to %u", children_max);
+        log_debug("set children_max to %u", arg_children_max);
 
         rc = udev_rules_apply_static_dev_perms(rules);
         if (rc < 0)
@@ -1383,21 +1399,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) > arg_event_timeout_warn_usec) {
+                                        if ((ts - worker->event_start_usec) > arg_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;
+                                        }
                                 }
                         }
 
@@ -1454,7 +1478,7 @@ int main(int argc, char *argv[]) {
                 if (!udev_list_node_is_empty(&event_list) && !udev_exit && !stop_exec_queue) {
                         udev_builtin_init(udev);
                         if (rules == NULL)
-                                rules = udev_rules_new(udev, resolve_names);
+                                rules = udev_rules_new(udev, arg_resolve_names);
                         if (rules != NULL)
                                 event_queue_start(udev);
                 }