Home lab & data vault

Explore

Data recovery stories

Data loss/corruption of CnMemory archive

Date 2021-07-16

System spec

The

filer⁠

is a kvm acting as a NAS data vault (

Debian⁠

omv⁠

) using XFS formatted virtual volumes for storage. Those storage partitions are merged into a single FUSE’ed hierarchy via

mergerfs⁠

with a category.create: lus policy. lus stands for least used, so writes happen on the partition (branch) with the least used space.

snapraid⁠

is used to maintain a triple parity of the store volumes.

CnMemory was an archive taken of portal USB drive.

The event

During an rsync of data between disks store4 > store4-backup (~2.7TiB), rsync logged an input/output error for file CnMemory-USB.tar.gz.aa.

The archive total size is 166GiB containing 53,072 file/dirs, and split into 1GiB chunks to distribute the data across multiple disks avoiding uneven disk fill levels (see system spec for more info).

rsync: read errors mapping "/srv/dev-disk-by-label-store4/!backups/.../CnMemory-USB-compressed/CnMemory-USB.tar.gz.aa": Input/output error (5)

WARNING: !backups/.../CnMemory-USB-compressed/CnMemory-USB.tar.gz.aa failed verification -- update discarded (will try again).

rsync: read errors mapping "/srv/dev-disk-by-label-store4/!backups/.../CnMemory-USB-compressed/CnMemory-USB.tar.gz.aa": Input/output error (5)

ERROR: !backups/.../CnMemory-USB-compressed/CnMemory-USB.tar.gz.aa failed verification -- update discarded.

rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1207) [sender=3.1.3]

Closer inspection determined that one 4k block was not readable in CnMemory-USB.tar.gz.aa.

4k is the bsize=4096 of the underlying XFS filesystem, verified with xfs_info.

Using dd to read the file in 512 blocks (sectors), the error was found to start at file block 4544 and ended at 4552. The eight 512 sectors would failed to read with dd (one 4k filesystem block).

With this info it was possible to read the file and skip the bad 4k block, writing two parts to another disk to be concatenated later.

Corrupt file file info based on 512 sector/block size:

CnMemory-USB.tar.gz.aa bad blocks:

sector byte kib mib

start 4544 2326528 2272 2.2

end 4552 2330624 2276 2.2

delta 8 4096 4

time dd conv=noerror bs=512 count=4544 status=progress iflag=direct if=CnMemory-USB.tar.gz.aa oflag=direct of=/srv/dev-disk-by-label-store5/\!backups/.../CnMemory-USB-compressed/CnMemory-USB.tar.gz.aa.dd-part1

time dd conv=noerror bs=2276k skip=1 status=progress iflag=direct if=CnMemory-USB.tar.gz.aa oflag=direct of=/srv/dev-disk-by-label-store5/\!backups/.../CnMemory-USB-compressed/CnMemory-USB.tar.gz.aa.dd-part2

in hindsight, the final output might of been easier using conv=noerror to skip the read errors:

time dd conv=noerror bs=4k status=progress iflag=direct if=CnMemory-USB.tar.gz.aa oflag=direct of=/srv/dev-disk-by-label-store5/\!backups/.../CnMemory-USB-compressed/recovery/CnMemory-USB.tar.gz.aa.recovery

⁉ question: with this approach, what is written for the unreadable 4k block? I would guess nothing or zero bytes. Something to consider checking next time.

I was successful in using the gzrecover util to recover the tar archive.

One expects at least 4k damage to one or more files because of the 4k hole in the gzip compression stream. At that moment I was under the impression I did not have backup/parity of this file (excluded from snapraid). It was an interesting experiment to see what was possible.

I combined the parts from the dd commands in the relevant dir and moved the corrupt file out of the way, the idea being the byte stream would be complete aside from the 4k hole:

pv *.tar.gz* | gzrecover -v -o /mnt/store4-backup/\!backups/.../CnMemory-USB-compressed/CnMemory-USB.tar.gz.aa.recovery

with tar option --ignore-zeros I was then able to skip the tar error(s) and extract the files:

pv /mnt/store4-backup/\!backups/.../CnMemory-USB-compressed/CnMemory-USB.tar.gz.recovery | tar vxf - --ignore-zeros

All the file/dirs appeared to be present.

Currently a recursive checksum file does not exist for the full archive content, so it was not possible at that moment to see which file(s) were corrupt.

TODO: extract archive and make a recursive checksum for the files. Given I know the exact byte offset of the missing 4k block, I could even reproduce the scenario to see what file inside the archive would of been corrupt.

smartd alerts

Fri, 16 Jul, 02:41 CEST the following warning/error was logged and alerted by the smartd daemon on the hypervisor:

Device: /dev/sdl [SAT], 8 Currently unreadable (pending) sectors

Device: /dev/sdl [SAT], 8 Offline uncorrectable sectors

Device: /dev/sdl [SAT], ATA error count increased from 0 to 3

Device info:

ST5000LM000-2AN170, S/N:WCJ_____, WWN:5-000c50-0aa2ba9ee, FW:0001, 5.00 TB

Examining smart details for this device revealed there had been a number of UNCorrectable errors logged.

link:

useful reading on UNC errors⁠

root@viper:~# smartctl --all /dev/disk/by-id/ata-ST5000LM000-2AN170_WCJ_____ | less

Error: UNC at LBA = 0x0fffffff = 268435455

Note that the number of pending sectors 8 in the alert matched the number of 512 sectors in the file that could not be read. Probably not a coincidence.

snapraid parity to the rescue

The corrupt file was fortunately included in snapraid parity (initially I believed it was excluded) and it was possible to use snapraid to fully recover the file.

snapraid --log ">>/var/log/snapraid/snapraid-manualrun-%D-%T-fix.log" fix -f '/!backups/.../CnMemory-USB-compressed/CnMemory-USB.tar.gz.aa'

Afterwards I performed a full data extraction without errors and created a file list to provide to the archive data owner, in hindsight I should of made a recursive checksum file list at the same time. 😲😊

health checks on the disk

First of all I rsynced all data from store4 to a new disk, there were no errors logged, and followed the procedure to replace store4 disk in the snapraid array. This included verifying all the files bytes copied to the new disk matched the snapraid checksums.

Once the disk was out, I ran the short and long SMART self tests. These tests were clean and the errors logged by smartd were not committed to the “SMART Attributes Data Structure”.

⚠ This is actually a curious point, it seems like smartd is reading an online/live set of attributes, and smartctl is reading stored/committed set of attributes? Here are the corresponding attributes per the email alerts after the self tests:

ID# ATTRIBUTE_NAME FLAG VALUE WORST THRESH TYPE UPDATED RAW_VALUE

197 Current_Pending_Sector 0x0012 100 100 000 Old_age Always 0

198 Offline_Uncorrectable 0x0010 100 100 000 Old_age Offline 0

(omitted WHEN_FAILED column for readability)

Here we can see that the value, worst, thresh look nominal, and don’t reflect the email alerts, even after short and long self tests.

a normalized value, which ranges from 1 to 253 (with 1 representing the worst case and 253 representing the best) and a worst value, which represents the lowest recorded normalized value. The initial default value of attributes is 100 but can vary between manufacturer.

cite:

S.M.A.R.T attributes⁠

Two more attributes to study, the Reported_Uncorrect doesn’t look so good:

ID# ATTRIBUTE_NAME FLAG VALUE WORST THRESH TYPE UPDATED RAW_VALUE

187 Reported_Uncorrect 0x0032 001 001 000 Old_age Always 120

195 Hardware_ECC_Recovered 0x001a 077 064 000 Old_age Always 45615178

Observation ATA Error Count was equal to 120, I’m assuming that is a correlation to the Reported_Uncorrect.

Hypothesis on the raw value 120 and ATA Error Count: I was trying different ways to diagnose and read the file with the error, producing more errors as a result.

To cite a 3rd party,

BackBlaze⁠

blog on SMART stats in this case:

SMART 187: Reported_Uncorrect:

Backblaze uses this one. Number 187 reports the number of reads that could not be corrected using hardware ECC. Drives with zero uncorrectable errors hardly ever fail. This is one of the SMART stats we use to determine hard drive failure; once SMART 187 goes above zero, we schedule the drive for replacement.

This first chart shows the failure rates by number of errors. Because this is one of the attributes we use to decide whether a drive has failed, there has to be a strong correlation:

⁠
⁠
⁠

Backblaze replace disks that have a non zero for 187 Reported_Uncorrect which is the action I took. However I’m still really curious about this disk real health status because once I fixed the file and did a full bytes rsync of the disk content the disk seemed fine and the long SMART self test was also fine...

As suggested in

this insightful reddit comment⁠

, I performed a ddrescue to check for issues, reading the full disk and writing to /dev/null and this ~14 hours of stress didn’t reveal anything:

root@viper:~# ddrescue -f /dev/disk/by-uuid/ef51ecbd-b57e-42c3-8e73-dc56fdab454b /dev/null /root/ef51ecbd-b57e-42c3-8e73-dc56fdab454b.ddrescue.log

GNU ddrescue 1.23

Press Ctrl-C to interrupt

ipos: 5000 GB, non-trimmed: 0 B, current rate: 12869 kB/s

opos: 5000 GB, non-scraped: 0 B, average rate: 103 MB/s

non-tried: 0 B, bad-sector: 0 B, error rate: 0 B/s

rescued: 5000 GB, bad areas: 0, run time: 13h 27m 34s

pct rescued: 100.00%, read errors: 0, remaining time: n/a

time since last successful read: n/a

Finished

root@viper:~# less /root/ef51ecbd-b57e-42c3-8e73-dc56fdab454b.ddrescue.log

I use dd to skip to the LBA with the reported UNC error and read the bytes:

Error 120 occurred at disk power-on lifetime: 25726 hours (1071 days + 22 hours)

When the command that caused the error occurred, the device was active or idle.

After command completion occurred, registers were:

ER ST SC SN CL CH DH

-- -- -- -- -- -- --

40 51 00 ff ff ff 0f Error: UNC at LBA = 0x0fffffff = 268435455

root@viper:~# dd iflag=direct oflag=nocache if=$device bs=512 skip=268435455 count=8 |stdbuf -o0 xxd | less

Note: The LBA 268435455 of 9767541168 is located at the start of the disk approx 2.7% of 100%

There were no issues, no new errors logged.

Next I wanted to test writing to the LBA with issues. i.e. overwriting the LBA with new data. Using dd I wrote a 4k block starting at the LBA reporting issues, and then checked the results were as expected:

root@viper:~# dd iflag=nocache oflag=direct status=progress if=/dev/zero of=$device bs=512 seek=268435455 count=8

8+0 records in

8+0 records out

4096 bytes (4.1 kB, 4.0 KiB) copied, 0.00267102 s, 1.5 MB/s

root@viper:~# dd iflag=direct oflag=nocache status=progress if=$device bs=512 skip=268435455 count=8 |stdbuf -o0 od | head

0000000 000000 000000 000000 000000 000000 000000 000000 000000

8+0 records in

8+0 records out

0010000

4096 bytes (4.1 kB, 4.0 KiB) copied, 0.00188757 s, 2.2 MB/s

Note: the od command writes * when it encounters repeated bytes, therefore its possible to pipe it to head to monitor that all bytes in the stream are zero. If more than the default 10 lines of output are received by head, the pipeline will be aborted.

More info⁠

I repeated the dd write a handful of times, no errors.

Next I wanted to stress write IO on the drive and check for any issues, I used dd to zero the drive. The dd block size was a calculated factor of the disks 9767541168 sectors close to 1MiB. I did this to ensure that the last block written is a full block. I’m not sure of the behaviour of dd if there is a remainder/partial write on the last block, if it really zeros every byte in that case? I would assume there could be trailing bytes left unzeroed.

⚠⚠⚠ WARNING / ACHTUNG: This is a destructive command and fills the provided $device with zeros.

root@viper:~# fdisk -l $device

Disk /dev/disk/by-id/ata-ST5000LM000-2AN170_WCJ_____: 4.6 TiB, 5000981078016 bytes, 9767541168 sectors

Disk model: ST5000LM000-2AN1

Units: sectors of 1 * 512 = 512 bytes

Sector size (logical/physical): 512 bytes / 4096 bytes

I/O size (minimum/optimal): 4096 bytes / 4096 bytes

root@viper:~# dd iflag=nocache oflag=direct status=progress if=/dev/zero of=$device bs=1064448

5000922533376 bytes (5.0 TB, 4.5 TiB) copied, 47318 s, 106 MB/s

dd: error writing '/dev/disk/by-id/ata-ST5000LM000-2AN170_WCXXXX32': No space left on device

4698193+0 records in

4698192+0 records out

5000981078016 bytes (5.0 TB, 4.5 TiB) copied, 47318.9 s, 106 MB/s

bs=1064448 * records=4698192 = bytes=5000981078016 which is equal with the device total bytes.

The No space left on device error is expected as I did not limit the dd on purpose.

checking the start and end of the disk, it has been zeroed:

root@viper:~# pv $device | stdbuf -o0 od | head

0000000 000000 000000 000000 000000 000000 000000 000000 000000

...

root@viper:~# tail -c 4096 $device | stdbuf -o0 od | head

0000000 000000 000000 000000 000000 000000 000000 000000 000000

System spec

The event

smartd alerts

snapraid parity to the rescue

health checks on the disk

conclusions

TODO’s

misc notes

useful reading / references

Want to print your doc?
This is not the way.

Try clicking the ⋯ next to your doc name or using a keyboard shortcut (

CtrlP

) instead.