If you've seen the following output from cdparanoia, MAIL ME!!:
"SCSI transport: writeable when reading packet"
The above message indicates you've probably tripped a kernel bug that
shows up only very rarely, and I need to know more about that bug!
Now, on to the part I want Doug, Jens, Joerg and the bughunter hordes
to read:
I've finally found hard evidence of a bug in 2.2.x [at least
manifested] in SG. It's possible this has been fixed in dougg's and
joerg's recent drivers (it took a long time to find hard
proof/documentation of this problem, and the machine is remote; I'm
leading the user through debugging now), but the nature of the bug
leads me to believe I should report it because I'm only 80% certain
it's SG.
I'm throwing this open to others now because after sleepless nights
with the kernel source, I honestly can't say how the below report is
possible even under the strangest conditions; given that I can't find
even a remote explanation of the problem and that I've only seen two
reports (only one with enough documentation) I doubt this has been
fixed unless accidently. OTOH, I'm honestly hoping Joerg or Doug is
going to say "oh, yeah, *that* bug. It's fixed." so I can stop
worrying :-)
The story thus-far in chronological order:
In cdparanoia when I'm doing SCSI commands, rather than just doing
'write()' and then immediately blocking on the following 'read()', I
select() for readable before read()ing. On a lark, in alpha 9.4 I also
decided to return from select() if the SG device's fd ever went
writable rather than readable. From looking at the SG code I didn't
think it would happen, but a test costs nothing so I put it in.
What is happening on just two machines is much weirder than I expected
could be possible. The SG device fd is in fact immediately returning
'writable' from a select() call immediately after successfully writing
a packet to SG; from reading the kernel source, I see absolutely no
way this is possible, and on the two machines in question, the
behavior is apparently 100% reproducable on at least one device (eg,
every SG command written does this, causing cdparanoia to fail
instantly. No SG commands succeed; all end up indicating 'writable'
immediately after writing the packet. One user also reported that the
command occasionally just hangs, never returning readable or writable,
and occasionally returns 'writable').
I gave the users in question a patch to paranoia to ignore the fd
indicating writable and wait for readable status from select(); SG
commands suddenly work with no errors. I have not yet given code that
logs for certain whether or not the fd first select()s writable and
then upon a subsequent select() indicates readable; all I know is that
on these machines, giving select() a readable fd_set only works, but
when passing the same fd in the both a read and write fd_set to
select(), writeable status is returned (which, as I'm beating into the
ground, seems impossible from reading the kernel source).
The two machines for which I have documented evidence of the bug are
running 2.2.2 and 2.2.3. The description of the problem matches
behavior that was first reported to me by users in late 2.1 (before
the release of a paranoia version with this check). Note that I do
not have documented evidence that this is the same bug as appeared to
happen earlier in 2.1; it could be a coincidence. However, the late
2.1 SG driver did see the select() infrastructure replaced with
poll()...
I'm bringing this up despite the newer drivers because from looking at
the 2.2 SG, I don't see how it could be making this mistake--- and
thus I'm worried it could be select(). I have a patch out to the user
that will test exactly this theory and I'll report back as soon as I
know. I'm also sending him Doug's and Joerg's newest SGs to try.
I have an strace below that shows that the fd is indeed becoming
writable after successfully write()ing a SCSI packet to SG. I'm in the
process of gathering more debugging information from the user, but the
machine is remote and disconnected from the net, so debugging must
happen through email exchanges.
Note that despite my interjections, all the straces lines are unedited
and in order:
>open("/dev/sg3", O_RDWR|O_EXCL) = 4
The SG device is fd 4
>stat("/dev/scd0", {st_mode=S_ISUID|S_ISVTX|0400, st_size=0, ...}) = 0
>brk(0x807e000) = 0x807e000
>ioctl(3, CDROMAUDIOBUFSIZ, 0xbffff51c) = 0
strace is reporting a different ioctl() name here that uses the same
number. this is actually SCSI_IOCTL_GET_IDLUN
>ioctl(3, 0x5386, 0xbffff518) = 0
..and SCSI_IOCTL_GET_BUS_NUMBER
>select(5, [4], NULL, NULL, {0, 0}) = 0 (Timeout)
going into handle_command, the fresh SG fd has no data to be read
back, as expected.
>select(5, NULL, [4], NULL, {5, 0}) = 1 (out [4], left {5, 0})
ready to write a packet command, as expected...
>sigprocmask(SIG_BLOCK, [INT PIPE TERM PROF], NULL) = 0
Block SIGINT, etc... closing an SG fd with a command outstanding is a
great way to 'oops'.
>write(4, "\0\0\0\0\\\0\0\0\0\0\0\0\0\0\0\0"..., 98) = 98
The packet command write succeeds. device->pending is set to 1.
>select(5, [4], [4], [4], {15, 0}) = 1 (out [4], left {15, 0})
!!! the select returns only one fd and it's in the writable fd_set!
This should only be possible if device->pending is zero. There are no
intervening operations that could unset it (eg, close, read, etc).
>write(2, "\nSCSI transport: writeable when"..., 48
>SCSI transport: writeable when reading packet
Death and taxes.
Any explanations? I'm stumped (for now).
Monty
-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.rutgers.edu
Please read the FAQ at http://www.tux.org/lkml/