Bug 235257
| Summary: | snd_uaudio not getting loaded automatically after migration to devmatch | ||||||||
|---|---|---|---|---|---|---|---|---|---|
| Product: | Base System | Reporter: | Max <maxsteciuk> | ||||||
| Component: | usb | Assignee: | freebsd-usb (Nobody) <usb> | ||||||
| Status: | In Progress --- | ||||||||
| Severity: | Affects Some People | CC: | hselasky, imp, maxsteciuk | ||||||
| Priority: | --- | Keywords: | needs-qa, regression | ||||||
| Version: | CURRENT | Flags: | koobs:
mfc-stable12?
|
||||||
| Hardware: | amd64 | ||||||||
| OS: | Any | ||||||||
| Attachments: |
|
||||||||
|
Description
Max
2019-01-27 23:32:39 UTC
> Could you please help me understand how devmatch is supposed to work for such cases? Do I need to configure anything else?
The mask field should select which fields are target for comparison.
There should be multiple snd_uaudio rules. Are you sure your USB audio device is not quirked?
--HPS
The output from "usbconfig -d X.Y dump_device_desc dump_curr_config_desc" would also be useful. Created attachment 201483 [details] snd_uaudio ugen0.6 device and config descriptor dump So far I compared with previous version of system where devd successfully matched the same device to snd_uaudio module (by bus, vendorID, productID as per usb.conf). Although currently it appears like devd does not support this behavior because an attempt to reinstate /etc/devd/usb.conf didn't have any effect. In addition I noticed a flood of weird uhub messages in syslog such as the following: >>>Jan 28 12:41:43 kernel: uhub_reattach_port: giving up port reset - device vanished But it does not say which port. I am not sure whether this is relevant to this issue or this is a separate one. As someone suggested I switched the following config and these log messages disappeared: >>>sysctl hw.usb.disable_enumeration=1 Also having enumeration enabled makes invocation of usbconfig getting stuck. Please find the usbconfig dump of device and config descriptors for the snd_uaudio device in question Thanks, Max Hi, The USB descriptors are all OK and should match USB audio. Can you invoke devmatch manually: devmatch -a -h /boot/kernel/linker.hints Typical errors: 1) Due to "struct stat" changes: ll /boot/kernel/linker.hints -rw-r--r-- 1 root wheel 321712 Nov 16 11:54 /boot/kernel/linker.hints devmatch -a -h /boot/kernel/linker.hints devmatch: Can't read in 17599000 bytes from /boot/kernel/linker.hints: No error: 0 2) Due to kernel changes: devmatch -a -h /boot/kernel/linker.hints devmatch: kernel bus interface version mismatch: No error: 0 devmatch: devinfo_init: No error: 0 --HPS Hi I ran the following and it didn't any of the error conditions when reading linker.hints >>>devmatch -a -h /boot/kernel/linker.hints This was the resulting output: >>> read_hints() sb.st_size 323176 Additionally when I checked for the following verbose logging I could only see search for 'ACPI', 'PCI' and 'CPU' buses, search_hints() didn't hit 'uhub' or 'usb' buses >>>"Searching bus %s dev %s for pnpinfo %s\n Although when running with -d option to dump /boot/kernel/linker.hints I see pnpinfo output for 'uhub' bus. Thanks Max And you have devmatch_enable="YES" in /etc/rc.conf ? --HPS Yes I do >>>[~]$ tail -1 /etc/rc.conf >>>devmatch_enable="YES" The /etc/devd/devmatch.conf is also in-place: >>>[~]$ cat /etc/devd/devmatch.conf| head -13 >># >>># $FreeBSD$ >>># >> >>># >>># Example devd configuration file for automatically >>># loading what modules we can based on nomatch >>># events. >>># >>># Generic NOMATCH event >>>nomatch 100 { >>> action "service devmatch quietstart '?'$_"; >>>}; Thanks Max I guess I need to update my system to reproduce this issue. I'm running older binaries which don't exhibit this problem yet. Warner: Any input on this issue? --HPS I found it: Try these two commands: service devmatch quietstart '? at bus=0 hubaddr=2 port=4 devaddr=4 interface=0 ugen=ugen0.4 vendor=0x046d product=0xc069 devclass=0x00 devsubclass=0x00 devproto=0x00 sernum="" release=0x5601 mode=host intclass=0x03 intsubclass=0x01 intprotocol=0x02 on uhub1' /etc/rc.d/devmatch quietstart '? at bus=0 hubaddr=2 port=4 devaddr=4 interface=0 ugen=ugen0.4 vendor=0x046d product=0xc069 devclass=0x00 devsubclass=0x00 devproto=0x00 sernum="" release=0x5601 mode=host intclass=0x03 intsubclass=0x01 intprotocol=0x02 on uhub1' Warner: This commit seems the culpit: commit 32f4fdcb26f048c7febb92c663ea3edebf34300b Author: imp <imp@FreeBSD.org> Date: Mon Jun 11 22:48:34 2018 +0000 User service foo rather than /etc/rc.d/foo. devd predates service in the system. Modernize usage to use service to start/stop things in reaction to events rather than calling the rc file directly. This was pointed out in my talk at BSDcan as well as indirectly referrred to as a barrier to entry for OpenRC in that working group. Created attachment 201550 [details]
Fix for (/etc/devd/devmatch.conf)
Can you test this patch?
Hi This worked: >>>sudo /etc/rc.d/devmatch start '? at bus=0 hubaddr=2 port=4 devaddr=4 interface=0 ugen=ugen0.4 >>>vendor=0x046d product=0xc069 devclass=0x00 devsubclass=0x00 devproto=0x00 sernum="" >>>release=0x5601 mode=host intclass=0x03 intsubclass=0x01 intprotocol=0x02 on uhub1' >>>Autoloading module: uhid.ko >>>Autoloading module: ums.ko >>>sudo devmatch -p '? at bus=0 hubaddr=2 port=4 devaddr=4 interface=0 ugen=ugen0.4 vendor=0x046d >>>product=0xc069 devclass=0x00 devsubclass=0x00 devproto=0x00 sernum="" release=0x5601 mode=host >>>intclass=0x03 intsubclass=0x01 intprotocol=0x02 on uhub1' >>>uhid.ko >>>ums.ko Although it only matched uhid and ums but no snd_uaudio even when I specified idVendor, idProduct of the device as per attached usbconfig dump Should devmatch without arguments return these modules as part its output? Also is it possible to add this as an example in dematch(8) man page? I was searching for 'nomatch' string examples for -p option but I could not find any. Thanks, Max You need to specify arguments for devmatch. Devd will print these arguments. Can you try to kill devd. Run it in the foreground and attach your USB audio device. Also make sure devd is up-to-date. --HPS Hi
Here is output of devd upon attaching uaudio device:
>>>setting *=+uaudio1 at bus=0 hubaddr=4 port=1 devaddr=13 interface=0 ugen=ugen0.13 vendor=0x041e >>>product=0x323c devclass=0x00 devsubclass=0x00 devproto=0x00 sernum="***" >>>release=0x0100 mode=host intclass=0x01 intsubclass=0x01 intprotocol=0x00 on uhub3
>>>setting _=uaudio1 at bus=0 hubaddr=4 port=1 devaddr=13 interface=0 ugen=ugen0.13 vendor=0x041e >>>product=0x323c devclass=0x00 devsubclass=0x00 devproto=0x00 sernum="***" >>>release=0x0100 mode=host intclass=0x01 intsubclass=0x01 intprotocol=0x00 on uhub3
Let try to apply the patch for startup test
Thanks,
Max
As we discovered on IRC, this is caused by an out of date /usr/sbin/service file, I think. The patch, if it works, confirms that's the case. Hi
1. It seems /sbin/service does not recognize 'quietstart' option
>>>sudo /sbin/service devmatch quietstart
>>> * devmatch: unknown function `quietstart'
Are there any plans to patch /sbin/service?
2. I think the integration with OpenRC will be another story
Thanks,
Max
Although on startup I see devd service is starting but devmatch nomatch action is not getting triggered... Thanks, Max And I see why. devmatch binary is not in the execution when launched by rc. >>>Executing 'sh /etc/rc.devd devmatch start.'?'$' at bus=0 hubaddr=3 port=4 devaddr=9 interface=0 >>>ugen=ugen0.9 vendor=0x0451 product=0xca01 devclass=0x00 devsubclass=0x00 devproto=0x00 >>>sernum="" release=0x0100 mode=host intclass=0x03 intsubclass=0x00 intprotocol=0x00 on uhub2' '?'$' at >>>bus=0 hubaddr=3 port=4 devaddr=9 interface=0 ugen=ugen0.9 vendor=0x0451 product=0xca01 ?>>>devclass=0x00 devsubclass=0x00 devproto=0x00 sernum="" release=0x0100 mode=host intclass=0x03 >>>ntsubclass=0x00 intprotocol=0x00 on uhub2'' >>>... >>>exec: /devmatch: not found I tried putting absolute path in the script but it didn't help >>> binary_path="/sbin/devmatch" >>>... >>> if [ -n "$one_nomatch" ]; then >>> list=$(${binary_path} -p "${one_nomatch}" | sort -u) >>> else >>> list=$(${binary_path}| sort -u) >>> fi Thanks, Max Hi The latter is related to OpenRC integration where devd configuration for OpenRC is: >>>action "sh /etc/rc.devd devmatch start.'?'$_ '?'$_"; Replacing with >>> action "/etc/rc.d/devmatch quietstart '?'$_"; fixes the issue of starting devmatch on devd event. I will contact TrueOS team on this unless patching of /sbin/service is planned in order to make more consistent configuration for both FreeBSD and TrueOS cases. Thanks, Max Hello Still on startup module is not autoloaded. It only works when devd is started in foreground and then USB device is attached. On startup according to syslog XHCI controller detects device attachment before devd rc service actually starts up. So when it is rc turn there is no nomatch event and hence no devmatch action is triggered. At least this is my current understanding as per my observations. Please correct me if I'm wrong. Could you please help me understand whether there is some configuration in devmatch / devd to handle the device attachment - event dependency scenario on start-up? Thanks, Max Hi, The kernel will buffer all nomatch events until devd is loaded or the first client starts reading them. --HPS Hi So any ideas why nomatch evens are not picked up by devd in the daemon mode after the system starts up? Even if I restart devd as daemon instead of in foreground and detach / attach device, there is no event and so no module loaded. I have devmatch enabled in rc.conf >>>cat /etc/rc.conf|grep devmatch >>>devmatch_enable="YES" Is this related to another weird behavior that USB device enumeration takes kind of longer compared to the kernel build prior late March? Here is chronological illustration of events: rc.log >>>rc boot logging started at Fri Feb 1 12:15:42 2019 >>>... >>>... >>>... >>> * Starting devd ... messages >>>Feb 1 12:15:46 kernel: FreeBSD is a registered trademark of The FreeBSD Foundation. >>>Feb 1 12:15:46 kernel: FreeBSD 13.0-CURRENT r324678+8f6b5a3ad62(bugfix/excessive-port-reset->>>logging) GENERIC-NODEBUG amd64 >>>Feb 1 12:15:46 kernel: FreeBSD clang version 7.0.1 (branches/release_70 348686) (based on LLVM 7.0.1) ... .... .... >>>Feb 1 12:15:46 kernel: ugen0.6: <Dell DELL PROFESSIONAL SOUND BAR AE515> at usbus0 >>>Feb 1 12:15:46 kernel: Root mount waiting for: usbus0 devd.log is empty >>>root wheel 0 Feb 1 12:15 /var/log/devd.log devd service is up >>>service devd status >>> * status: started Several minutes after login: >>>Fri Feb 1 12:33:30 EST 2019 >>>[ ~]$ kldstat|grep uaudio >>>[ ~]$ Thanks, Max How can I verify nomatch events are really queued by USB hub controller in the kernel for devd? I see devd registers descriptor for /dev/devctl with select() in devd.cc:event_loop()... Thanks, Max There are a couple of functions in the kernel, where you might want to add a print: sys/kern/subr_bus.c:devctl_queue_data(char *data) sys/kern/subr_bus.c: devctl_queue_data_f(data, M_NOWAIT); sys/kern/subr_bus.c:devctl_notify_f(cons --HPS I am able to trace event through from sys/dev/usb/usb_hub.c:usb_notify_addq to sys/kern/subrc_bus.c:devctl_queue_data_f where it is supposed to invoke pgsigio() but still I don't see devd triggering module loading... The devctl queue is not getting full as per printout. It is set to default hw.bus.devctl_queue = 1000 >>>Feb 1 16:57:06 kernel: usb_alloc_device: new dev (addr 5), udev=0xfffff80006677000, >>>parent_hub=0xfffff800062df000 >>>Feb 1 16:57:06 kernel: ugen0.6: <Dell DELL PROFESSIONAL SOUND BAR AE515> at usbus0 >>>Feb 1 16:57:06 kernel: usb_notify_addq: ++++ sending devctl_notify() about type ATTACH ugen_name ugen0.6 >>>Feb 1 16:57:06 kernel: +++ devctl_notify_f() system USB, subsystem DEVICE, type ATTACH, data [ugen=ugen0.6 cdev=ugen0.6 vendor=0x413c product=0xa506 devclass=0x00 devsubclass=0x00 sernum="" release=0xe001 mode=host port=2 parent=ugen0.3], flags 1 >>>+++ 1 devctl_queue_data_f() data [!system=USB subsystem=DEVICE type=ATTACH ugen=ugen0.6 cdev=ugen0.6 vendor=0x413c product=0xa506 devclass=0x00 devsubclass=0x00 sernum="" release=0xe001 mode=host port=2 parent=ugen0.3 >>>Feb 1 16:57:06 kernel: ] flags 1, devctl_queue_length 1000 >>>Feb 1 16:57:06 kernel: +++ 2 devctl_queue_data_f() data [!system=USB subsystem=DEVICE >>>type=ATTACH ugen=ugen0.6 cdev=ugen0.6 vendor=0x413c product=0xa506 devclass=0x00 devsubclass=0x00 sernum="" release=0xe001 mode=host port=2 parent=ugen0.3 >>>Feb 1 16:57:06 kernel: ] flags 1, devctl_queue_length 1000, devsoftc.queued 368 Hitting this point where the only condition of not sending request would be if devsoft.async == 0 or devsoftc.sigio is null. >>>printf("+++ 2 devctl_queue_data_f() data [%s] flags %d, devctl_queue_length %d, devsoftc.queued >>>%d\n", data, flags, devctl_queue_length, devsoftc.queued); >>> /* Leave at least one spot in the queue... */ >>> while (devsoftc.queued > devctl_queue_length - 1) { >>> n2 = TAILQ_FIRST(&devsoftc.devq); >>> TAILQ_REMOVE(&devsoftc.devq, n2, dei_link); >>> free(n2->dei_data, M_BUS); >>> free(n2, M_BUS); >>> devsoftc.queued--; >>> } >>> TAILQ_INSERT_TAIL(&devsoftc.devq, n1, dei_link); >>> devsoftc.queued++; >>> cv_broadcast(&devsoftc.cv); >>> KNOTE_LOCKED(&devsoftc.sel.si_note, 0); >>> mtx_unlock(&devsoftc.mtx); >>> selwakeup(&devsoftc.sel); >>> if (devsoftc.async && devsoftc.sigio != NULL) >>> pgsigio(&devsoftc.sigio, SIGIO, 0); >>> return; Thanks, Max In the devfs read routine for the events, try to print who is reading the events:
printf("PID=%d %s\n", curthread->td_proc->p_pid, curthread->td_proc->p_comm);
Maybe some program is draining all the events before devd is invoked.
--HPS
The first one who is getting to devfs_read_f is openrc. devd under openrc seems to use the following configuration which I previously corrected: >>> sbin/devd/devmatch-openrc.conf https://github.com/trueos/trueos/pull/284/files#diff-b1e03f7592cbd83f86aee1203c133630 which is triggered only when devd is in foreground (-d option) Here is a list I was able to capture: >>>grep devfs_read_f /var/log/messages| grep -oe 'PID [0-9]*, comm [a-zA-Z0-9]*'|sort|uniq >>>PID 34682, comm openrc >>>PID 43896, comm dbus >>>PID 52611, comm avahi >>>PID 56180, comm devd >>>PID 62204, comm savecore >>>PID 72639, comm dd >>>PID 74986, comm openrc >>>PID 760, comm openrc >>>PID 90002, comm syslogd >>>PID 90404, comm init >>>PID 90404, comm sh Thanks, Max Try to put the print inside this function instead.
static int
devread(struct cdev *dev, struct uio *uio, int ioflag)
{
--HPS
Hi devd seems to be the only process getting to sys/kern/subr_bus.c:devread() and it is pretty active there. >>>grep devread /var/log/messages |grep -oe 'PID [0-9]*, comm [a-zA-Z0-9]*'|sort |uniq >>>PID 86168, comm devd Here is chronological sequence of my debug checkpoints: >>>Feb 2 12:01:07 kernel: ugen0.6: <Dell DELL PROFESSIONAL SOUND BAR AE515> at usbus0 >>>... >>>Feb 2 12:01:07 kernel: +++ 2 devctl_queue_data_f() data [? at bus=0 hubaddr=3 port=2 devaddr=6 interface=3 ugen=ugen0.6 vendor=0x413c product=0xa506 devclass=0x00 devsubclass=0x00 devproto=0x00 sernum="" release=0xe001 mode=host intclass=0x03 intsubclass=0x00 intprotocol=0x00 on uhub2 >>>... >>>Feb 2 12:01:08 kernel: +++ 1 devread(): si_name devctl PID 86168, comm devd >>>Feb 2 12:01:08 kernel: +++ 2 devread(): PID 86168, comm devd >>>Feb 2 12:01:08 kernel: +++ 1 devread(): si_name devctl PID 86168, comm devd >>>Feb 2 12:01:08 kernel: +++ 2 devread(): PID 86168, comm devd >>>... >>>... >>>... >>>Feb 2 12:01:09 kernel: +++ 1 devread(): si_name devctl PID 86168, comm devd >>>Feb 2 12:01:09 kernel: +++ 2 devread(): PID 86168, comm devd >>>Feb 2 12:01:09 kernel: +++ 1 devctl_queue_data_f() data [!system=IFNET subsystem=em0 type=LINK_UP >>>Feb 2 12:01:09 kernel: ] flags 1, devctl_queue_length 1000 >>>Feb 2 12:01:09 kernel: +++ 2 devctl_queue_data_f() data [!system=IFNET subsystem=em0 type=LINK_UP >>>Feb 2 12:01:09 kernel: ] flags 1, devctl_queue_length 1000, devsoftc.queued 382 >>>Feb 2 12:01:09 kernel: em0: link state changed to UP Thanks, Max Hello, FYI: The symptoms of the issue still keep occurring on the latest *FreeBSD-13.0-CURRENT* Could you please let me know whether you found something on your side? Thanks Max |
