Closing unused descriptors

[Jean-Christian de Rivaz]

Le 24. 09. 15 16:23, Dan Williams a écrit :
> On Thu, 2015-09-24 at 13:43 +0200, Jean-Christian de Rivaz wrote:
>> Hi Aleksander,
>>
>> Le 24. 09. 15 13:10, Aleksander Morgado a écrit :
>>> On Thu, Sep 24, 2015 at 9:49 AM, Jean-Christian de Rivaz <jc at eclis.ch> wrote:
>>>> While trying to reproduce a bug by power cycling a USB modem 4 time per
>>>> hour, I faced this message from the kernel:
>>>>
>>>> cdc_acm 1-2:1.0: no more free acm devices
>>>>
>>>> I found the the problem is caused by ModemManager that still have file
>>>> descriptors open on old ports that was deleted, preventing the kernel to
>>>> recycle the port numbers:
>>> When you power cycle the modem 4 times per hour, do you just cut the
>>> power to the modem externally?
>>>
>> Yes, for 10 minutes before power it up again. The lsusb and dmesg
>> clearly show that all the CDC of the modem disconnected at the power
>> off. Probably the udev noticed the event too, I have not verified.
> The kernel won't kill an open device node if MM is using it, so MM has
> to be notified by either a TTY hangup, or by udev that the device has
> disappeared.

Hi Dan,

Actually the /dev/ttyACM* device node has been deleted by the kernel. 
Only the MM file descriptor on it still exists, but correspond to 
nothing anymore. And it's certain that the kernel notified the 
application with an input event that will make the next read() return 0 
to indicate the EOF of that descriptor. This is the basic semantic of 
the file descriptor API on UNIX.

See for example this strace on minicom while unpluged the USB converter 
it uses:

select(4, [0 3], NULL, NULL, {1, 0})    = 1 (in [3], left {0, 459161})
read(3, "", 127)                        = 0
close(3)                                = 0

Compared to ModemManager is the same situation:

write(11, "A", 1)                       = -1 EIO (Input/output error)
poll([{fd=4, events=POLLIN}, {fd=12, events=POLLIN}, {fd=11, 
events=POLLIN}, {fd=9, events=POLLIN}], 4, 0) = 2 ([{fd=11, 
revents=POLLIN|POLLERR|POLLHUP}, {fd=9, revents=POLLIN}])
recvmsg(9, {msg_name(12)={sa_family=AF_NETLINK, pid=899, 
groups=00000002}, 
msg_iov(1)=[{"libudev\0\376\355\312\376(\0\0\0(\0\0\0\245\3\0\0\212\372\220\310\0\0\0\0"..., 
8192}], msg_controllen=24, {cmsg_len=24, cmsg_level=SOL_SOCKET, 
cmsg_type=SCM_CREDENTIALS{pid=19526, uid=0, gid=0}}, msg_flags=0}, 0) = 973
write(11, "A", 1)                       = -1 EIO (Input/output error)
[14 more identical write()]

I was unable to detect any read(11, ...) or close(11) in the traces, 
even minutes after the device node was deleted.


>    So I'd be very curious what the udev event stream is when
> you remove the device.
>

Using udevadm monitor --kernel --udev --property showed a lot events. 
Below are the ones I think are relevant for this device node:

KERNEL[726.208510] remove 
/devices/platform/ahb/700000.ehci/usb1/1-2/1-2:1.0/tty/ttyACM3 (tty)
ACTION=remove
DEVNAME=/dev/ttyACM3
DEVPATH=/devices/platform/ahb/700000.ehci/usb1/1-2/1-2:1.0/tty/ttyACM3
MAJOR=166
MINOR=3
SEQNUM=925
SUBSYSTEM=tty

UDEV  [726.267864] remove 
/devices/platform/ahb/700000.ehci/usb1/1-2/1-2:1.0/tty/ttyACM3 (tty)
ACTION=remove
DEVLINKS=/dev/gsm0 
/dev/serial/by-id/usb-u-blox_u-blox_Wireless_Module_352253060606182-if00 
/dev/serial/by-path/platform-700000.ehci-usb-0:2:1.0
DEVNAME=/dev/ttyACM3
DEVPATH=/devices/platform/ahb/700000.ehci/usb1/1-2/1-2:1.0/tty/ttyACM3
ID_BUS=usb
ID_MM_CANDIDATE=1
ID_MODEL=u-blox_Wireless_Module
ID_MODEL_ENC=u-blox\x20Wireless\x20Module
ID_MODEL_ID=1102
ID_PATH=platform-700000.ehci-usb-0:2:1.0
ID_PATH_TAG=platform-700000_ehci-usb-0_2_1_0
ID_REVISION=1729
ID_SERIAL=u-blox_u-blox_Wireless_Module_352253060606182
ID_SERIAL_SHORT=352253060606182
ID_TYPE=generic
ID_USB_CLASS_FROM_DATABASE=Miscellaneous Device
ID_USB_DRIVER=cdc_acm
ID_USB_INTERFACES=:020201:0a0000:
ID_USB_INTERFACE_NUM=00
ID_USB_PROTOCOL_FROM_DATABASE=Interface Association
ID_VENDOR=u-blox
ID_VENDOR_ENC=u-blox
ID_VENDOR_FROM_DATABASE=U-Blox AG
ID_VENDOR_ID=1546
MAJOR=166
MINOR=3
SEQNUM=925
SUBSYSTEM=tty
TAGS=:systemd:
USEC_INITIALIZED=64168


Regards,
Jean-Christian