finally solve the bad sysfs-timing for all of us

[Kay Sievers <kay.sievers@vrfy.org>]

[-- Attachment #1: Type: text/plain, Size: 3912 bytes --]

During the integration of HAL into the linux hotplug system, we dicover
every week a new signaling path that fails cause of the delayed
population of the sysfs files, which are connected by symlinks and
appear in something like a random order in userspace.

It's pretty complicated to understand the connection between all these
files for all the different subsystems with all the exceptions, so most
of the users simply sleep a few seconds, but that is not acceptable for
our integration work.

Here I try to get all the special knowledge about that behavior together
and place that in a simple binary. That program _must_ run first of all
other hotplug processsing and every later script, udev or HAL all can get
rid of the wild guesses about the right time sysfs is ready.

It will not only wait for the "dev"-file events we handle with udev, also
for every /device-device with the corresponding bus link.

It is provided as a patch against the current udev tree and a "install" will
place the new program in the hotplug.d directory:

  [kay@pim ~]$ tree /etc/hotplug.d/
  /etc/hotplug.d/
  `-- default
      |-- 00-wait_for_sysfs.hotplug -> /sbin/wait_for_sysfs
      |-- 10-udev.hotplug -> /sbin/udevsend
      |-- 20-hal.hotplug -> /usr/libexec/hal.hotplug
      |-- default.hotplug
      `-- log.hotplug


For now, it logs the result of the waiting to syslog, to catch any
device, that needs special treatment. All newly discovered delay problems,
device black/whitelist updates should go into that program and we may remove
that kind of specialisation from all the other hotplug programs.

Any patches, reports, testing is more than welcome.

Sample debug:
  Sep 21 18:44:07 localhost kernel: usb 3-2: new full speed USB device using address 12
  Sep 21 18:44:07 localhost kernel: hub 3-2:1.0: USB hub found
  Sep 21 18:44:07 localhost kernel: hub 3-2:1.0: 2 ports detected
  Sep 21 18:44:07 localhost 00-wait_for_sysfs.hotplug: result: waiting for sysfs successful '/devices/pci0000:00/0000:00:1d.1/usb3/3-2'
  Sep 21 18:44:07 localhost 00-wait_for_sysfs.hotplug: result: waiting for sysfs successful '/devices/pci0000:00/0000:00:1d.1/usb3/3-2/3-2:1.0'
  Sep 21 18:44:08 localhost kernel: usb 3-2.1: new full speed USB device using address 13
  Sep 21 18:44:08 localhost 00-wait_for_sysfs.hotplug: result: waiting for sysfs successful '/class/usb/lp0'
  Sep 21 18:44:08 localhost kernel: drivers/usb/class/usblp.c: usblp0: USB Bidirectional printer dev 13 if 0 alt 1 proto 2 vid 0x067B pid 0x2305
  Sep 21 18:44:08 localhost 00-wait_for_sysfs.hotplug: result: waiting for sysfs successful '/devices/pci0000:00/0000:00:1d.1/usb3/3-2/3-2.1/3-2.1:1.0'
  Sep 21 18:44:08 localhost 00-wait_for_sysfs.hotplug: result: waiting for sysfs successful '/devices/pci0000:00/0000:00:1d.1/usb3/3-2/3-2.1'
  Sep 21 18:44:08 localhost udev: configured rule in '/etc/udev/rules.d/50-udev.rules' at line 29 applied, 'lp0' becomes 'usb/%k'
  Sep 21 18:44:08 localhost udev: creating device node '/udev/usb/lp0'
  Sep 21 18:44:09 localhost kernel: usb 3-2.2: new full speed USB device using address 14
  Sep 21 18:44:09 localhost kernel: pl2303 3-2.2:1.0: PL-2303 converter detected
  Sep 21 18:44:09 localhost kernel: usb 3-2.2: PL-2303 converter now attached to ttyUSB0
  Sep 21 18:44:09 localhost 00-wait_for_sysfs.hotplug: result: waiting for sysfs successful '/devices/pci0000:00/0000:00:1d.1/usb3/3-2/3-2.2'
  Sep 21 18:44:09 localhost 00-wait_for_sysfs.hotplug: result: waiting for sysfs successful '/devices/pci0000:00/0000:00:1d.1/usb3/3-2/3-2.2/3-2.2:1.0'
  Sep 21 18:44:09 localhost 00-wait_for_sysfs.hotplug: result: waiting for sysfs successful '/devices/pci0000:00/0000:00:1d.1/usb3/3-2/3-2.2/3-2.2:1.0/ttyUSB0'
  Sep 21 18:44:09 localhost 00-wait_for_sysfs.hotplug: result: waiting for sysfs successful '/class/tty/ttyUSB0'
  Sep 21 18:44:09 localhost udev: creating device node '/udev/ttyUSB0'

Thanks,
Kay

[-- Attachment #2: wait-for-sysfs-01.patch --]
[-- Type: text/plain, Size: 10837 bytes --]

diff -Nru a/Makefile b/Makefile
--- a/Makefile	2004-09-21 18:45:16 +02:00
+++ b/Makefile	2004-09-21 18:45:16 +02:00
@@ -33,6 +33,7 @@
 TESTER =	udevtest
 STARTER =	udevstart
 RULER =		udevruler
+WAIT =		wait_for_sysfs
 VERSION =	032
 INSTALL_DIR =	/usr/local/bin
 RELEASE_NAME =	$(ROOT)-$(VERSION)
@@ -172,7 +173,7 @@
 
 CFLAGS += -I$(PWD)/libsysfs
 
-all: $(ROOT) $(SENDER) $(DAEMON) $(INFO) $(TESTER)
+all: $(ROOT) $(SENDER) $(DAEMON) $(INFO) $(TESTER) $(WAIT)
 	@extras="$(EXTRAS)" ; for target in $$extras ; do \
 		echo $$target ; \
 		$(MAKE) prefix=$(prefix) \
@@ -285,10 +286,14 @@
 	$(LD) $(LDFLAGS) -o $@ $(CRT0) udevruler.o udev_lib.o udev_config.o udevdb.o $(SYSFS) $(TDB) $(LIB_OBJS) $(ARCH_LIB_OBJS) -lnewt
 	$(STRIPCMD) $@
 
+$(WAIT): $(WAIT).o $(OBJS) $(HEADERS) $(LIBC)
+	$(LD) $(LDFLAGS) -o $@ $(CRT0) $(WAIT).o $(SYSFS) $(LIB_OBJS) $(ARCH_LIB_OBJS)
+	$(STRIPCMD) $@
+
 clean:
 	-find . \( -not -type d \) -and \( -name '*~' -o -name '*.[oas]' \) -type f -print \
 	 | xargs rm -f 
-	-rm -f core $(ROOT) $(GEN_HEADERS) $(GEN_CONFIGS) $(GEN_MANPAGES) $(INFO) $(DAEMON) $(SENDER) $(TESTER) $(RULER)
+	-rm -f core $(ROOT) $(GEN_HEADERS) $(GEN_CONFIGS) $(GEN_MANPAGES) $(INFO) $(DAEMON) $(SENDER) $(TESTER) $(RULER) $(WAIT)
 	$(MAKE) -C klibc clean
 	@extras="$(EXTRAS)" ; for target in $$extras ; do \
 		echo $$target ; \
@@ -388,8 +393,10 @@
 	$(INSTALL_PROGRAM) -D $(SENDER) $(DESTDIR)$(sbindir)/$(SENDER)
 	$(INSTALL_PROGRAM) -D $(INFO) $(DESTDIR)$(usrbindir)/$(INFO)
 	$(INSTALL_PROGRAM) -D $(TESTER) $(DESTDIR)$(usrbindir)/$(TESTER)
-	ln -sf $(sbindir)/udev $(DESTDIR)$(sbindir)/$(STARTER)
+	$(INSTALL_PROGRAM) -D $(WAIT) $(DESTDIR)$(sbindir)/$(WAIT)
+	- ln -f -s $(sbindir)/udev $(DESTDIR)$(sbindir)/$(STARTER)
 	- ln -f -s $(sbindir)/$(SENDER) $(DESTDIR)$(hotplugdir)/10-udev.hotplug
+	- ln -f -s $(sbindir)/$(WAIT) $(DESTDIR)$(hotplugdir)/00-wait_for_sysfs.hotplug
 ifndef DESTDIR
 	- killall udevd
 	- rm -f $(udevdir)/.udev.tdb
@@ -402,6 +409,7 @@
 
 uninstall: uninstall-man uninstall-dev.d
 	- rm $(hotplugdir)/10-udev.hotplug
+	- rm $(hotplugdir)/00-wait_for_sysfs.hotplug
 	- rm $(configdir)/rules.d/50-udev.rules
 	- rm $(configdir)/permissions.d/50-udev.permissions
 	- rm $(configdir)/udev.conf
@@ -415,6 +423,7 @@
 	- rm $(sbindir)/$(STARTER)
 	- rm $(usrbindir)/$(INFO)
 	- rm $(usrbindir)/$(TESTER)
+	- rm $(usrbindir)/$(WAIT)
 	- rmdir $(hotplugdir)
 	- rm $(udevdir)/.udev.tdb
 	- rmdir $(udevdir)
diff -Nru a/wait_for_sysfs.c b/wait_for_sysfs.c
--- /dev/null	Wed Dec 31 16:00:00 196900
+++ b/wait_for_sysfs.c	2004-09-21 18:45:16 +02:00
@@ -0,0 +1,316 @@
+/*
+ * wait_for_sysfs.c  - small program to delay the execution
+ *		       of /etc/hotplug.d/ programs, until sysfs
+ *		       is populated by the kernel. Depending on
+ *		       the type of device, we wait for all expected
+ *		       directories and then just exit.
+ *
+ * Copyright (C) 2004 Kay Sievers <kay.sievers@vrfy.org>
+ *
+ *	This program is free software; you can redistribute it and/or modify it
+ *	under the terms of the GNU General Public License as published by the
+ *	Free Software Foundation version 2 of the License.
+ * 
+ *	This program is distributed in the hope that it will be useful, but
+ *	WITHOUT ANY WARRANTY; without even the implied warranty of
+ *	MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
+ *	General Public License for more details.
+ * 
+ *	You should have received a copy of the GNU General Public License along
+ *	with this program; if not, write to the Free Software Foundation, Inc.,
+ *	675 Mass Ave, Cambridge, MA 02139, USA.
+ *
+ */
+
+#include <stdio.h>
+#include <stddef.h>
+#include <stdlib.h>
+#include <unistd.h>
+#include <string.h>
+#include <ctype.h>
+#include <errno.h>
+#include <sys/stat.h>
+
+#include "logging.h"
+#include "libsysfs/sysfs/libsysfs.h"
+
+#ifdef LOG
+unsigned char logname[LOGNAME_SIZE];
+void log_message(int level, const char *format, ...)
+{
+	va_list args;
+
+	va_start(args, format);
+	vsyslog(level, format, args);
+	va_end(args);
+}
+#endif
+
+#define WAIT_MAX_SECONDS		5
+#define WAIT_LOOP_PER_SECOND		20
+
+static int wait_for_class_device_attributes(struct sysfs_class_device *class_dev)
+{
+	static struct class_file {
+		char *subsystem;
+		char *file;
+	} class_files[] = {
+		{ .subsystem = "net",		.file = "ifindex" },
+		{ .subsystem = "usb_host",	.file = "" },
+		{ .subsystem = "pcmcia_socket",	.file = "" },
+		{ NULL, NULL }
+	};
+	struct class_file *classfile;
+	const char *file = "dev";
+	int loop;
+
+	/* look if we want to look for another file instead of "dev" */
+	for (classfile = class_files; classfile->subsystem != NULL; classfile++) {
+		if (strcmp(class_dev->classname, classfile->subsystem) == 0) {
+			dbg("looking at class '%s' for specific file '%s'", class_dev->classname, classfile->file);
+			file = classfile->file;
+		}
+	}
+
+	loop = WAIT_MAX_SECONDS * WAIT_LOOP_PER_SECOND;
+	while (--loop) {
+		if (sysfs_get_classdev_attr(class_dev, file) != NULL) {
+			dbg("class '%s' specific file '%s' found", class_dev->classname, file);
+			return 0;
+		}
+	}
+
+	dbg("error: getting bus '%s' specific file '%s'", class_dev->classname, file);
+	return -1;
+}
+
+static int class_device_expect_no_device_link(struct sysfs_class_device *class_dev)
+{
+	char **device;
+
+	static char *devices_without_link[] = {
+		"nb",
+		"ram",
+		"loop",
+		"fd",
+		"md",
+		"dos_cd",
+		"double",
+		"flash",
+		"msd",
+		"rflash",
+		"rom",
+		"rrom",
+		"sbpcd",
+		"pcd",
+		"pf",
+		"scd",
+		"sit",
+		"lp",
+		"ubd",
+		"vcs",
+		"vcsa",
+		NULL
+	};
+
+	for (device = devices_without_link; *device != NULL; device++) {
+		if (strncmp(class_dev->name, *device, strlen(*device)) == 0)
+			return 1;
+	}
+
+	return 0;
+}
+
+static int wait_for_bus_device(struct sysfs_device *device_dev)
+{
+	static struct bus_file {
+		char *bus;
+		char *file;
+	} bus_files[] = {
+		{ .bus = "scsi",	.file = "vendor" },
+		{ .bus = "usb",		.file = "idVendor" },
+		{ .bus = "usb",		.file = "iInterface" },
+		{ .bus = "usb-serial",	.file = "detach_state" },
+		{ .bus = "ide",		.file = "detach_state" },
+		{ .bus = "pci",		.file = "vendor" },
+		{ NULL }
+	};
+	struct bus_file *busfile;
+	int loop;
+
+	/* wait for the /bus-device link to the /device-device */
+	loop = WAIT_MAX_SECONDS * WAIT_LOOP_PER_SECOND;
+	while (--loop) {
+		if (sysfs_get_device_bus(device_dev) == 0)
+			break;
+
+		usleep(1000 * 1000 / WAIT_LOOP_PER_SECOND);
+	}
+	if (loop == 0) {
+		dbg("error: getting /bus-device link");
+		return -1;
+	}
+	dbg("/bus-device link found for bus '%s'", device_dev->bus);
+
+	/* wait for a bus specific file to show up */
+	loop = WAIT_MAX_SECONDS * WAIT_LOOP_PER_SECOND;
+	while (--loop) {
+		for (busfile = bus_files; busfile->bus != NULL; busfile++) {
+			if (strcmp(device_dev->bus, busfile->bus) == 0) {
+				dbg("looking at bus '%s' for specific file '%s'", device_dev->bus, busfile->file);
+				if (sysfs_get_device_attr(device_dev, busfile->file) != NULL) {
+					dbg("bus '%s' specific file '%s' found", device_dev->bus, busfile->file);
+					return 0;
+				}
+				if (busfile->bus == NULL) {
+					info("error: unknown bus, update the build-in list '%s'", device_dev->bus);
+					return -1;
+				}
+			}
+		}
+	}
+
+	dbg("error: getting bus '%s' specific file '%s'", device_dev->bus, busfile->file);
+	return -1;
+}
+
+int main(int argc, char *argv[], char *envp[])
+{
+	const char *devpath = "";
+	const char *action;
+	const char *subsystem;
+	char sysfs_path[SYSFS_PATH_MAX];
+	char filename[SYSFS_PATH_MAX];
+	struct sysfs_class_device *class_dev;
+	struct sysfs_class_device *class_dev_parent;
+	struct sysfs_device *device_dev = NULL;
+	int loop;
+	int rc = 0;
+
+	if (argc != 2) {
+		dbg("error: subsystem");
+		return 1;
+	}
+	subsystem = argv[1];
+
+	devpath = getenv ("DEVPATH");
+	if (!devpath) {
+		dbg("error: no DEVPATH");
+		return 1;
+	}
+
+	action = getenv ("ACTION");
+	if (!action) {
+		dbg("error: no ACTION");
+		return 1;
+	}
+
+	if (strcmp(action, "add") != 0)
+		return 0;
+
+	if (sysfs_get_mnt_path(sysfs_path, SYSFS_PATH_MAX) != 0) {
+		dbg("error: no sysfs path");
+		return 2;
+	}
+
+	if ((strncmp(devpath, "/block/", 7) == 0) || (strncmp(devpath, "/class/", 7) == 0)) {
+		/* open the class device we are called for */
+		snprintf(filename, SYSFS_PATH_MAX-1, "%s%s", sysfs_path, devpath);
+		filename[SYSFS_PATH_MAX-1] = '\0';
+
+		loop = WAIT_MAX_SECONDS * WAIT_LOOP_PER_SECOND;
+		while (--loop) {
+			class_dev = sysfs_open_class_device_path(filename);
+			if (class_dev)
+				break;
+		}
+		if (class_dev == NULL) {
+			dbg("error: getting class_device");
+			rc = 4;
+			goto exit;
+		}
+		dbg("class_device opened '%s'", filename);
+
+		wait_for_class_device_attributes(class_dev);
+
+		if (class_device_expect_no_device_link(class_dev)) {
+			dbg("no device symlink expected");
+			sysfs_close_class_device(class_dev);
+			goto exit;
+		}
+
+		/* the symlink may be on the parent device */
+		class_dev_parent = sysfs_get_classdev_parent(class_dev);
+		if (class_dev_parent)
+			dbg("looking at parent device for device link '%s'", class_dev_parent->path);
+
+		/* wait for the symlink to the /device-device */
+		dbg("waiting for symlink to /device-device");
+		loop = WAIT_MAX_SECONDS * WAIT_LOOP_PER_SECOND;
+		while (--loop) {
+			if (class_dev_parent)
+				device_dev = sysfs_get_classdev_device(class_dev_parent);
+			else
+				device_dev = sysfs_get_classdev_device(class_dev);
+
+			if (device_dev)
+				break;
+
+			usleep(1000 * 1000 / WAIT_LOOP_PER_SECOND);
+		}
+		if (device_dev == NULL) {
+			dbg("error: getting /device-device");
+			sysfs_close_class_device(class_dev);
+			rc = 5;
+			goto exit;
+		}
+		dbg("device symlink found pointing to '%s'", device_dev->path);
+
+		/* wait for the bus value */
+		if (wait_for_bus_device(device_dev) != 0)
+			rc = 6;
+		sysfs_close_class_device(class_dev);
+
+		/* finished */
+		goto exit;
+
+	} else if ((strncmp(devpath, "/devices/", 9) == 0)) {
+		/* open the path we are called for */
+		snprintf(filename, SYSFS_PATH_MAX-1, "%s%s", sysfs_path, devpath);
+		filename[SYSFS_PATH_MAX-1] = '\0';
+
+		loop = WAIT_MAX_SECONDS * WAIT_LOOP_PER_SECOND;
+		while (--loop) {
+			device_dev = sysfs_open_device_path(filename);
+			if (device_dev)
+				break;
+		}
+		if (device_dev == NULL) {
+			dbg("error: getting /device-device");
+			rc = 4;
+			goto exit;
+		}
+		dbg("device_device opened '%s'", filename);
+
+		/* wait for the bus value */
+		if (wait_for_bus_device(device_dev) != 0)
+			rc = 9;
+
+		sysfs_close_device(device_dev);
+
+		/* finished */
+		goto exit;
+
+	} else {
+		dbg("error: unhandled sysfs path");
+		rc = 10;
+	}
+
+exit:
+	if (rc == 0)
+		info("result: waiting for sysfs successful '%s'", devpath);
+	else
+		info("result: waiting for sysfs failed '%s'", devpath);
+
+	return rc;
+}