Bug 782280

Summary: ext4 write took more than 2 minutes to complete.
Product: [Fedora] Fedora Reporter: George R. Goffe <grgoffe>
Component: kernelAssignee: Eric Sandeen <esandeen>
Status: CLOSED INSUFFICIENT_DATA QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 16CC: gansalmon, itamar, jforbes, jonathan, kernel-maint, madhu.chinakonda
Target Milestone: ---   
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2012-11-14 17:04:37 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
/var/log/messages
none
gzip'd copy of parts of /var/log/messages during a problem event. none

Description George R. Goffe 2012-01-17 04:09:21 UTC 
Description of problem:

System left running scripts; system apparently panic'd; system retried boot; system repeatedly crashes.

Version-Release number of selected component (if applicable):

3.1.9-1.fc16.x86_64.debug
3.1.8-2.fc16.x86_64.debug

How reproducible:

Seems to happen every few days.

Steps to Reproduce:
1.unknown
2.
3.
  
Actual results:

System reboots and hangs the last time.

Expected results:

Normal system operation.

Additional info:

Output of last command:

root     pts/0        :0               Mon Jan 16 19:49   still logged in                                                                                                                                         
reboot   system boot  3.1.8-2.fc16.x86 Mon Jan 16 19:48 - 20:07  (00:19)                                                                                                                                          
root     tty1                          Mon Jan 16 19:48 - crash  (00:00)                                                                                                                                          
root     pts/0        :0               Mon Jan 16 19:35 - 19:41  (00:06)                                                                                                                                          
root     pts/4        :0               Mon Jan 16 19:34 - down   (00:13)                                                                                                                                          
root     pts/9        :0               Mon Jan 16 19:34 - 19:41  (00:07)                                                                                                                                          
root     pts/3        :0               Mon Jan 16 19:34 - down   (00:13)                                                                                                                                          
root     pts/2        :0               Mon Jan 16 19:34 - down   (00:13)                                                                                                                                          
root     pts/6        :0               Mon Jan 16 19:34 - 19:34  (00:00)                                                                                                                                          
root     pts/5        :0               Mon Jan 16 19:34 - 19:34  (00:00)                                                                                                                                          
root     pts/1        :0               Mon Jan 16 19:34 - 19:34  (00:00)                                                                                                                                          
root     pts/8        :0               Mon Jan 16 19:34 - down   (00:13)                                                                                                                                          
root     pts/7        :0               Mon Jan 16 19:34 - down   (00:13)                                                                                                                                          
root     pts/0        :0               Mon Jan 16 19:34 - 19:35  (00:00)                                                                                                                                          
root     tty1                          Mon Jan 16 19:02 - down   (00:44)                                                                                                                                          
reboot   system boot  3.1.9-1.fc16.x86 Mon Jan 16 19:01 - 19:47  (00:45)                                                                                                                                          
root     pts/12       :0               Mon Jan 16 16:21 - crash  (02:40)                                                                                                                                          
root     pts/11       :0               Mon Jan 16 16:04 - crash  (02:57)                                                                                                                                          
root     pts/11       :0               Mon Jan 16 15:18 - 15:18  (00:00)                                                                                                                                          
root     pts/10       :0               Mon Jan 16 11:50 - 17:29  (05:39)                                                                                                                                          
root     pts/9        :0               Mon Jan 16 07:19 - crash  (11:42)                                                                                                                                          
root     pts/4        :0               Mon Jan 16 07:19 - crash  (11:42)                                                                                                                                          
root     pts/3        :0               Mon Jan 16 07:19 - crash  (11:42)                                                                                                                                          
root     pts/2        :0               Mon Jan 16 07:19 - crash  (11:42)                                                                                                                                          
root     pts/6        :0               Mon Jan 16 07:19 - crash  (11:42)                                                                                                                                          
root     pts/5        :0               Mon Jan 16 07:19 - crash  (11:42)                                                                                                                                          
root     pts/1        :0               Mon Jan 16 07:19 - crash  (11:42)                                                                                                                                          
root     pts/8        :0               Mon Jan 16 07:19 - crash  (11:42)                                                                                                                                          
root     pts/7        :0               Mon Jan 16 07:19 - crash  (11:42)                                                                                                                                          
root     pts/0        :0               Mon Jan 16 07:19 - crash  (11:42)                                                                                                                                          
reboot   system boot  3.1.8-2.fc16.x86 Mon Jan 16 07:18 - 19:47  (12:28)                                                                                                                                          
root     tty1                          Mon Jan 16 07:19 - crash  (00:00)                                                                                                                                          
root     pts/0        :0               Sun Jan 15 02:39 - 07:17 (1+04:37)                                                                                                                                         
root     pts/11       :0               Sun Jan 15 02:18 - 02:18  (00:00)                                                                                                                                          
root     pts/12       :0               Sun Jan 15 02:16 - 02:17  (00:00)                                                                                                                                          
root     pts/10       :0               Sat Jan 14 13:14 - 07:15 (1+18:01)   
root     pts/9        :0               Thu Jan 12 19:54 - 07:17 (3+11:22)   
root     pts/4        :0               Thu Jan 12 19:54 - 02:36 (2+06:42)   
root     pts/3        :0               Thu Jan 12 19:54 - 02:36 (2+06:42)   
root     pts/2        :0               Thu Jan 12 19:54 - 07:16 (3+11:21)   
root     pts/6        :0               Thu Jan 12 19:54 - 02:36 (2+06:41)   
root     pts/5        :0               Thu Jan 12 19:54 - 02:36 (2+06:41)   
root     pts/1        :0               Thu Jan 12 19:54 - 02:36 (2+06:41)   
root     pts/8        :0               Thu Jan 12 19:54 - 07:17 (3+11:22)   
root     pts/7        :0               Thu Jan 12 19:54 - 02:39 (2+06:44)   
root     pts/0        :0               Thu Jan 12 19:54 - 02:36 (2+06:42)   
reboot   system boot  3.1.7-1.fc16.x86 Thu Jan 12 19:53 - 07:18 (3+11:24)   
root     tty1                          Thu Jan 12 19:53 - crash  (00:00)    
root     tty2                          Thu Jan 12 19:51 - down   (00:01)    
root     pts/10       :0               Thu Jan 12 19:50 - 19:50  (00:00)    
root     pts/4        :0               Wed Jan 11 19:49 - 19:50 (1+00:00)   
root     pts/9        :0               Wed Jan 11 19:49 - 19:50 (1+00:00)   
root     pts/3        :0               Wed Jan 11 19:49 - 19:50 (1+00:00)   
root     pts/2        :0               Wed Jan 11 19:49 - 19:50 (1+00:00)   
root     pts/6        :0               Wed Jan 11 19:49 - 19:50 (1+00:00)   
root     pts/5        :0               Wed Jan 11 19:49 - 19:50 (1+00:00)   
root     pts/1        :0               Wed Jan 11 19:49 - 19:50 (1+00:00)   
root     pts/8        :0               Wed Jan 11 19:49 - 19:50 (1+00:00)   
root     pts/7        :0               Wed Jan 11 19:49 - 19:50 (1+00:00)   
root     pts/0        :0               Wed Jan 11 19:49 - 19:50 (1+00:00)   
root     tty1                          Wed Jan 11 19:49 - down  (1+00:03)   
reboot   system boot  3.1.7-1.fc16.x86 Wed Jan 11 19:48 - 19:52 (1+00:04)   
reboot   system boot  3.1.7-1.fc16.x86 Wed Jan 11 19:33 - 19:48  (00:14)    
root     tty1                          Wed Jan 11 19:33 - crash  (00:00)    
reboot   system boot  3.1.7-1.fc16.x86 Wed Jan 11 19:29 - 19:48  (00:18)    
root     pts/9        :0               Wed Jan 11 03:10 - crash  (16:19)    
root     pts/8        :0               Wed Jan 11 03:10 - crash  (16:19)    
root     pts/7        :0               Wed Jan 11 03:10 - crash  (16:19)    
root     pts/6        :0               Wed Jan 11 03:10 - crash  (16:19)    
root     pts/5        :0               Wed Jan 11 03:10 - crash  (16:19)    
root     pts/4        :0               Wed Jan 11 03:10 - crash  (16:19)    
root     pts/2        :0               Wed Jan 11 03:09 - crash  (16:19)    
root     pts/1        :0               Wed Jan 11 03:09 - crash  (16:19)    
root     pts/0        :0               Wed Jan 11 03:09 - crash  (16:19)    
root     pts/3        :0               Wed Jan 11 03:08 - crash  (16:21)    
root     pts/2        :0               Wed Jan 11 03:08 - 03:09  (00:01)    
root     pts/1        :0               Wed Jan 11 03:08 - 03:09  (00:01)    
root     pts/0        :0               Wed Jan 11 03:08 - 03:09  (00:01)    
root     tty1                          Wed Jan 11 03:07 - crash  (16:22)    
reboot   system boot  3.1.7-1.fc16.x86 Wed Jan 11 03:07 - 19:48  (16:41)    
root     pts/3        :0               Wed Jan 11 02:55 - 03:06  (00:10)    
root     pts/2        :0               Wed Jan 11 02:55 - 03:06  (00:10)    
root     pts/1        :0               Wed Jan 11 02:55 - 03:06  (00:10)    
root     pts/0        :0               Wed Jan 11 02:55 - 03:06  (00:10)    
root     tty1                          Wed Jan 11 02:55 - down   (00:11)    
reboot   system boot  3.1.7-1.fc16.x86 Wed Jan 11 02:54 - 03:06  (00:12)    
root     tty2                          Wed Jan 11 02:43 - down   (00:03)    
root     pts/0        :0               Wed Jan 11 02:03 - 02:43  (00:39)    
root     pts/5        :0               Tue Jan 10 20:51 - 21:08  (00:17)    
root     pts/15       :0               Sun Jan  8 14:06 - 20:45 (2+06:39)   
root     pts/14       :0               Sun Jan  8 13:40 - 20:41 (2+07:01)   
root     pts/13       :0               Sun Jan  8 13:22 - 20:41 (2+07:19)   
root     pts/12       :0               Sun Jan  8 13:22 - 20:41 (2+07:19)   
root     pts/11       :0               Sun Jan  8 13:22 - 20:41 (2+07:19)   
root     pts/10       :0               Sun Jan  8 02:06 - 20:45 (2+18:39)   
root     pts/9        :0               Sun Jan  8 01:42 - 20:45 (2+19:02)   
root     pts/8        :0               Sun Jan  8 01:22 - 23:22 (2+22:00)   
root     pts/7        :0               Sat Jan  7 14:58 - 20:41 (3+05:43)   
root     pts/6        :0               Sat Jan  7 03:07 - 23:22 (3+20:15)   
root     pts/5        :0               Sat Jan  7 02:21 - 20:45 (3+18:23)   
root     pts/4        :0               Sat Jan  7 02:21 - 02:34 (4+00:12)   
root     pts/3        :0               Sat Jan  7 02:14 - 02:43 (4+00:28)   
root     pts/2        :0               Sat Jan  7 02:14 - 02:43 (4+00:28)   
root     pts/1        :0               Sat Jan  7 02:14 - 20:43 (3+18:28)   
root     pts/0        :0               Sat Jan  7 02:14 - 20:45 (3+18:31)   
root     tty1                          Sat Jan  7 02:13 - down  (4+00:33)   
reboot   system boot  3.1.6-1.fc16.x86 Sat Jan  7 02:13 - 02:46 (4+00:33)   
root     tty2                          Sat Jan  7 02:09 - down   (00:02)    
root     tty1                          Sat Jan  7 01:56 - down   (00:16)    
reboot   system boot  3.1.6-1.fc16.x86 Sat Jan  7 01:56 - 02:12  (00:16)    
root     pts/3        :0               Sat Jan  7 01:02 - 01:55  (00:53)    
root     pts/2        :0               Sat Jan  7 01:02 - 01:55  (00:53)    
root     pts/1        :0               Sat Jan  7 01:02 - 01:55  (00:53)    
root     pts/0        :0               Sat Jan  7 00:43 - 01:55  (01:12)    
root     tty1                          Fri Jan  6 23:54 - down   (02:01)    
reboot   system boot  3.1.0-7.fc16.x86 Fri Jan  6 23:54 - 01:55  (02:01)    
reboot   system boot  3.1.0-7.fc16.x86 Fri Jan  6 23:34 - 01:55  (02:21)    
(unknown tty3         :0               Fri Jan  6 23:33 - down   (00:00)    
(unknown tty3         :0               Fri Jan  6 23:32 - 23:32  (00:00)    
(unknown tty3         :0               Fri Jan  6 23:32 - 23:32  (00:00)    
(unknown tty3         :0               Fri Jan  6 23:32 - 23:32  (00:00)    
(unknown tty2         :0               Fri Jan  6 23:30 - 23:32  (00:01)    
reboot   system boot  3.1.0-7.fc16.x86 Fri Jan  6 23:29 - 23:33  (00:03)
Comment 1 George R. Goffe 2012-01-17 04:11:31 UTC 
I know this isn't enough information to debug this problem. PLEASE let me know what you need and I'll do my best. This is my only system so network console or serial console will not work.
Comment 2 Josh Boyer 2012-01-17 14:56:32 UTC 
Are there any backtraces in /var/log/messages?  Does a backtrace show up on your screen when this happens?  If so, a digital picture is sometimes good enough to start from.
Comment 3 George R. Goffe 2012-01-17 21:55:55 UTC 
Hi Josh,

I'll check again for back traces.

When I get to the machine it's in an odd state (frozen/hung? NOT sleeping). The GUI/monitor has NOTHING on it. The system appears to ignore alt-ctrl-del... I have to power cycle to get it to come back.

Thanks,

George...
Comment 4 George R. Goffe 2012-01-18 06:20:39 UTC 
Josh,

The mystery is partially resolved.

I got home tonight and found messages on the console! The hdd was busy and there were some messages relating to processes being frozen. I checked the KDE settings for power and found that various settings had freeze/hibernate specified. I'm embarrassed that I didn't catch this. I couldn't get the system to un-freeze/un-hibernate so I power cycled it (keyboard was disabled and a short tap of the power off button didn't do anything). I have disabled this behavior so we'll see if it actually works.

/var/log/messages had several call traces in it AND some mention of "freeze" (see enclosed).

The question remains relating to the many crashes shown in the last log output AND apparently NO messages about freeze/hibernate (success or failures) in /var/log/messages.

How would like to proceed with this bug?

Again, my apologies for missing the freeze messages.

Regards,

George...
Comment 5 George R. Goffe 2012-01-18 06:31:30 UTC 
Created attachment 555920 [details]
/var/log/messages
Comment 6 Dave Jones 2012-01-30 18:52:25 UTC 
There's a number of things going wrong in there. The most important though, is that ext4 took more than two minutes to complete a write. Perhaps Eric has some idea what went wrong.

Is there anything special about the backing device that filesystem is on ?



Jan 16 16:32:38 joker kernel: [33208.116324] INFO: task rs:main Q:Reg:1086 blocked for more than 120 seconds.
Jan 16 16:32:39 joker kernel: [33208.116335] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jan 16 16:32:39 joker kernel: [33208.116341] rs:main Q:Reg   D 0000000101f4a95d  3408  1086      1 0x00000080
Jan 16 16:32:39 joker kernel: [33208.116356]  ffff88023475b9a8 0000000000000046 ffffffff00000000 ffff88023475ba60
Jan 16 16:32:39 joker kernel: [33208.116371]  ffff8802379ac960 ffff88023475bfd8 ffff88023475bfd8 ffff88023475bfd8
Jan 16 16:32:39 joker kernel: [33208.116384]  ffff88023f558000 ffff8802379ac960 ffff88023475b968 000000013475b968
Jan 16 16:32:39 joker kernel: [33208.116397] Call Trace:
Jan 16 16:32:39 joker kernel: [33208.116414]  [<ffffffff8113be70>] ? __lock_page+0x70/0x70
Jan 16 16:32:39 joker kernel: [33208.116426]  [<ffffffff8165da1f>] schedule+0x3f/0x60
Jan 16 16:32:39 joker kernel: [33208.116435]  [<ffffffff8165dacf>] io_schedule+0x8f/0xd0
Jan 16 16:32:39 joker kernel: [33208.116444]  [<ffffffff8113be7e>] sleep_on_page+0xe/0x20
Jan 16 16:32:39 joker kernel: [33208.116453]  [<ffffffff8165e49f>] __wait_on_bit+0x5f/0x90
Jan 16 16:32:39 joker kernel: [33208.116462]  [<ffffffff8113bfa8>] wait_on_page_bit+0x78/0x80
Jan 16 16:32:39 joker kernel: [33208.116476]  [<ffffffff810a19e0>] ? autoremove_wake_function+0x50/0x50
Jan 16 16:32:39 joker kernel: [33208.116486]  [<ffffffff8113d065>] grab_cache_page_write_begin+0x95/0xe0
Jan 16 16:32:39 joker kernel: [33208.116499]  [<ffffffff812695fe>] ? jbd2_journal_stop+0x1fe/0x3a0
Jan 16 16:32:39 joker kernel: [33208.116511]  [<ffffffff8122ce50>] ext4_da_write_begin+0xa0/0x2b0
Jan 16 16:32:39 joker kernel: [33208.116520]  [<ffffffff812695fe>] ? jbd2_journal_stop+0x1fe/0x3a0
Jan 16 16:32:39 joker kernel: [33208.116531]  [<ffffffff8113c325>] generic_file_buffered_write+0x105/0x260
Jan 16 16:32:39 joker kernel: [33208.116590]  [<ffffffff812313e0>] ? ext4_dirty_inode+0x50/0x60
Jan 16 16:32:39 joker kernel: [33208.116600]  [<ffffffff8165e9a4>] ? mutex_lock_nested+0x2b4/0x3a0
Jan 16 16:32:39 joker kernel: [33208.116611]  [<ffffffff8113de6c>] __generic_file_aio_write+0x22c/0x440
Jan 16 16:32:39 joker kernel: [33208.116623]  [<ffffffff81161789>] ? __do_fault+0x3e9/0x4f0
Jan 16 16:32:39 joker kernel: [33208.116633]  [<ffffffff8113e0f4>] generic_file_aio_write+0x74/0xe0
Jan 16 16:32:39 joker kernel: [33208.116646]  [<ffffffff81225b6a>] ext4_file_write+0xca/0x270
Jan 16 16:32:39 joker kernel: [33208.116657]  [<ffffffff810a8f4f>] ? local_clock+0x6f/0x80
Jan 16 16:32:39 joker kernel: [33208.116668]  [<ffffffff810b73f5>] ? lock_release_holdtime.part.9+0x15/0x1a0
Jan 16 16:32:39 joker kernel: [33208.116680]  [<ffffffff811a2582>] do_sync_write+0xd2/0x110
Jan 16 16:32:39 joker kernel: [33208.116693]  [<ffffffff8101f909>] ? sched_clock+0x9/0x10
Jan 16 16:32:39 joker kernel: [33208.116702]  [<ffffffff811a4b2f>] ? fget_light+0xcf/0x3b0
Jan 16 16:32:39 joker kernel: [33208.116714]  [<ffffffff8129985c>] ? security_file_permission+0x2c/0xb0
Jan 16 16:32:39 joker kernel: [33208.116723]  [<ffffffff811a2a31>] ? rw_verify_area+0x61/0x100
Jan 16 16:32:39 joker kernel: [33208.116732]  [<ffffffff811a2da6>] vfs_write+0xb6/0x180
Jan 16 16:32:39 joker kernel: [33208.116745]  [<ffffffff811a30cd>] sys_write+0x4d/0x90
Jan 16 16:32:39 joker kernel: [33208.116748]  [<ffffffff81669d42>] system_call_fastpath+0x16/0x1b
Jan 16 16:32:39 joker kernel: [33208.116750] 2 locks held by rs:main Q:Reg/1086:
Jan 16 16:32:39 joker kernel: [33208.116752]  #0:  (&sb->s_type->i_mutex_key#13){+.+.+.}, at: [<ffffffff8113e0d8>] generic_file_aio_write+0x58/0xe0
Jan 16 16:32:39 joker kernel: [33208.116757]  #1:  (jbd2_handle){+.+...}, at: [<ffffffff81268957>] start_this_handle+0x507/0x700
Comment 7 Eric Sandeen 2012-01-30 20:34:24 UTC 
It's stuck down this path:

vfs_write...
...
ext4_da_write_begin
grab_cache_page_write_begin
wait_on_page_bit

I assume that last bit is waiting in wait_on_page_writeback()

I've not seen us stuck here before; it's a bit of a copout, but if you had been through a hibernate/resume cycle, I'm somewhat inclined to suspect the possibility of memory corruption.

Can you disable hibernation, and see if any of these problems persist?
Comment 8 George R. Goffe 2012-01-31 01:54:40 UTC 
Eric,

This system has 2 Seagate 750GB HDDs in it. 

One is internal and the other is external, connected via USB to a sata docking station. I don't recall now as to whether this second drive was powered up when I had this problem.

There was an earlier bug against this situation that was fixed. I still see the problem now but it's much more rare. It's like the drive decides to stop working. A switch is made from /dev/sdb to /dev/sdc. When I power cycle the drive, /dev/sdb is again selected. The device is again made available. This has happened during moderate I/O activity as well as 0 I/O activity. I would be willing to test this if it's necessary. Something like dd if=/dev/sdb of=/dev/null bs=1024000

I'm on the latest kernel as of 29 Jan, 2012... no problems yet.

Regards,

George...
Comment 9 George R. Goffe 2012-01-31 01:56:35 UTC 
Eric,

This is a recent NEW purchase so I would expect somewhat newer hardware.

Do you need any other information?

George...
Comment 10 Eric Sandeen 2012-01-31 03:03:51 UTC 
I would not expect a hardware problem, but -

What do you mean by "a switch?"  Are there kernel messages that go along with that?  Is this something like a mirror where one leg goes out, or ... ?

-Eric
Comment 11 George R. Goffe 2012-01-31 06:18:03 UTC 
Created attachment 558529 [details]
gzip'd copy of parts of /var/log/messages during a problem event.

Eric,

The switch I'm talking about is that /dev/sdb had problems and dropped or tried to disappear(?) and then re-appeared as /dev/sdc. I ran or tried to run e2fsck -f /dev/sdc1 but that had troubles and the drive switched back to /dev/sdb. This happened a couple of times then it settled down.

I'm adding an attachment that's an excerpt from /var/log/messages from an incident I had recently.

George...
Comment 12 George R. Goffe 2012-02-25 23:53:34 UTC 
Eric,

I just plugged in a brand new Seagate 75GB hdd to the docking station. I was attempting to run fdisk -l towards the end of the log below. Initially, the system didn't seem to see the drive at all.

Your thoughts please?

Regards,

George...

I'm at this kernel level now (3.2.3-2.fc16.x86_64.debug) but will test this with the latest kernel I have (3.2.7-1.fc16.x86_64.debug) and post the results here.

Here's the /var/log/messages relating to this current situation.


Feb 25 15:34:13 joker kernel: [497712.393393] usb 2-1.4.3: new high-speed USB device number 23 using ehci_hcd
Feb 25 15:34:13 joker kernel: [497712.480304] usb 2-1.4.3: New USB device found, idVendor=152d, idProduct=2336
Feb 25 15:34:13 joker kernel: [497712.480308] usb 2-1.4.3: New USB device strings: Mfr=1, Product=2, SerialNumber=5
Feb 25 15:34:13 joker kernel: [497712.480310] usb 2-1.4.3: Product: JM20336 SATA, USB Combo
Feb 25 15:34:13 joker kernel: [497712.480312] usb 2-1.4.3: Manufacturer: JMicron
Feb 25 15:34:13 joker kernel: [497712.480314] usb 2-1.4.3: SerialNumber: 610888888888
Feb 25 15:34:13 joker kernel: [497712.483426] scsi16 : usb-storage 2-1.4.3:1.0
Feb 25 15:34:13 joker mtp-probe: checking bus 2, device 23: "/sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4/2-1.4.3"
Feb 25 15:34:13 joker mtp-probe: bus: 2, device: 23 was not an MTP device
Feb 25 15:34:14 joker kernel: [497713.485464] scsi 16:0:0:0: Direct-Access     ST975042 0AS                   PQ: 0 ANSI: 2 CCS
Feb 25 15:34:14 joker kernel: [497713.492618] sd 16:0:0:0: Attached scsi generic sg2 type 0
Feb 25 15:34:14 joker kernel: [497713.493573] sd 16:0:0:0: [sdb] 1465149168 512-byte logical blocks: (750 GB/698 GiB)
Feb 25 15:34:14 joker kernel: [497713.495067] sd 16:0:0:0: [sdb] Write Protect is off
Feb 25 15:34:14 joker kernel: [497713.496198] sd 16:0:0:0: [sdb] Asking for cache data failed
Feb 25 15:34:14 joker kernel: [497713.496202] sd 16:0:0:0: [sdb] Assuming drive cache: write through
Feb 25 15:34:14 joker kernel: [497713.500691] sd 16:0:0:0: [sdb] Asking for cache data failed
Feb 25 15:34:14 joker kernel: [497713.500696] sd 16:0:0:0: [sdb] Assuming drive cache: write through
Feb 25 15:34:14 joker kernel: [497713.525863]  sdb: unknown partition table
Feb 25 15:34:14 joker kernel: [497713.529625] sd 16:0:0:0: [sdb] Asking for cache data failed
Feb 25 15:34:14 joker kernel: [497713.529629] sd 16:0:0:0: [sdb] Assuming drive cache: write through
Feb 25 15:34:14 joker kernel: [497713.529636] sd 16:0:0:0: [sdb] Attached SCSI disk
Feb 25 15:34:14 joker ata_id[21931]: HDIO_GET_IDENTITY failed for '/dev/sdb': Invalid argument
Feb 25 15:34:55 joker kernel: [497754.342362] usb 2-1.4.3: reset high-speed USB device number 23 using ehci_hcd
Feb 25 15:35:04 joker kernel: [497763.363070] sd 16:0:0:0: Device offlined - not ready after error recovery
Feb 25 15:35:04 joker kernel: [497763.363094] sd 16:0:0:0: [sdb] Unhandled error code
Feb 25 15:35:04 joker kernel: [497763.363097] sd 16:0:0:0: [sdb]  Result: hostbyte=DID_ABORT driverbyte=DRIVER_OK
Feb 25 15:35:04 joker kernel: [497763.363102] sd 16:0:0:0: [sdb] CDB: Read(10): 28 00 00 00 00 00 00 00 08 00
Feb 25 15:35:04 joker kernel: [497763.363115] end_request: I/O error, dev sdb, sector 0
Feb 25 15:35:04 joker kernel: [497763.363120] Buffer I/O error on device sdb, logical block 0
Feb 25 15:35:04 joker kernel: [497763.363203] sd 16:0:0:0: rejecting I/O to offline device
Feb 25 15:35:04 joker kernel: [497763.364001] usb 2-1.4.3: USB disconnect, device number 23
Feb 25 15:35:06 joker kernel: [497765.070533] usb 2-1.4.3: new high-speed USB device number 24 using ehci_hcd
Feb 25 15:35:06 joker kernel: [497765.157674] usb 2-1.4.3: New USB device found, idVendor=152d, idProduct=2336
Feb 25 15:35:06 joker kernel: [497765.157680] usb 2-1.4.3: New USB device strings: Mfr=1, Product=2, SerialNumber=5
Feb 25 15:35:06 joker kernel: [497765.157684] usb 2-1.4.3: Product: JM20336 SATA, USB Combo
Feb 25 15:35:06 joker kernel: [497765.157686] usb 2-1.4.3: Manufacturer: JMicron
Feb 25 15:35:06 joker kernel: [497765.157689] usb 2-1.4.3: SerialNumber: 610888888888
Feb 25 15:35:06 joker kernel: [497765.160664] scsi17 : usb-storage 2-1.4.3:1.0
Feb 25 15:35:06 joker mtp-probe: checking bus 2, device 24: "/sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4/2-1.4.3"
Feb 25 15:35:06 joker mtp-probe: bus: 2, device: 24 was not an MTP device
Feb 25 15:35:07 joker kernel: [497766.162659] scsi 17:0:0:0: Direct-Access     ST975042 0AS                   PQ: 0 ANSI: 2 CCS
Feb 25 15:35:07 joker kernel: [497766.170119] sd 17:0:0:0: Attached scsi generic sg2 type 0
Feb 25 15:35:07 joker kernel: [497766.173958] sd 17:0:0:0: [sdb] 1465149168 512-byte logical blocks: (750 GB/698 GiB)
Feb 25 15:35:07 joker kernel: [497766.175334] sd 17:0:0:0: [sdb] Write Protect is off
Feb 25 15:35:07 joker kernel: [497766.176453] sd 17:0:0:0: [sdb] Asking for cache data failed
Feb 25 15:35:07 joker kernel: [497766.176457] sd 17:0:0:0: [sdb] Assuming drive cache: write through
Feb 25 15:35:07 joker kernel: [497766.181695] sd 17:0:0:0: [sdb] Asking for cache data failed
Feb 25 15:35:07 joker kernel: [497766.181699] sd 17:0:0:0: [sdb] Assuming drive cache: write through
Feb 25 15:35:07 joker kernel: [497766.231354]  sdb: unknown partition table
Feb 25 15:35:07 joker kernel: [497766.235661] sd 17:0:0:0: [sdb] Asking for cache data failed
Feb 25 15:35:07 joker kernel: [497766.235666] sd 17:0:0:0: [sdb] Assuming drive cache: write through
Feb 25 15:35:07 joker kernel: [497766.235675] sd 17:0:0:0: [sdb] Attached SCSI disk
Feb 25 15:35:07 joker ata_id[22262]: HDIO_GET_IDENTITY failed for '/dev/sdb': Invalid argument
Feb 25 15:35:45 joker kernel: [497804.297430] usb 2-1.4.3: reset high-speed USB device number 24 using ehci_hcd
Feb 25 15:35:49 joker kernel: [497808.414877] usb 2-1.4.3: reset high-speed USB device number 24 using ehci_hcd
Feb 25 15:35:58 joker kernel: [497817.768613] usb 2-1.4.3: USB disconnect, device number 24
Feb 25 15:35:58 joker kernel: [497817.774665] sd 17:0:0:0: [sdb] Unhandled error code
Feb 25 15:35:58 joker kernel: [497817.774670] sd 17:0:0:0: [sdb]  Result: hostbyte=DID_NO_CONNECT driverbyte=DRIVER_OK
Feb 25 15:35:58 joker kernel: [497817.774675] sd 17:0:0:0: [sdb] CDB: Read(10): 28 00 00 00 00 00 00 00 20 00
Feb 25 15:35:58 joker kernel: [497817.774689] end_request: I/O error, dev sdb, sector 0
Feb 25 15:35:58 joker kernel: [497817.774694] Buffer I/O error on device sdb, logical block 0
Feb 25 15:35:58 joker kernel: [497817.774715] Buffer I/O error on device sdb, logical block 1
Feb 25 15:35:58 joker kernel: [497817.774727] Buffer I/O error on device sdb, logical block 2
Feb 25 15:35:58 joker kernel: [497817.774739] Buffer I/O error on device sdb, logical block 3
Feb 25 15:36:00 joker kernel: [497819.538691] usb 2-1.4.3: new high-speed USB device number 25 using ehci_hcd
Feb 25 15:36:00 joker kernel: [497819.625716] usb 2-1.4.3: New USB device found, idVendor=152d, idProduct=2336
Feb 25 15:36:00 joker kernel: [497819.625722] usb 2-1.4.3: New USB device strings: Mfr=1, Product=2, SerialNumber=5
Feb 25 15:36:00 joker kernel: [497819.625726] usb 2-1.4.3: Product: JM20336 SATA, USB Combo
Feb 25 15:36:00 joker kernel: [497819.625728] usb 2-1.4.3: Manufacturer: JMicron
Feb 25 15:36:00 joker kernel: [497819.625731] usb 2-1.4.3: SerialNumber: 610888888888
Feb 25 15:36:00 joker kernel: [497819.629436] scsi18 : usb-storage 2-1.4.3:1.0
Feb 25 15:36:00 joker mtp-probe: checking bus 2, device 25: "/sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4/2-1.4.3"
Feb 25 15:36:00 joker mtp-probe: bus: 2, device: 25 was not an MTP device
Feb 25 15:36:01 joker kernel: [497820.631045] scsi 18:0:0:0: Direct-Access     ST975042 0AS                   PQ: 0 ANSI: 2 CCS
Feb 25 15:36:01 joker kernel: [497820.640745] sd 18:0:0:0: [sdb] 1465149168 512-byte logical blocks: (750 GB/698 GiB)
Feb 25 15:36:01 joker kernel: [497820.641089] sd 18:0:0:0: Attached scsi generic sg2 type 0
Feb 25 15:36:01 joker kernel: [497820.641891] sd 18:0:0:0: [sdb] Write Protect is off
Feb 25 15:36:01 joker kernel: [497820.643111] sd 18:0:0:0: [sdb] Asking for cache data failed
Feb 25 15:36:01 joker kernel: [497820.643114] sd 18:0:0:0: [sdb] Assuming drive cache: write through
Feb 25 15:36:01 joker kernel: [497820.648988] sd 18:0:0:0: [sdb] Asking for cache data failed
Feb 25 15:36:01 joker kernel: [497820.648993] sd 18:0:0:0: [sdb] Assuming drive cache: write through
Feb 25 15:36:01 joker kernel: [497820.697633]  sdb: unknown partition table
Feb 25 15:36:01 joker kernel: [497820.702288] sd 18:0:0:0: [sdb] Asking for cache data failed
Feb 25 15:36:01 joker kernel: [497820.702292] sd 18:0:0:0: [sdb] Assuming drive cache: write through
Feb 25 15:36:01 joker kernel: [497820.702299] sd 18:0:0:0: [sdb] Attached SCSI disk
Feb 25 15:36:01 joker ata_id[22635]: HDIO_GET_IDENTITY failed for '/dev/sdb': Invalid argument
Feb 25 15:36:21 joker kernel: [497839.970734] sd 18:0:0:0: [sdb] Asking for cache data failed
Feb 25 15:36:21 joker kernel: [497839.970739] sd 18:0:0:0: [sdb] Assuming drive cache: write through
Feb 25 15:36:21 joker kernel: [497840.013475]  sdb: sdb1
Feb 25 15:36:21 joker ata_id[22858]: HDIO_GET_IDENTITY failed for '/dev/sdb': Invalid argument
Feb 25 15:36:21 joker ata_id[22868]: HDIO_GET_IDENTITY failed for '/dev/sdb': Invalid argument
Comment 13 George R. Goffe 2012-03-03 03:28:17 UTC 
Eric,

I took that drive back because it was reporting numerous I/O errors (/var/log/messages).

Now, the new replacement drive is having problems. It survived a 3 day long "mke2fs -c -c -j" but when I started using the drive it started having problems.

Here's the latest spontaneous failure messages. The drive is gone from the bus(?) now. Sigh...

What would you recommend?

Regards,

George...


  28463 Mar  2 19:19:59 joker dbus-daemon[997]: ** (upowerd:1666): WARNING **: Property get or set does not have an interface string as first arg
  28464 Mar  2 19:20:29 joker dbus-daemon[997]: ** (upowerd:1666): WARNING **: Property get or set does not have an interface string as first arg
  28465 Mar  2 19:20:29 joker dbus-daemon[997]: ** (upowerd:1666): WARNING **: Property get or set does not have an interface string as first arg
  28466 Mar  2 19:20:37 joker kernel: [20738.447318] usb 2-1.3.1: reset high-speed USB device number 6 using ehci_hcd
  28467 Mar  2 19:20:38 joker kernel: [20738.533343] usb 2-1.3.1: device descriptor read/64, error -71
  28468 Mar  2 19:20:38 joker kernel: [20738.720124] usb 2-1.3.1: device descriptor read/64, error -71
  28469 Mar  2 19:20:38 joker kernel: [20738.893831] usb 2-1.3.1: reset high-speed USB device number 6 using ehci_hcd
  28470 Mar  2 19:20:38 joker kernel: [20738.979717] usb 2-1.3.1: device descriptor read/64, error -71
  28471 Mar  2 19:20:38 joker kernel: [20739.166518] usb 2-1.3.1: device descriptor read/64, error -71
  28472 Mar  2 19:20:38 joker kernel: [20739.340475] usb 2-1.3.1: reset high-speed USB device number 6 using ehci_hcd
  28473 Mar  2 19:20:39 joker kernel: [20739.749548] usb 2-1.3.1: device not accepting address 6, error -71
  28474 Mar  2 19:20:39 joker kernel: [20739.822937] usb 2-1.3.1: reset high-speed USB device number 6 using ehci_hcd
  28475 Mar  2 19:20:39 joker kernel: [20740.232045] usb 2-1.3.1: device not accepting address 6, error -71
  28476 Mar  2 19:20:39 joker kernel: [20740.233117] sd 6:0:0:0: Device offlined - not ready after error recovery
  28477 Mar  2 19:20:39 joker kernel: [20740.233139] sd 6:0:0:0: [sdb] Unhandled error code
  28478 Mar  2 19:20:39 joker kernel: [20740.233142] sd 6:0:0:0: [sdb]  Result: hostbyte=DID_ABORT driverbyte=DRIVER_OK
  28479 Mar  2 19:20:39 joker kernel: [20740.233147] sd 6:0:0:0: [sdb] CDB: Write(10): 2a 00 2b 85 8f f8 00 00 a0 00
  28480 Mar  2 19:20:39 joker kernel: [20740.233160] end_request: I/O error, dev sdb, sector 730173432
  28481 Mar  2 19:20:39 joker kernel: [20740.233292] usb 2-1.3.1: USB disconnect, device number 6
  28482 Mar  2 19:20:39 joker kernel: [20740.233587] Aborting journal on device sdb1-8.
  28483 Mar  2 19:20:39 joker kernel: [20740.233608] EXT4-fs error (device sdb1) in ext4_create:1766: IO failure
  28484 Mar  2 19:20:39 joker kernel: [20740.233643] sd 6:0:0:0: rejecting I/O to offline device
  28485 Mar  2 19:20:39 joker kernel: [20740.233683] JBD2: I/O error detected when updating journal superblock for sdb1-8.
  28486 Mar  2 19:20:39 joker kernel: [20740.296713] EXT4-fs (sdb1): previous I/O error to superblock detected
  28487 Mar  2 19:20:39 joker kernel: [20740.297379] EXT4-fs error (device sdb1): ext4_journal_start_sb:327: Detected aborted journal
  28488 Mar  2 19:20:39 joker kernel: [20740.297386] EXT4-fs (sdb1): Remounting filesystem read-only
  28489 Mar  2 19:20:39 joker kernel: [20740.297389] EXT4-fs (sdb1): previous I/O error to superblock detected
  28490 Mar  2 19:20:59 joker dbus-daemon[997]: ** (upowerd:1666): WARNING **: Property get or set does not have an interface string as first arg
  28491 Mar  2 19:20:59 joker dbus-daemon[997]: ** (upowerd:1666): WARNING **: Property get or set does not have an interface string as first arg
  28492 Mar  2 19:21:18 joker kernel: [20778.651228] EXT4-fs (sdb1): previous I/O error to superblock detected
  28493 Mar  2 19:21:18 joker kernel: [20778.651562] EXT4-fs error (device sdb1): ext4_put_super:818: Couldn't clean up the journal
  28494 Mar  2 19:21:18 joker kernel: [20778.949716] usb 2-1.3.1: new high-speed USB device number 9 using ehci_hcd
  28495 Mar  2 19:21:18 joker kernel: [20779.034618] usb 2-1.3.1: device descriptor read/64, error -71
  28496 Mar  2 19:21:18 joker kernel: [20779.220412] usb 2-1.3.1: device descriptor read/64, error -71
  28497 Mar  2 19:21:18 joker kernel: [20779.394232] usb 2-1.3.1: new high-speed USB device number 10 using ehci_hcd
  28498 Mar  2 19:21:19 joker kernel: [20779.479135] usb 2-1.3.1: device descriptor read/64, error -71
  28499 Mar  2 19:21:19 joker kernel: [20779.664922] usb 2-1.3.1: device descriptor read/64, error -71
  28500 Mar  2 19:21:19 joker kernel: [20779.838769] usb 2-1.3.1: new high-speed USB device number 11 using ehci_hcd
  28501 Mar  2 19:21:19 joker kernel: [20780.248066] usb 2-1.3.1: device not accepting address 11, error -71
  28502 Mar  2 19:21:19 joker kernel: [20780.321205] usb 2-1.3.1: new high-speed USB device number 12 using ehci_hcd
  28503 Mar  2 19:21:20 joker kernel: [20780.730649] usb 2-1.3.1: device not accepting address 12, error -71
  28504 Mar  2 19:21:20 joker kernel: [20780.730906] hub 2-1.3:1.0: unable to enumerate USB device on port 1
  28505 Mar  2 19:21:29 joker dbus-daemon[997]: ** (upowerd:1666): WARNING **: Property get or set does not have an interface string as first arg
  28506 Mar  2 19:21:29 joker dbus-daemon[997]: ** (upowerd:1666): WARNING **: Property get or set does not have an interface string as first arg
  28507 Mar  2 19:21:59 joker dbus-daemon[997]: ** (upowerd:1666): WARNING **: Property get or set does not have an interface string as first arg
Comment 14 Dave Jones 2012-10-23 15:40:52 UTC 
# Mass update to all open bugs.

Kernel 3.6.2-1.fc16 has just been pushed to updates.
This update is a significant rebase from the previous version.

Please retest with this kernel, and let us know if your problem has been fixed.

In the event that you have upgraded to a newer release and the bug you reported
is still present, please change the version field to the newest release you have
encountered the issue with.  Before doing so, please ensure you are testing the
latest kernel update in that release and attach any new and relevant information
you may have gathered.

If you are not the original bug reporter and you still experience this bug,
please file a new report, as it is possible that you may be seeing a
different problem. 
(Please don't clone this bug, a fresh bug referencing this bug in the comment is sufficient).
Comment 15 Justin M. Forbes 2012-11-14 17:04:37 UTC 
With no response, we are closing this bug under the assumption that it is no longer an issue. If you still experience this bug, please feel free to reopen the bug report.