Filesystem errors when restoring many files

Question

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.

Answer 1

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...