Re: problem with USB-CD drive

From: Eugene Grosbein <eugen_at_grosbein.net>
Date: Wed, 02 Mar 2022 16:44:59 UTC
02.03.2022 16:07, Wojciech Puchar wrote:

>> It looks like the device or driver do not like size of reading request,
>> f.e. short read. It should be possible to verify that using several ways:
>> 1) run "ktrace -i mount_cd9660 ..." then study ouput of kdump;
>    847 mount_cd9660 STRU  struct stat {dev=156, ino=261120, mode=040755, nlink=2, uid=0, gid=0, rdev=2085752, atime=1581328619, mtime=15
> 81328630.081523000, ctime=1581328648.345917000, birthtime=315532800, size=1024, blksize=32768, blocks=8, flags=0x0 }
>    847 mount_cd9660 RET   lstat 0
>    847 mount_cd9660 CALL  stat(0x7fffffffe440,0x7fffffffe3a0)
>    847 mount_cd9660 NAMI  "/mnt"
>    847 mount_cd9660 STRU  struct stat {dev=156, ino=261120, mode=040755, nlink=2, uid=0, gid=0, rdev=2085752, atime=1581328619, mtime=15
> 81328630.081523000, ctime=1581328648.345917000, birthtime=315532800, size=1024, blksize=32768, blocks=8, flags=0x0 }
>    847 mount_cd9660 RET   stat 0
>    847 mount_cd9660 CALL  openat(AT_FDCWD,0x7fffffffee6d,0<O_RDONLY>)
>    847 mount_cd9660 NAMI  "/dev/cd1"
>    847 mount_cd9660 RET   openat 3
>    847 mount_cd9660 CALL  ioctl(0x3,CDIOREADTOCHEADER,0x7fffffffeb88)
>    847 mount_cd9660 RET   ioctl 0
>    847 mount_cd9660 CALL  ioctl(0x3,CDIOREADTOCENTRYS,0x7fffffffeb60)
>    847 mount_cd9660 RET   ioctl 0
>    847 mount_cd9660 CALL  close(0x3)
>    847 mount_cd9660 RET   close 0
>    847 mount_cd9660 CALL mmap(0,0x200000,0x3<PROT_READ|PROT_WRITE>,0x1002<MAP_PRIVATE|MAP_ANON>,0xffffffff,0)
>    847 mount_cd9660 RET   mmap 34376515584/0x801000000
>    847 mount_cd9660 CALL  nmount(0x801015080,0x8,0x1<MNT_RDONLY>)
>    847 mount_cd9660 NAMI  "/mnt"
>    847 mount_cd9660 NAMI  "/mnt"
>    847 mount_cd9660 NAMI  "/dev/cd1"
>    847 mount_cd9660 RET   nmount -1 errno 22 Invalid argument
> could you please help me to understand this?
> is it something about CDIOREADTOCHEADER and CDIOREADTOCENTRYS returning not what it should return?

No. We see here that at user level the sequence breaks on nmount system call.
There is no more details but we may assume that nmount leads to short reads inside the kernel land (and breaks).

>> 2) enable debug logs at GEOM level, use sysctl kern.geom.debugflags=255
>> (beware of large amount of logs) then run mount_cd9660
>> 3) use gcache(8) that is capable of limiting minimum request size by caching "extra" data,
>> but try using only single gcache(8) instance per system because of known instability in the gcache code
>> when you create multiple geom_cache's.
>>
> did gcache with 2kB blocks. works fine. Seems like a problem is here - some requests are not handled.
> 
> now i tested reading it with dd with 2,4,8,16 and 32kB blocks. seems fine.
> 
> trying to read with blocks like 1k, 512 doesn't work but it is i think normal - CDs have 2kB blocks.
> 
> real CD drive behaves the same way.

It's time to enable geom logs to look at size of read requests going to low level driver.