0

I had an external hard drive that I mounted internally. It came formatted with NTFS, and I wanted to move to ext4. So I copied everything I wanted to keep onto other drives, created a brand new partition table (GPT) with a single ext4 partition, and now I'm trying to copy everything back. I'm using rsync -a --info=progress2 for most of the copy operations.

My problem is that after 100 GB or so, I tend to get weird errors:

rsync: write failed on "somepath": Read-only file system (30)
rsync error: error in file IO (code 11) at receiver.c(389) [receiver=3.1.0]

If I try to list the directory that rsync was working on when it failed, I see weird results:

drwx------  3 pdaddy pdaddy 4096 Aug 28 2011 subdirectory1
drwx------  3 pdaddy pdaddy 4096 Mar 12 2014 subdirectory2
d?????????  ? ?      ?         ?           ? subdirectory3
d?????????  ? ?      ?         ?           ? subdirectory4

Trying to list the directories with question marks in their listings, and even some of them without, gives me:

ls: reading directory subdirectory3: Input/output error
total 0

Even fdisk has errors:

~ % fdisk /dev/sde   
fdisk: unable to read /dev/sde: Input/output error

If I try to unmount the drive, the umount command hangs. I ran htop and saw that umount was using 100% of one CPU core. I assumed it was committing journals or some such, so I let it go all night once, but it was in the same state in the morning. Issuing sudo reboot or sudo init 6 while umount is hung results in yet another hung terminal. I have to hold the power button. Just now I tried rebooting without explicitly unmounting, and it hung with a black screen (the monitor went to sleep), and no response via ssh or the keyboard.

After a hard power cycle, I unmounted the disk and did sudo fsck.ext4 -f /dev/sde1, and there were no errors. I checked the files, and they seemed to all be there and a sample of them were correct.

I assumed the errors had something to do with the journal being too large (maybe it's limited to a maximum size?), so I remounted with -o data=writeback. I figured it's a good idea anyway to mount this way temporarily while restoring terabytes worth of files.

This helped to marginally speed the copy, but did not help with the errors. Twice more, I've gotten into the same state. A hard power cycle is the only thing I can do, and afterward, a disk check shows no errors, the files seem okay, and I can copy another 100 GB or so.

What's going on? I think the disk itself is healthy. I had no problems with it before reformatting. Should I do a sector scan on the disk? It's 5 TB, so I'm hesitant to do that.


I've restored some more files, watching the kernel logs, as suggested by Stephen Kitt. Before rsync failed, I started seeing some funky errors:

[ 8807.572286] ata4.00: exception Emask 0x0 SAct 0x7fffffff SErr 0x0 action 0x6 frozen
[ 8807.572290] ata4.00: failed command: WRITE FPDMA QUEUED
[ 8807.572293] ata4.00: cmd 61/40:00:c0:57:b6/05:00:b7:00:00/40 tag 0 ncq 688128 out
[ 8807.572293]          res 40/00:00:00:4f:c2/00:00:00:00:00/40 Emask 0x4 (timeout)
[ 8807.572295] ata4.00: status: { DRDY }

The last three messages repeat many times, then I get:

[ 8807.572412] ata4: hard resetting link
[ 8808.060464] ata4: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[ 8808.062462] ata4.00: configured for UDMA/133
[ 8808.076459] ata4.00: device reported invalid CHS sector 0

The last message repeats 20 times or so, and then I get:

[ 8808.076526] ata4: EH complete

47 seconds later, the sequence repeats itself. And again 81 seconds after that, and 120 seconds after that, except this time, it starts with:

[ 9160.779935] ata4.00: NCQ disabled due to excessive errors

The next time, it's different. It starts the same, but then I see:

[ 9235.819291] ata4: hard resetting link
[ 9241.181501] ata4: link is slow to respond, please be patient (ready=0)
[ 9245.839449] ata4: COMRESET failed (errno=-16)

This repeats a couple of times, and then:

[ 9290.922301] ata4: limiting SATA link speed to 1.5 Gbps
[ 9290.922303] ata4: hard resetting link
[ 9295.948393] ata4: COMRESET failed (errno=-16)
[ 9295.948400] ata4: reset failed, giving up
[ 9295.948401] ata4.00: disabled

There are some new errors:

[ 9295.948522] sd 3:0:0:0: [sdf] FAILED Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK
[ 9295.948524] sd 3:0:0:0: [sdf] CDB: 
[ 9295.948525] Write(16): 8a 00 00 00 00 00 b9 0c fd 00 00 00 40 00 00 00
[ 9295.948538] blk_update_request: I/O error, dev sdf, sector 3104636160
[ 9295.948542] EXT4-fs warning (device sdf1): ext4_end_bio:317: I/O error -5 writing to inode 49807774 (offset 155189248 size 4194304 starting block 388079688)
[ 9295.948543] Buffer I/O error on device sdf1, logical block 388079264

(Note that I've shuffled some drives since I started this post, and this drive is now sdf instead of sde.)

This last error repeats several times with different logical blocks, and then I get this an equal number of times:

[ 9295.948585] EXT4-fs warning (device sdf1): ext4_end_bio:317: I/O error -5 writing to inode 49807774 (offset 155189248 size 4194304 starting block 388079856)

There's more of the same, and all the while the copy is still going on without complaining. Finally I get:

[ 9295.950321] Aborting journal on device sdf1-8.
[ 9295.950345] Buffer I/O error on dev sdf1, logical block 610304000, lost sync page write
[ 9295.950361] EXT4-fs (sdf1): Delayed block allocation failed for inode 49807775 at logical offset 0 with max blocks 1024 with error 30
[ 9295.950362] Buffer I/O error on dev sdf1, logical block 0, lost sync page write
[ 9295.950365] EXT4-fs (sdf1): This should not happen!! Data will be lost
[ 9295.950365] 
[ 9295.950366] EXT4-fs error (device sdf1) in ext4_writepages:2421: Journal has aborted
[ 9295.950368] EXT4-fs error (device sdf1): ext4_journal_check_start:56: Detected aborted journal
[ 9295.950370] JBD2: Error -5 detected when updating journal superblock for sdf1-8.
[ 9295.950371] EXT4-fs (sdf1): Remounting filesystem read-only
[ 9295.950372] EXT4-fs (sdf1): previous I/O error to superblock detected
[ 9295.950379] Buffer I/O error on dev sdf1, logical block 0, lost sync page write
[ 9295.950394] Buffer I/O error on dev sdf1, logical block 0, lost sync page write
[ 9326.009002] scsi_io_completion: 10 callbacks suppressed
[ 9326.009007] sd 3:0:0:0: [sdf] FAILED Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK
[ 9326.009009] sd 3:0:0:0: [sdf] CDB: 
[ 9326.009011] Write(16): 8a 00 00 00 00 00 00 00 0f b8 00 00 00 08 00 00
[ 9326.009018] blk_update_request: 10 callbacks suppressed
[ 9326.009020] blk_update_request: I/O error, dev sdf, sector 4024
[ 9326.009023] Buffer I/O error on dev sdf1, logical block 247, lost async page write

(Note that this time I did not unmount and remount with data=writeback, so it was doing its default journaling.)

After this, the rsync failed, presumably because the file system was remounted read-only.

I'm sorry for the log dump. I've tried to pare it down to the essentials, but I'm afraid I'm not familiar enough with what's going on here to pare it down any further.

  • Going on a whim here but if the number of files that you are copying via rsync is very high, your disk may be having hard time catching up to the write requests. Is it possible for you to divide up the files in to smaller chunks and run several rsync commands, one after finishing another ? Maybe per directory or subdirectory level ? – MelBurslan Mar 31 '16 at 13:41
  • are there filesystems mounted under the mountpoint of /dev/sde1 that are read-only? cd-rom, /proc, etc? – Jeff Schaller Mar 31 '16 at 13:50
  • @MelBurslan: Is the state of Linux's buffered I/O really so bad that one can overflow the buffers that easily and cause such a catastrophic failure like this? – P Daddy Mar 31 '16 at 14:45
  • @JeffSchaller: No, this disk is mounted in a directory beneath the root, and nothing else is mounted inside of it. – P Daddy Mar 31 '16 at 14:46
  • @PDaddy I'm not sure where Mel got his theory, but there's no reason for slow drives to cause failures. Does dmesg show any drive errors? – Stephen Kitt Mar 31 '16 at 15:06
2

This looks like a hardware issue, rather than a kernel bug. You can try the following:

  • re-seat the SATA cable
  • use another SATA cable
  • run SMART diagnostics (the self-tests, see smartmontools)
  • run a destructive badblocks scan

If you have a spare drive or computer you could also try switching (use another drive in the same computer, use the troublesome drive in another computer) to check whether the motherboard's at fault. Since the drive seems to have issues under load a simple dd if=/dev/zero of=... with appropriate size parameters might be enough to reproduce the errors.

I'm not sure if your drive's warranty would apply since it was originally an external drive...

  • Thanks, I'll look into hardware issues. You're right that I was able to reproduce the problem by dding /dev/zero to the drive. I got 32 GB written before it failed the same way. I ran smartctl -a beforehand, and Raw_Read_Error_Rate, Spin_Up_Time, Reallocated_Sector_Ct, Seek_Error_Rate, and Spin_Retry_Count were all in pre-fail state. I'm going to try to see if power might be an issue, since I have 4 internal and 2 external drives and this computer has a modest power supply at best, and this drive, being 3.5" and probably having multiple platters, is likely quite electron thirsty. – P Daddy Mar 31 '16 at 19:14
  • Preliminary results look like power is indeed the issue. Thanks for pointing me down this path. I'm going to mess with it some more over the next couple of days, and I will likely come back and accept your answer. – P Daddy Mar 31 '16 at 20:35
  • To reduce power draw, I eliminated the two external drives and one internal one. I don't have an alternate power source right now. My initial tests with /dev/zero looked positive, but after resuming file restoration, I began seeing errors again. I'm still tracking down the issue with the drive (I'm convinced it's an issue with the drive now). – P Daddy Mar 31 '16 at 23:36
  • I'd actually be surprised if it was power – spinning drives take most power when the spin up, not when they're running, so systems with power issues generally show problems at boot up; once it's spinning, it takes very little extra power for a drive to write data and the power requirement doesn't increase with the amount of data to be written. Of course hardware is always surprising (when you're familiar with software ;-) so you can't assume it's not power-related, but it's more likely to be something else. – Stephen Kitt Apr 1 '16 at 7:06
  • Well, you're right. Power adjustments haven't fixed it, and unfortunately, neither has relocation (different data and power cables, different SATA port, different bay with potentially different cooling characteristics). I successfully wrote 75,000 small files (~5 MB), but failed three minutes into trying to write a large file (~35 GB). That seems to be the trigger, I think, larger files. I have no idea why that would be. – P Daddy Apr 1 '16 at 7:14

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.