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 1
http://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.