> OK, I will bite the bullet and check with the old kernel (starting around 2.2.6)
> and see when and how the problems appeared.
> Of course, I can't rule out the fact that my Nakamichi changer is finally
> reaching the end of its life...
>
> I will keep you posted via main scsi-linux list.
Hi,
Sorry for this lengthy post.
I tried the pristine kernel 2.2.6 and found that
to my surprise, the error was already in 2.2.6.
Yes, I thought the test succeeded earlier last year.
But I am not sure now which version it was!
I am afraid that I might have to backtrack even to 2.1.1[12][0-9].
So that path takes a long time before I would be able to
report something sensible.
(BTW, gcc 2.95.2 could grok the 2.2.6 kernel source files if
someone is interested in about this.!)
The error is that running simultaneous
"ls -lR" on two CDs in Nakamichi MBR-7 changer device
results in erratical behavior: incorrect output, or
I/O errors and such.
Before doing the further backtracking,
I attach slightly edited portion from
the "syslog" log file when I ran
the two "ls -lR" commands under 2.2.14 and
experienced errors.
I wonder if the error code mentioned in the attached log such as
080000 or 07008 in scsi_done() printk() statemens are useful for
analyzing the problem to experienced scsi hackers.
Happy Hacking,
Chiaki Ishikawa
PS: I am wondering if there is some timeout or pause
value that I might need to increase after the
first reset.
If I recall correctly, a certain Yamaha CD-RW unit required a longer
wait time after reset.
I am not surprised if MBR CD changer required something like this.
MBR seems to try to check what CD is in each of the 7 available slots
by reloading the CD into read mechanism one by one
after reset. And this reloading obviously takes time.
(Does Brendan's unit also do this?)
I have no idea
if the unit is answering SCSI command sensibly during these
reset-induced re-loading (for checking purposes) of the CD slots.
Yeah, in that case, we can call the firmware buggy probably.
But I am trying to see if the problem can be solved since the
unit worked flawlessly under Windows when I tried and
I would like to see linux handle this unit if possible.
(No problem accessing the different units simultaneously although
how true the multitasking under the window is a question in itself.)
---- FYI,
In the attached output,
"Non-zero result in scsi_done ..."
"In scsi_done ..."
messages are printed in the debug printk in the scsi_obsolete.c
below .
Yes, the tmscsim driver uses the old error handling code.
Also, in my previous attempts,
I might have inserted my own printk() statements not in
the standard distribution myself.
void scsi_old_done (Scsi_Cmnd * SCpnt)
{
int status=0;
int exit=0;
int checked;
int oldto;
struct Scsi_Host * host = SCpnt->host;
int result = SCpnt->result;
SCpnt->serial_number = 0;
SCpnt->serial_number_at_timeout = 0;
oldto = update_timeout(SCpnt, 0);
#ifdef DEBUG_TIMEOUT
if(result) printk("Non-zero result in scsi_done %x %d:%d\n",
result, SCpnt->target, SCpnt->lun);
#endif
/* If we requested an abort, (and we got it) then fix up the return
* status to say why
*/
if(host_byte(result) == DID_ABORT && SCpnt->abort_reason)
SCpnt->result = result = (result & 0xff00ffff) |
(SCpnt->abort_reason << 16);
#define CMD_FINISHED 0
#define MAYREDO 1
#define REDO 3
#define PENDING 4
#ifdef DEBUG
/*CI*/
if(result != 0)
printk("In scsi_done(host = %d, result = %06x)\n", host->host_no, result);
#endif
----------------------------------------
(2) The log.
The relevant log from syslog.
(kern.log and message had similar message lines, but somehow
syslog contains the more complete lines.)
I inserted my commet by "****" marker.
Aside from removing the similar repetitive lines indicated by
"...", these are taken verbatim from the syslog file.
Jan 27 03:23:00 standard /USR/SBIN/CRON[351]: (mail) CMD (runq)
**** I believe that the next line appeared when I tried mount /dev/scd1 /mnt1
**** The disk is Free Solaris 7 Japanese edition.
Jan 27 03:31:01 standard kernel: VFS: Disk change detected on device sr(11,1)
Jan 27 03:31:06 standard kernel: ISO 9660 Extensions: RRIP_1991A
**** I believe that the next line appeared when I tried mount /dev/scd2 /mnt2
**** The disk is a CD which contains GNU tar balls and such.
Jan 27 03:31:11 standard kernel: VFS: Disk change detected on device sr(11,2)
Jan 27 03:31:18 standard kernel: ISO 9660 Extensions: Microsoft Joliet Level 3
Jan 27 03:31:18 standard kernel: ISO 9660 Extensions: RRIP_1991A
**** I ran ls -lR on one of the CD and then tried another ls on
**** the other CD and the error ensued.
Jan 27 03:32:48 standard kernel: Non-zero result in scsi_done 70008 4:1
Jan 27 03:32:48 standard kernel: In scsi_done(host = 1, result = 070008)
Jan 27 03:32:48 standard kernel: In MAYREDO, allowing 3 retries, have 0
Jan 27 03:32:48 standard kernel: scsi1 channel 0 : resetting for second half of
retries.
Jan 27 03:32:48 standard kernel: SCSI bus is being reset for host 1 channel 0.
Jan 27 03:32:48 standard kernel: DC390: RESET ... Non-zero result in scsi_done
80000 4:0
***** I wonder what the error 80000 4:0 means.
***** We see that the scsi subsystem re-tried the command.
***** Somehow scsi_done began returning 070008 instead of
***** 080000. I wonder what 070008 means.
***** Also, note that the scsi system tried resetting the bus.
Jan 27 03:32:48 standard kernel: In scsi_done(host = 1, result = 080000)
Jan 27 03:32:48 standard kernel: done
Jan 27 03:32:48 standard kernel: scsi reset function returned 2
Jan 27 03:32:48 standard kernel: SCSI_RESET_SUCCESS:
Jan 27 03:32:48 standard kernel: Non-zero result in scsi_done 70008 4:1
Jan 27 03:32:48 standard kernel: In scsi_done(host = 1, result = 070008)
Jan 27 03:32:48 standard kernel: In MAYREDO, allowing 3 retries, have 1
Jan 27 03:32:48 standard kernel: Non-zero result in scsi_done 70008 4:1
Jan 27 03:32:48 standard kernel: In scsi_done(host = 1, result = 070008)
Jan 27 03:32:48 standard kernel: In MAYREDO, allowing 3 retries, have 2
Jan 27 03:32:48 standard kernel: SCSI CD error : host 1 id 4 lun 1 return code =
27070008
Jan 27 03:32:48 standard kernel: CD-ROM I/O error: dev 0b:02, sector 156
Jan 27 03:32:49 standard kernel: Non-zero result in scsi_done 70008 4:1
Jan 27 03:32:49 standard kernel: In scsi_done(host = 1, result = 070008)
Jan 27 03:32:49 standard kernel: In MAYREDO, allowing 3 retries, have 0
Jan 27 03:32:49 standard kernel: scsi1 channel 0 : resetting for second half of
retries.
Jan 27 03:32:49 standard kernel: SCSI bus is being reset for host 1 channel 0.
Jan 27 03:32:49 standard kernel: DC390: RESET ... Non-zero result in scsi_done
80000 4:0
Jan 27 03:32:49 standard kernel: In scsi_done(host = 1, result = 080000)
Jan 27 03:32:49 standard kernel: done
Jan 27 03:32:49 standard kernel: scsi reset function returned 2
Jan 27 03:32:49 standard kernel: SCSI_RESET_SUCCESS:
Jan 27 03:32:50 standard kernel: Non-zero result in scsi_done 70008 4:1
Jan 27 03:32:50 standard kernel: In scsi_done(host = 1, result = 070008)
Jan 27 03:32:50 standard kernel: In MAYREDO, allowing 3 retries, have 1
Jan 27 03:32:50 standard kernel: Non-zero result in scsi_done 70008 4:1
Jan 27 03:32:50 standard kernel: In scsi_done(host = 1, result = 070008)
Jan 27 03:32:50 standard kernel: In MAYREDO, allowing 3 retries, have 2
Jan 27 03:32:50 standard kernel: SCSI CD error : host 1 id 4 lun 1 return code =
27070008
Jan 27 03:32:50 standard kernel: CD-ROM I/O error: dev 0b:02, sector 160
Jan 27 03:32:52 standard kernel: Non-zero result in scsi_done 70008 4:1
Jan 27 03:32:52 standard kernel: In scsi_done(host = 1, result = 070008)
Jan 27 03:32:52 standard kernel: In MAYREDO, allowing 3 retries, have 0
Jan 27 03:32:52 standard kernel: scsi1 channel 0 : resetting for second half of
retries.
Jan 27 03:32:52 standard kernel: SCSI bus is being reset for host 1 channel 0.
Jan 27 03:32:52 standard kernel: DC390: RESET ... Non-zero result in scsi_done
80000 4:0
Jan 27 03:32:52 standard kernel: In scsi_done(host = 1, result = 080000)
Jan 27 03:32:52 standard kernel: done
Jan 27 03:32:52 standard kernel: scsi reset function returned 2
Jan 27 03:32:52 standard kernel: SCSI_RESET_SUCCESS:
Jan 27 03:32:52 standard kernel: Non-zero result in scsi_done 70008 4:1
Jan 27 03:32:52 standard kernel: In scsi_done(host = 1, result = 070008)
Jan 27 03:32:52 standard kernel: In MAYREDO, allowing 3 retries, have 1
Jan 27 03:32:52 standard kernel: Non-zero result in scsi_done 70008 4:1
Jan 27 03:32:52 standard kernel: In scsi_done(host = 1, result = 070008)
Jan 27 03:32:52 standard kernel: In MAYREDO, allowing 3 retries, have 2
Jan 27 03:32:52 standard kernel: SCSI CD error : host 1 id 4 lun 1 return code =
27070008
Jan 27 03:32:52 standard kernel: CD-ROM I/O error: dev 0b:02, sector 164
Jan 27 03:32:53 standard kernel: Non-zero result in scsi_done 70008 4:1
Jan 27 03:32:53 standard kernel: In scsi_done(host = 1, result = 070008)
Jan 27 03:32:53 standard kernel: In MAYREDO, allowing 3 retries, have 0
Jan 27 03:32:53 standard kernel: scsi1 channel 0 : resetting for second half of
retries.
Jan 27 03:32:53 standard kernel: SCSI bus is being reset for host 1 channel 0.
Jan 27 03:32:53 standard kernel: DC390: RESET ... Non-zero result in scsi_done
80000 4:0
Jan 27 03:32:53 standard kernel: In scsi_done(host = 1, result = 080000)
Jan 27 03:32:53 standard kernel: done
Jan 27 03:32:53 standard kernel: scsi reset function returned 2
Jan 27 03:32:53 standard kernel: SCSI_RESET_SUCCESS:
Jan 27 03:32:54 standard kernel: Non-zero result in scsi_done 70008 4:1
Jan 27 03:32:54 standard kernel: In scsi_done(host = 1, result = 070008)
Jan 27 03:32:54 standard kernel: In MAYREDO, allowing 3 retries, have 1
Jan 27 03:32:54 standard kernel: Non-zero result in scsi_done 70008 4:1
Jan 27 03:32:54 standard kernel: In scsi_done(host = 1, result = 070008)
Jan 27 03:32:54 standard kernel: In MAYREDO, allowing 3 retries, have 2
Jan 27 03:32:54 standard kernel: SCSI CD error : host 1 id 4 lun 1 return code =
27070008
Jan 27 03:32:54 standard kernel: CD-ROM I/O error: dev 0b:02, sector 168
**** ... similar sequence above would repeat for
**** sector 168, 172, 176, 180
**** 184, 188, 192, 196, 200, 204, 208, 212, 216
**** ... then suddenly 900 appears.
Jan 27 03:33:20 standard kernel: CD-ROM I/O error: dev 0b:02, sector 900
Jan 27 03:33:21 standard kernel: Non-zero result in scsi_done 70008 4:1
Jan 27 03:33:21 standard kernel: In scsi_done(host = 1, result = 070008)
Jan 27 03:33:21 standard kernel: In MAYREDO, allowing 3 retries, have 0
Jan 27 03:33:21 standard kernel: scsi1 channel 0 : resetting for second half of
retries.
Jan 27 03:33:21 standard kernel: SCSI bus is being reset for host 1 channel 0.
Jan 27 03:33:21 standard kernel: DC390: RESET ... Non-zero result in scsi_done
80000 4:0
Jan 27 03:33:21 standard kernel: In scsi_done(host = 1, result = 080000)
Jan 27 03:33:21 standard kernel: done
Jan 27 03:33:21 standard kernel: scsi reset function returned 2
Jan 27 03:33:21 standard kernel: SCSI_RESET_SUCCESS:
Jan 27 03:33:22 standard kernel: Non-zero result in scsi_done 70008 4:1
Jan 27 03:33:22 standard kernel: In scsi_done(host = 1, result = 070008)
Jan 27 03:33:22 standard kernel: In MAYREDO, allowing 3 retries, have 1
Jan 27 03:33:22 standard kernel: Non-zero result in scsi_done 70008 4:1
Jan 27 03:33:22 standard kernel: In scsi_done(host = 1, result = 070008)
Jan 27 03:33:22 standard kernel: In MAYREDO, allowing 3 retries, have 2
Jan 27 03:33:22 standard kernel: SCSI CD error : host 1 id 4 lun 1 return code =
27070008
Jan 27 03:33:22 standard kernel: CD-ROM I/O error: dev 0b:02, sector 904
**** ... similar error appeared for
**** ... sector 908, 912, 916, 920, 924, 928
**** ...
Jan 27 03:33:34 standard kernel: CD-ROM I/O error: dev 0b:02, sector 928
Jan 27 03:33:34 standard kernel: Non-zero result in scsi_done 70008 4:1
Jan 27 03:33:34 standard kernel: In scsi_done(host = 1, result = 070008)
Jan 27 03:33:34 standard kernel: In MAYREDO, allowing 5 retries, have 0
Jan 27 03:33:35 standard kernel: Non-zero result in scsi_done 70008 4:1
Jan 27 03:33:35 standard kernel: In scsi_done(host = 1, result = 070008)
Jan 27 03:33:35 standard kernel: In MAYREDO, allowing 5 retries, have 1
Jan 27 03:33:35 standard kernel: scsi1 channel 0 : resetting for second half of
retries.
Jan 27 03:33:35 standard kernel: SCSI bus is being reset for host 1 channel 0.
Jan 27 03:33:35 standard kernel: DC390: RESET ... Non-zero result in scsi_done
80000 4:0
Jan 27 03:33:35 standard kernel: In scsi_done(host = 1, result = 080000)
Jan 27 03:33:35 standard kernel: done
Jan 27 03:33:35 standard kernel: scsi reset function returned 2
Jan 27 03:33:35 standard kernel: SCSI_RESET_SUCCESS:
Jan 27 03:33:36 standard kernel: Non-zero result in scsi_done 70008 4:1
Jan 27 03:33:36 standard kernel: In scsi_done(host = 1, result = 070008)
Jan 27 03:33:36 standard kernel: In MAYREDO, allowing 5 retries, have 2
Jan 27 03:33:36 standard kernel: Non-zero result in scsi_done 70008 4:1
Jan 27 03:33:36 standard kernel: In scsi_done(host = 1, result = 070008)
Jan 27 03:33:36 standard kernel: In MAYREDO, allowing 5 retries, have 3
Jan 27 03:33:36 standard kernel: Non-zero result in scsi_done 70008 4:1
Jan 27 03:33:36 standard kernel: In scsi_done(host = 1, result = 070008)
Jan 27 03:33:36 standard kernel: In MAYREDO, allowing 5 retries, have 4
Jan 27 03:33:36 standard kernel: SCSI error: host 1 id 4 lun 1 return code =
27070008
Jan 27 03:33:36 standard kernel: ^ISense class 0, sense error 0, extended sense 0
Jan 27 03:33:41 standard kernel: Non-zero result in scsi_done 8000000 4:0
Jan 27 03:33:41 standard kernel: In scsi_done(host = 1, result = 8000000)
Jan 27 03:33:41 standard kernel: CD-ROM I/O error: dev 0b:01, sector 15492
Jan 27 03:33:41 standard kernel: CD-ROM I/O error: dev 0b:01, sector 15496
Jan 27 03:33:41 standard kernel: CD-ROM I/O error: dev 0b:01, sector 15500
Jan 27 03:33:41 standard kernel: CD-ROM I/O error: dev 0b:01, sector 15516
Jan 27 03:33:41 standard kernel: CD-ROM I/O error: dev 0b:01, sector 15540
Jan 27 03:33:41 standard kernel: CD-ROM I/O error: dev 0b:01, sector 15556
Jan 27 03:33:41 standard kernel: CD-ROM I/O error: dev 0b:01, sector 15560
Jan 27 03:33:41 standard kernel: CD-ROM I/O error: dev 0b:01, sector 8788
Jan 27 03:33:41 standard kernel: CD-ROM I/O error: dev 0b:01, sector 1388
**** obviously from here to 2884. the reported
**** sector number increases by 4.****
...
Jan 27 03:33:42 standard kernel: CD-ROM I/O error: dev 0b:01, sector 2884
Jan 27 03:33:42 standard kernel: CD-ROM I/O error: dev 0b:01, sector 2888
Jan 27 03:33:42 standard kernel: CD-ROM I/O error: dev 0b:01, sector 2892
Jan 27 03:33:42 standard kernel: CD-ROM I/O error: dev 0b:01, sector 2896
Jan 27 03:33:42 standard kernel: CD-ROM I/O error: dev 0b:01, sector 2900
Jan 27 03:33:42 standard kernel: CD-ROM I/O error: dev 0b:01, sector 2904
Jan 27 03:33:42 standard kernel: CD-ROM I/O error: dev 0b:01, sector 2908
Jan 27 03:33:42 standard kernel: CD-ROM I/O error: dev 0b:01, sector 2912
Jan 27 03:33:42 standard kernel: CD-ROM I/O error: dev 0b:01, sector 1052
... around this time, I killed the ls processes by control-C somehow
although the shell-prompt didn't appear immediately.
......
Jan 27 03:40:00 standard /USR/SBIN/CRON[381]: (root) CMD (test -f /proc/modules &&
/sbin/rmmod -a)
Jan 27 03:43:00 standard /USR/SBIN/CRON[384]: (mail) CMD (runq)
-
To unsubscribe from this list: send the line "unsubscribe linux-scsi" in
the body of a message to [EMAIL PROTECTED]
