mdev: improve $SEQ handling; improve debug logging

Sequential run of concurrent mdev's was too simplistic:
they waited for /dev/mdev.seq to match. This could sometimes
cause cumulative loss of time on the order of a second.

Added SIGCHLD signaling from exiting mdev to all other mdev's.
Added debugging required to see that code actually works as intended.

Example of /dev/mdev.log (with "woken up" elevated from dbg lvl 3 to 2):

mdev[1023]: first seq written
     ^^^^ seq, not pid
mdev[1023]: 35.022395 ACTION:add SUBSYSTEM:module DEVNAME:(null) DEVPATH:/module/lib80211
mdev[1023]: rule matched, line -1
                          ^^^^^^^ means "default rule"
mdev[1023]: 35.022676 exiting
            ^^^^^^^^^ second,usec timestamp
mdev[1024]: 35.069691 ACTION:add SUBSYSTEM:vc DEVNAME:vcs9 DEVPATH:/devices/virtual/vc/vcs9
mdev[1024]: dev 7,9
mdev[1025]: 35.069889 waiting for '1024'
mdev[1026]: 35.069946 waiting for '1024'
mdev[1027]: 35.070151 waiting for '1024'
mdev[1024]: rule matched, line -1
mdev[1024]: mknod vcs9 (7,9) 20660 0:0
mdev[1024]: 35.070346 exiting
mdev[1025]: woken up
mdev[1026]: woken up
mdev[1025]: 35.071213 ACTION:add SUBSYSTEM:vc DEVNAME:vcsa9 DEVPATH:/devices/virtual/vc/vcsa9
            ^^^^^^^^^ took only a millisecond to start running after prev mdev exited
mdev[1025]: dev 7,137
mdev[1027]: woken up
mdev[1025]: rule matched, line -1
mdev[1025]: mknod vcsa9 (7,137) 20660 0:0
mdev[1025]: 35.072109 exiting

function                                             old     new   delta
mdev_main                                            849    1372    +523
curtime                                                -      59     +59
dirAction                                             87     134     +47
static.ts                                              -       8      +8
keywords                                              19      12      -7
make_device                                         2189    2119     -70

Signed-off-by: Denys Vlasenko <vda.linux@googlemail.com>

1 files changed, 177 insertions, 88 deletions

diff --git a/util-linux/mdev.c b/util-linux/mdev.c
index 775e5c241..c5c0d613c 100644
--- a/util-linux/mdev.c
+++ b/util-linux/mdev.c
@@ -230,7 +230,26 @@
  * SUBSYSTEM=block
  */
 
-static const char keywords[] ALIGN1 = "add\0remove\0change\0";
+#define DEBUG_LVL 2
+
+#if DEBUG_LVL >= 1
+# define dbg1(...) do { if (G.verbose) bb_error_msg(__VA_ARGS__); } while(0)
+#else
+# define dbg1(...) ((void)0)
+#endif
+#if DEBUG_LVL >= 2
+# define dbg2(...) do { if (G.verbose >= 2) bb_error_msg(__VA_ARGS__); } while(0)
+#else
+# define dbg2(...) ((void)0)
+#endif
+#if DEBUG_LVL >= 3
+# define dbg3(...) do { if (G.verbose >= 3) bb_error_msg(__VA_ARGS__); } while(0)
+#else
+# define dbg3(...) ((void)0)
+#endif
+
+
+static const char keywords[] ALIGN1 = "add\0remove\0"; // "change\0"
 enum { OP_add, OP_remove };
 
 struct envmatch {
@@ -256,6 +275,7 @@ struct globals {
 	int root_major, root_minor;
 	smallint verbose;
 	char *subsystem;
+	char *subsys_env; /* for putenv("SUBSYSTEM=subsystem") */
 #if ENABLE_FEATURE_MDEV_CONF
 	const char *filename;
 	parser_t *parser;
@@ -263,6 +283,7 @@ struct globals {
 	unsigned rule_idx;
 #endif
 	struct rule cur_rule;
+	char timestr[sizeof("60.123456")];
 } FIX_ALIASING;
 #define G (*(struct globals*)&bb_common_bufsiz1)
 #define INIT_G() do { \
@@ -277,13 +298,6 @@ struct globals {
 /* We use additional 64+ bytes in make_device() */
 #define SCRATCH_SIZE 80
 
-#if 0
-# define dbg(...) bb_error_msg(__VA_ARGS__)
-#else
-# define dbg(...) ((void)0)
-#endif
-
-
 #if ENABLE_FEATURE_MDEV_CONF
 
 static void make_default_cur_rule(void)
@@ -349,7 +363,7 @@ static void parse_next_rule(void)
 			break;
 
 		/* Fields: [-]regex uid:gid mode [alias] [cmd] */
-		dbg("token1:'%s'", tokens[1]);
+		dbg3("token1:'%s'", tokens[1]);
 
 		/* 1st field */
 		val = tokens[0];
@@ -417,7 +431,7 @@ static void parse_next_rule(void)
 		clean_up_cur_rule();
 	} /* while (config_read) */
 
-	dbg("config_close(G.parser)");
+	dbg3("config_close(G.parser)");
 	config_close(G.parser);
 	G.parser = NULL;
 
@@ -434,7 +448,7 @@ static const struct rule *next_rule(void)
 
 	/* Open conf file if we didn't do it yet */
 	if (!G.parser && G.filename) {
-		dbg("config_open('%s')", G.filename);
+		dbg3("config_open('%s')", G.filename);
 		G.parser = config_open2(G.filename, fopen_for_read);
 		G.filename = NULL;
 	}
@@ -443,7 +457,7 @@ static const struct rule *next_rule(void)
 		/* mdev -s */
 		/* Do we have rule parsed already? */
 		if (G.rule_vec[G.rule_idx]) {
-			dbg("< G.rule_vec[G.rule_idx:%d]=%p", G.rule_idx, G.rule_vec[G.rule_idx]);
+			dbg3("< G.rule_vec[G.rule_idx:%d]=%p", G.rule_idx, G.rule_vec[G.rule_idx]);
 			return G.rule_vec[G.rule_idx++];
 		}
 		make_default_cur_rule();
@@ -460,7 +474,7 @@ static const struct rule *next_rule(void)
 			rule = memcpy(xmalloc(sizeof(G.cur_rule)), &G.cur_rule, sizeof(G.cur_rule));
 			G.rule_vec = xrealloc_vector(G.rule_vec, 4, G.rule_idx);
 			G.rule_vec[G.rule_idx++] = rule;
-			dbg("> G.rule_vec[G.rule_idx:%d]=%p", G.rule_idx, G.rule_vec[G.rule_idx]);
+			dbg3("> G.rule_vec[G.rule_idx:%d]=%p", G.rule_idx, G.rule_vec[G.rule_idx]);
 		}
 	}
 
@@ -538,9 +552,6 @@ static void make_device(char *device_name, char *path, int operation)
 {
 	int major, minor, type, len;
 
-	if (G.verbose)
-		bb_error_msg("device: %s, %s", device_name, path);
-
 	/* Try to read major/minor string.  Note that the kernel puts \n after
 	 * the data, so we don't need to worry about null terminating the string
 	 * because sscanf() will stop at the first nondigit, which \n is.
@@ -559,8 +570,7 @@ static void make_device(char *device_name, char *path, int operation)
 			/* no "dev" file, but we can still run scripts
 			 * based on device name */
 		} else if (sscanf(++dev_maj_min, "%u:%u", &major, &minor) == 2) {
-			if (G.verbose)
-				bb_error_msg("maj,min: %u,%u", major, minor);
+			dbg1("dev %u,%u", major, minor);
 		} else {
 			major = -1;
 		}
@@ -570,7 +580,8 @@ static void make_device(char *device_name, char *path, int operation)
 	/* Determine device name, type, major and minor */
 	if (!device_name)
 		device_name = (char*) bb_basename(path);
-	/* http://kernel.org/doc/pending/hotplug.txt says that only
+	/*
+	 * http://kernel.org/doc/pending/hotplug.txt says that only
 	 * "/sys/block/..." is for block devices. "/sys/bus" etc is not.
 	 * But since 2.6.25 block devices are also in /sys/class/block.
 	 * We use strstr("/block/") to forestall future surprises.
@@ -608,7 +619,7 @@ static void make_device(char *device_name, char *path, int operation)
 		}
 		if (rule->envvar) { /* $envvar=regex rule */
 			str_to_match = getenv(rule->envvar);
-			dbg("getenv('%s'):'%s'", rule->envvar, str_to_match);
+			dbg3("getenv('%s'):'%s'", rule->envvar, str_to_match);
 			if (!str_to_match)
 				continue;
 		}
@@ -616,7 +627,7 @@ static void make_device(char *device_name, char *path, int operation)
 
 		if (rule->regex_compiled) {
 			int regex_match = regexec(&rule->match, str_to_match, ARRAY_SIZE(off), off, 0);
-			dbg("regex_match for '%s':%d", str_to_match, regex_match);
+			dbg3("regex_match for '%s':%d", str_to_match, regex_match);
 			//bb_error_msg("matches:");
 			//for (int i = 0; i < ARRAY_SIZE(off); i++) {
 			//	if (off[i].rm_so < 0) continue;
@@ -636,7 +647,7 @@ static void make_device(char *device_name, char *path, int operation)
 		/* else: it's final implicit "match-all" rule */
  rule_matches:
 #endif
-		dbg("rule matched");
+		dbg2("rule matched, line %d", G.parser ? G.parser->lineno : -1);
 
 		/* Build alias name */
 		alias = NULL;
@@ -680,34 +691,30 @@ static void make_device(char *device_name, char *path, int operation)
 				}
 			}
 		}
-		dbg("alias:'%s'", alias);
+		dbg3("alias:'%s'", alias);
 
 		command = NULL;
 		IF_FEATURE_MDEV_EXEC(command = rule->r_cmd;)
 		if (command) {
-			const char *s = "$@*";
-			const char *s2 = strchr(s, command[0]);
-
 			/* Are we running this command now?
-			 * Run $cmd on delete, @cmd on create, *cmd on both
+			 * Run @cmd on create, $cmd on delete, *cmd on any
 			 */
-			if (s2 - s != (operation == OP_remove) || *s2 == '*') {
-				/* We are here if: '*',
-				 * or: '@' and delete = 0,
-				 * or: '$' and delete = 1
-				 */
+			if ((command[0] == '@' && operation == OP_add)
+			 || (command[0] == '$' && operation == OP_remove)
+			 || (command[0] == '*')
+			) {
 				command++;
 			} else {
 				command = NULL;
 			}
 		}
-		dbg("command:'%s'", command);
+		dbg3("command:'%s'", command);
 
 		/* "Execute" the line we found */
 		node_name = device_name;
 		if (ENABLE_FEATURE_MDEV_RENAME && alias) {
 			node_name = alias = build_alias(alias, device_name);
-			dbg("alias2:'%s'", alias);
+			dbg3("alias2:'%s'", alias);
 		}
 
 		if (operation == OP_add && major >= 0) {
@@ -717,13 +724,20 @@ static void make_device(char *device_name, char *path, int operation)
 				mkdir_recursive(node_name);
 				*slash = '/';
 			}
-			if (G.verbose)
-				bb_error_msg("mknod: %s (%d,%d) %o", node_name, major, minor, rule->mode | type);
+			if (ENABLE_FEATURE_MDEV_CONF) {
+				dbg1("mknod %s (%d,%d) %o"
+					" %u:%u",
+					node_name, major, minor, rule->mode | type,
+					rule->ugid.uid, rule->ugid.gid
+				);
+			} else {
+				dbg1("mknod %s (%d,%d) %o",
+					node_name, major, minor, rule->mode | type
+				);
+			}
 			if (mknod(node_name, rule->mode | type, makedev(major, minor)) && errno != EEXIST)
 				bb_perror_msg("can't create '%s'", node_name);
 			if (ENABLE_FEATURE_MDEV_CONF) {
-				if (G.verbose)
-					bb_error_msg("chmod: %o chown: %u:%u", rule->mode, rule->ugid.uid, rule->ugid.gid);
 				chmod(node_name, rule->mode);
 				chown(node_name, rule->ugid.uid, rule->ugid.gid);
 			}
@@ -734,8 +748,7 @@ static void make_device(char *device_name, char *path, int operation)
 //TODO: on devtmpfs, device_name already exists and symlink() fails.
 //End result is that instead of symlink, we have two nodes.
 //What should be done?
-					if (G.verbose)
-						bb_error_msg("symlink: %s", device_name);
+					dbg1("symlink: %s", device_name);
 					symlink(node_name, device_name);
 				}
 			}
@@ -744,27 +757,21 @@ static void make_device(char *device_name, char *path, int operation)
 		if (ENABLE_FEATURE_MDEV_EXEC && command) {
 			/* setenv will leak memory, use putenv/unsetenv/free */
 			char *s = xasprintf("%s=%s", "MDEV", node_name);
-			char *s1 = xasprintf("%s=%s", "SUBSYSTEM", G.subsystem);
 			putenv(s);
-			putenv(s1);
-			if (G.verbose)
-				bb_error_msg("running: %s", command);
+			dbg1("running: %s", command);
 			if (system(command) == -1)
 				bb_perror_msg("can't run '%s'", command);
-			bb_unsetenv_and_free(s1);
 			bb_unsetenv_and_free(s);
 		}
 
 		if (operation == OP_remove && major >= -1) {
 			if (ENABLE_FEATURE_MDEV_RENAME && alias) {
 				if (aliaslink == '>') {
-					if (G.verbose)
-						bb_error_msg("unlink: %s", device_name);
+					dbg1("unlink: %s", device_name);
 					unlink(device_name);
 				}
 			}
-			if (G.verbose)
-				bb_error_msg("unlink: %s", node_name);
+			dbg1("unlink: %s", node_name);
 			unlink(node_name);
 		}
 
@@ -809,10 +816,15 @@ static int FAST_FUNC dirAction(const char *fileName UNUSED_PARAM,
 	 * under /sys/class/ */
 	if (1 == depth) {
 		free(G.subsystem);
+		if (G.subsys_env) {
+			bb_unsetenv_and_free(G.subsys_env);
+			G.subsys_env = NULL;
+		}
 		G.subsystem = strrchr(fileName, '/');
 		if (G.subsystem) {
 			G.subsystem = xstrdup(G.subsystem + 1);
-			xsetenv("SUBSYSTEM", G.subsystem);
+			G.subsys_env = xasprintf("%s=%s", "SUBSYSTEM", G.subsystem);
+			putenv(G.subsys_env);
 		}
 	}
 
@@ -885,6 +897,100 @@ static void load_firmware(const char *firmware, const char *sysfs_path)
 	}
 }
 
+static char *curtime(void)
+{
+	struct timeval tv;
+	gettimeofday(&tv, NULL);
+	sprintf(G.timestr, "%u.%06u", (unsigned)tv.tv_sec % 60, (unsigned)tv.tv_usec);
+	return G.timestr;
+}
+
+static void open_mdev_log(const char *seq, unsigned my_pid)
+{
+	int logfd = open("mdev.log", O_WRONLY | O_APPEND);
+	if (logfd >= 0) {
+		xmove_fd(logfd, STDERR_FILENO);
+		G.verbose = 2;
+		applet_name = xasprintf("%s[%s]", applet_name, seq ? seq : utoa(my_pid));
+	}
+}
+
+/* If it exists, does /dev/mdev.seq match $SEQNUM?
+ * If it does not match, earlier mdev is running
+ * in parallel, and we need to wait.
+ * Active mdev pokes us with SIGCHLD to check the new file.
+ */
+static int
+wait_for_seqfile(const char *seq)
+{
+	/* We time out after 2 sec */
+	static const struct timespec ts = { 0, 32*1000*1000 };
+	int timeout = 2000 / 32;
+	int seq_fd = -1;
+	int do_once = 1;
+	sigset_t set_CHLD;
+
+	sigemptyset(&set_CHLD);
+	sigaddset(&set_CHLD, SIGCHLD);
+	sigprocmask(SIG_BLOCK, &set_CHLD, NULL);
+
+	for (;;) {
+		int seqlen;
+		char seqbuf[sizeof(int)*3 + 2];
+
+		if (seq_fd < 0) {
+			seq_fd = open("mdev.seq", O_RDWR);
+			if (seq_fd < 0)
+				break;
+		}
+		seqlen = pread(seq_fd, seqbuf, sizeof(seqbuf) - 1, 0);
+		if (seqlen < 0) {
+			close(seq_fd);
+			seq_fd = -1;
+			break;
+		}
+		seqbuf[seqlen] = '\0';
+		if (seqbuf[0] == '\n') {
+			/* seed file: write out seq ASAP */
+			xwrite_str(seq_fd, seq);
+			xlseek(seq_fd, 0, SEEK_SET);
+			dbg2("first seq written");
+			break;
+		}
+		if (strcmp(seq, seqbuf) == 0) {
+			/* correct idx */
+			break;
+		}
+		if (do_once) {
+			dbg2("%s waiting for '%s'", curtime(), seqbuf);
+			do_once = 0;
+		}
+		if (sigtimedwait(&set_CHLD, NULL, &ts) >= 0) {
+			dbg3("woken up");
+			continue; /* don't decrement timeout! */
+		}
+		if (--timeout == 0) {
+			dbg1("%s waiting for '%s'", "timed out", seqbuf);
+			break;
+		}
+	}
+	sigprocmask(SIG_UNBLOCK, &set_CHLD, NULL);
+	return seq_fd;
+}
+
+static void signal_mdevs(unsigned my_pid)
+{
+	procps_status_t* p = NULL;
+	while ((p = procps_scan(p, PSSCAN_ARGV0)) != NULL) {
+		if (p->pid != my_pid
+		 && p->argv0
+		 && strcmp(bb_basename(p->argv0), "mdev") == 0
+		) {
+			kill(p->pid, SIGCHLD);
+		}
+	}
+}
+
 int mdev_main(int argc, char **argv) MAIN_EXTERNALLY_VISIBLE;
 int mdev_main(int argc UNUSED_PARAM, char **argv)
 {
@@ -946,11 +1052,13 @@ int mdev_main(int argc UNUSED_PARAM, char **argv)
 		char *action;
 		char *env_devname;
 		char *env_devpath;
+		unsigned my_pid;
+		int seq_fd;
 		smalluint op;
 
 		/* Hotplug:
 		 * env ACTION=... DEVPATH=... SUBSYSTEM=... [SEQNUM=...] mdev
-		 * ACTION can be "add" or "remove"
+		 * ACTION can be "add", "remove", "change"
 		 * DEVPATH is like "/block/sda" or "/class/input/mice"
 		 */
 		action = getenv("ACTION");
@@ -961,41 +1069,20 @@ int mdev_main(int argc UNUSED_PARAM, char **argv)
 		if (!action || !env_devpath /*|| !G.subsystem*/)
 			bb_show_usage();
 		fw = getenv("FIRMWARE");
-		/* If it exists, does /dev/mdev.seq match $SEQNUM?
-		 * If it does not match, earlier mdev is running
-		 * in parallel, and we need to wait */
 		seq = getenv("SEQNUM");
-		if (seq) {
-			int timeout = 2000 / 32; /* 2000 msec */
-			do {
-				int seqlen;
-				char seqbuf[sizeof(int)*3 + 2];
-
-				seqlen = open_read_close("mdev.seq", seqbuf, sizeof(seqbuf) - 1);
-				if (seqlen < 0) {
-					seq = NULL;
-					break;
-				}
-				seqbuf[seqlen] = '\0';
-				if (seqbuf[0] == '\n' /* seed file? */
-				 || strcmp(seq, seqbuf) == 0 /* correct idx? */
-				) {
-					break;
-				}
-				usleep(32*1000);
-			} while (--timeout);
-		}
 
-		{
-			int logfd = open("mdev.log", O_WRONLY | O_APPEND);
-			if (logfd >= 0) {
-				xmove_fd(logfd, STDERR_FILENO);
-				G.verbose = 1;
-				if (seq)
-					applet_name = xasprintf("%s[%s]", applet_name, seq);
-				bb_error_msg("action: %s", action);
-			}
-		}
+		my_pid = getpid();
+		open_mdev_log(seq, my_pid);
+
+		seq_fd = seq ? wait_for_seqfile(seq) : -1;
+
+		dbg1("%s "
+			"ACTION:%s SUBSYSTEM:%s DEVNAME:%s DEVPATH:%s"
+			"%s%s",
+			curtime(),
+			action, G.subsystem, env_devname, env_devpath,
+			fw ? " FW:" : "", fw ? fw : ""
+		);
 
 		snprintf(temp, PATH_MAX, "/sys%s", env_devpath);
 		if (op == OP_remove) {
@@ -1005,16 +1092,18 @@ int mdev_main(int argc UNUSED_PARAM, char **argv)
 			if (!fw)
 				make_device(env_devname, temp, op);
 		}
-		else if (op == OP_add) {
+		else {
 			make_device(env_devname, temp, op);
 			if (ENABLE_FEATURE_MDEV_LOAD_FIRMWARE) {
-				if (fw)
+				if (op == OP_add && fw)
 					load_firmware(fw, temp);
 			}
 		}
 
-		if (seq) {
-			xopen_xwrite_close("mdev.seq", utoa(xatou(seq) + 1));
+		dbg1("%s exiting", curtime());
+		if (seq_fd >= 0) {
+			xwrite_str(seq_fd, utoa(xatou(seq) + 1));
+			signal_mdevs(my_pid);
 		}
 	}