run/udev/links not working automatically...

[onimatrix81]

What I have done (and what does /run/udev look like after each step):

1. start vdevd in the sysinit (tree /run/udev http://pastebin.com/sTHrB3BS )
2. as it's obvious vdevd didn't create all the stuff there (I suspect this is because of the wrong runlevel and/or service order, but $
   All is fine at that point, I start X and mouse and keyboard work fine.
   Then I remove the usb mouse and plug it back in and it won't start working.
   Here's the /run/udev tree after this http://pastebin.com/401s4Ak7
   and here's the vdevd.log including the mouse disco/reconnection: https://bpaste.net/show/7572e90b1bbe

At this point restarting vdevd is of no use.
After not having a mouse, I killed xorg from a terminal and dropped off at console, logged out my user and as root restarted vdev. This gave me the right /run/udev/links directories and I could log back in as user and start xorg with a working mouse

Anyways, here's the Xorg.0.log.old too https://bpaste.net/show/d99731e7d17a (it seems as if evdev is removing the mouse when it closes down, not when I disconnected the mouse?)

Sorry if this seems incoherent :) I'm happy to follow any advice for testing this stuff if it could be simplier.

[jcnelson]

Hi @onimatrix81,

Thank you as always for your reports! Apologies for not replying sooner; my $DAYJOB has been keeping me extremely busy this week :/.

There are a couple interesting things happening in your logs related to the event-pushing and udev compatibility code. What I suspect is happening is that there's a bug in one of the scripts that accidentally removes most symlinks. I think you are also seeing this in #47.

I will dig deeper into this this weekend, and see if I can duplicate the problem on my end. The errors in the Xorg log are probably due to the fact that Xorg still thinks your mouse is present, and gets confused when it tries to shut it down.

Thank you again for everything!

[onimatrix81]

Heh, don't sweat it about replying instantly. One thing you should maybe add/improve is the debug messages. I mean I for one wouldn't be bothered if vdevd/scripts produced tons of debug info. Maybe make the individual scripts log in their own files too? And log EVERYTHING.

Also, one thing: if I rm /run/vdev/vdevd.log while the daemon is running, the daemon won't write to that file any more. I mean, it would be handy to start from an empty slate when I start for example diddling with the mouse.

[fbt]

Does vdevd reopen file descriptors on reload? If so, then move/remove the file and reload vdevd. If not, do the same, but restart the thing.

[onimatrix81]

fbt, I'm not sure what this "reload" is? Anyways, restarting the daemon works to some extent, but there's still kazillion lines of debug messages produced just by starting the daemon up.

[fbt]

Sorry, I've used the wrong terminology, because reload is not some magical thing.

I've just tested, and vdev just dies on SIGHUP, which is usually the signal daemons catch and re-read configs, re-open files, etc. So no reload for vdev (yet?).

[onimatrix81]

Oh yeah. That realoading functionality would be cool too, although I'd still like to see giga-debug-logger thingie that makes logs for each of the helpers and something readable instead of numeric error codes :).

[onimatrix81]

This might be interesting. http://pastebin.com/cDjChZrQ That's a part of vdevd log of mouse getting disconnected. I've been playing around for a while though, but you can see some sort of pattern there. I mean:
09730:00007F9194AAB700: [ device.c:0651] vdev_device_remove_metadata_file: WARN: removing '/dev/metadata//dev/input/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2' rc = -40

looks bad, right =).
Anyways, I caught that while I was trying to figure out why is it that if I run rm -rf /run/udev/* restart vdevd while xorg is running, the run/udev/input/links directories don't all appear, but when I stop xorg, log my user out and do the same, they do... I'm none the wiser, but here are the logs:
Restarting vdevd while Xorg is running: http://pastebin.com/cDjChZrQ
Restarting vdevd with Corg not running: https://bpaste.net/show/ca715ee77ef0
I also added a bunch of echos piped to a file to udev-compat.sh (trying to be careful not to mess anything up).
Here's what I got from it with Xorg running: https://bpaste.net/show/37a693b05faf
And the same when restarting vdevd after shutting down Xorg: https://bpaste.net/show/6e96f03e494f

[jcnelson]

@fbt Vdev currently does not handle SIGHUP, but it should reload its config (just opened #53).

@onimatrix81 Thank you for your new logs! The repetitive mouse2 path is most definitely a bug :). I will take a close look at this tomorrow.

The numeric error codes you see are your standard errno values [1]. I should start replacing cases where I print them out directly with calls to strerror, though.

Regarding helper logs, the problem up until recently was that helpers running asynchronously from vdevd were not inheriting the log file descriptor, meaning that any logging they did would get silently dropped. This was the case for event-push.sh and udev-compat.sh. I considered this to be a feature originally, since providing the ability to run helpers asynchronously was meant to allow the admin to have vdevd spin up long-running device management programs that have their own logging facilities anyway (like lvmetad, for example). Such programs should inherit an empty environment from vdevd.

However, it seems that in practice the more common case for asynchronous mode is going to be running the relatively-slow-but-nevertheless short-lived event-pushing helpers, which should log to vdevd. This should have been fixed in 9814a4b, but let me know if it hasn't.

[1] http://www-numi.fnal.gov/offline_software/srt_public_context/WebDocs/Errors/unix_system_errors.html

[onimatrix81]

One thing I noticed is that lsusb shows the added mouse just fine. What I'm wondering here, is that does hotplugging hid devices work for everybody else? Heh, am I the only one they don't work for or am I the only one who's happening to try this at all =).

[jcnelson]

@onimatrix81 I just pushed a somewhat large patchset to master that I hope fix this problem.

I basically spent this weekend moving my production machine over to vdev, and forced myself to deal with all of these little annoyances in a systematic way. I'm not quite done squashing all the bugs, but I'm close. Among them were bugs related to how udev-compat.sh maintains its link database. I tried the same experiments as you with an optical mouse, and I don't have any more of the links problems you discovered :)

[onimatrix81]

Just cloned and installed the latest vdev. The mouse problem persists :). Here's logs:
vdevd.log right after boot: https://bpaste.net/show/29fc1d4efd95 (not very related to the mouse matter, but maybe informative on to how my vdev init script doesn't work too well) Xorg log: https://bpaste.net/show/538864f4e288 Here's the vdevd log after I've got to X and connect and disconnect the mouse: https://bpaste.net/show/9c7674b23b60

I also tried to log off xorg and the user and rm -rf /run/udev/*, restarting vdevd. That didn't work, so I went one step further and umounted the hwdb, rm -rf'd everything in /dev and restarted vdevd. That had some interesting results. Mainly that it didn't work either, but also that vdevd didn't recover from it very well (ie. I didn't get back (the /run/udev/links to) my other mouse, the one that has been working all along). Not that I recommend anybody to rm -rf their /dev, but there comes a time in every man's life when they just gotta do it, and just saying that vdevd doesn't deal well with it ;)

Anyways, if anybody has ideas what more I could log, or how I could be of use, suggestions are welcomed.

[jcnelson]

Hi @onimatrix81,

Thank you for testing it again! I was grepping your logs, and I didn't see any case of the error you reported earlier (i.e. this one:)

09730:00007F9194AAB700: [ device.c:0651] vdev_device_remove_metadata_file: WARN: removing '/dev/metadata//dev/input/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2/mouse2' rc = -40

Part of my patch set should have temporarily forced udev-compat.sh to run synchronously, and not as a daemonlet (i.e. the patch should have touched example/actions/zzz-udev-compat.act, which should have installed to /etc/vdev/actions/zzz-udev-compat.act). It looks like this was not the case for you when you ran this last test.

The reason I bring it up is that I was testing with a very similar mouse to yours (Logitech HID USB mouse), and I get no problems when I remove the async=true and daemonlet=true lines from /etc/vdev/actions/zzz-udev-compat.act. Can you verify that this is the case for you? If that works on your end, then it narrows down the bug to a logic error in the daemonlet code, as opposed to something specific to udev-compat.sh.

but there comes a time in every man's life when they just gotta do it, and just saying that vdevd doesn't deal well with it ;)

Heh, that probably has more to do with the fact that you blew away some vital system device nodes (like /dev/tty*, /dev/console, and /dev/null), which the shell needs in order to function :)