Bug 235257 - snd_uaudio not getting loaded automatically after migration to devmatch
Summary: snd_uaudio not getting loaded automatically after migration to devmatch
Status: In Progress
Alias: None
Product: Base System
Classification: Unclassified
Component: usb (show other bugs)
Version: CURRENT
Hardware: amd64 Any
: --- Affects Some People
Assignee: freebsd-usb mailing list
URL:
Keywords: needs-qa, regression
Depends on:
Blocks:
 
Reported: 2019-01-27 23:32 UTC by Max
Modified: 2019-07-14 20:59 UTC (History)
3 users (show)

See Also:
koobs: mfc-stable12?


Attachments
snd_uaudio ugen0.6 device and config descriptor dump (6.62 KB, text/plain)
2019-01-28 18:13 UTC, Max
no flags Details
Fix for (/etc/devd/devmatch.conf) (411 bytes, patch)
2019-01-31 07:24 UTC, Hans Petter Selasky
no flags Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Max 2019-01-27 23:32:39 UTC
Certain USB modules such as snd_uaudio, uplcom are not loading automatically since /etc/devd/usb.conf was replaced by devmatch. When running devmatch tool with no arguments (as /etc/rc.d/devmatch script has) it does not return any matches. 

I checked /boot/kernel/linker.hints has the pnpinfo string for uaudio. Also /sys/dev/sound/usb/uaudio.c has call to USB_PNP_HOST_INFO(uaudio_dev) macro.

>>>audio
>>>snd_uaudio.ko
>>>uhub
>>>M:mask;I:vendor;I:product;L:release;G:release;I:devclass;I:devsubclass;I:devpr>>>oto;I:intclass;I:intsubclass;I:intprotocol;T:mode=host

Yet devmatch was not able to match module by the parsed fields. When debugging  I noticed the following mismatch condition for type 'I' was hit (values were different)

/sbin/devmatch/devmatch.c:319-328
>>>ival = getint(&ptr);
>>>...
>>>v = pnpval_as_int(cp + 2, pnpinfo);
>>>...
>>> case 'I':
>>>     if(v != ival) notme++; 

BSDCan 2018 devmatch presentation  mentioned some USB module issues due to pnpinfo string being too long for 128 byte limit. Is this one of the cases? Or is this because vendorID/productID of my device is not in the uaudio module  table?

Could you please help me understand how devmatch is supposed to work for such cases? Do I need to configure anything else?


Please let me know if additional information is needed.


The environment:
OS:                13.0-CURRENT FreeBSD 13.0-CURRENT GENERIC-NODEBUG  amd64
Build date/time:   2019/01/21 16:38:41

Thanks,
Max
Comment 1 Hans Petter Selasky freebsd_committer 2019-01-28 08:37:27 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
Comment 2 Hans Petter Selasky freebsd_committer 2019-01-28 09:45:38 UTC
The output from "usbconfig -d X.Y dump_device_desc dump_curr_config_desc" would also be useful.
Comment 3 Max 2019-01-28 18:13:12 UTC
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
Comment 4 Hans Petter Selasky freebsd_committer 2019-01-30 17:24:58 UTC
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
Comment 5 Max 2019-01-30 18:03:21 UTC
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
Comment 6 Hans Petter Selasky freebsd_committer 2019-01-30 18:22:44 UTC
And you have devmatch_enable="YES" in /etc/rc.conf ?

--HPS
Comment 7 Max 2019-01-30 18:35:46 UTC
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
Comment 8 Hans Petter Selasky freebsd_committer 2019-01-30 19:15:48 UTC
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
Comment 9 Hans Petter Selasky freebsd_committer 2019-01-31 07:04:43 UTC
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.
Comment 10 Hans Petter Selasky freebsd_committer 2019-01-31 07:24:03 UTC
Created attachment 201550 [details]
Fix for (/etc/devd/devmatch.conf)

Can you test this patch?
Comment 11 Max 2019-01-31 16:34:04 UTC
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
Comment 12 Hans Petter Selasky freebsd_committer 2019-01-31 17:11:29 UTC
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
Comment 13 Max 2019-01-31 18:39:24 UTC
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
Comment 14 Warner Losh freebsd_committer 2019-01-31 19:10:29 UTC
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.
Comment 15 Max 2019-01-31 19:37:19 UTC
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
Comment 16 Max 2019-01-31 19:39:15 UTC
Although on startup I see devd service is starting but devmatch nomatch action is not getting triggered...

Thanks,
Max
Comment 17 Max 2019-01-31 19:55:32 UTC
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
Comment 18 Max 2019-01-31 22:22:02 UTC
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
Comment 19 Max 2019-01-31 23:29:38 UTC
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
Comment 20 Hans Petter Selasky freebsd_committer 2019-02-01 08:48:06 UTC
Hi,

The kernel will buffer all nomatch events until devd is loaded or the first client starts reading them.

--HPS
Comment 21 Max 2019-02-01 17:38:47 UTC
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
Comment 22 Max 2019-02-01 19:08:20 UTC
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
Comment 23 Hans Petter Selasky freebsd_committer 2019-02-01 20:35:02 UTC
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
Comment 24 Max 2019-02-01 22:21:06 UTC
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
Comment 25 Hans Petter Selasky freebsd_committer 2019-02-01 22:29:28 UTC
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
Comment 26 Max 2019-02-01 23:19:57 UTC
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
Comment 27 Hans Petter Selasky freebsd_committer 2019-02-02 14:42:33 UTC
Try to put the print inside this function instead.

static int
devread(struct cdev *dev, struct uio *uio, int ioflag)
{


--HPS
Comment 28 Max 2019-02-02 17:20:26 UTC
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
Comment 29 Max 2019-07-14 20:59:52 UTC
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