Re: USB Attached SCSI breakage due no udev involvement

[Dio Putra <dioput12@gmail.com>]

On 5/10/20 12:47 PM, Greg KH wrote:
> On Sun, May 10, 2020 at 09:55:57AM +0700, Dio Putra wrote:
>> Hi, it's first time for me to report user-space breakage in here, so
>> i'm begging your pardon.
>>
>> I want to report that Linux 5.4 breaking my USB mount workflow due
>> udevadm monitor report here (I'm using vanilla kernel 5.4.39 on
>> Slackware64 Current and vanilla kernel 4.4.221 on Slackware64 14.2):
> 
> <snip>
> 
> Sorry, but what actually changed that you can see in the logs?
Sorry, what do you mean? The dmesg log or the kernel changelogs?

> 
> What functionality broke?  What used to work that no longer does work?
> 
Yes, it supposed that just work and kernel could talk with udev, not just handled by the kernel.

Here's my personal conclusion:

[Slackware64-Current linux-5.4.39]$ sudo strace -p 2417
strace: Process 2417 attached
write(1, "KERNEL[672.150926] remove   /dev"..., 84) = 84
epoll_wait(3, [{EPOLLIN, {u32=5, u64=5}}], 4, -1) = 1
recvmsg(5, {msg_name={sa_family=AF_NETLINK, nl_pid=0, nl_groups=0x000001}, msg_namelen=128->12, msg_iov=[{iov_base="remove@/devices/pci0000:00/0000:"..., iov_len=8192}], msg_iovlen=1, msg_control=[{cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS, cmsg_data={pid=0, uid=0, gid=0}}], msg_controllen=32, msg_flags=0}, 0) = 269
write(1, "KERNEL[672.151622] remove   /dev"..., 122) = 122
epoll_wait(3, [{EPOLLIN, {u32=5, u64=5}}], 4, -1) = 1
recvmsg(5, {msg_name={sa_family=AF_NETLINK, nl_pid=0, nl_groups=0x000001}, msg_namelen=128->12, msg_iov=[{iov_base="remove@/devices/pci0000:00/0000:"..., iov_len=8192}], msg_iovlen=1, msg_control=[{cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS, cmsg_data={pid=0, uid=0, gid=0}}], msg_controllen=32, msg_flags=0}, 0) = 255
write(1, "KERNEL[672.152396] remove   /dev"..., 138) = 138
epoll_wait(3, [{EPOLLIN, {u32=5, u64=5}}], 4, -1) = 1
recvmsg(5, {msg_name={sa_family=AF_NETLINK, nl_pid=0, nl_groups=0x000001}, msg_namelen=128->12, msg_iov=[{iov_base="remove@/devices/virtual/bdi/11:0"..., iov_len=8192}], msg_iovlen=1, msg_control=[{cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS, cmsg_data={pid=0, uid=0, gid=0}}], msg_controllen=32, msg_flags=0}, 0) = 107
write(1, "KERNEL[672.153191] remove   /dev"..., 60) = 60
...<snip>...

"So the summary of syscall on linux-5.4.39 it's something like: write -->  epoll_wait --> recvmsg (direct call from kernel only, no udev dependencies has been called ever) --> write"

[Slackware64-14.2 linux-kernel-4.4.221] $ sudo strace -p 2102
strace: Process 2102 attached
write(1, "KERNEL[160.475104] remove   /dev"..., 84) = 84
epoll_wait(3, [{EPOLLIN, {u32=4, u64=4}}], 4, -1) = 1
recvmsg(4, {msg_name(12)={sa_family=AF_NETLINK, pid=598, groups=00000002}, msg_iov(1)=[{"libudev\0\376\355\312\376(\0\0\0(\0\0\0\375\0\0\0\5w\305\345\261\2Ge"..., 8192}], msg_controllen=32, [{cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS, {pid=2116, uid=0, gid=0}}], msg_flags=0}, 0) = 293
write(1, "UDEV  [160.476746] remove   /dev"..., 84) = 84
epoll_wait(3, [{EPOLLIN, {u32=5, u64=5}}], 4, -1) = 1
recvmsg(5, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000001}, msg_iov(1)=[{"remove@/devices/pci0000:00/0000:"..., 8192}], msg_controllen=32, [{cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS, {pid=0, uid=0, gid=0}}], msg_flags=0}, 0) = 256
write(1, "KERNEL[160.478096] remove   /dev"..., 76) = 76
epoll_wait(3, [{EPOLLIN, {u32=4, u64=4}}], 4, -1) = 1
recvmsg(4, {msg_name(12)={sa_family=AF_NETLINK, pid=598, groups=00000002}, msg_iov(1)=[{"libudev\0\376\355\312\376(\0\0\0(\0\0\0\26\2\0\0\5w\305\345'\370\365\f"..., 8192}], msg_controllen=32, [{cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS, {pid=2116, uid=0, gid=0}}], msg_flags=0}, 0) = 574
write(1, "UDEV  [160.495353] remove   /dev"..., 76) = 76
epoll_wait(3, [{EPOLLIN, {u32=5, u64=5}}], 4, -1) = 1
recvmsg(5, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000001}, msg_iov(1)=[{"add@/devices/pci0000:00/0000:00:"..., 8192}], msg_controllen=32, [{cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS, {pid=0, uid=0, gid=0}}], msg_flags=0}, 0) = 250
write(1, "KERNEL[161.109310] add      /dev"..., 76) = 76
...<snip>...

"So the summary of syscall on linux-4.4.221 it's something like: write --> epoll_wait --> recvmsg (libudev has been called) --> write (UDEV has been called) --> epoll_wait -> recvmsg (libudev has been called again)-> write"
  
> And 4.4.221 is quite different from 5.4, is that the jump that you are
> seeing breakage in, or is it in some smaller jump?
> 
Yeah, I know it's really different between linux-4.4 and linux-5.4

> thanks,
> 
> greg k-h
>