Re: finally solve the bad sysfs-timing for all of us

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

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

On Tue, Sep 21, 2004 at 07:17:34PM +0200, Kay Sievers wrote:
> 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'

New version with more devices excluded from /device-link saerch and
a better maching for device names.

Thanks,
Kay

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

diff -Nru a/Makefile b/Makefile
--- a/Makefile	2004-09-21 22:00:29 +02:00
+++ b/Makefile	2004-09-21 22:00:29 +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 22:00:29 +02:00
@@ -0,0 +1,334 @@
+/*
+ * 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 = NULL },
+		{ .subsystem = "pcmcia_socket",	.file = NULL },
+		{ 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) {
+			if (classfile->file == NULL) {
+				dbg("class '%s' has no file to wait for", class_dev->classname);
+				return 0;
+			}
+			file = classfile->file;
+			break;
+		}
+	}
+	dbg("looking at class '%s' for specific file '%s'", class_dev->classname, 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",
+		"console",
+		"tty",
+		"ttyS",
+		NULL
+	};
+
+	for (device = devices_without_link; *device != NULL; device++) {
+		int len = strlen(*device);
+
+		/* look if name matches */
+		if (strncmp(class_dev->name, *device, len) != 0)
+			continue;
+
+		/* exact match */
+		if (strlen(class_dev->name) == len)
+			return 1;
+
+		/* instance numbers are matching too */
+		if (isdigit(class_dev->name[len]))
+			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("unhandled sysfs path, no need to wait");
+	}
+
+exit:
+	if (rc == 0)
+		info("result: waiting for sysfs successful '%s'", devpath);
+	else
+		info("result: waiting for sysfs failed '%s'", devpath);
+
+	return rc;
+}