[lucid] USB storage disconnects after certain period causing ext3 I/O errors and OOPS
Affects | Status | Importance | Assigned to | Milestone | |
---|---|---|---|---|---|
Linux |
Confirmed
|
Medium
|
|||
linux (Ubuntu) |
Confirmed
|
Undecided
|
Unassigned |
Bug Description
An embedded system, comprising COM Express module and USB SSD with Ubuntu Linux Server 10.04 (Lucid Lynx), hangs after certain period of activity. Period between the hangs varies from two days to one week.
Symptoms of the hang:
* machine is unreachable over ssh
* machine is pingable
* file system appears to be empty for SSH sessions started before the hang (ls doesn't list anything, unable to start any command)
This issue was not present when using Ubuntu Linux 8.04.
In order to get details about the hang, Ubuntu Linux kernel was compiled with additional options:
CONFIG_
CONFIG_USB=y
CONFIG_USB_DEBUG=y
In addition to that, netconsole module was used to redirect syslog to another machine to be able to analyse it.
It seems that the problem happens in the following lines and causes ext3 to OOPS a bit later:
Jan 10 10:41:15 hudson-slave [262388.606612] usb-storage: usb_stor_
Jan 10 10:41:24 hudson-slave [262397.557075] hub 1-0:1.0: state 7 ports 8 chg 0000 evt 0040
Jan 10 10:41:24 hudson-slave [262397.558208] ehci_hcd 0000:00:1d.7: GetStatus port 6 status 001002 POWER sig=se0 CSC
Jan 10 10:41:24 hudson-slave [262397.559358] hub 1-0:1.0: port 6, status 0100, change 0001, 12 Mb/s
Jan 10 10:41:24 hudson-slave [262397.560489] usb 1-6: USB disconnect, address 6
Jan 10 10:41:24 hudson-slave [262397.561671] usb 1-6: unregistering device
Jan 10 10:41:24 hudson-slave [262397.562805] usb 1-6: usb_disable_device nuking all URBs
Jan 10 10:41:24 hudson-slave [262397.563983] ehci_hcd 0000:00:1d.7: shutdown urb f27f4100 ep2out-bulk
Jan 10 10:41:24 hudson-slave [262397.566277] usb 1-6: unregistering interface 1-6:1.0
Jan 10 10:41:24 hudson-slave [262397.566321] usb-storage: Status code -108; transferred 31/31
Jan 10 10:41:24 hudson-slave [262397.566325] usb-storage: -- unknown error
Jan 10 10:41:24 hudson-slave [262397.566329] usb-storage: Bulk command transfer result=4
Jan 10 10:41:24 hudson-slave [262397.566332] usb-storage: -- transport indicates error, resetting
...
Jan 10 10:41:26 hudson-slave [262397.572511] Buffer I/O error on device sda6, logical block 0
Jan 10 10:41:26 hudson-slave [262397.572515] lost page write due to I/O error on sda6
Jan 10 10:41:26 hudson-slave [262397.584278] usb-storage: queuecommand called
Jan 10 10:41:26 hudson-slave [262397.584297] usb-storage: *** thread awakened.
Jan 10 10:41:26 hudson-slave [262397.584301] usb-storage: Command WRITE_10 (10 bytes)
Jan 10 10:41:26 hudson-slave [262397.584303] usb-storage: 2a 00 00 38 e1 e8 00 00 10 00
Jan 10 10:41:26 hudson-slave [262397.584316] usb-storage: Bulk Command S 0x43425355 T 0x4cb0d L 8192 F 0 Trg 0 LUN 0 CL 10
Jan 10 10:41:26 hudson-slave [262397.584320] usb-storage: usb_stor_
Jan 10 10:41:26 hudson-slave [262397.584325] usb-storage: Status code -19; transferred 0/31
Jan 10 10:41:26 hudson-slave [262397.584328] usb-storage: -- unknown error
Jan 10 10:41:26 hudson-slave [262397.584330] usb-storage: Bulk command transfer result=4
Jan 10 10:41:26 hudson-slave [262397.584333] usb-storage: -- transport indicates error, resetting
Jan 10 10:41:26 hudson-slave [262397.584336] usb-storage: unable to lock device for reset: -19
Jan 10 10:41:26 hudson-slave [262397.584340] usb-storage: usb_stor_Bulk_reset called
Jan 10 10:41:26 hudson-slave [262397.584344] usb-storage: usb_stor_
Jan 10 10:41:26 hudson-slave [262397.584348] usb-storage: Soft reset failed: -19
Jan 10 10:41:26 hudson-slave [262397.584351] usb-storage: scsi cmd done, result=0x70000
Jan 10 10:41:26 hudson-slave [262397.584356] usb-storage: *** thread sleeping.
Jan 10 10:41:26 hudson-slave [262397.584364] usb-storage: queuecommand called
Jan 10 10:41:26 hudson-slave [262397.584372] usb-storage: *** thread awakened.
Jan 10 10:41:26 hudson-slave [262397.584375] usb-storage: Command WRITE_10 (10 bytes)
Jan 10 10:41:26 hudson-slave [262397.584377] usb-storage: 2a 00 00 38 e1 e8 00 00 10 00
Jan 10 10:41:26 hudson-slave [262397.584389] usb-storage: Bulk Command S 0x43425355 T 0x4cb0e L 8192 F 0 Trg 0 LUN 0 CL 10
Jan 10 10:41:26 hudson-slave [262397.584393] usb-storage: usb_stor_
Jan 10 10:41:26 hudson-slave [262397.584397] usb-storage: Status code -19; transferred 0/31
Jan 10 10:41:26 hudson-slave [262397.584399] usb-storage: -- unknown error
Jan 10 10:41:26 hudson-slave [262397.584402] usb-storage: Bulk command transfer result=4
Jan 10 10:41:26 hudson-slave [262397.584405] usb-storage: -- transport indicates error, resetting
Jan 10 10:41:26 hudson-slave [262397.584408] usb-storage: unable to lock device for reset: -19
Jan 10 10:41:26 hudson-slave [262397.584411] usb-storage: usb_stor_Bulk_reset called
Jan 10 10:41:26 hudson-slave [262397.584415] usb-storage: usb_stor_
Jan 10 10:41:26 hudson-slave [262397.584419] usb-storage: Soft reset failed: -19
Jan 10 10:41:26 hudson-slave [262397.584422] usb-storage: scsi cmd done, result=0x70000
Jan 10 10:41:26 hudson-slave [262397.584427] usb-storage: *** thread sleeping.
Jan 10 10:41:26 hudson-slave [262397.584434] usb-storage: queuecommand called
Jan 10 10:41:26 hudson-slave [262397.584441] usb-storage: *** thread awakened.
Jan 10 10:41:26 hudson-slave [262397.584444] usb-storage: Command WRITE_10 (10 bytes)
Jan 10 10:41:26 hudson-slave [262397.584447] usb-storage: 2a 00 00 38 e1 e8 00 00 10 00
Jan 10 10:41:26 hudson-slave [262397.584458] usb-storage: Bulk Command S 0x43425355 T 0x4cb0f L 8192 F 0 Trg 0 LUN 0 CL 10
Jan 10 10:41:26 hudson-slave [262397.584463] usb-storage: usb_stor_
Jan 10 10:41:26 hudson-slave [262397.584467] usb-storage: Status code -19; transferred 0/31
Jan 10 10:41:26 hudson-slave [262397.584469] usb-storage: -- unknown error
Jan 10 10:41:26 hudson-slave [262397.584472] usb-storage: Bulk command transfer result=4
Jan 10 10:41:26 hudson-slave [262397.584475] usb-storage: -- transport indicates error, resetting
Jan 10 10:41:26 hudson-slave [262397.584478] usb-storage: unable to lock device for reset: -19
Jan 10 10:41:26 hudson-slave [262397.584482] usb-storage: usb_stor_Bulk_reset called
Jan 10 10:41:26 hudson-slave [262397.584486] usb-storage: usb_stor_
Jan 10 10:41:26 hudson-slave [262397.584489] usb-storage: Soft reset failed: -19
Jan 10 10:41:26 hudson-slave [262397.584492] usb-storage: scsi cmd done, result=0x70000
Jan 10 10:41:26 hudson-slave [262397.584497] usb-storage: *** thread sleeping.
Jan 10 10:41:26 hudson-slave [262397.584504] usb-storage: queuecommand called
Jan 10 10:41:26 hudson-slave [262397.584510] usb-storage: *** thread awakened.
Jan 10 10:41:26 hudson-slave [262397.584514] usb-storage: Command WRITE_10 (10 bytes)
Jan 10 10:41:26 hudson-slave [262397.584516] usb-storage: 2a 00 00 38 e1 e8 00 00 10 00
Jan 10 10:41:26 hudson-slave [262397.584528] usb-storage: Bulk Command S 0x43425355 T 0x4cb10 L 8192 F 0 Trg 0 LUN 0 CL 10
Jan 10 10:41:26 hudson-slave [262397.584532] usb-storage: usb_stor_
Jan 10 10:41:26 hudson-slave [262397.584536] usb-storage: Status code -19; transferred 0/31
Jan 10 10:41:26 hudson-slave [262397.584539] usb-storage: -- unknown error
Jan 10 10:41:26 hudson-slave [262397.584541] usb-storage: Bulk command transfer result=4
Jan 10 10:41:26 hudson-slave [262397.584544] usb-storage: -- transport indicates error, resetting
Jan 10 10:41:26 hudson-slave [262397.584547] usb-storage: unable to lock device for reset: -19
Jan 10 10:41:26 hudson-slave [262397.584551] usb-storage: usb_stor_Bulk_reset called
Jan 10 10:41:26 hudson-slave [262397.584555] usb-storage: usb_stor_
Jan 10 10:41:26 hudson-slave [262397.584558] usb-storage: Soft reset failed: -19
Jan 10 10:41:26 hudson-slave [262397.584561] usb-storage: scsi cmd done, result=0x70000
Jan 10 10:41:26 hudson-slave [262397.584566] usb-storage: *** thread sleeping.
Jan 10 10:41:26 hudson-slave [262397.584572] usb-storage: queuecommand called
Jan 10 10:41:26 hudson-slave [262397.584579] usb-storage: *** thread awakened.
Jan 10 10:41:26 hudson-slave [262397.584582] usb-storage: Command WRITE_10 (10 bytes)
Jan 10 10:41:26 hudson-slave [262397.584585] usb-storage: 2a 00 00 38 e1 e8 00 00 10 00
Jan 10 10:41:26 hudson-slave [262397.584597] usb-storage: Bulk Command S 0x43425355 T 0x4cb11 L 8192 F 0 Trg 0 LUN 0 CL 10
Jan 10 10:41:26 hudson-slave [262397.584601] usb-storage: usb_stor_
Jan 10 10:41:26 hudson-slave [262397.584605] usb-storage: Status code -19; transferred 0/31
Jan 10 10:41:26 hudson-slave [262397.584608] usb-storage: -- unknown error
Jan 10 10:41:26 hudson-slave [262397.584611] usb-storage: Bulk command transfer result=4
Jan 10 10:41:26 hudson-slave [262397.584613] usb-storage: -- transport indicates error, resetting
Jan 10 10:41:26 hudson-slave [262397.584617] usb-storage: unable to lock device for reset: -19
Jan 10 10:41:26 hudson-slave [262397.584620] usb-storage: usb_stor_Bulk_reset called
Jan 10 10:41:26 hudson-slave [262397.584625] usb-storage: usb_stor_
Jan 10 10:41:26 hudson-slave [262397.584628] usb-storage: Soft reset failed: -19
Jan 10 10:41:26 hudson-slave [262397.584631] usb-storage: scsi cmd done, result=0x70000
Jan 10 10:41:26 hudson-slave [262397.584636] usb-storage: *** thread sleeping.
Jan 10 10:41:26 hudson-slave [262397.584642] usb-storage: queuecommand called
Jan 10 10:41:26 hudson-slave [262397.584649] usb-storage: *** thread awakened.
Jan 10 10:41:26 hudson-slave [262397.584652] usb-storage: Command WRITE_10 (10 bytes)
Jan 10 10:41:26 hudson-slave [262397.584655] usb-storage: 2a 00 00 38 e1 e8 00 00 10 00
Jan 10 10:41:26 hudson-slave [262397.584666] usb-storage: Bulk Command S 0x43425355 T 0x4cb12 L 8192 F 0 Trg 0 LUN 0 CL 10
Jan 10 10:41:26 hudson-slave [262397.584670] usb-storage: usb_stor_
Jan 10 10:41:26 hudson-slave [262397.584675] usb-storage: Status code -19; transferred 0/31
Jan 10 10:41:26 hudson-slave [262397.584677] usb-storage: -- unknown error
Jan 10 10:41:26 hudson-slave [262397.584680] usb-storage: Bulk command transfer result=4
Jan 10 10:41:26 hudson-slave [262397.584683] usb-storage: -- transport indicates error, resetting
Jan 10 10:41:26 hudson-slave [262397.584686] usb-storage: unable to lock device for reset: -19
Jan 10 10:41:26 hudson-slave [262397.584689] usb-storage: usb_stor_Bulk_reset called
Jan 10 10:41:26 hudson-slave [262397.584694] usb-storage: usb_stor_
Jan 10 10:41:26 hudson-slave [262397.584698] usb-storage: Soft reset failed: -19
Jan 10 10:41:26 hudson-slave [262397.584701] usb-storage: scsi cmd done, result=0x70000
Jan 10 10:41:26 hudson-slave [262397.584706] usb-storage: *** thread sleeping.
Jan 10 10:41:26 hudson-slave [262397.584714] sd 2:0:0:0: [sda] Unhandled error code
Jan 10 10:41:26 hudson-slave [262397.584718] sd 2:0:0:0: [sda] Result: hostbyte=DID_ERROR driverbyte=
Jan 10 10:41:26 hudson-slave [262397.584723] sd 2:0:0:0: [sda] CDB: Write(10): 2a 00 00 38 e1 e8 00 00 10 00
Jan 10 10:41:26 hudson-slave [262397.584735] end_request: I/O error, dev sda, sector 3727848
Jan 10 10:41:26 hudson-slave [262397.584757] Aborting journal on device sda6.
Jan 10 10:41:26 hudson-slave [262397.584775] usb-storage: queuecommand called
Jan 10 10:41:26 hudson-slave [262397.584788] EXT3-fs error (device sda6) in ext3_reserve_
Jan 10 10:41:26 hudson-slave [262397.584794] ------------[ cut here ]------------
Jan 10 10:41:26 hudson-slave [262397.584806] WARNING: at /devel/
Jan 10 10:41:26 hudson-slave [262397.584810] Modules linked in: libera fbcon tileblit font bitblit softcursor vga16fb vgastate netconsole configfs coretemp lp parport i915 drm_kms_helper drm i2c_algo_bit video serio_raw output snd_intel8x0 snd_ac97_codec ac97_bus snd_pcm snd_timer snd soundcore snd_page_alloc intel_agp agpgart usbhid hid usb_storage e1000e r8169 mii
Jan 10 10:41:26 hudson-slave [262397.584858] Pid: 892, comm: rsyslogd Not tainted 2.6.32-
Jan 10 10:41:26 hudson-slave [262397.584861] Call Trace:
Jan 10 10:41:26 hudson-slave [262397.584871] [<c01543f2>] warn_slowpath_
Jan 10 10:41:26 hudson-slave [262397.584877] [<c0237140>] ? mark_buffer_
Jan 10 10:41:26 hudson-slave [262397.584883] [<c0237140>] ? mark_buffer_
Jan 10 10:41:26 hudson-slave [262397.584889] [<c015443a>] warn_slowpath_
Jan 10 10:41:26 hudson-slave [262397.584894] [<c0237140>] mark_buffer_
Jan 10 10:41:26 hudson-slave [262397.584900] [<c027a6fa>] T.1021+0x4a/0x70
Jan 10 10:41:26 hudson-slave [262397.584906] [<c027a78b>] ext3_handle_
Jan 10 10:41:26 hudson-slave [262397.584913] [<c05b9ebf>] ? printk+0x1d/0x26
Jan 10 10:41:26 hudson-slave [262397.584918] [<c027a852>] __ext3_
Jan 10 10:41:26 hudson-slave [262397.584925] [<c027f210>] ? __ext3_
Jan 10 10:41:26 hudson-slave [262397.584932] [<c0272382>] ext3_reserve_
Jan 10 10:41:26 hudson-slave [262397.584937] [<c02723fb>] ext3_mark_
Jan 10 10:41:26 hudson-slave [262397.584943] [<c027254e>] ext3_dirty_
Jan 10 10:41:26 hudson-slave [262397.584950] [<c02fe85e>] ? cap_inode_
Jan 10 10:41:26 hudson-slave [262397.584957] [<c0231351>] __mark_
Jan 10 10:41:26 hudson-slave [262397.584963] [<c01d2a14>] ? file_remove_
Jan 10 10:41:26 hudson-slave [262397.584970] [<c016fec0>] ? autoremove_
Jan 10 10:41:26 hudson-slave [262397.584977] [<c0226b35>] file_update_
Jan 10 10:41:26 hudson-slave [262397.584984] [<c01d4a88>] __generic_
Jan 10 10:41:26 hudson-slave [262397.584991] [<c02c6ef4>] ? journal_
Jan 10 10:41:26 hudson-slave [262397.584997] [<c0271c28>] ? ext3_mark_
Jan 10 10:41:26 hudson-slave [262397.585003] [<c01d4e37>] generic_
Jan 10 10:41:26 hudson-slave [262397.585008] [<c027255a>] ? ext3_dirty_
Jan 10 10:41:26 hudson-slave [262397.585016] [<c02126f4>] do_sync_
Jan 10 10:41:26 hudson-slave [262397.585023] [<c016fea0>] ? autoremove_
Jan 10 10:41:26 hudson-slave [262397.585029] [<c02289f3>] ? notify_
Jan 10 10:41:26 hudson-slave [262397.585035] [<c02749e0>] ? ext3_ioctl+
Jan 10 10:41:26 hudson-slave [262397.585042] [<c02ffa34>] ? security_
Jan 10 10:41:26 hudson-slave [262397.585048] [<c0212894>] ? rw_verify_
Jan 10 10:41:26 hudson-slave [262397.585054] [<c02129b2>] vfs_write+
Jan 10 10:41:26 hudson-slave [262397.585059] [<c0221529>] ? do_vfs_
Jan 10 10:41:26 hudson-slave [262397.585065] [<c0212630>] ? do_sync_
Jan 10 10:41:26 hudson-slave [262397.585071] [<c02132d2>] sys_write+0x42/0x70
Jan 10 10:41:26 hudson-slave [262397.585078] [<c01096c3>] sysenter_
Jan 10 10:41:26 hudson-slave [262397.585083] ---[ end trace 3922152202b7311d ]---
Complete log is attached.
---
AlsaDevices:
total 0
crw-rw---- 1 root audio 116, 2 2011-01-10 13:32 timer
AlsaVersion: Advanced Linux Sound Architecture Driver Version 1.0.21.
AplayDevices: Error: [Errno 2] No such file or directory
Architecture: i386
ArecordDevices: Error: [Errno 2] No such file or directory
AudioDevicesInUse: Error: command ['fuser', '-v', '/dev/snd/timer'] failed with exit code 1:
CRDA: Error: [Errno 2] No such file or directory
DistroRelease: Ubuntu 10.04
InstallationMedia: Ubuntu-Server 10.04.1 LTS "Lucid Lynx" - Release i386 (20100816.2)
IwConfig:
lo no wireless extensions.
eth1 no wireless extensions.
eth2 no wireless extensions.
NonfreeKernelMo
Package: linux (not installed)
ProcCmdLine: BOOT_IMAGE=
ProcEnviron:
PATH=(custom, no user)
LANG=en_US.UTF-8
SHELL=/bin/bash
ProcVersionSign
Regression: Yes
RelatedPackageV
Reproducible: Yes
RfKill:
Tags: lucid regression-release needs-upstream-
Uname: Linux 2.6.32-
UserGroups:
tags: | added: kj-triage |
Changed in linux: | |
importance: | Unknown → Medium |
status: | Unknown → Confirmed |
Changed in linux (Ubuntu): | |
status: | New → Confirmed |
apport information