SCSI Log for non working 3ware Controller with Xen

SCSI Log for non working 3ware Controller with Xen

[Sven Kretzschmar]

As reported earlier, booting xenLinux 2.4.36 with a 3ware ATA-RAID Controller (7500-4)
does not work and runs into timeouts during the boot process and then goes into
an inifinite loop while trying to initialize the 3ware card.

I have now added an additonal normal ATA-Harddisk directly to the system.
Then I configured the 3w-xxxx driver as a module and booted from the single ATA-Harddisk.
This gives me the chance to activate SCSI-Logging (That's a Kernel-Option and is activated
via echo "scsi log all" > /proc/scsi/scsi") which logs a lot of SCSI tracing to the kernel log.

After booting I just activated the SCSi logging and then did "modprobe 3w-xxxx". This tries
to load the 3ware module and to initialize the 3ware driver  -- with the same failiure again btw. ;-)

However, now there's a lot of SCSI debugging available, perhaps the Xen team or somebody
else has some ideas what the problem might be by looking at the log ? TIA.
I know too little about the linux SCSI system to make much out of it.

Also as reported earlier, I could not get any additional output from Xen on the serial
console while the system tried to initialize the 3ware controller.
I build Xen (being in the "xen" directory) with "make clean", "debug=y make",
"debug=y install". Are there any additional options to get more tracing from Xen or
even from XenLinux 2.4 ?
This might be very helpfull in order to trace what's happening during the timeouts.

Log is attached to this message.

  Sven


Aug 13 16:05:30 filer11 kernel: scsi logging level set to 0xffffffff
Aug 13 16:05:40 filer11 kernel: 3ware Storage Controller device driver for Linux v1.02.00.037.
Aug 13 16:05:40 filer11 kernel: PCI: Obtained IRQ 72 for device 03:03.0
Aug 13 16:05:40 filer11 kernel: scsi1 : Found a 3ware Storage Controller at 0xc800, IRQ: 72, P-chip: 1.3
Aug 13 16:05:40 filer11 kernel: Wake up parent -1
Aug 13 16:05:40 filer11 kernel: Error handler sleeping
Aug 13 16:05:40 filer11 kernel: scsi1 : 3ware Storage Controller
Aug 13 16:05:40 filer11 kernel: scsi: performing INQUIRY
Aug 13 16:05:40 filer11 kernel: scsi_do_req (host = 1, channel = 0 target = 0, buffer =c608fdc0, bufflen = 256, done = c023a1a0, timeout = 600, retries = 3)
Aug 13 16:05:40 filer11 kernel: command : 12  00  00  00  ff  00
Aug 13 16:05:40 filer11 kernel: Activating command for device 0 (1)
Aug 13 16:05:40 filer11 kernel: Leaving scsi_init_cmd_from_req()
Aug 13 16:05:40 filer11 kernel: Adding timer for command c1536e00 at 600 (c023f5e0)
Aug 13 16:05:40 filer11 kernel: scsi_dispatch_cmnd (host = 1, channel = 0, target = 0, command = c1536e58, buffer = c608fdc0,
Aug 13 16:05:40 filer11 kernel: bufflen = 256, done = c023a1a0)
Aug 13 16:05:40 filer11 kernel: queuecommand : routine at c84e1cb0
Aug 13 16:05:40 filer11 kernel: leaving scsi_dispatch_cmnd()
Aug 13 16:05:40 filer11 kernel: Leaving scsi_do_req()
Aug 13 16:05:46 filer11 kernel: Command timed out active=1 busy=1 failed=1
Aug 13 16:05:49 filer11 kernel: Error handler waking up
Aug 13 16:05:49 filer11 kernel: scsi_unjam_host: Checking to see if we need to request sense
Aug 13 16:05:49 filer11 kernel: Command to ID 0 timedout
Aug 13 16:05:49 filer11 kernel: Total of 0+1 commands on 1 devices require eh work
Aug 13 16:05:49 filer11 kernel: scsi_unjam_host: Checking to see if we want to try abort
Aug 13 16:05:49 filer11 kernel: 3w-xxxx: scsi1: Unit #0: Command (c1536e00) timed out, resetting card.
Aug 13 16:05:49 filer11 kernel: Clearing timer for command c1536e00 0
Aug 13 16:05:49 filer11 kernel: Adding timer for command c1536e00 at 1000 (c023f7b0)
Aug 13 16:05:59 filer11 kernel: In scsi_eh_times_out c1536e00
Aug 13 16:06:04 filer11 kernel: 3w-xxxx: scsi1: Unit #0: Command (c1536e00) timed out, resetting card.
Aug 13 16:06:04 filer11 kernel: send_eh_cmnd: c1536e00 eh_state:2003
Aug 13 16:06:04 filer11 kernel: scsi_test_unit_ready: SCpnt c1536e00 eh_state 2003
Aug 13 16:06:04 filer11 kernel: scsi_unjam_host: Checking to see if we want to try BDR
Aug 13 16:06:04 filer11 kernel: scsi_unjam_host: Try hard bus reset
Aug 13 16:06:04 filer11 kernel: scsi_unjam_host: Try hard host reset
Aug 13 16:06:04 filer11 kernel: 3w-xxxx: scsi1: Reset succeeded.
Aug 13 16:06:04 filer11 kernel: Sleeping for timer tics 1000
Aug 13 16:06:14 filer11 kernel: Adding timer for command c1536e00 at 1000 (c023f7b0)
Aug 13 16:06:24 filer11 kernel: In scsi_eh_times_out c1536e00
Aug 13 16:06:26 filer11 kernel: 3w-xxxx: scsi1: Unit #0: Command (c1536e00) timed out, resetting card.
Aug 13 16:06:26 filer11 kernel: send_eh_cmnd: c1536e00 eh_state:2003
Aug 13 16:06:26 filer11 kernel: scsi_test_unit_ready: SCpnt c1536e00 eh_state 2003
Aug 13 16:06:26 filer11 kernel: scsi: device set offline - not ready or command retry failed after host reset: host 1 channel 0 id 0 lun 0
Aug 13 16:06:26 filer11 kernel: Adding timer for command c1536e00 at 100 (c023f7b0)
Aug 13 16:06:26 filer11 kernel: Clearing timer for command c1536e00 1
Aug 13 16:06:26 filer11 kernel: scsi_error.c: Waking up host to restart
Aug 13 16:06:26 filer11 kernel: Error handler sleeping
Aug 13 16:06:26 filer11 kernel: scsi_error.c: device offline - report as SUCCESS
Aug 13 16:06:26 filer11 kernel: Command finished 1 0 0x80000
Aug 13 16:06:26 filer11 kernel: Notifying upper driver of completion for device 0 80000
Aug 13 16:06:26 filer11 kernel: Deactivating command for device 0 (active=0, failed=0)
Aug 13 16:06:26 filer11 kernel: scsi: INQUIRY failed with code 0x80000
Aug 13 16:06:26 filer11 kernel: scsi: performing INQUIRY
Aug 13 16:06:26 filer11 kernel: scsi_do_req (host = 1, channel = 0 target = 1, buffer =c608fdc0, bufflen = 256, done = c023a1a0, timeout = 600, retries = 3)
Aug 13 16:06:26 filer11 kernel: command : 12  00  00  00  ff  00
Aug 13 16:06:26 filer11 kernel: Activating command for device 1 (1)
Aug 13 16:06:26 filer11 kernel: Leaving scsi_init_cmd_from_req()
Aug 13 16:06:26 filer11 kernel: Adding timer for command c5f80800 at 600 (c023f5e0)
Aug 13 16:06:26 filer11 kernel: scsi_dispatch_cmnd (host = 1, channel = 0, target = 1, command = c5f80858, buffer = c608fdc0,
Aug 13 16:06:26 filer11 kernel: bufflen = 256, done = c023a1a0)
Aug 13 16:06:26 filer11 kernel: queuecommand : routine at c84e1cb0
Aug 13 16:06:26 filer11 kernel: leaving scsi_dispatch_cmnd()
Aug 13 16:06:26 filer11 kernel: Leaving scsi_do_req()
Aug 13 16:06:32 filer11 kernel: Command timed out active=1 busy=1 failed=1
Aug 13 16:06:35 filer11 kernel: Error handler waking up
Aug 13 16:06:35 filer11 kernel: scsi_unjam_host: Checking to see if we need to request sense
Aug 13 16:06:35 filer11 kernel: Command to ID 1 timedout
Aug 13 16:06:35 filer11 kernel: Total of 0+1 commands on 1 devices require eh work
Aug 13 16:06:35 filer11 kernel: scsi_unjam_host: Checking to see if we want to try abort
Aug 13 16:06:35 filer11 kernel: 3w-xxxx: scsi1: Unit #1: Command (c5f80800) timed out, resetting card.
Aug 13 16:06:35 filer11 kernel: Clearing timer for command c5f80800 0
Aug 13 16:06:35 filer11 kernel: Adding timer for command c5f80800 at 1000 (c023f7b0)
Aug 13 16:06:45 filer11 kernel: In scsi_eh_times_out c5f80800
Aug 13 16:06:50 filer11 kernel: 3w-xxxx: scsi1: Unit #1: Command (c5f80800) timed out, resetting card.
Aug 13 16:06:50 filer11 kernel: send_eh_cmnd: c5f80800 eh_state:2003
Aug 13 16:06:50 filer11 kernel: scsi_test_unit_ready: SCpnt c5f80800 eh_state 2003
Aug 13 16:06:50 filer11 kernel: scsi_unjam_host: Checking to see if we want to try BDR
Aug 13 16:06:50 filer11 kernel: scsi_unjam_host: Try hard bus reset
Aug 13 16:06:50 filer11 kernel: scsi_unjam_host: Try hard host reset
Aug 13 16:06:50 filer11 kernel: 3w-xxxx: scsi1: Reset succeeded.
Aug 13 16:06:50 filer11 kernel: Sleeping for timer tics 1000
Aug 13 16:07:00 filer11 kernel: Adding timer for command c5f80800 at 1000 (c023f7b0)
Aug 13 16:07:10 filer11 kernel: In scsi_eh_times_out c5f80800
Aug 13 16:07:13 filer11 kernel: 3w-xxxx: scsi1: Unit #1: Command (c5f80800) timed out, resetting card.
Aug 13 16:07:13 filer11 kernel: send_eh_cmnd: c5f80800 eh_state:2003
Aug 13 16:07:13 filer11 kernel: scsi_test_unit_ready: SCpnt c5f80800 eh_state 2003
Aug 13 16:07:13 filer11 kernel: scsi: device set offline - not ready or command retry failed after host reset: host 1 channel 0 id 1 lun 0
Aug 13 16:07:13 filer11 kernel: Adding timer for command c5f80800 at 100 (c023f7b0)
Aug 13 16:07:13 filer11 kernel: Clearing timer for command c5f80800 1
Aug 13 16:07:13 filer11 kernel: scsi_error.c: Waking up host to restart
Aug 13 16:07:13 filer11 kernel: Error handler sleeping
Aug 13 16:07:13 filer11 kernel: scsi_error.c: device offline - report as SUCCESS
Aug 13 16:07:13 filer11 kernel: Command finished 1 0 0x80000
Aug 13 16:07:13 filer11 kernel: Notifying upper driver of completion for device 1 80000
Aug 13 16:07:13 filer11 kernel: Deactivating command for device 1 (active=0, failed=0)
Aug 13 16:07:13 filer11 kernel: scsi: INQUIRY failed with code 0x80000
Aug 13 16:07:13 filer11 kernel: scsi: performing INQUIRY
Aug 13 16:07:13 filer11 kernel: scsi_do_req (host = 1, channel = 0 target = 2, buffer =c608fdc0, bufflen = 256, done = c023a1a0, timeout = 600, retries = 3)
Aug 13 16:07:13 filer11 kernel: command : 12  00  00  00  ff  00
Aug 13 16:07:13 filer11 kernel: Activating command for device 2 (1)
Aug 13 16:07:13 filer11 kernel: Leaving scsi_init_cmd_from_req()
Aug 13 16:07:13 filer11 kernel: Adding timer for command c5f80800 at 600 (c023f5e0)
Aug 13 16:07:13 filer11 kernel: scsi_dispatch_cmnd (host = 1, channel = 0, target = 2, command = c5f80858, buffer = c608fdc0,
Aug 13 16:07:13 filer11 kernel: bufflen = 256, done = c023a1a0)
Aug 13 16:07:13 filer11 kernel: queuecommand : routine at c84e1cb0
Aug 13 16:07:13 filer11 kernel: leaving scsi_dispatch_cmnd()
Aug 13 16:07:13 filer11 kernel: Leaving scsi_do_req()
Aug 13 16:07:19 filer11 kernel: Command timed out active=1 busy=1 failed=1
Aug 13 16:07:22 filer11 kernel: Error handler waking up
Aug 13 16:07:22 filer11 kernel: scsi_unjam_host: Checking to see if we need to request sense
Aug 13 16:07:22 filer11 kernel: Command to ID 2 timedout
Aug 13 16:07:22 filer11 kernel: Total of 0+1 commands on 1 devices require eh work
Aug 13 16:07:22 filer11 kernel: scsi_unjam_host: Checking to see if we want to try abort
Aug 13 16:07:22 filer11 kernel: 3w-xxxx: scsi1: Unit #2: Command (c5f80800) timed out, resetting card.
Aug 13 16:07:22 filer11 kernel: Clearing timer for command c5f80800 0
Aug 13 16:07:22 filer11 kernel: Adding timer for command c5f80800 at 1000 (c023f7b0)
Aug 13 16:07:32 filer11 kernel: In scsi_eh_times_out c5f80800
Aug 13 16:07:37 filer11 kernel: 3w-xxxx: scsi1: Unit #2: Command (c5f80800) timed out, resetting card.
Aug 13 16:07:37 filer11 kernel: send_eh_cmnd: c5f80800 eh_state:2003
Aug 13 16:07:37 filer11 kernel: scsi_test_unit_ready: SCpnt c5f80800 eh_state 2003
Aug 13 16:07:37 filer11 kernel: scsi_unjam_host: Checking to see if we want to try BDR
Aug 13 16:07:37 filer11 kernel: scsi_unjam_host: Try hard bus reset
Aug 13 16:07:37 filer11 kernel: scsi_unjam_host: Try hard host reset
Aug 13 16:07:37 filer11 kernel: 3w-xxxx: scsi1: Reset succeeded.
Aug 13 16:07:37 filer11 kernel: Sleeping for timer tics 1000
Aug 13 16:07:47 filer11 kernel: Adding timer for command c5f80800 at 1000 (c023f7b0)
Aug 13 16:07:55 filer11 shutdown: shutting down for system reboot
...




-------------------------------------------------------
SF.Net email is sponsored by Shop4tech.com-Lowest price on Blank Media
100pk Sonic DVD-R 4x for only $29 -100pk Sonic DVD+R for only $33
Save 50% off Retail on Ink & Toner - Free Shipping and Free Gift.
http://www.shop4tech.com/z/Inkjet_Cartridges/9_108_r285

Re: SCSI Log for non working 3ware Controller with Xen

[Ian Pratt]

> 
> As reported earlier, booting xenLinux 2.4.36 with a 3ware ATA-RAID Controller (7500-4)
> does not work and runs into timeouts during the boot process and then goes into
> an inifinite loop while trying to initialize the 3ware card.
> 
> I have now added an additonal normal ATA-Harddisk directly to the system.
> Then I configured the 3w-xxxx driver as a module and booted from the single ATA-Harddisk.

I don't think the scsi tracing is going to be too much help as
it's a 3ware driver issue.

Doing a cat /proc/interrupts and seeing if you're getting any
for the device would be interesting.

Also, comparing the output of 'lspci -v' with a stock 2.6 kernel
might reveal something (same with  cat /proc/ioports )

Ian


-------------------------------------------------------
SF.Net email is sponsored by Shop4tech.com-Lowest price on Blank Media
100pk Sonic DVD-R 4x for only $29 -100pk Sonic DVD+R for only $33
Save 50% off Retail on Ink & Toner - Free Shipping and Free Gift.
http://www.shop4tech.com/z/Inkjet_Cartridges/9_108_r285

Re: SCSI Log for non working 3ware Controller with Xen

[Nuno Silva]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Hi!

Sven Kretzschmar wrote:

[..]

| Aug 13 16:05:30 filer11 kernel: scsi logging level set to 0xffffffff
| Aug 13 16:05:40 filer11 kernel: 3ware Storage Controller device driver
for Linux v1.02.00.037.
| Aug 13 16:05:40 filer11 kernel: PCI: Obtained IRQ 72 for device 03:03.0
| Aug 13 16:05:40 filer11 kernel: scsi1 : Found a 3ware Storage
Controller at 0xc800, IRQ: 72, P-chip: 1.3

IRQ 72? It seams that you enabled the vector irq pci stuff
(CONFIG_PCI_MSI=y). Maybe disabling that will work better?

Do you any any other devices with irq lines bigger than 32 working
correctly?

cat /proc/interrupts

It just a wild guess...
Regards,
Nuno Silva


-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.2.5 (GNU/Linux)
Comment: Using GnuPG with Thunderbird - http://enigmail.mozdev.org

iD8DBQFBHPx5OPig54MP17wRApiaAJ4pljOtCWS9F8TmEfT7VLG/02xm0QCffEob
2n69Elhr47tLIWo9D/QIwgw=
=myc0
-----END PGP SIGNATURE-----


-------------------------------------------------------
SF.Net email is sponsored by Shop4tech.com-Lowest price on Blank Media
100pk Sonic DVD-R 4x for only $29 -100pk Sonic DVD+R for only $33
Save 50% off Retail on Ink & Toner - Free Shipping and Free Gift.
http://www.shop4tech.com/z/Inkjet_Cartridges/9_108_r285