Troubleshooting Logs
8th February 2008. Printing doesn't work. Debian Sarge.
lpq and lpstat report: "Unable to connect to server: Connection refused"
http://server:631 is unavailable
/etc/init.d/cupsys restart doesn't help
ps aux | grep cupsys:
root 28266 0.0 0.0 1840 600 pts/0 S+ 13:18 0:00 grep cupsys server:/etc/cups# ps aux | grep cups root 18299 0.0 0.0 3396 768 ? D 06:25 0:00 /usr/lib/cups/backend/epson root 28201 0.0 0.0 3396 768 ? D 13:14 0:00 /usr/lib/cups/backend/epson root 28223 0.0 0.0 5764 1820 ? Ss 13:14 0:00 /usr/sbin/cupsd -F root 28224 0.0 0.0 3392 764 ? D 13:14 0:00 /usr/lib/cups/backend/epson
Why do I see /usr/lib/cups/backend/epson and not a HP backend in the above?
/var/log/cups/error.log from today:
I [07/Feb/2008:06:25:42 +0000] Listening to 0:631 I [07/Feb/2008:06:25:42 +0000] Loaded configuration file "/etc/cups/cupsd.conf" I [07/Feb/2008:06:25:42 +0000] Configured for up to 100 clients. I [07/Feb/2008:06:25:42 +0000] Allowing up to 100 client connections per host. I [07/Feb/2008:06:25:42 +0000] Full reload is required. W [07/Feb/2008:06:26:12 +0000] LoadDevices: Backend did not respond within 30 seconds!
/var/log/cups/error.log from yesterday when I was installing software and rebooting:
I [06/Feb/2008:18:22:31 +0000] Scheduler shutting down normally. I [06/Feb/2008:18:24:36 +0000] Listening to 0:631 I [06/Feb/2008:18:24:36 +0000] Loaded configuration file "/etc/cups/cupsd.conf" I [06/Feb/2008:18:24:36 +0000] Configured for up to 100 clients. I [06/Feb/2008:18:24:36 +0000] Allowing up to 100 client connections per host. I [06/Feb/2008:18:24:36 +0000] Full reload is required. I [06/Feb/2008:18:24:38 +0000] LoadPPDs: Read "/etc/cups/ppds.dat", 2805 PPDs... I [06/Feb/2008:18:24:39 +0000] LoadPPDs: Wrote "/etc/cups/ppds.dat", 2805 PPDs... I [06/Feb/2008:18:24:40 +0000] Full reload complete.
There are also these positive messages yesterday that we don't have today:
Started filter /usr/lib/cups/filter/pstops (PID 29192) for job 12989. Started filter /usr/lib/cups/filter/foomatic-rip (PID 29193) for job 12989. Started backend /usr/lib/cups/backend/socket (PID 29194) for job 12989.
Usually we have this:
Full reload is required. LoadPPDs: Read "/etc/cups/ppds.dat", 2805 PPDs... LoadPPDs: Wrote "/etc/cups/ppds.dat", 2805 PPDs... Full reload complete.
Now we have this:
Full reload is required. LoadDevices: Backend did not respond within 30 seconds!
Is it something that would have been set previously but not taken effect until the server's restart?
Has some user deleted something by mistake? they're all lpadmin; is there any mention in the log?
I have no notes on how the print server is setup for this particular printer.
|-- ppd | `-- Colour_Laserjet.ppd
I did used to have a list of the driver that was used or something...
ii hplip 0.9.2-2 HP Linux Printing and Imaging System (hplip) ii hpijs 2.1.2+0.9.2-2 HP Linux Printing and Imaging - gs IJS driver (hpijs)
# /etc/init.d/hplip start Starting HP Linux Printing and Imaging System: (hpiod already running), (hpssd already running) server:/etc/cups# /etc/init.d/hplip restart Stopping HP Linux Printing and Imaging System GUIs: done. Stopping HP Linux Printing and Imaging System: hpssd, hpiod Starting HP Linux Printing and Imaging System: hpiod, hpssd
The only thing I can find on the web is people saying they fixed it with a reboot and indeed a reboot fixed it.
This is afterward when it's working:
# ps aux | grep cups root 2424 0.6 0.2 8496 4868 ? Ss 19:03 0:00 /usr/sbin/cupsd -F
# lpq Colour_Laserjet is ready no entries
15th September 2007. mdadm when added missing third SCSI disk to RAID1 and RAID5 array. Debian Etch
SCSI device sda: 156301488 512-byte hdwr sectors (80026 MB)
sda: Write Protect is off
sda: Mode Sense: 00 38 00 00
sda: assuming drive cache: write through
SCSI device sda: 156301488 512-byte hdwr sectors (80026 MB)
sda: Write Protect is off
sda: Mode Sense: 00 38 00 00
sda: assuming drive cache: write through
sda: sda1
sd 1:0:0:0: Attached scsi disk sda
scsi0 : Adaptec AIC7XXX EISA/VLB/PCI SCSI HBA DRIVER, Rev 7.0
<Adaptec aic7899 Ultra160 SCSI adapter>
aic7899: Ultra160 Wide Channel A, SCSI Id=7, 32/253 SCBs
Vendor: MAXTOR Model: ATLAS10K4_36WLS Rev: DFV0
Type: Direct-Access ANSI SCSI revision: 03
scsi0:A:0:0: Tagged Queuing enabled. Depth 8
target0:0:0: Beginning Domain Validation
target0:0:0: wide asynchronous
target0:0:0: FAST-80 WIDE SCSI 160.0 MB/s DT (12.5 ns, offset 127)
target0:0:0: Ending Domain Validation
SCSI device sdb: 71833096 512-byte hdwr sectors (36779 MB)
sdb: Write Protect is off
sdb: Mode Sense: ed 00 10 08
SCSI device sdb: drive cache: write back w/ FUA
SCSI device sdb: 71833096 512-byte hdwr sectors (36779 MB)
sdb: Write Protect is off
sdb: Mode Sense: ed 00 10 08
SCSI device sdb: drive cache: write back w/ FUA
sdb: sdb1 sdb2
sd 0:0:0:0: Attached scsi disk sdb
Vendor: MAXTOR Model: ATLAS10K4_36WLS Rev: DFV0
Type: Direct-Access ANSI SCSI revision: 03
scsi0:A:2:0: Tagged Queuing enabled. Depth 8
target0:0:2: Beginning Domain Validation
target0:0:2: wide asynchronous
target0:0:2: FAST-80 WIDE SCSI 160.0 MB/s DT (12.5 ns, offset 127)
target0:0:2: Ending Domain Validation
SCSI device sdc: 71833096 512-byte hdwr sectors (36779 MB)
sdc: Write Protect is off
sdc: Mode Sense: ed 00 10 08
SCSI device sdc: drive cache: write back w/ FUA
SCSI device sdc: 71833096 512-byte hdwr sectors (36779 MB)
sdc: Write Protect is off
sdc: Mode Sense: ed 00 10 08
SCSI device sdc: drive cache: write back w/ FUA
sdc: sdc1 sdc2
sd 0:0:2:0: Attached scsi disk sdc
Vendor: MAXTOR Model: ATLAS10K4_36WLS Rev: DFV0
Type: Direct-Access ANSI SCSI revision: 03
scsi0:A:4:0: Tagged Queuing enabled. Depth 8
target0:0:4: Beginning Domain Validation
target0:0:4: wide asynchronous
target0:0:4: FAST-80 WIDE SCSI 160.0 MB/s DT (12.5 ns, offset 127)
target0:0:4: Ending Domain Validation
SCSI device sdd: 71833096 512-byte hdwr sectors (36779 MB)
sdd: Write Protect is off
sdd: Mode Sense: ed 00 10 08
SCSI device sdd: drive cache: write back w/ FUA
SCSI device sdd: 71833096 512-byte hdwr sectors (36779 MB)
sdd: Write Protect is off
sdd: Mode Sense: ed 00 10 08
SCSI device sdd: drive cache: write back w/ FUA
sdd: sdd1 sdd2
sd 0:0:4:0: Attached scsi disk sdd
ACPI: PCI Interrupt 0000:03:01.1[B] -> GSI 20 (level, low) -> IRQ 185
scsi2 : Adaptec AIC7XXX EISA/VLB/PCI SCSI HBA DRIVER, Rev 7.0
<Adaptec aic7899 Ultra160 SCSI adapter>
aic7899: Ultra160 Wide Channel B, SCSI Id=7, 32/253 SCBs
Probing IDE interface ide0...
md: md driver 0.90.3 MAX_MD_DEVS=256, MD_SB_DISKS=27
md: bitmap version 4.39
md: raid1 personality registered for level 1
raid5: automatically using best checksumming function: pIII_sse
pIII_sse : 2532.000 MB/sec
raid5: using function: pIII_sse (2532.000 MB/sec)
raid6: int32x1 548 MB/s
raid6: int32x2 586 MB/s
raid6: int32x4 539 MB/s
raid6: int32x8 368 MB/s
raid6: mmxx1 1592 MB/s
raid6: mmxx2 1732 MB/s
raid6: sse1x1 823 MB/s
raid6: sse1x2 1387 MB/s
raid6: sse2x1 1491 MB/s
raid6: sse2x2 1985 MB/s
raid6: using algorithm sse2x2 (1985 MB/s)
md: raid6 personality registered for level 6
md: raid5 personality registered for level 5
md: raid4 personality registered for level 4
md: md0 stopped.
md: bind<sdc1>
md: bind<sdd1>
md: bind<sdb1>
md: kicking non-fresh sdd1 from array!
md: unbind<sdd1>
md: export_rdev(sdd1)
raid1: raid set md0 active with 2 out of 3 mirrors
md: md1 stopped.
md: bind<sdc2>
md: bind<sdd2>
md: bind<sdb2>
md: kicking non-fresh sdd2 from array!
md: unbind<sdd2>
md: export_rdev(sdd2)
raid5: device sdb2 operational as raid disk 0
raid5: device sdc2 operational as raid disk 1
raid5: allocated 3163kB for md1
raid5: raid level 5 set md1 active with 2 out of 3 devices, algorithm 2
RAID5 conf printout:
--- rd:3 wd:2 fd:1
disk 0, o:1, dev:sdb2
disk 1, o:1, dev:sdc2
server:~# mdadm --query /dev/md0
/dev/md0: 478.38MiB raid1 3 devices, 0 spares. Use mdadm --detail for more detail.
server:~# mdadm --query /dev/md1
/dev/md1: 67.56GiB raid5 3 devices, 0 spares. Use mdadm --detail for more detail.
server:~# mdadm --detail /dev/md0
/dev/md0:
Version : 00.90.03
Creation Time : Sun Jun 24 16:44:00 2007
Raid Level : raid1
Array Size : 489856 (478.46 MiB 501.61 MB)
Device Size : 489856 (478.46 MiB 501.61 MB)
Raid Devices : 3
Total Devices : 2
Preferred Minor : 0
Persistence : Superblock is persistent
Update Time : Sat Sep 15 12:26:35 2007
State : clean, degraded
Active Devices : 2
Working Devices : 2
Failed Devices : 0
Spare Devices : 0
UUID : d7a7a102:c84787cc:9bbd2e14:1a819d79
Events : 0.36972
Number Major Minor RaidDevice State
0 8 17 0 active sync /dev/sdb1
1 8 33 1 active sync /dev/sdc1
2 0 0 2 removed
server:~# mdadm --detail /dev/md1
/dev/md1:
Version : 00.90.03
Creation Time : Sun Jun 24 16:44:18 2007
Raid Level : raid5
Array Size : 70846464 (67.56 GiB 72.55 GB)
Device Size : 35423232 (33.78 GiB 36.27 GB)
Raid Devices : 3
Total Devices : 2
Preferred Minor : 1
Persistence : Superblock is persistent
Update Time : Sat Sep 15 12:26:40 2007
State : clean, degraded
Active Devices : 2
Working Devices : 2
Failed Devices : 0
Spare Devices : 0
Layout : left-symmetric
Chunk Size : 64K
UUID : 676ff7ff:4f3d8fca:8b39f793:f5695a1f
Events : 0.834362
Number Major Minor RaidDevice State
0 8 18 0 active sync /dev/sdb2
1 8 34 1 active sync /dev/sdc2
2 0 0 2 removed
It's rejected the new disk because it isn't fresh, so does it need adding manually?
Rebooted and got this:
md: md0 stopped. md: bind<sdb1> md: bind<sdc1> md: bind<sda1> md: kicking non-fresh sdc1 from array! md: unbind<sdc1> md: export_rdev(sdc1) raid1: raid set md0 active with 2 out of 3 mirrors md: md1 stopped. md: bind<sdb2> md: bind<sdc2> md: bind<sda2> md: kicking non-fresh sdc2 from array! md: unbind<sdc2> md: export_rdev(sdc2) raid5: device sda2 operational as raid disk 0 raid5: device sdb2 operational as raid disk 1 raid5: allocated 3163kB for md1 raid5: raid level 5 set md1 active with 2 out of 3 devices, algorithm 2 RAID5 conf printout: --- rd:3 wd:2 fd:1 disk 0, o:1, dev:sda2 disk 1, o:1, dev:sdb2
2nd October 2007. Debian Sarge.
From screen:
EXT3-fs warning: maximal mount count reached, running e2fsck is recommended
When filesystem mounted:
hub 2-0:1.0: port 1 disabled bu hub (EMI?), re-enabling... reset full speed usb device using address 105 device not accepting address 105, error -22 device offlines - not ready after error recovery: host 83 channel 0 id 0 lun 0 USB disconnect, address 105 sd 83:0:0:0: Illegal state transition canel->offline Badness in scsi_device_set_state at drivers/scsi/scsi_lib.c:1643 [<f8869409>] scsi_device_set_state+0xc9/0x120 [scsi_mod] [<f8866a1e>] scsi_eh_offline_sdevs+0x6e/0x90 [scsi_mod] [<f8867091>] scsi_unjam_host+0xe1/0x220[scsi_mod] [<c011c500>] default_wake_function+0x0/0x20 [<f8867308>] scsi_error_handler+0x138/0x200 [scsi_mod] [<f88671d0>] scsi_error_handler+0x0/0x10 [scsi_mod] [<c01042c5>] kernel_threah_helper+0x5/0x10 scsi: Device offlined - not ready after error recovery: ...
The above repeated, probably once, maybe twice.
kernel BUG at drivers/block/as-iosched.c:1853 invalid operand: 0000 [#1] PREEMPT SMP Modules linked in: ... Badness in kobkect_get at lib/kobject.c:433 Unable to handle kernel paging request at virtual address 00200200
From syslog:
Oct 2 04:32:30 localhost kernel: hub 2-0:1.0: port 1 disabled by hub (EMI?), re-enabling... Oct 2 04:32:30 localhost kernel: usb 2-1: reset full speed USB device using address 105 Oct 2 04:32:30 localhost kernel: usb 2-1: device not accepting address 105, error -22 Oct 2 04:32:30 localhost kernel: scsi: Device offlined - not ready after error recovery: host 83 channel 0 id 0 lun 0 Oct 2 04:32:30 localhost kernel: usb 2-1: USB disconnect, address 105 Oct 2 04:32:30 localhost kernel: sd 83:0:0:0: Illegal state transition cancel->offline Oct 2 04:32:30 localhost kernel: Badness in scsi_device_set_state at drivers/scsi/scsi_lib.c:1643 Oct 2 04:32:30 localhost kernel: [__crc_fb_load_cursor_image+3657700/4340314] scsi_device_set_state+0xc9/0x120 [scsi_mod] Oct 2 04:32:30 localhost kernel: [__crc_fb_load_cursor_image+3646969/4340314] scsi_eh_offline_sdevs+0x6e/0x90 [scsi_mod] Oct 2 04:32:30 localhost kernel: [__crc_fb_load_cursor_image+3648620/4340314] scsi_unjam_host+0xe1/0x220 [scsi_mod] Oct 2 04:32:30 localhost kernel: [default_wake_function+0/32] default_wake_function+0x0/0x20 Oct 2 04:32:30 localhost kernel: [__crc_fb_load_cursor_image+3649251/4340314] scsi_error_handler+0x138/0x200 [scsi_mod] Oct 2 04:32:30 localhost kernel: [__crc_fb_load_cursor_image+3648939/4340314] scsi_error_handler+0x0/0x200 [scsi_mod] Oct 2 04:32:30 localhost kernel: [kernel_thread_helper+5/16] kernel_thread_helper+0x5/0x10 Oct 2 04:33:00 localhost kernel: scsi: Device offlined - not ready after error recovery: host 83 channel 0 id 0 lun 0 Oct 2 04:33:00 localhost kernel: sd 83:0:0:0: Illegal state transition cancel->offline Oct 2 04:33:00 localhost kernel: Badness in scsi_device_set_state at drivers/scsi/scsi_lib.c:1643 Oct 2 04:33:00 localhost kernel: [__crc_fb_load_cursor_image+3657700/4340314] scsi_device_set_state+0xc9/0x120 [scsi_mod] Oct 2 04:33:00 localhost kernel: [__crc_fb_load_cursor_image+3646969/4340314] scsi_eh_offline_sdevs+0x6e/0x90 [scsi_mod] Oct 2 04:33:00 localhost kernel: [__crc_fb_load_cursor_image+3648620/4340314] scsi_unjam_host+0xe1/0x220 [scsi_mod] Oct 2 04:33:00 localhost kernel: [default_wake_function+0/32] default_wake_function+0x0/0x20 Oct 2 04:33:00 localhost kernel: [__crc_fb_load_cursor_image+3649251/4340314] scsi_error_handler+0x138/0x200 [scsi_mod] Oct 2 04:33:00 localhost kernel: [__crc_fb_load_cursor_image+3648939/4340314] scsi_error_handler+0x0/0x200 [scsi_mod] Oct 2 04:33:00 localhost kernel: [kernel_thread_helper+5/16] kernel_thread_helper+0x5/0x10 Oct 2 04:33:01 localhost kernel: ------------[ cut here ]------------ Oct 2 04:33:01 localhost kernel: kernel BUG at drivers/block/as-iosched.c:1853! Oct 2 04:33:01 localhost kernel: invalid operand: 0000 [#1] Oct 2 04:33:01 localhost kernel: PREEMPT SMP Oct 2 04:33:01 localhost kernel: Modules linked in: ipv6 capability commoncap ext3 jbd mbcache lp st 3c59x parport_pc parport evdev pcspkr hw_random shpchp pciehp pci_hotplug psmouse genrtc sd_mod e1000 e100 mii ds yenta_socket pcmcia_core ide_cd cdrom ide_disk ide_generic pdc202xx_new aec62xx alim15x3 amd74xx atiixp cmd64x cs5520 cs5530 cy82c693 generic hpt34x ns87415 opti621 pdc202xx_old rz1000 sc1200 serverworks siimage sis5513 slc90e66 triflex trm290 via82cxxx floppy piix fbcon vga16fb vgastate usbserial usbhid usbkbd uhci_hcd thermal processor fan usb_storage usbcore ide_core aic7xxx 3w_xxxx scsi_mod unix font vesafb cfbcopyarea cfbimgblt cfbfillrect Oct 2 04:33:01 localhost kernel: CPU: 1 Oct 2 04:33:01 localhost kernel: EIP: 0060:[as_exit+101/128] Not tainted Oct 2 04:33:01 localhost kernel: EFLAGS: 00010297 (2.6.8-3-686-smp) Oct 2 04:33:01 localhost kernel: EIP is at as_exit+0x65/0x80 Oct 2 04:33:01 localhost kernel: eax: f7b0398c ebx: f7b03980 ecx: 00000000 edx: 00000000 Oct 2 04:33:01 localhost kernel: esi: f7bb7284 edi: 00000292 ebp: f687d8c4 esp: d31fdf20 Oct 2 04:33:01 localhost kernel: ds: 007b es: 007b ss: 0068 Oct 2 04:33:01 localhost kernel: Process scsi_eh_83 (pid: 23292, threadinfo=d31fc000 task=cd1566d0) Oct 2 04:33:01 localhost kernel: Stack: f7b03a08 f7bb71f8 c020f34e f7bb71f8 f7bb7204 c02115a8 f7bb71f8 c32ab800 Oct 2 04:33:01 localhost kernel: ca67e02c ca67e000 f886b56e f7bb71f8 ca67e1b0 c031e348 c031e360 f687d8e8 Oct 2 04:33:01 localhost kernel: c020a96b ca67e18c d31fdfa0 f886705d d31fdf98 c01b70b8 ca67e1b0 ca67e000 Oct 2 04:33:01 localhost kernel: Call Trace: Oct 2 04:33:01 localhost kernel: [elevator_exit+30/32] elevator_exit+0x1e/0x20 Oct 2 04:33:01 localhost kernel: [blk_cleanup_queue+56/144] blk_cleanup_queue+0x38/0x90 Oct 2 04:33:01 localhost kernel: [__crc_fb_load_cursor_image+3666249/4340314] scsi_device_dev_release+0x10e/0x130 [scsi_mod] Oct 2 04:33:01 localhost kernel: [device_release+91/96] device_release+0x5b/0x60 Oct 2 04:33:01 localhost kernel: [__crc_fb_load_cursor_image+3648568/4340314] scsi_unjam_host+0xad/0x220 [scsi_mod] Oct 2 04:33:01 localhost kernel: [kobject_cleanup+152/160] kobject_cleanup+0x98/0xa0 Oct 2 04:33:01 localhost kernel: [__crc_fb_load_cursor_image+3632512/4340314] __scsi_iterate_devices+0x85/0xa0 [scsi_mod] Oct 2 04:33:01 localhost kernel: [__crc_fb_load_cursor_image+3647865/4340314] scsi_restart_operations+0x3e/0xb0 [scsi_mod] Oct 2 04:33:01 localhost kernel: [__crc_fb_load_cursor_image+3649235/4340314] scsi_error_handler+0x128/0x200 [scsi_mod] Oct 2 04:33:01 localhost kernel: [__crc_fb_load_cursor_image+3648939/4340314] scsi_error_handler+0x0/0x200 [scsi_mod] Oct 2 04:33:01 localhost kernel: [kernel_thread_helper+5/16] kernel_thread_helper+0x5/0x10 Oct 2 04:33:01 localhost kernel: Code: 0f 0b 3d 07 cf a8 2b c0 eb c2 0f 0b 3c 07 cf a8 2b c0 eb b0 Oct 2 04:33:01 localhost kernel: Badness in kobject_get at lib/kobject.c:433 Oct 2 04:33:01 localhost kernel: [kobject_get+80/96] kobject_get+0x50/0x60 Oct 2 04:33:01 localhost kernel: [get_device+24/32] get_device+0x18/0x20 Oct 2 04:33:01 localhost kernel: [__crc_fb_load_cursor_image+3655264/4340314] scsi_request_fn+0x25/0x4d0 [scsi_mod] Oct 2 04:33:01 localhost kernel: [elv_next_request+22/272] elv_next_request+0x16/0x110 Oct 2 04:33:01 localhost kernel: [__generic_unplug_device+65/80] __generic_unplug_device+0x41/0x50 Oct 2 04:33:01 localhost kernel: [generic_unplug_device+49/112] generic_unplug_device+0x31/0x70 Oct 2 04:33:01 localhost kernel: [blk_unplug_work+16/32] blk_unplug_work+0x10/0x20 Oct 2 04:33:01 localhost kernel: [worker_thread+502/736] worker_thread+0x1f6/0x2e0 Oct 2 04:33:01 localhost kernel: [blk_unplug_work+0/32] blk_unplug_work+0x0/0x20 Oct 2 04:33:01 localhost kernel: [default_wake_function+0/32] default_wake_function+0x0/0x20 Oct 2 04:33:01 localhost kernel: [default_wake_function+0/32] default_wake_function+0x0/0x20 Oct 2 04:33:01 localhost kernel: [worker_thread+0/736] worker_thread+0x0/0x2e0 Oct 2 04:33:01 localhost kernel: [kthread+186/192] kthread+0xba/0xc0 Oct 2 04:33:01 localhost kernel: [kthread+0/192] kthread+0x0/0xc0 Oct 2 04:33:01 localhost kernel: [kernel_thread_helper+5/16] kernel_thread_helper+0x5/0x10 Oct 2 04:33:01 localhost kernel: Unable to handle kernel paging request at virtual address 00200200 Oct 2 04:33:01 localhost kernel: printing eip: Oct 2 04:33:01 localhost kernel: f886b4a2 Oct 2 04:33:01 localhost kernel: *pde = 00000000 Oct 2 04:33:01 localhost kernel: Oops: 0002 [#2] Oct 2 04:33:01 localhost kernel: PREEMPT SMP Oct 2 04:33:01 localhost kernel: Modules linked in: ipv6 capability commoncap ext3 jbd mbcache lp st 3c59x parport_pc parport evdev pcspkr hw_random shpchp pciehp pci_hotplug psmouse genrtc sd_mod e1000 e100 mii ds yenta_socket pcmcia_core ide_cd cdrom ide_disk ide_generic pdc202xx_new aec62xx alim15x3 amd74xx atiixp cmd64x cs5520 cs5530 cy82c693 generic hpt34x ns87415 opti621 pdc202xx_old rz1000 sc1200 serverworks siimage sis5513 slc90e66 triflex trm290 via82cxxx floppy piix fbcon vga16fb vgastate usbserial usbhid usbkbd uhci_hcd thermal processor fan usb_storage usbcore ide_core aic7xxx 3w_xxxx scsi_mod unix font vesafb cfbcopyarea cfbimgblt cfbfillrect Oct 2 04:33:01 localhost kernel: CPU: 1 Oct 2 04:33:01 localhost kernel: EIP: 0060:[__crc_fb_load_cursor_image+3666045/4340314] Not tainted Oct 2 04:33:01 localhost kernel: EFLAGS: 00010046 (2.6.8-3-686-smp) Oct 2 04:33:01 localhost kernel: EIP is at scsi_device_dev_release+0x42/0x130 [scsi_mod] Oct 2 04:33:01 localhost kernel: eax: 00100100 ebx: ca67e008 ecx: 00200200 edx: ca67e18c Oct 2 04:33:01 localhost kernel: esi: ca67e000 edi: 00000292 ebp: f687d8c4 esp: f7b19ebc Oct 2 04:33:01 localhost kernel: ds: 007b es: 007b ss: 0068 Oct 2 04:33:01 localhost kernel: Process kblockd/1 (pid: 59, threadinfo=f7b18000 task=f7edf6b0) Oct 2 04:33:01 localhost kernel: Stack: ca67e000 ca67e1b0 c031e348 c031e360 f687d8e8 c020a96b ca67e18c ca67e1b0 Oct 2 04:33:01 localhost kernel: c031e348 c031e360 c01b70b8 ca67e1b0 f7b18000 ca67e000 f7b18000 f7b18000 Oct 2 04:33:01 localhost kernel: f8868cee ca67e1b0 ed90540c c020f5d6 f7bb71f8 ca67e18c f7bb71f8 f7bb71f8 Oct 2 04:33:01 localhost kernel: Call Trace: Oct 2 04:33:01 localhost kernel: [device_release+91/96] device_release+0x5b/0x60 Oct 2 04:33:01 localhost kernel: [kobject_cleanup+152/160] kobject_cleanup+0x98/0xa0 Oct 2 04:33:01 localhost kernel: [__crc_fb_load_cursor_image+3655881/4340314] scsi_request_fn+0x28e/0x4d0 [scsi_mod] Oct 2 04:33:01 localhost kernel: [elv_next_request+22/272] elv_next_request+0x16/0x110 Oct 2 04:33:01 localhost kernel: [__generic_unplug_device+65/80] __generic_unplug_device+0x41/0x50 Oct 2 04:33:01 localhost kernel: [generic_unplug_device+49/112] generic_unplug_device+0x31/0x70 Oct 2 04:33:01 localhost kernel: [blk_unplug_work+16/32] blk_unplug_work+0x10/0x20 Oct 2 04:33:01 localhost kernel: [worker_thread+502/736] worker_thread+0x1f6/0x2e0 Oct 2 04:33:01 localhost kernel: [blk_unplug_work+0/32] blk_unplug_work+0x0/0x20 Oct 2 04:33:01 localhost kernel: [default_wake_function+0/32] default_wake_function+0x0/0x20 Oct 2 04:33:01 localhost kernel: [default_wake_function+0/32] default_wake_function+0x0/0x20 Oct 2 04:33:01 localhost kernel: [worker_thread+0/736] worker_thread+0x0/0x2e0 Oct 2 04:33:01 localhost kernel: [kthread+186/192] kthread+0xba/0xc0 Oct 2 04:33:01 localhost kernel: [kthread+0/192] kthread+0x0/0xc0 Oct 2 04:33:01 localhost kernel: [kernel_thread_helper+5/16] kernel_thread_helper+0x5/0x10 Oct 2 04:33:01 localhost kernel: Code: 89 01 89 48 04 b8 00 01 10 00 c7 43 04 00 02 20 00 8d 9a 84 Oct 2 04:33:01 localhost kernel: <6>note: kblockd/1[59] exited with preempt_count 1 Oct 2 04:33:08 localhost postfix/smtpd[27872]: connect from localhost.localdomain[127.0.0.1] Oct 2 04:33:08 localhost postfix/smtpd[27872]: NOQUEUE: reject: RCPT from localhost.localdomain[127.0.0.1]: 550 <USER@HOST.org>: Recipient address rejected: User unknown in virtual mailbox table; from=<keith@usabilitylinks.com> to=<USER@HOST.org> proto=ESMTP helo=<localhost> I have then have continuous mail logs: Oct 2 04:33:08 localhost postfix/smtpd[27877]: connect from localhost.localdomain[127.0.0.1] thru to: Oct 2 04:35:28 localhost postfix/cleanup[27880]: 2BD6F17634: message-id=<20071002033527.CA5BF176B7@server.localdomain>
From messages:
Oct 2 04:00:02 localhost kernel: kjournald starting. Commit interval 5 seconds Oct 2 04:00:02 localhost kernel: EXT3 FS on sdb1, internal journal Oct 2 04:00:02 localhost kernel: EXT3-fs: mounted filesystem with ordered data mode. Oct 2 04:18:52 localhost -- MARK -- Oct 2 04:32:30 localhost kernel: usb 2-1: reset full speed USB device using address 105 Oct 2 04:32:30 localhost kernel: scsi: Device offlined - not ready after error recovery: host 83 channel 0 id 0 lun 0 Oct 2 04:32:30 localhost kernel: usb 2-1: USB disconnect, address 105 Oct 2 04:32:30 localhost kernel: Badness in scsi_device_set_state at drivers/scsi/scsi_lib.c:1643 Oct 2 04:32:30 localhost kernel: [__crc_fb_load_cursor_image+3657700/4340314] scsi_device_set_state+0xc9/0x120 [scsi_mod] Oct 2 04:32:30 localhost kernel: [__crc_fb_load_cursor_image+3646969/4340314] scsi_eh_offline_sdevs+0x6e/0x90 [scsi_mod] Oct 2 04:32:30 localhost kernel: [__crc_fb_load_cursor_image+3648620/4340314] scsi_unjam_host+0xe1/0x220 [scsi_mod] Oct 2 04:32:30 localhost kernel: [default_wake_function+0/32] default_wake_function+0x0/0x20 Oct 2 04:32:30 localhost kernel: [__crc_fb_load_cursor_image+3649251/4340314] scsi_error_handler+0x138/0x200 [scsi_mod] Oct 2 04:32:30 localhost kernel: [__crc_fb_load_cursor_image+3648939/4340314] scsi_error_handler+0x0/0x200 [scsi_mod] Oct 2 04:32:30 localhost kernel: [kernel_thread_helper+5/16] kernel_thread_helper+0x5/0x10 Oct 2 04:33:00 localhost kernel: scsi: Device offlined - not ready after error recovery: host 83 channel 0 id 0 lun 0 Oct 2 04:33:00 localhost kernel: Badness in scsi_device_set_state at drivers/scsi/scsi_lib.c:1643 Oct 2 04:33:00 localhost kernel: [__crc_fb_load_cursor_image+3657700/4340314] scsi_device_set_state+0xc9/0x120 [scsi_mod] Oct 2 04:33:00 localhost kernel: [__crc_fb_load_cursor_image+3646969/4340314] scsi_eh_offline_sdevs+0x6e/0x90 [scsi_mod] Oct 2 04:33:00 localhost kernel: [__crc_fb_load_cursor_image+3648620/4340314] scsi_unjam_host+0xe1/0x220 [scsi_mod] Oct 2 04:33:00 localhost kernel: [default_wake_function+0/32] default_wake_function+0x0/0x20 Oct 2 04:33:00 localhost kernel: [__crc_fb_load_cursor_image+3649251/4340314] scsi_error_handler+0x138/0x200 [scsi_mod] Oct 2 04:33:00 localhost kernel: [__crc_fb_load_cursor_image+3648939/4340314] scsi_error_handler+0x0/0x200 [scsi_mod] Oct 2 04:33:00 localhost kernel: [kernel_thread_helper+5/16] kernel_thread_helper+0x5/0x10 Oct 2 04:33:01 localhost kernel: ------------[ cut here ]------------ Oct 2 04:33:01 localhost kernel: PREEMPT SMP Oct 2 04:33:01 localhost kernel: Modules linked in: ipv6 capability commoncap ext3 jbd mbcache lp st 3c59x parport_pc parport evdev pcspkr hw_random shpchp pciehp pci_hotplug psmouse genrtc sd_mod e1000 e100 mii ds yenta_socket pcmcia_core ide_cd cdrom ide_disk ide_generic pdc202xx_new aec62xx alim15x3 amd74xx atiixp cmd64x cs5520 cs5530 cy82c693 generic hpt34x ns87415 opti621 pdc202xx_old rz1000 sc1200 serverworks siimage sis5513 slc90e66 triflex trm290 via82cxxx floppy piix fbcon vga16fb vgastate usbserial usbhid usbkbd uhci_hcd thermal processor fan usb_storage usbcore ide_core aic7xxx 3w_xxxx scsi_mod unix font vesafb cfbcopyarea cfbimgblt cfbfillrect Oct 2 04:33:01 localhost kernel: CPU: 1 Oct 2 04:33:01 localhost kernel: EIP: 0060:[as_exit+101/128] Not tainted Oct 2 04:33:01 localhost kernel: EFLAGS: 00010297 (2.6.8-3-686-smp) Oct 2 04:33:01 localhost kernel: EIP is at as_exit+0x65/0x80 Oct 2 04:33:01 localhost kernel: eax: f7b0398c ebx: f7b03980 ecx: 00000000 edx: 00000000 Oct 2 04:33:01 localhost kernel: esi: f7bb7284 edi: 00000292 ebp: f687d8c4 esp: d31fdf20 Oct 2 04:33:01 localhost kernel: ds: 007b es: 007b ss: 0068 Oct 2 04:33:01 localhost kernel: Process scsi_eh_83 (pid: 23292, threadinfo=d31fc000 task=cd1566d0) Oct 2 04:33:01 localhost kernel: Stack: f7b03a08 f7bb71f8 c020f34e f7bb71f8 f7bb7204 c02115a8 f7bb71f8 c32ab800 Oct 2 04:33:01 localhost kernel: ca67e02c ca67e000 f886b56e f7bb71f8 ca67e1b0 c031e348 c031e360 f687d8e8 Oct 2 04:33:01 localhost kernel: c020a96b ca67e18c d31fdfa0 f886705d d31fdf98 c01b70b8 ca67e1b0 ca67e000 Oct 2 04:33:01 localhost kernel: Call Trace: Oct 2 04:33:01 localhost kernel: [elevator_exit+30/32] elevator_exit+0x1e/0x20 Oct 2 04:33:01 localhost kernel: [blk_cleanup_queue+56/144] blk_cleanup_queue+0x38/0x90 Oct 2 04:33:01 localhost kernel: [__crc_fb_load_cursor_image+3666249/4340314] scsi_device_dev_release+0x10e/0x130 [scsi_mod] Oct 2 04:33:01 localhost kernel: [device_release+91/96] device_release+0x5b/0x60 Oct 2 04:33:01 localhost kernel: [__crc_fb_load_cursor_image+3648568/4340314] scsi_unjam_host+0xad/0x220 [scsi_mod] Oct 2 04:33:01 localhost kernel: [kobject_cleanup+152/160] kobject_cleanup+0x98/0xa0 Oct 2 04:33:01 localhost kernel: [__crc_fb_load_cursor_image+3632512/4340314] __scsi_iterate_devices+0x85/0xa0 [scsi_mod] Oct 2 04:33:01 localhost kernel: [__crc_fb_load_cursor_image+3647865/4340314] scsi_restart_operations+0x3e/0xb0 [scsi_mod] Oct 2 04:33:01 localhost kernel: [__crc_fb_load_cursor_image+3649235/4340314] scsi_error_handler+0x128/0x200 [scsi_mod] Oct 2 04:33:01 localhost kernel: [__crc_fb_load_cursor_image+3648939/4340314] scsi_error_handler+0x0/0x200 [scsi_mod] Oct 2 04:33:01 localhost kernel: [kernel_thread_helper+5/16] kernel_thread_helper+0x5/0x10 Oct 2 04:33:01 localhost kernel: Code: 0f 0b 3d 07 cf a8 2b c0 eb c2 0f 0b 3c 07 cf a8 2b c0 eb b0 Oct 2 04:33:01 localhost kernel: Badness in kobject_get at lib/kobject.c:433 Oct 2 04:33:01 localhost kernel: [kobject_get+80/96] kobject_get+0x50/0x60 Oct 2 04:33:01 localhost kernel: [get_device+24/32] get_device+0x18/0x20 Oct 2 04:33:01 localhost kernel: [__crc_fb_load_cursor_image+3655264/4340314] scsi_request_fn+0x25/0x4d0 [scsi_mod] Oct 2 04:33:01 localhost kernel: [elv_next_request+22/272] elv_next_request+0x16/0x110 Oct 2 04:33:01 localhost kernel: [__generic_unplug_device+65/80] __generic_unplug_device+0x41/0x50 Oct 2 04:33:01 localhost kernel: [generic_unplug_device+49/112] generic_unplug_device+0x31/0x70 Oct 2 04:33:01 localhost kernel: [blk_unplug_work+16/32] blk_unplug_work+0x10/0x20 Oct 2 04:33:01 localhost kernel: [worker_thread+502/736] worker_thread+0x1f6/0x2e0 Oct 2 04:33:01 localhost kernel: [blk_unplug_work+0/32] blk_unplug_work+0x0/0x20 Oct 2 04:33:01 localhost kernel: [default_wake_function+0/32] default_wake_function+0x0/0x20 Oct 2 04:33:01 localhost kernel: [default_wake_function+0/32] default_wake_function+0x0/0x20 Oct 2 04:33:01 localhost kernel: [worker_thread+0/736] worker_thread+0x0/0x2e0 Oct 2 04:33:01 localhost kernel: [kthread+186/192] kthread+0xba/0xc0 Oct 2 04:33:01 localhost kernel: [kthread+0/192] kthread+0x0/0xc0 Oct 2 04:33:01 localhost kernel: [kernel_thread_helper+5/16] kernel_thread_helper+0x5/0x10 Oct 2 04:33:01 localhost kernel: f886b4a2 Oct 2 04:33:01 localhost kernel: PREEMPT SMP Oct 2 04:33:01 localhost kernel: Modules linked in: ipv6 capability commoncap ext3 jbd mbcache lp st 3c59x parport_pc parport evdev pcspkr hw_random shpchp pciehp pci_hotplug psmouse genrtc sd_mod e1000 e100 mii ds yenta_socket pcmcia_core ide_cd cdrom ide_disk ide_generic pdc202xx_new aec62xx alim15x3 amd74xx atiixp cmd64x cs5520 cs5530 cy82c693 generic hpt34x ns87415 opti621 pdc202xx_old rz1000 sc1200 serverworks siimage sis5513 slc90e66 triflex trm290 via82cxxx floppy piix fbcon vga16fb vgastate usbserial usbhid usbkbd uhci_hcd thermal processor fan usb_storage usbcore ide_core aic7xxx 3w_xxxx scsi_mod unix font vesafb cfbcopyarea cfbimgblt cfbfillrect Oct 2 04:33:01 localhost kernel: CPU: 1 Oct 2 04:33:01 localhost kernel: EIP: 0060:[__crc_fb_load_cursor_image+3666045/4340314] Not tainted Oct 2 04:33:01 localhost kernel: EFLAGS: 00010046 (2.6.8-3-686-smp) Oct 2 04:33:01 localhost kernel: EIP is at scsi_device_dev_release+0x42/0x130 [scsi_mod] Oct 2 04:33:01 localhost kernel: eax: 00100100 ebx: ca67e008 ecx: 00200200 edx: ca67e18c Oct 2 04:33:01 localhost kernel: esi: ca67e000 edi: 00000292 ebp: f687d8c4 esp: f7b19ebc Oct 2 04:33:01 localhost kernel: ds: 007b es: 007b ss: 0068 Oct 2 04:33:01 localhost kernel: Process kblockd/1 (pid: 59, threadinfo=f7b18000 task=f7edf6b0) Oct 2 04:33:01 localhost kernel: Stack: ca67e000 ca67e1b0 c031e348 c031e360 f687d8e8 c020a96b ca67e18c ca67e1b0 Oct 2 04:33:01 localhost kernel: c031e348 c031e360 c01b70b8 ca67e1b0 f7b18000 ca67e000 f7b18000 f7b18000 Oct 2 04:33:01 localhost kernel: f8868cee ca67e1b0 ed90540c c020f5d6 f7bb71f8 ca67e18c f7bb71f8 f7bb71f8 Oct 2 04:33:01 localhost kernel: Call Trace: Oct 2 04:33:01 localhost kernel: [device_release+91/96] device_release+0x5b/0x60 Oct 2 04:33:01 localhost kernel: [kobject_cleanup+152/160] kobject_cleanup+0x98/0xa0 Oct 2 04:33:01 localhost kernel: [__crc_fb_load_cursor_image+3655881/4340314] scsi_request_fn+0x28e/0x4d0 [scsi_mod] Oct 2 04:33:01 localhost kernel: [elv_next_request+22/272] elv_next_request+0x16/0x110 Oct 2 04:33:01 localhost kernel: [__generic_unplug_device+65/80] __generic_unplug_device+0x41/0x50 Oct 2 04:33:01 localhost kernel: [generic_unplug_device+49/112] generic_unplug_device+0x31/0x70 Oct 2 04:33:01 localhost kernel: [blk_unplug_work+16/32] blk_unplug_work+0x10/0x20 Oct 2 04:33:01 localhost kernel: [worker_thread+502/736] worker_thread+0x1f6/0x2e0 Oct 2 04:33:01 localhost kernel: [blk_unplug_work+0/32] blk_unplug_work+0x0/0x20 Oct 2 04:33:01 localhost kernel: [default_wake_function+0/32] default_wake_function+0x0/0x20 Oct 2 04:33:01 localhost kernel: [default_wake_function+0/32] default_wake_function+0x0/0x20 Oct 2 04:33:01 localhost kernel: [worker_thread+0/736] worker_thread+0x0/0x2e0 Oct 2 04:33:01 localhost kernel: [kthread+186/192] kthread+0xba/0xc0 Oct 2 04:33:01 localhost kernel: [kthread+0/192] kthread+0x0/0xc0 Oct 2 04:33:01 localhost kernel: [kernel_thread_helper+5/16] kernel_thread_helper+0x5/0x10 Oct 2 04:33:01 localhost kernel: Code: 89 01 89 48 04 b8 00 01 10 00 c7 43 04 00 02 20 00 8d 9a 84 Oct 2 04:33:01 localhost kernel: <6>note: kblockd/1[59] exited with preempt_count 1http://lkml.org/lkml/2004/12/10/216
"This should be fixed in 2.6.10-rc3" - Greg K H - http://lkml.org/lkml/2004/12/10/219
http://kerneltrap.org/node/3844
the current Linux kernel (~2.6.10) eventually reset USB card during huge transfer.