SCSI Bus Resets after hal upgraded to .5.5.1 from .5.4
Pat Kellaher
qqxm5gf39 at siren.ocn.ne.jp
Sun Dec 18 23:40:36 PST 2005
I forgot...
udev version 0.70
hotplug dated Thu Sep 23 2004
lshal produces a lot of output, so if you need it ask.
Pat
Pat Kellaher wrote:
> I am running Slackware Linux 10.2 with Dropline Gnome 2.12.2 and am
> currently running kernel 2.6.14.4. I noticed the SCSI bus that my
> optical drives are on (Pioneer DVD-ROM 304 and Plextor 1210 CDRW)
> consistently reseting after I upgraded to Dropline Gnome 2.12.2. I
> tracked the problem down to hald. If I stopped hald then the reseting
> stopped. If I started hald then the reset happened. At the time I
> was using kernel 2.6.14.3 and hald had been upgraded from .5.4 to .5.5.1.
>
> To troubleshoot, I am starting hald like this:
> /usr/sbin/hald --daemon=yes --retain-privileges --verbose=yes
> --use-syslog
>
> The next line in rc.hal is:
> echo /sbin/udevsend >/proc/sys/kernel/hotplug
>
> Here are snippets from /var/log/messages:
>
> Dec 19 16:18:00 wecoyote hald[11854]: 16:18:00.217 [I] hald.c:511: hal
> 0.5.5.1
> Dec 19 16:18:00 wecoyote hald[11854]: 16:18:00.217 [I] hald.c:519:
> Will daemonize
> Dec 19 16:18:00 wecoyote hald[11854]: 16:18:00.217 [I] hald.c:520:
> Becoming a daemon
> Dec 19 16:18:00 wecoyote hald[11855]: 16:18:00.218 [I]
> hald_dbus.c:3048: local server is listening at
> unix:abstract=/tmp/hald-local/dbus-8dPaxlfJMC,guid=a85ea6436d6279ae147a64a90d1a3a00
>
> Dec 19 16:18:00 wecoyote hald[11855]: 16:18:00.218 [I] osspec.c:347:
> sysfs mount point is '/sys'
> Dec 19 16:18:00 wecoyote hald[11855]: 16:18:00.218 [I] osspec.c:352:
> proc mount point is '/proc'
> Dec 19 16:18:00 wecoyote hald[11855]: 16:18:00.221 [I] osspec.c:524:
> Synthesizing sysfs events...
> Dec 19 16:18:00 wecoyote hald[11855]: 16:18:00.223 [I] coldplug.c:129:
> dev_root is /dev
> Dec 19 16:18:00 wecoyote hald[11855]: 16:18:00.246 [I] coldplug.c:230:
> sysfs_path /sys/class/tty/ttyS1 not in udevdb
> Dec 19 16:18:00 wecoyote hald[11855]: 16:18:00.246 [I] coldplug.c:245:
> return sysfs_path /dev/ttyS1
> Dec 19 16:18:00 wecoyote hald[11855]: 16:18:00.246 [I] coldplug.c:230:
> sysfs_path /sys/class/tty/ttyS0 not in udevdb
> Dec 19 16:18:00 wecoyote hald[11855]: 16:18:00.246 [I] coldplug.c:245:
> return sysfs_path /dev/ttyS0
> Dec 19 16:18:00 wecoyote hald[11855]: 16:18:00.248 [I] coldplug.c:230:
> sysfs_path /sys/class/net/eth0 not in udevdb
> Dec 19 16:18:00 wecoyote hald[11855]: 16:18:00.249 [I] coldplug.c:230:
> sysfs_path /sys/class/spi_host/host0 not in udevdb
> Dec 19 16:18:00 wecoyote hald[11855]: 16:18:00.249 [I] coldplug.c:230:
> sysfs_path /sys/class/scsi_host/host0 not in udevdb
> Dec 19 16:18:00 wecoyote hald[11855]: 16:18:00.249 [I] coldplug.c:230:
> sysfs_path /sys/class/spi_transport/target0:0:4 not in udevdb
> Dec 19 16:18:00 wecoyote hald[11855]: 16:18:00.249 [I] coldplug.c:230:
> sysfs_path /sys/class/scsi_generic/sg3 not in udevdb
> Dec 19 16:18:00 wecoyote hald[11855]: 16:18:00.249 [I] coldplug.c:245:
> return sysfs_path /dev/sg3
> Dec 19 16:18:00 wecoyote hald[11855]: 16:18:00.249 [I] coldplug.c:230:
> sysfs_path /sys/class/scsi_device/0:0:4:0 not in udevdb
> Dec 19 16:18:00 wecoyote hald[11855]: 16:18:00.249 [I] coldplug.c:230:
> sysfs_path /sys/class/spi_transport/target0:0:3 not in udevdb
> Dec 19 16:18:00 wecoyote hald[11855]: 16:18:00.250 [I] coldplug.c:230:
> sysfs_path /sys/class/scsi_generic/sg2 not in udevdb
> Dec 19 16:18:00 wecoyote hald[11855]: 16:18:00.250 [I] coldplug.c:245:
> return sysfs_path /dev/sg2
> Dec 19 16:18:00 wecoyote hald[11855]: 16:18:00.250 [I] coldplug.c:230:
> sysfs_path /sys/class/scsi_device/0:0:3:0 not in udevdb
> Dec 19 16:18:00 wecoyote hald[11855]: 16:18:00.250 [I] coldplug.c:230:
> sysfs_path /sys/class/spi_transport/target0:0:2 not in udevdb
> Dec 19 16:18:00 wecoyote hald[11855]: 16:18:00.250 [I] coldplug.c:230:
> sysfs_path /sys/class/scsi_generic/sg1 not in udevdb
> Dec 19 16:18:00 wecoyote hald[11855]: 16:18:00.250 [I] coldplug.c:245:
> return sysfs_path /dev/sg1
> Dec 19 16:18:00 wecoyote hald[11855]: 16:18:00.250 [I] coldplug.c:230:
> sysfs_path /sys/class/scsi_device/0:0:2:0 not in udevdb
> Dec 19 16:18:00 wecoyote hald[11855]: 16:18:00.251 [I] coldplug.c:230:
> sysfs_path /sys/class/spi_transport/target0:0:0 not in udevdb
> Dec 19 16:18:00 wecoyote hald[11855]: 16:18:00.251 [I] coldplug.c:230:
> sysfs_path /sys/class/scsi_generic/sg0 not in udevdb
> Dec 19 16:18:00 wecoyote hald[11855]: 16:18:00.251 [I] coldplug.c:245:
> return sysfs_path /dev/sg0
> Dec 19 16:18:00 wecoyote hald[11855]: 16:18:00.251 [I] coldplug.c:230:
> sysfs_path /sys/class/scsi_device/0:0:0:0 not in udevdb
>
> [snip]
>
> Dec 19 16:18:02 wecoyote hald[11855]: 16:18:02.684 [I] blockdev.c:180:
> Update mount point for
> /org/freedesktop/Hal/devices/volume_part_1_size_542375936 (device_file
> /dev/sr1)
> Dec 19 16:18:02 wecoyote hald[11855]: 16:18:02.986 [I] blockdev.c:227:
> Clearing mount point for /dev/sr1
> Dec 19 16:18:02 wecoyote hald[11855]: 16:18:02.989 [I] blockdev.c:139:
> Add callouts completed
> udi=/org/freedesktop/Hal/devices/volume_part_1_size_542375936
> Dec 19 16:18:02 wecoyote hald[11855]: 16:18:02.989 [I] hald.c:89:
> Added device to GDL;
> udi=/org/freedesktop/Hal/devices/volume_part_1_size_542375936
> Dec 19 16:18:02 wecoyote hald[11855]: 16:18:02.989 [I] hald.c:653:
> Device probing completed
> Dec 19 16:18:02 wecoyote hald[11855]: 16:18:02.989 [I]
> hald_dbus.c:3063: entering
> Dec 19 16:18:03 wecoyote kernel: sr 0:0:4:0: SCSI error: return code =
> 0x10000
> Dec 19 16:18:44 wecoyote last message repeated 3 times
> Dec 19 16:19:33 wecoyote last message repeated 3 times
> Dec 19 16:19:36 wecoyote hald[11855]: 16:19:36.830 [I] hald.c:273:
> Caught SIGTERM, initiating shutdown
> Dec 19 16:19:36 wecoyote hald[11855]: 16:19:36.830 [I] util.c:1262:
> Killing helper with pid 11890
> Dec 19 16:19:36 wecoyote hald[11855]: 16:19:36.830 [I] util.c:1262:
> Killing helper with pid 11877
> Dec 19 16:19:36 wecoyote hald[11855]: 16:19:36.830 [I] util.c:1262:
> Killing helper with pid 11874
> Dec 19 16:19:36 wecoyote hald[11855]: 16:19:36.830 [I] util.c:1262:
> Killing helper with pid 11861
> Dec 19 16:19:36 wecoyote hald[11855]: 16:19:36.830 [I] hald.c:275:
> Killed 134679508 helpers; exiting
>
> Here is /var/log/syslog during that time:
>
> Dec 19 16:18:00 wecoyote hald[11855]: 16:18:00.358 [E] acpi.c:766:
> Couldn't open /proc/acpi/battery: Error opening directory
> '/proc/acpi/b attery': No such file or directory
> Dec 19 16:18:00 wecoyote hald[11855]: 16:18:00.358 [E] acpi.c:766:
> Couldn't open /proc/acpi/ac_adapter: Error opening directory
> '/proc/acp i/ac_adapter': No such file or directory
> Dec 19 16:18:00 wecoyote hald[11855]: 16:18:00.358 [E] acpi.c:766:
> Couldn't open /proc/acpi/button/lid: Error opening directory
> '/proc/acp i/button/lid': No such file or directory
> Dec 19 16:18:00 wecoyote hald[11855]: 16:18:00.520 [E] util.c:456:
> Cannot open
> '/sys/devices/pci0000:00/0000:00:08.0/0000:01:08.2/fw-host0
> /00023c0021044b30/00023c0021044b30-0/../vendor_oui'
> Dec 19 16:18:00 wecoyote hald[11855]: 16:18:00.520 [E] util.c:315:
> Cannot open
> '/sys/devices/pci0000:00/0000:00:08.0/0000:01:08.2/fw-host0
> /00023c0021044b30/00023c0021044b30-0/model_id'
> Dec 19 16:18:00 wecoyote hald[11855]: 16:18:00.608 [E] util.c:456:
> Cannot open '/sys/devices/pci0000:00/0000:00:02.2/usb1/1-2/serial'
> Dec 19 16:18:00 wecoyote hald[11855]: 16:18:00.608 [E] util.c:456:
> Cannot open '/sys/devices/pci0000:00/0000:00:02.2/usb1/1-2/serial'
> Dec 19 16:18:01 wecoyote hald[11855]: 16:18:01.311 [W] blockdev.c:218:
> Could not find /dev/sdc1 in /proc/mounts retry to find.
> Dec 19 16:18:01 wecoyote hald[11855]: 16:18:01.312 [W] blockdev.c:213:
> Could not find /dev/sdc1 in /proc/mounts, no second retry.
> Dec 19 16:18:01 wecoyote hald[11855]: 16:18:01.834 [W] blockdev.c:218:
> Could not find /dev/sda3 in /proc/mounts retry to find.
> Dec 19 16:18:01 wecoyote hald[11855]: 16:18:01.835 [W] blockdev.c:213:
> Could not find /dev/sda3 in /proc/mounts, no second retry.
> Dec 19 16:18:02 wecoyote hald[11855]: 16:18:02.149 [W] blockdev.c:218:
> Could not find /dev/sda2 in /proc/mounts retry to find.
> Dec 19 16:18:02 wecoyote hald[11855]: 16:18:02.150 [W] blockdev.c:213:
> Could not find /dev/sda2 in /proc/mounts, no second retry.
> Dec 19 16:18:02 wecoyote hald[11855]: 16:18:02.464 [W] blockdev.c:218:
> Could not find /dev/sda1 in /proc/mounts retry to find.
> Dec 19 16:18:02 wecoyote hald[11855]: 16:18:02.465 [W] blockdev.c:213:
> Could not find /dev/sda1 in /proc/mounts, no second retry.
> Dec 19 16:18:02 wecoyote hald[11855]: 16:18:02.985 [W] blockdev.c:218:
> Could not find /dev/sr1 in /proc/mounts retry to find.
> Dec 19 16:18:02 wecoyote hald[11855]: 16:18:02.985 [W] blockdev.c:213:
> Could not find /dev/sr1 in /proc/mounts, no second retry.
> Dec 19 16:18:03 wecoyote kernel: (scsi0:A:4:0): No or incomplete CDB
> sent to device.
> Dec 19 16:18:03 wecoyote kernel: scsi0: Issued Channel A Bus Reset. 1
> SCBs aborted
> Dec 19 16:18:15 wecoyote kernel: (scsi0:A:4:0): No or incomplete CDB
> sent to device.
> Dec 19 16:18:15 wecoyote kernel: scsi0: Issued Channel A Bus Reset. 1
> SCBs aborted
> Dec 19 16:18:31 wecoyote kernel: (scsi0:A:4:0): No or incomplete CDB
> sent to device.
> Dec 19 16:18:31 wecoyote kernel: scsi0: Issued Channel A Bus Reset. 1
> SCBs aborted
> Dec 19 16:18:44 wecoyote kernel: (scsi0:A:4:0): No or incomplete CDB
> sent to device.
> Dec 19 16:18:44 wecoyote kernel: scsi0: Issued Channel A Bus Reset. 1
> SCBs aborted
> Dec 19 16:19:04 wecoyote kernel: (scsi0:A:4:0): No or incomplete CDB
> sent to device.
> Dec 19 16:19:04 wecoyote kernel: scsi0: Issued Channel A Bus Reset. 1
> SCBs aborted
> Dec 19 16:19:18 wecoyote kernel: (scsi0:A:4:0): No or incomplete CDB
> sent to device.
> Dec 19 16:19:18 wecoyote kernel: scsi0: Issued Channel A Bus Reset. 1
> SCBs aborted
> Dec 19 16:19:33 wecoyote kernel: (scsi0:A:4:0): No or incomplete CDB
> sent to device.
> Dec 19 16:19:33 wecoyote kernel: scsi0: Issued Channel A Bus Reset. 1
> SCBs aborted
>
> Here is the contents of /proc/scsi/scsi:
>
> # cat /proc/scsi/scsi
> Attached devices:
> Host: scsi0 Channel: 00 Id: 00 Lun: 00
> Vendor: QUANTUM Model: ATLAS10K2-TY184L Rev: DDD6
> Type: Direct-Access ANSI SCSI revision: 03
> Host: scsi0 Channel: 00 Id: 02 Lun: 00
> Vendor: QUANTUM Model: ATLAS10K2-TY184L Rev: DDD6
> Type: Direct-Access ANSI SCSI revision: 03
> Host: scsi0 Channel: 00 Id: 03 Lun: 00
> Vendor: PIONEER Model: DVD-ROM DVD-304 Rev: 1.03
> Type: CD-ROM ANSI SCSI revision: 02
> Host: scsi0 Channel: 00 Id: 04 Lun: 00
> Vendor: PLEXTOR Model: CD-R PX-W1210S Rev: 1.06
> Type: CD-ROM ANSI SCSI revision: 02
> Host: scsi1 Channel: 00 Id: 00 Lun: 00
> Vendor: WDC WD80 Model: 0UE-00HCT0 Rev: 0 0
> Type: Direct-Access ANSI SCSI revision: 02
>
> (Note: That WD80 is an external USB HD)
>
> Here are the contents of /proc/scsi/aic7xxx/0:
>
> /proc/scsi/aic7xxx# cat 0
> Adaptec AIC7xxx driver version: 7.0
> Adaptec 29160 Ultra160 SCSI adapter
> aic7892: Ultra160 Wide Channel A, SCSI Id=7, 32/253 SCBs
> Allocated SCBs: 36, SG List Length: 128
>
> Serial EEPROM:
> 0xc33a 0xc33a 0xc33a 0xc33a 0xc33a 0xc13a 0xc13a 0xc13a
> 0xc13a 0xc13a 0xc13a 0xc13a 0xc13a 0xc13a 0xc13a 0xc13a
> 0xb8f4 0x7c5d 0x2807 0x0010 0xffff 0xffff 0xffff 0xffff
> 0xffff 0xffff 0xffff 0xffff 0xffff 0xffff 0x0250 0x7d4e
>
> Target 0 Negotiation Settings
> User: 160.000MB/s transfers (80.000MHz DT, offset 127, 16bit)
> Goal: 160.000MB/s transfers (80.000MHz DT, offset 127, 16bit)
> Curr: 160.000MB/s transfers (80.000MHz DT, offset 127, 16bit)
> Channel A Target 0 Lun 0 Settings
> Commands Queued 36831
> Commands Active 0
> Command Openings 32
> Max Tagged Openings 32
> Device Queue Frozen Count 0
> Target 1 Negotiation Settings
> User: 160.000MB/s transfers (80.000MHz DT, offset 127, 16bit)
> Target 2 Negotiation Settings
> User: 160.000MB/s transfers (80.000MHz DT, offset 127, 16bit)
> Goal: 160.000MB/s transfers (80.000MHz DT, offset 127, 16bit)
> Curr: 3.300MB/s transfers
> Channel A Target 2 Lun 0 Settings
> Commands Queued 75566
> Commands Active 0
> Command Openings 32
> Max Tagged Openings 32
> Device Queue Frozen Count 0
> Target 3 Negotiation Settings
> User: 160.000MB/s transfers (80.000MHz DT, offset 127, 16bit)
> Goal: 20.000MB/s transfers (20.000MHz, offset 16)
> Curr: 20.000MB/s transfers (20.000MHz, offset 16)
> Channel A Target 3 Lun 0 Settings
> Commands Queued 28147
> Commands Active 0
> Command Openings 1
> Max Tagged Openings 0
> Device Queue Frozen Count 0
> Target 4 Negotiation Settings
> User: 160.000MB/s transfers (80.000MHz DT, offset 127, 16bit)
> Goal: 20.000MB/s transfers (20.000MHz, offset 16)
> Curr: 20.000MB/s transfers (20.000MHz, offset 16)
> Channel A Target 4 Lun 0 Settings
> Commands Queued 903256
> Commands Active 0
> Command Openings 1
> Max Tagged Openings 0
> Device Queue Frozen Count 0
>
> What could be causing my SCSI bus resets?
>
> Pat
>
> _______________________________________________
> hal mailing list
> hal at lists.freedesktop.org
> http://lists.freedesktop.org/mailman/listinfo/hal
>
More information about the hal
mailing list