soft lockup while copying data from a FAT usb stick and consequentFAT table corruption

From: Riccardo Magliocchetti
Date: Mon Jul 28 2008 - 09:34:20 EST

Next message: Ingo Molnar: "Re: [PATCH] i386: improve double fault handling"
Previous message: Vivek Goyal: "Re: [patch] crashdump: fix undefined reference to `elfcorehdr_addr'"
Next in thread: OGAWA Hirofumi: "Re: soft lockup while copying data from a FAT usb stick and consequent FAT table corruption"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

Hi,

[I'm not subscribed please CC me.]

I got a system lockup while copying some data from an usb stick formatted in FAT, the kernel is a debian 2.6.25-2 which is based on vanilla 2.6.25.11. The stick is a cheap one. This an excerpt from the logs:

Jul 24 19:03:04 eurasia kernel: [25069.980240] usb 1-5: configuration #1 chosen from 1 choice
Jul 24 19:03:04 eurasia kernel: [25069.980240] usb 1-5: New USB device found, idVendor=0402, idProduct=5661
Jul 24 19:03:04 eurasia kernel: [25069.980240] usb 1-5: New USB device strings: Mfr=3, Product=1, SerialNumber=2
Jul 24 19:03:04 eurasia kernel: [25069.980240] usb 1-5: Product: Audio Player
Jul 24 19:03:04 eurasia kernel: [25069.980240] usb 1-5: Manufacturer: ALi Corp.
Jul 24 19:03:04 eurasia kernel: [25069.980240] usb 1-5: SerialNumber: 00101000101410066364
Jul 24 19:03:05 eurasia kernel: [25070.196765] Initializing USB Mass Storage driver...
Jul 24 19:03:05 eurasia kernel: [25070.198256] scsi0 : SCSI emulation for USB Mass Storage devices
Jul 24 19:03:05 eurasia kernel: [25070.198682] usbcore: registered new interface driver usb-storage
Jul 24 19:03:05 eurasia kernel: [25070.198689] USB Mass Storage support registered.
Jul 24 19:03:05 eurasia kernel: [25070.206876] usb-storage: device found at 2
Jul 24 19:03:05 eurasia kernel: [25070.206883] usb-storage: waiting for device to settle before scanning
Jul 24 19:03:10 eurasia kernel: [25075.519313] usb-storage: device scan complete
Jul 24 19:03:10 eurasia kernel: [25075.520143] scsi 0:0:0:0: Direct-Access Audio Player PQ: 0 ANSI: 0 CCS
Jul 24 19:03:10 eurasia kernel: [25075.608201] Driver 'sd' needs updating - please use bus_type methods
Jul 24 19:03:10 eurasia kernel: [25075.610031] sd 0:0:0:0: [sda] 4073984 512-byte hardware sectors (2086 MB)
Jul 24 19:03:10 eurasia kernel: [25075.610886] sd 0:0:0:0: [sda] Write Protect is off
Jul 24 19:03:10 eurasia kernel: [25075.610891] sd 0:0:0:0: [sda] Mode Sense: 3b 00 00 00
Jul 24 19:03:10 eurasia kernel: [25075.610893] sd 0:0:0:0: [sda] Assuming drive cache: write through
Jul 24 19:03:10 eurasia kernel: [25075.615127] sd 0:0:0:0: [sda] 4073984 512-byte hardware sectors (2086 MB)
Jul 24 19:03:10 eurasia kernel: [25075.616142] sd 0:0:0:0: [sda] Write Protect is off
Jul 24 19:03:10 eurasia kernel: [25075.616147] sd 0:0:0:0: [sda] Mode Sense: 3b 00 00 00
Jul 24 19:03:10 eurasia kernel: [25075.616150] sd 0:0:0:0: [sda] Assuming drive cache: write through
Jul 24 19:03:10 eurasia kernel: [25075.616153] sda: sda1
Jul 24 19:03:10 eurasia kernel: [25075.617510] sd 0:0:0:0: [sda] Attached SCSI removable disk
Jul 24 19:03:17 eurasia kernel: [25083.820927] usb 1-5: reset high speed USB device using ehci_hcd and address 2
Jul 24 19:03:19 eurasia kernel: [25085.483682] usb 1-5: reset high speed USB device using ehci_hcd and address 2
Jul 24 19:03:19 eurasia kernel: [25085.624466] sd 0:0:0:0: [sda] Result: hostbyte=DID_ERROR driverbyte=DRIVER_OK,SUGGEST_OK
Jul 24 19:03:19 eurasia kernel: [25085.624466] end_request: I/O error, dev sda, sector 37
Jul 24 19:03:26 eurasia kernel: [25093.125099] usb 1-5: reset high speed USB device using ehci_hcd and address 2
Jul 24 19:03:30 eurasia kernel: [25097.113851] usb 1-5: reset high speed USB device using ehci_hcd and address 2
Jul 24 19:03:30 eurasia kernel: [25097.576447] usb 1-5: reset high speed USB device using ehci_hcd and address 2
Jul 24 19:03:31 eurasia kernel: [25098.410646] usb 1-5: reset high speed USB device using ehci_hcd and address 2
Jul 24 19:03:32 eurasia kernel: [25099.269510] usb 1-5: reset high speed USB device using ehci_hcd and address 2
Jul 24 19:03:33 eurasia kernel: [25100.769788] usb 1-5: reset high speed USB device using ehci_hcd and address 2
Jul 24 19:03:34 eurasia kernel: [25101.468735] usb 1-5: reset high speed USB device using ehci_hcd and address 2
Jul 24 19:03:35 eurasia kernel: [25102.535667] usb 1-5: reset high speed USB device using ehci_hcd and address 2
Jul 24 19:03:35 eurasia kernel: [25102.849478] usb 1-5: reset high speed USB device using ehci_hcd and address 2
Jul 24 19:03:36 eurasia kernel: [25103.152891] usb 1-5: reset high speed USB device using ehci_hcd and address 2
Jul 24 19:03:48 eurasia kernel: [25115.838545] usb 1-5: reset high speed USB device using ehci_hcd and address 2
Jul 24 19:03:48 eurasia kernel: [25116.112641] usb 1-5: reset high speed USB device using ehci_hcd and address 2
Jul 24 19:03:48 eurasia kernel: [25116.407009] usb 1-5: reset high speed USB device using ehci_hcd and address 2
Jul 24 19:03:59 eurasia kernel: [25127.511585] usb 1-5: reset high speed USB device using ehci_hcd and address 2
Jul 24 19:04:05 eurasia kernel: [25133.857934] usb 1-5: reset high speed USB device using ehci_hcd and address 2
Jul 24 19:04:05 eurasia kernel: [25134.138299] usb 1-5: reset high speed USB device using ehci_hcd and address 2
Jul 24 19:04:05 eurasia kernel: [25134.280260] usb 1-5: can't restore configuration #1 (error=-71)
Jul 24 19:04:05 eurasia kernel: [25134.280289] usb 1-5: USB disconnect, address 2
Jul 24 19:04:05 eurasia kernel: [25134.280291] sd 0:0:0:0: [sda] Result: hostbyte=DID_ERROR driverbyte=DRIVER_OK,SUGGEST_OK
Jul 24 19:04:05 eurasia kernel: [25134.280291] end_request: I/O error, dev sda, sector 1018212
Jul 24 19:04:05 eurasia kernel: [25134.280291] sd 0:0:0:0: [sda] Result: hostbyte=DID_ERROR driverbyte=DRIVER_OK,SUGGEST_OK
Jul 24 19:04:05 eurasia kernel: [25134.280291] end_request: I/O error, dev sda, sector 1018452
Jul 24 19:04:05 eurasia kernel: [25134.280292] sd 0:0:0:0: [sda] Result: hostbyte=DID_ERROR driverbyte=DRIVER_OK,SUGGEST_OK
Jul 24 19:04:05 eurasia kernel: [25134.280292] end_request: I/O error, dev sda, sector 1018484
Jul 24 19:04:05 eurasia kernel: [25134.280292] sd 0:0:0:0: [sda] Result: hostbyte=DID_ERROR driverbyte=DRIVER_OK,SUGGEST_OK
Jul 24 19:04:05 eurasia kernel: [25134.280292] end_request: I/O error, dev sda, sector 1018724
Jul 24 19:04:05 eurasia kernel: [25134.280292] sd 0:0:0:0: [sda] Result: hostbyte=DID_ERROR driverbyte=DRIVER_OK,SUGGEST_OK
Jul 24 19:04:05 eurasia kernel: [25134.280292] end_request: I/O error, dev sda, sector 1018964
Jul 24 19:04:05 eurasia kernel: [25134.280292] sd 0:0:0:0: [sda] Result: hostbyte=DID_ERROR driverbyte=DRIVER_OK,SUGGEST_OK
Jul 24 19:04:05 eurasia kernel: [25134.280292] end_request: I/O error, dev sda, sector 1018212
Jul 24 19:04:05 eurasia kernel: [25134.280708] Buffer I/O error on device sda1, logical block 500
Jul 24 19:04:05 eurasia kernel: [25134.280716] lost page write due to I/O error on sda1
Jul 24 19:04:05 eurasia kernel: [25134.280720] Buffer I/O error on device sda1, logical block 501
Jul 24 19:04:05 eurasia kernel: [25134.280723] lost page write due to I/O error on sda1
Jul 24 19:04:05 eurasia kernel: [25134.280726] Buffer I/O error on device sda1, logical block 502
Jul 24 19:04:05 eurasia kernel: [25134.280729] lost page write due to I/O error on sda1
Jul 24 19:04:05 eurasia kernel: [25134.280732] Buffer I/O error on device sda1, logical block 503
Jul 24 19:04:05 eurasia kernel: [25134.280734] lost page write due to I/O error on sda1
Jul 24 19:04:05 eurasia kernel: [25134.280739] Buffer I/O error on device sda1, logical block 504
Jul 24 19:04:05 eurasia kernel: [25134.280742] lost page write due to I/O error on sda1
Jul 24 19:04:05 eurasia kernel: [25134.280745] Buffer I/O error on device sda1, logical block 505
Jul 24 19:04:05 eurasia kernel: [25134.280748] lost page write due to I/O error on sda1
Jul 24 19:04:05 eurasia kernel: [25134.280755] Buffer I/O error on device sda1, logical block 507
Jul 24 19:04:05 eurasia kernel: [25134.280758] lost page write due to I/O error on sda1
Jul 24 19:04:05 eurasia kernel: [25134.280761] Buffer I/O error on device sda1, logical block 508
Jul 24 19:04:05 eurasia kernel: [25134.280763] lost page write due to I/O error on sda1
Jul 24 19:04:05 eurasia kernel: [25134.280766] Buffer I/O error on device sda1, logical block 509
Jul 24 19:04:05 eurasia kernel: [25134.280769] lost page write due to I/O error on sda1
Jul 24 19:04:05 eurasia kernel: [25134.280773] Buffer I/O error on device sda1, logical block 512
Jul 24 19:04:05 eurasia kernel: [25134.280775] lost page write due to I/O error on sda1
Jul 24 19:04:05 eurasia kernel: [25134.396333] usb 1-5: new high speed USB device using ehci_hcd and address 3
Jul 24 19:04:05 eurasia kernel: [25134.530771] usb 1-5: configuration #1 chosen from 1 choice
Jul 24 19:04:05 eurasia kernel: [25134.537483] scsi1 : SCSI emulation for USB Mass Storage devices
Jul 24 19:04:05 eurasia kernel: [25134.541818] usb 1-5: New USB device found, idVendor=0402, idProduct=5661
Jul 24 19:04:05 eurasia kernel: [25134.541826] usb 1-5: New USB device strings: Mfr=3, Product=1, SerialNumber=2
Jul 24 19:04:05 eurasia kernel: [25134.541829] usb 1-5: Product: Audio Player
Jul 24 19:04:05 eurasia kernel: [25134.541831] usb 1-5: Manufacturer: ALi Corp.
Jul 24 19:04:05 eurasia kernel: [25134.541833] usb 1-5: SerialNumber: 00101000101410066364
Jul 24 19:04:05 eurasia kernel: [25134.542383] usb-storage: device found at 3
Jul 24 19:04:05 eurasia kernel: [25134.542388] usb-storage: waiting for device to settle before scanning
Jul 24 19:04:05 eurasia kernel: 34.580436] FAT: Directory bread(block 501) failed
Jul 24 19:04:05 eurasia kernel: [25134.580443] FAT: Directory bread(block 502) failed
Jul 24 19:04:05 eurasia kernel: [25134.580451] FAT: Directory bread(block 503) failed
Jul 24 19:04:05 eurasia kernel: [25134.580461] FAT: Directory bread(block 504) failed
Jul 24 19:04:05 eurasia kernel: [25134.580468] FAT: Directory bread(block 505) failed
Jul 24 19:04:05 eurasia kernel: [25134.580475] FAT: Directory bread(block 506) failed
Jul 24 19:04:05 eurasia kernel: [25134.580482] FAT: Directory bread(block 507) failed
Jul 24 19:04:05 eurasia kernel: [25134.580489] FAT: Directory bread(block 508) failed
Jul 24 19:04:05 eurasia kernel: [25134.580495] FAT: Directory bread(block 509) failed
Jul 24 19:04:05 eurasia kernel: [25134.580502] FAT: Directory bread(block 510) failed
Jul 24 19:04:05 eurasia kernel: [25134.580508] FAT: Directory bread(block 511) failed
Jul 24 19:04:05 eurasia kernel: [25134.580518] FAT: Directory bread(block 512) failed
Jul 24 19:04:05 eurasia kernel: [25134.580525] FAT: Directory bread(block 513) failed
Jul 24 19:04:05 eurasia kernel: [25134.580531] FAT: Directory bread(block 514) failed
Jul 24 19:04:05 eurasia kernel: [25134.580538] FAT: Directory bread(block 515) failed
Jul 24 19:04:05 eurasia kernel: [25134.580544] FAT: Directory bread(block 516) failed
Jul 24 19:04:05 eurasia kernel: [25134.580551] FAT: Directory bread(block 517) failed
Jul 24 19:04:05 eurasia kernel: [25134.580557] FAT: Directory bread(block 518) failed
Jul 24 19:04:05 eurasia kernel: [25134.580564] FAT: Directory bread(block 519) failed
Jul 24 19:04:05 eurasia kernel: [25134.580573] FAT: Directory bread(block 520) failed
Jul 24 19:04:05 eurasia kernel: [25134.580580] FAT: Directory bread(block 521) failed
Jul 24 19:04:05 eurasia kernel: [25134.580587] FAT: Directory bread(block 522) failed
Jul 24 19:04:05 eurasia kernel: [25134.580593] FAT: Directory bread(block 523) failed
Jul 24 19:04:05 eurasia kernel: [25134.580600] FAT: Directory bread(block 524) failed
Jul 24 19:04:05 eurasia kernel: [25134.580607] FAT: Directory bread(block 525) failed
Jul 24 19:04:05 eurasia kernel: [25134.580613] FAT: Directory bread(block 526) failed
Jul 24 19:04:05 eurasia kernel: [25134.580620] FAT: Directory bread(block 527) failed
Jul 24 19:04:05 eurasia kernel: [25134.580634] FAT: Directory bread(block 528) failed
Jul 24 19:04:05 eurasia kernel: [25134.580641] FAT: Directory bread(block 529) failed
Jul 24 19:04:05 eurasia kernel: [25134.580648] FAT: Directory bread(block 530) failed
Jul 24 19:04:05 eurasia kernel: [25134.580655] FAT: Directory bread(block 531) failed

[this stuff is repeated n times]

i managed to get a syrq + p:

Jul 24 19:08:33 eurasia kernel: [25412.247908] Pid: 32692, comm: Thunar Not tainted (2.6.25-2-686 #1)
Jul 24 19:08:33 eurasia kernel: [25412.247908] EIP: 0060:[<f88e38e8>] EFLAGS: 00200206 CPU: 0
Jul 24 19:08:33 eurasia kernel: [25412.247908] EIP is at scsi_request_fn+0x2d3/0x322 [scsi_mod]
Jul 24 19:08:33 eurasia kernel: [25412.247908] EAX: f7840a00 EBX: 00000000 ECX: c034fe68 EDX: 00000000
Jul 24 19:08:33 eurasia kernel: [25412.247908] ESI: f6220800 EDI: e2631400 EBP: f78408c8 ESP: f6277abc
Jul 24 19:08:33 eurasia kernel: [25412.247908] DS: 007b ES: 007b FS: 00d8 GS: 0033 SS: 0068
Jul 24 19:08:33 eurasia kernel: [25412.247908] CR0: 8005003b CR2: 080aeca8 CR3: 367b9000 CR4: 000006d0
Jul 24 19:08:33 eurasia kernel: [25412.247908] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
Jul 24 19:08:33 eurasia kernel: [25412.247908] DR6: ffff0ff0 DR7: 00000400
Jul 24 19:08:33 eurasia kernel: [25412.247908] [<c01d197d>] ? __generic_unplug_device+0x1a/0x1c
Jul 24 19:08:33 eurasia kernel: [25412.247908] [<c01cf884>] ? elv_insert+0x10f/0x1a5
Jul 24 19:08:33 eurasia kernel: [25412.247908] [<c01d219a>] ? __make_request+0x2fe/0x348
Jul 24 19:08:33 eurasia kernel: [25412.247908] [<c0197121>] ? do_mpage_readpage+0x4f8/0x5bb
Jul 24 19:08:33 eurasia kernel: [25412.247908] [<c01d0e56>] ? generic_make_request+0x34d/0x37b
Jul 24 19:08:33 eurasia kernel: [25412.247908] [<c011309e>] ? lapic_next_event+0xc/0x10
Jul 24 19:08:33 eurasia kernel: [25412.247908] [<c013a254>] ? clockevents_program_event+0xc4/0xd2
Jul 24 19:08:33 eurasia kernel: [25412.247908] [<c01d1e95>] ? submit_bio+0xc6/0xcd
Jul 24 19:08:33 eurasia kernel: [25412.247908] [<c0197237>] ? mpage_end_io_read+0x0/0x53
Jul 24 19:08:33 eurasia kernel: [25412.247908] [<c0196566>] ? mpage_bio_submit+0x19/0x1d
Jul 24 19:08:33 eurasia kernel: [25412.247908] [<c0197231>] ? mpage_readpage+0x4d/0x53
Jul 24 19:08:33 eurasia kernel: [25412.247908] [<c0108314>] ? apic_timer_interrupt+0x28/0x30
Jul 24 19:08:33 eurasia kernel: [25412.247908] [<c0158705>] ? find_lock_page+0x19/0x7f
Jul 24 19:08:33 eurasia kernel: [25412.247908] [<c015a6f9>] ? filemap_fault+0x315/0x36d
Jul 24 19:08:33 eurasia kernel: [25412.247908] [<c0190899>] ? __find_get_block+0x176/0x180
Jul 24 19:08:33 eurasia kernel: [25412.247908] [<c0163360>] ? __do_fault+0x59/0x38e
Jul 24 19:08:33 eurasia kernel: [25412.247908] [<c01908ca>] ? __getblk+0x27/0x254
Jul 24 19:08:33 eurasia kernel: [25412.247908] [<c01654e2>] ? handle_mm_fault+0x2c5/0x6bb
Jul 24 19:08:33 eurasia kernel: [25412.247908] [<f894c55d>] ? __ext3_get_inode_loc+0x109/0x2b6 [ext3]
Jul 24 19:08:33 eurasia kernel: [25412.247908] [<f894c3ee>] ? ext3_mark_iloc_dirty+0x279/0x2df [ext3]
Jul 24 19:08:33 eurasia kernel: [25412.247908] [<c011cc1b>] ? __wake_up+0x29/0x39
Jul 24 19:08:33 eurasia kernel: [25412.247908] [<c0118b4c>] ? do_page_fault+0x268/0x584
Jul 24 19:08:33 eurasia kernel: [25412.247908] [<f89532ba>] ? __ext3_journal_stop+0x19/0x34 [ext3]
Jul 24 19:08:33 eurasia kernel: [25412.247908] [<c01188e4>] ? do_page_fault+0x0/0x584
Jul 24 19:08:33 eurasia kernel: [25412.247908] [<c02b579a>] ? error_code+0x72/0x78
Jul 24 19:08:33 eurasia kernel: [25412.247908] [<c0157d9c>] ? iov_iter_fault_in_readable+0x20/0x53
Jul 24 19:08:33 eurasia kernel: [25412.247908] [<c01592cd>] ? generic_file_buffered_write+0xc7/0x553
Jul 24 19:08:33 eurasia kernel: [25412.247908] [<f8959781>] ? ext3_xattr_security_get+0x31/0x3b [ext3]
Jul 24 19:08:33 eurasia kernel: [25412.247908] [<c018b1f0>] ? generic_getxattr+0x0/0x3d
Jul 24 19:08:33 eurasia kernel: [25412.247908] [<c0159bbd>] ? __generic_file_aio_write_nolock+0x464/0x4c6
Jul 24 19:08:33 eurasia kernel: [25412.247908] [<c0198483>] ? inotify_dev_queue_event+0xf8/0x109
Jul 24 19:08:33 eurasia kernel: [25412.247908] [<c0197a34>] ? inotify_inode_queue_event+0x9a/0xc6
Jul 24 19:08:33 eurasia kernel: [25412.247908] [<c0159c71>] ? generic_file_aio_write+0x52/0xa9
Jul 24 19:08:33 eurasia kernel: [25412.247908] [<f894af8d>] ? ext3_file_write+0x19/0x83 [ext3]
Jul 24 19:08:33 eurasia kernel: [25412.247908] [<c0175752>] ? do_sync_write+0xbf/0x100
Jul 24 19:08:33 eurasia kernel: [25412.247908] [<c01339f0>] ? autoremove_wake_function+0x0/0x2d
Jul 24 19:08:33 eurasia kernel: [25412.247908] [<c01b91a8>] ? security_file_permission+0xc/0xd
Jul 24 19:08:33 eurasia kernel: [25412.247908] [<c0175693>] ? do_sync_write+0x0/0x100
Jul 24 19:08:33 eurasia kernel: [25412.247908] [<c0175ebc>] ? vfs_write+0x83/0x120
Jul 24 19:08:33 eurasia kernel: [25412.247908] [<c0176488>] ? sys_write+0x3c/0x63
Jul 24 19:08:33 eurasia kernel: [25412.247908] [<c0107862>] ? syscall_call+0x7/0xb

Attached you'll find compressed my config and the full syslog stuff.

I have the log of a file recovery tool for windows called testdisk [1] if you find them useful.

This is the relevant fstab line:

/dev/sda1 /media/usb auto noauto,user,rw,async 0 0

thanks,
Riccardo

[1] http://www.cgsecurity.org/wiki/TestDisk

Attachment: kern.log.tgz
Description: application/compressed-tar

Attachment: config-2.6.25-2-686.tgz
Description: application/compressed-tar

Next message: Ingo Molnar: "Re: [PATCH] i386: improve double fault handling"
Previous message: Vivek Goyal: "Re: [patch] crashdump: fix undefined reference to `elfcorehdr_addr'"
Next in thread: OGAWA Hirofumi: "Re: soft lockup while copying data from a FAT usb stick and consequent FAT table corruption"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]