Friday 12 June 2020

Non-bootable Windows recovery (Part 5)

Context

This is the final post in a series dedicated to documenting a systematic approach of recovering a non-bootable Windows machine with Linux and open source tools. Make sure you read the first, second, third and fourth post to familiarize yourself with the context and previous activities.

A S.M.A.R.T. extended self test indicated one of the disks was failing, other hardware components seemed to be healthy.

The first 48 hours of data recovery were spent running ddrescue to read out as much disk area as possible, and ended up with 1081 unreadable kilobytes spread across 16 ranges of consecutive bad sectors. The filesystem was analyzed to identify the usage of the bad sector ranges, that is, the list of files and parts of filesystem metadata that could not be read. As the Master File Table of the NTFS partition was also damaged, information about file allocation on the bad blocks might have contained false negatives.

Priorities were set, calculated risks taken and four sector ranges, which did not seem to be used, were the largest and located towards the end of the partition were nuked with dd to force reallocation of the bad sectors. All calculations and steps involved were covered in detail. A bit more than three hours later the unreadable area reported by ddrescue decreased to around 68 kilobytes spread across 15 bad sector ranges. There was an additional finding: it was confirmed and demonstrated that the firmware of this Western Digital disk misreports Reallocated Sector Count and Reallocated_Event_Count, which raised serious concerns...

Next, a more sophisticated approach was taken to progress data recovery even further without overwriting any further sector of the failing disk. The goal was to focus only on those bad sector ranges, which are known to hold either files or MFT entries, which was done by manipulating the mapfile ddrescue created to track the state of the rescue process. After multiple runs of ddrescue totaling to around 38 hours and up to 700 retries of each bad sector, 5 bad areas remained, consisting of 8 bad sectors each.

Assessing the results achieved

Enough time was spent trying hard to resurrect data from bad sectors, and odds for further progress within the next days were negligible compared to the impact of service outage. The raw disk data read so far was backed up from the healthy drive to an image stored on the third drive, to have a snapshot to return to if subsequent action went wrong. No more attempt was taken to read from the failing disk.


[root@sysresccd ~]# ddrescue --ask --verbose --binary-prefixes /dev/sda4 /mnt/REPO/images/sda4-dd.img sda4-dd.map

Next came the well known steps of listing affected files and metadata based on the location of the remaining unrecoverable 5 instances of 8 sector ranges.


[root@sysresccd /mnt/REPO]# ddrescuelog --list-blocks=- disk-sdb-to-sda-priority.map | while read lba; do echo $(($lba - 1083392)); done >> bad-sectors-sdb4.txt
[root@sysresccd /mnt/REPO]# cat bad-sector-ranges-sdb4.txt 
3733376-3733383
9240544-9240551
9324120-9324127
10061520-10061527
16845920-16845927
[root@sysresccd /mnt/REPO]# cat affected-files-sdb4.txt 
Searching for sector range 3733376-3733383
Inode 112588 /ProgramData/Norton/{0C55C096-0F1D-4F28-AAA2-85EF591126E7}/NS_22.6.0.142/NCW/hlinks/ncwperfm.db.data/$DATA
* one inode found
Searching for sector range 9240544-9240551
Inode 248863 /Windows/ServiceProfiles/LocalService/AppData/Roaming/PeerNetworking/91e9854e5d4d7ac47cd0bf3ad8003817/922c235eb3d1d91e502cb02599cc24c7/grouping/edb02861.log/$DATA
* one inode found
Searching for sector range 9324120-9324127
Inode 96681 /$Extend/$UsnJrnl/$DATA($J)
* one inode found
Searching for sector range 10061520-10061527
Inode 0 /$MFT/$DATA
* one inode found
Searching for sector range 16845920-16845927
Inode 112588 /ProgramData/Norton/{0C55C096-0F1D-4F28-AAA2-85EF591126E7}/NS_22.6.0.142/NCW/hlinks/ncwperfm.db.data/$DATA
* one inode found

The results were interpreted as follows, along with potential next steps:

  • A database file most probably related to norton community watch, is damaged. Once Windows boots, norton community watch could be removed and reinstalled in worst case.
  • Another damaged file is probably a binary log file related to peer networking. Might need to delete folder and re-join home group or recreate the whole homegroup in case this was the machine that created the homegroup. This has to be done on-site.
  • Unfortunately, the bad sectors at both the user journal and the master file table remained. The next step was to work with the NTFS filesystem offline.

Looking into damaged NTFS

Knowing that the MFT is redundantly stored on NTFS, a dry run of ntfsfix was executed. The industry best practice had long been to leave checking NTFS volumes to Microsoft tools or commencial recovery software. A dry run was meant as a quick sanity check and it did not report any issue.


[root@sysresccd /mnt/REPO]# ntfsfix --no-action /dev/sda4
Mounting volume... OK
Processing of $MFT and $MFTMirr completed successfully.
Checking the alternate boot sector... OK
NTFS volume version is 3.1.
NTFS partition /dev/sda4 was processed successfully.

Next, testdisk was used to extract the two damaged files just in case they would be needed later. During this process, there was no sign of filesystem inconsistency.


[root@sysresccd /mnt/REPO]# testdisk /log /dev/sda
TestDisk 7.1, Data Recovery Utility, July 2019
Christophe GRENIER <grenier@cgsecurity.org>
https://www.cgsecurity.org
### backup corrupted files via testdisk
[root@sysresccd /mnt/REPO/files]# find . -type f
./Windows/ServiceProfiles/LocalService/AppData/Roaming/PeerNetworking/91e9854e5d4d7ac47cd0bf3ad8003817/922c235eb3d1d91e502cb02599cc24c7/grouping/edb02861.log
./ProgramData/Norton/{0C55C096-0F1D-4F28-AAA2-85EF591126E7}/NS_22.6.0.142/NCW/hlinks/ncwperfm.db.data

The SystemRescueCD session was running for 4 days without a reboot, and now the time has come to save all logs and intermediate files from the recovery session, shut down, remove the faulty disk and boot into Windows. The system greeted me with a message that it would continue installing fixes. Some time and a few reboots later I could log in, and performed a quick filesystem check. The system reported no errors, however I forced an offline filesystem check, which did find issues to repair. Once rebooted and logged in again, another filesystem check was made, and no errors were reported.

Next, SFC and DISM were run, but covering these built-in Windows tools is outside of the scope of this blog. fortunately, both tools reported there was nothing to fix.

Outside of business hours, the machine was transported back to the medical point and a quick sanity check was run to confirm the whole environment including networking, homegroup, file sharing and medical software were working. No further steps were required on this machine, but an extended self-test was scheduled for all disks of all the other machines.

Wrapping up

The points below capture my recommendation on solving problems of this kind.

  1. Understand circumstances such as time and resource constraints and the consequences of full or partial failure.
  2. Think, read up and learn. Develop a deep understanding of your possibilities before you execute actions.
  3. Do not panic, it does not help. Assess the stituation, evaluate options then take the best available alternative. Observe the results, adapt and start over again.
  4. Take as few assumption with as low risk as possible, and document them!
  5. Optimize for efficiency: prioritize targets and harvest as much result with low risk action as you can, then proceed to lower value targets or higher risk actions.
  6. Optimize for time: plan long running non-interactive tasks and set up sleep schedule accordingly. Understand the risk of shortcuts.

Happy end. No medical or business critical data was lost, computer fully recovered and business restored after a few days. As a bonus, an unexpected hard drive firmware issue was found and documented.

Remember that each real-life situation is somewhat different, so your milage may vary. The steps taken and shared here have worked in the particular case documented, but there is not prescriptive recipe to successful data recovery. There are merely tools and guidelines, but you are responsible for developing a plan and taking the right decision during the process, based on your findings as you progress.

If any reader spots a logical error, or recommends a superior alternative for a particular task, leave a comment. One lucky commenter - willing to pick up in person - will be awarded with a used Western Digital BLUE 1TB disk in reasonably fair condition, guaranteed to show zero Current_Pending_Sector, Reallocated Sector Count and Reallocated_Event_Count under S.M.A.R.T. Attributes. 😉 Just kidding...

I hope this systematic approach will serve as a good example and that particual steps can be adapted by the reader to overcome their respective challenges.

Thursday 11 June 2020

Non-bootable Windows recovery (Part 4)

Context

This is the fourth post in a series dedicated to documenting a systematic approach of recovering a non-bootable Windows machine with Linux and open source tools. Make sure you read the first, second and third post to familiarize yourself with the context and previous activities.

After initial diagnostics, the investigation was narrowed down to a disk that fails S.M.A.R.T. extended self test, and misreports Reallocated Sector Count.

The first round of data recovery consisted of two ddrescue sessions taking a total of 48 hours but successfully extracting all the data with the exception of 1081 kilobytes spread across 16 ranges of consecutive bad sectors. It was captured, how the file system used the bad sector ranges, which files or what kind of file system structures seem to be affected.

Next, a pragmatic decision was taken to overwrite the last four of the bad sector ranges to force reallocation of bad sectors. These sector ranges were the longest four, and based on available information it was almost certian that these areas are unallocated, unused by the file system. Due to damages in the Master File Table, this could not be confirmed for 100%, but the risk involved was acceptable. The four bad sector areas were nuked via dd, a firmware misbehavior around misreporting sector reallocation count was observed and confirmed again, and another round of ddrescue was run, decreasing bad sectors to around 68 kilobytes spread across 15 bad areas.

Third round

During the investigation of the bad sector ranges there were errors reading 4 MFT entries 222148-222151. Therefore, any bad sector shown as unallocated by the system still could be in use but masked due to the MFT errors.

A more sophisticated approach was taken to progress data recovery without overwriting any further sector of the failing disk. The goal was to focus only on those bad sector ranges, which are known to hold either files or MFT entries, which was done by manipulating the mapfile ddrescue created to track the state of the rescue process. Successfully recovering the MFT entries would bring certainty about the usage of those sector ranges, which seem to be unallocated according to the damaged MFT. The key steps involved were the following:

  • Regenerate the list of affected files from the healthy drive, based on the mapfile resulting from the second round
  • Backup, then alter the mapfile by deleting bad blocks which are not certainly related to files or MFT
  • Save the deleted bad blocks to another mapfile for later processing
  • Run ddrescue on the failing drive with the mapfile that contains only high priority bad blocks

The individual commands were covered in previous posts in sufficient detail, the exact commands of the first step were as follows:


[root@sysresccd /mnt/REPO]# mkdir round-3
[root@sysresccd ~]# cp disk-sdb-to-sda.map /mnt/REPO/
[root@sysresccd /mnt/REPO]# ddrescuelog --list-blocks=- disk-sdb-to-sda.map | while read lba; do echo $(($lba - 1083392)); done >> bad-sectors-sdb4.txt
[root@sysresccd /mnt/REPO]# cat bad-sector-ranges-sdb4.txt 
3733376-3733383
9217344-9217351
9220448-9220455
9240544-9240551
9324120-9324127
10061520-10061527
16845920-16845927
17032080-17032081
17032808-17032815
42682272-42682287
47500880-47500927
89082175
103509823
103707887
139004815
[root@sysresccd /mnt/REPO]# cat bad-sector-ranges-sdb4.txt | while read range; do ntfscluster -s $range /dev/sda4; done > affected-files-sdb4.txt
[root@sysresccd /mnt/REPO]# cat affected-files-sdb4.txt 
Searching for sector range 3733376-3733383
Inode 112588 /ProgramData/Norton/{0C55C096-0F1D-4F28-AAA2-85EF591126E7}/NS_22.6.0.142/NCW/hlinks/ncwperfm.db.data/$DATA
* one inode found
Searching for sector range 9217344-9217351
* no inode found
Searching for sector range 9220448-9220455
* no inode found
Searching for sector range 9240544-9240551
Inode 248863 /Windows/ServiceProfiles/LocalService/AppData/Roaming/PeerNetworking/91e9854e5d4d7ac47cd0bf3ad8003817/922c235eb3d1d91e502cb02599cc24c7/grouping/edb02861.log/$DATA
* one inode found
Searching for sector range 9324120-9324127
Inode 96681 /$Extend/$UsnJrnl/$DATA($J)
* one inode found
Searching for sector range 10061520-10061527
Inode 0 /$MFT/$DATA
* one inode found
Searching for sector range 16845920-16845927
Inode 112588 /ProgramData/Norton/{0C55C096-0F1D-4F28-AAA2-85EF591126E7}/NS_22.6.0.142/NCW/hlinks/ncwperfm.db.data/$DATA
* one inode found
Searching for sector range 17032080-17032081
Inode 216164 /Windows/WinSxS/Catalogs/824be8ecd9b27e0ee92936dfba7c9f759df9d2e2999542e22d6f3bacab5b6140.cat/$DATA
* one inode found
Searching for sector range 17032808-17032815
Inode 75215 /Windows/WinSxS/Manifests/amd64_microsoft-windows-c..rintscan-deployment_31bf3856ad364e35_6.3.9600.16384_none_5cfa2773ab911611.manifest/$DATA
* one inode found
Searching for sector range 42682272-42682287
* no inode found
Searching for sector range 47500880-47500927
* no inode found
Searching for sector 89082175
* no inode found
Searching for sector 103509823
* no inode found
Searching for sector 103707887
* no inode found
Searching for sector 139004815
* no inode found

Looking at the list of affected files, once can see that the second round covered in the previous post already decreased the amount of files, the Adobe language file was not present in the new listing.

Next, the map file was backed up and hand edited. The status of blocks of lower priority - the ones where no inode found was printed - was flipped from - to + and were marked with a hashmark which is just an annotation that does not influence the execution of ddrescue.


[root@sysresccd /mnt/REPO]# cat disk-sdb-to-sda-priority.map.backup 
# Mapfile. Created by GNU ddrescue version 1.25
# Command line: ddrescue --ask --verbose --binary-prefixes --idirect --retry=20 --force /dev/sdb /dev/sda disk-sdb-to-sda.map
# Start time:   2020-05-17 14:24:44
# Current time: 2020-05-17 17:40:41
# Finished
# current_pos  current_status  current_pass
0x92FF0200     +               20
#      pos        size  status
0x00000000  0x92FF0000  +
0x92FF0000  0x00001000  -
0x92FF1000  0xA75B7000  +
0x13A5A8000  0x00001000  + #
0x13A5A9000  0x00183000  +
0x13A72C000  0x00001000  + #
0x13A72D000  0x009CF000  +
0x13B0FC000  0x00001000  -
0x13B0FD000  0x028CE000  +
0x13D9CB000  0x00001000  -
0x13D9CC000  0x1680E000  +
0x1541DA000  0x00001000  -
0x1541DB000  0xCF0B1000  +
0x22328C000  0x00001000  -
0x22328D000  0x05AE5000  +
0x228D72000  0x00000400  -
0x228D72400  0x0005AC00  +
0x228DCD000  0x00001000  -
0x228DCE000  0x30EC26000  +
0x5379F4000  0x00002000  + #
0x5379F6000  0x930D4000  +
0x5CAACA000  0x00006000  + #
0x5CAAD0000  0x4F4F57E00  +
0xABFA27E00  0x00000200  + #
0xABFA28000  0x1B84BFE00  +
0xC77EE7E00  0x00000200  + #
0xC77EE8000  0x060B5E00  +
0xC7DF9DE00  0x00000200  + #
0xC7DF9E000  0x4352D3E00  +
0x10B3271E00  0x00000200  + #
0x10B3272000  0xD82DB44000  +
[root@sysresccd ~]# ddrescue --ask --verbose --binary-prefixes --idirect --retry=200 --force /dev/sdb /dev/sda /mnt/REPO/disk-sdb-to-sda-priority.map
GNU ddrescue 1.25
About to copy 953869 MiBytes
from '/dev/sdb' [UNKNOWN] (1_000_204_886_016)
  to '/dev/sda' [UNKNOWN] (1_000_204_886_016)
Proceed (y/N)? y
    Starting positions: infile = 0 B,  outfile = 0 B
    Copy block size: 128 sectors       Initial skip size: 19584 sectors
Sector size: 512 Bytes

Press Ctrl-C to interrupt
Initial status (read from mapfile)
rescued: 953869 MiB, tried: 25600 B, bad-sector: 25600 B, bad areas: 7

Current status
     ipos:   2351 MiB, non-trimmed:        0 B,  current rate:       0 B/s
     opos:   2351 MiB, non-scraped:        0 B,  average rate:       0 B/s
non-tried:        0 B,  bad-sector:    21504 B,    error rate:     128 B/s
  rescued: 953869 MiB,   bad areas:        6,        run time: 11h 37m 57s
pct rescued:   99.99%, read errors:     8826,  remaining time:         n/a
                              time since last successful read:  1h 16m 22s
Finished

A rather aggressive run of 200 retries laster more, than 11 hours but brought impressive results as it can be seen above. Further iterations of ddrescue were run to the point where no more progress could be made.

                          
[root@sysresccd ~]# ddrescue --ask --verbose --binary-prefixes --idirect --retry=100 --force /dev/sdb /dev/sda /mnt/REPO/disk-sdb-to-sda-priority.map
GNU ddrescue 1.25
About to copy 953869 MiBytes
from '/dev/sdb' [UNKNOWN] (1_000_204_886_016)
  to '/dev/sda' [UNKNOWN] (1_000_204_886_016)
Proceed (y/N)? y
    Starting positions: infile = 0 B,  outfile = 0 B
    Copy block size: 128 sectors       Initial skip size: 19584 sectors
Sector size: 512 Bytes

Press Ctrl-C to interrupt
Initial status (read from mapfile)
rescued: 953869 MiB, tried: 21504 B, bad-sector: 21504 B, bad areas: 6

Current status
     ipos:   2351 MiB, non-trimmed:        0 B,  current rate:       0 B/s
     opos:   2351 MiB, non-scraped:        0 B,  average rate:       0 B/s
non-tried:        0 B,  bad-sector:    20992 B,    error rate:     102 B/s
  rescued: 953869 MiB,   bad areas:        6,        run time:  5h 27m  5s
pct rescued:   99.99%, read errors:     4124,  remaining time:         n/a
                              time since last successful read:  4h  3m 54s
Finished                                     
[root@sysresccd ~]# ddrescue --ask --verbose --binary-prefixes --idirect --retry=100 --force /dev/sdb /dev/sda /mnt/REPO/disk-sdb-to-sda-priority.map
GNU ddrescue 1.25
About to copy 953869 MiBytes
from '/dev/sdb' [UNKNOWN] (1_000_204_886_016)
  to '/dev/sda' [UNKNOWN] (1_000_204_886_016)
Proceed (y/N)? y
    Starting positions: infile = 0 B,  outfile = 0 B
    Copy block size: 128 sectors       Initial skip size: 19584 sectors
Sector size: 512 Bytes

Press Ctrl-C to interrupt
Initial status (read from mapfile)
rescued: 953869 MiB, tried: 20992 B, bad-sector: 20992 B, bad areas: 6

Current status
     ipos:   2351 MiB, non-trimmed:        0 B,  current rate:       0 B/s
     opos:   2351 MiB, non-scraped:        0 B,  average rate:       0 B/s
non-tried:        0 B,  bad-sector:    20480 B,    error rate:     102 B/s
  rescued: 953869 MiB,   bad areas:        5,        run time:  5h 23m 26s
pct rescued:   99.99%, read errors:     4075,  remaining time:         n/a
                              time since last successful read:  1h 19m 28s
Finished 
[root@sysresccd ~]# ddrescue --ask --verbose --binary-prefixes --idirect --retry=100 --force /dev/sdb /dev/sda /mnt/REPO/disk-sdb-to-sda-priority.map
GNU ddrescue 1.25
About to copy 953869 MiBytes
from '/dev/sdb' [UNKNOWN] (1_000_204_886_016)
  to '/dev/sda' [UNKNOWN] (1_000_204_886_016)
Proceed (y/N)? y
    Starting positions: infile = 0 B,  outfile = 0 B
    Copy block size: 128 sectors       Initial skip size: 19584 sectors
Sector size: 512 Bytes

Press Ctrl-C to interrupt
Initial status (read from mapfile)
rescued: 953869 MiB, tried: 20480 B, bad-sector: 20480 B, bad areas: 5

Current status
     ipos:   2351 MiB, non-trimmed:        0 B,  current rate:       0 B/s
     opos:   2351 MiB, non-scraped:        0 B,  average rate:       0 B/s
non-tried:        0 B,  bad-sector:    20480 B,    error rate:     102 B/s
  rescued: 953869 MiB,   bad areas:        5,        run time:  5h 17m 47s
pct rescued:   99.99%, read errors:     4000,  remaining time:         n/a
                              time since last successful read:         n/a
Finished 

After the first run that did not bring a single successful read, only 5 instances remained, with 8 sectors each. As this milestone was achieved in the middle of the night, the decision was taken to launch another session 200 retries and take a nap.

                                    
[root@sysresccd ~]# ddrescue --ask --verbose --binary-prefixes --idirect --retry=200 --force /dev/sdb /dev/sda /mnt/REPO/disk-sdb-to-sda-priority.map
GNU ddrescue 1.25
About to copy 953869 MiBytes
from '/dev/sdb' [UNKNOWN] (1_000_204_886_016)
  to '/dev/sda' [UNKNOWN] (1_000_204_886_016)
Proceed (y/N)? y
    Starting positions: infile = 0 B,  outfile = 0 B
    Copy block size: 128 sectors       Initial skip size: 19584 sectors
Sector size: 512 Bytes

Press Ctrl-C to interrupt
Initial status (read from mapfile)
rescued: 953869 MiB, tried: 20480 B, bad-sector: 20480 B, bad areas: 5

Current status
     ipos:   2351 MiB, non-trimmed:        0 B,  current rate:       0 B/s
     opos:   2351 MiB, non-scraped:        0 B,  average rate:       0 B/s
non-tried:        0 B,  bad-sector:    20480 B,    error rate:     102 B/s
  rescued: 953869 MiB,   bad areas:        5,        run time: 10h 35m 32s
pct rescued:   99.99%, read errors:     8000,  remaining time:         n/a
                              time since last successful read:         n/a
Finished

As the session completed without further progress, the data recovery process entered the final phase. Read the next post to learn more!

Wednesday 10 June 2020

Non-bootable Windows recovery (Part 3)

Context

This is the third post in a series dedicated to documenting a systematic approach of recovering a non-bootable Windows machine with Linux and open source tools. Make sure you read the first and second to familiarize yourself with the context and previous activities.

In a nutshell, the investigation was narrowed down to a disk that fails S.M.A.R.T. extended self test, and misreports Reallocated Sector Count. An initial invocation of ddrescue copied most of the unhealthy disk's content to a healthy destination in almost 7 hours, and a second pass ran for more than 40 hours to focus on the unreadable areas only, which has successfully squeezed a few more sectors out of the failing disk.

It was demonstrated, how to:

  1. calculate the remaining bad sector ranged from the map file of ddrescue
  2. identify affected partitions
  3. convert raw offsets to partition-relative sectors
  4. find out, what one bad sector range is used for by the filesystem, in this case, NTFS

Previous posts stressed the importance of understanding, what kind of data a bad sector range stored (such as file content, directory structure, journal, superblock or unused area) in order to evaluate the impact of permanently loosing that piece of data.

During the investigation of the bad sector range there were errors reading 4 MFT entries 222148-222151. Addressing this potential file system corruption was postponed to a later phase of the analysis.

Carry on with identifying affected files

A total of 1081 kilobytes of bad sectory remained, spread across 16 areas of the disk.


[root@sysresccd /mnt/REPO]# cat bad-sector-ranges-sdb4.txt 
3733376-3733383
9217344-9217351
9220448-9220455
9240544-9240551
9324120-9324127
10061520-10061527
16845920-16845927
17032080-17032081
17032113
17032808-17032815
42682272-42682287
47500880-47500927
89082000-89082175
103508872-103509823
103707120-103707887
139004680-139004815

[root@sysresccd /mnt/REPO]# cat bad-sector-ranges-sdb4.txt | while read range; do ntfscluster -s $range /dev/sda4; done > affected-files-sdb4.txt
[root@sysresccd /mnt/REPO]# cat affected-files-sdb4.txt 
Searching for sector range 3733376-3733383
Inode 112588 /ProgramData/Norton/{0C55C096-0F1D-4F28-AAA2-85EF591126E7}/NS_22.6.0.142/NCW/hlinks/ncwperfm.db.data/$DATA
* one inode found
Searching for sector range 9217344-9217351
* no inode found
Searching for sector range 9220448-9220455
* no inode found
Searching for sector range 9240544-9240551
Inode 248863 /Windows/ServiceProfiles/LocalService/AppData/Roaming/PeerNetworking/91e9854e5d4d7ac47cd0bf3ad8003817/922c235eb3d1d91e502cb02599cc24c7/grouping/edb02861.log/$DATA
* one inode found
Searching for sector range 9324120-9324127
Inode 96681 /$Extend/$UsnJrnl/$DATA($J)
* one inode found
Searching for sector range 10061520-10061527
Inode 0 /$MFT/$DATA
* one inode found
Searching for sector range 16845920-16845927
Inode 112588 /ProgramData/Norton/{0C55C096-0F1D-4F28-AAA2-85EF591126E7}/NS_22.6.0.142/NCW/hlinks/ncwperfm.db.data/$DATA
* one inode found
Searching for sector range 17032080-17032081
Inode 216164 /Windows/WinSxS/Catalogs/824be8ecd9b27e0ee92936dfba7c9f759df9d2e2999542e22d6f3bacab5b6140.cat/$DATA
* one inode found
Searching for sector 17032113
Inode 133052 /Program Files (x86)/Common Files/Adobe/OOBE/PDApp/P6/ZStringResources/es_LA/stringtable.xml/$DATA
* one inode found
Searching for sector range 17032808-17032815
Inode 75215 /Windows/WinSxS/Manifests/amd64_microsoft-windows-c..rintscan-deployment_31bf3856ad364e35_6.3.9600.16384_none_5cfa2773ab911611.manifest/$DATA
* one inode found
Searching for sector range 42682272-42682287
* no inode found
Searching for sector range 47500880-47500927
* no inode found
Searching for sector range 89082000-89082175
* no inode found
Searching for sector range 103508872-103509823
* no inode found
Searching for sector range 103707120-103707887
* no inode found
Searching for sector range 139004680-139004815
* no inode found

Interpreting the results and taking decisions

The impact of the unreadable sectors could be summarized as follows, without going into detail:

  • Norton Antivirus is affected, a single file at two distant areas on the disk
  • Windows networking related file is affected
  • Two of Windows Side-by-Side assemblies are affected
  • Adobe OOBE Latin American Spanish language file is affected
  • The NTFS journal and Master File Table are affected, the damaged MFT suggests that the list of affected files might be incomplete
  • Many large bad areas are reported as unallocated by the file system, but this is not a hard fact since the MFT is damaged

In order to make further progress with data recover within a realistic timeframe, the decision was made to take calculated risks and nuke the last 4 bad areas, which are the largest by size. This carries risks described in the previous post, and the next post will show a more risk-avoiding approach to narrowing down the the area the recovery of which will be attempted.

The advantage of nuking the last four bad sector ranges is the ability to obverse how Reallocated_Sector_Ct and Current_Pending_Sector are updated in response to the forced reallocation, and prove the Western Digital firmware bug.

Nuking the selected bad sector ranges

The first and last sector relative to the partition was used to calculate the lenght of the bad area and then the offset of the partition was added to the offset of the first sector of the sector range within the partition to calculate the starting position within the disk. Prior experience has shown that operating on the disk /dev/sdb is preferred to operating on the partition./dev/sdb4. Further, output flag direct should be used skip any caching logic, and a block size one sector, that is, 512 bytes has to be applied.


[root@sysresccd /mnt/REPO]# echo $((139004815-139004680))
135
[root@sysresccd /mnt/REPO]# echo $((139004680+1083392))
140088072
[root@sysresccd /mnt/REPO]# dd seek=140088072 count=135 oflag=direct if=/dev/zero of=/dev/sdb
135+0 records in
135+0 records out
69120 bytes (69 kB, 68 KiB) copied, 0.427308 s, 162 kB/s
[root@sysresccd /mnt/REPO]# smartctl -a /dev/sdb
smartctl 7.1 2019-12-30 r5022 [x86_64-linux-5.4.32-1-lts] (local build)
...
  5 Reallocated_Sector_Ct   0x0033   200   200   140    Pre-fail  Always       -       0
...
196 Reallocated_Event_Count 0x0032   200   200   000    Old_age   Always       -       0
197 Current_Pending_Sector  0x0032   199   197   000    Old_age   Always       -       275
198 Offline_Uncorrectable   0x0030   199   198   000    Old_age   Offline      -       285
199 UDMA_CRC_Error_Count    0x0032   200   200   000    Old_age   Always       -       0
200 Multi_Zone_Error_Rate   0x0008   200   198   000    Old_age   Offline      -       289
...

[root@sysresccd /mnt/REPO]# dd skip=140088072 count=135 iflag=direct if=/dev/sdb of=/dev/null
135+0 records in
135+0 records out
69120 bytes (69 kB, 68 KiB) copied, 0.0161237 s, 4.3 MB/s

It can be seen that no error was encoutered when overwriting the given sectors. The number of pendig sectors decreased from 292 ro 275, however, both Reallocated_Event_Count and Reallocated_Sector_Ct remained 0. With that, the false reporting of reallocations on this Western Digital Blue disk is confirmed. The careful reader should have noticed, that a read test was also done on the freshly overwritten disk area to confirm successful reallocation.

Next, the remaining three bad sector ranges were nuked.


[root@sysresccd /mnt/REPO]# echo count $((103707887-103707120))
count 767
[root@sysresccd /mnt/REPO]# echo first sector without offset $((103707120+1083392))
first sector without offset 104790512
[root@sysresccd /mnt/REPO]# dd seek=104790512 count=767 oflag=direct if=/dev/zero of=/dev/sdb
767+0 records in
767+0 records out
392704 bytes (393 kB, 384 KiB) copied, 0.454273 s, 864 kB/s
[root@sysresccd /mnt/REPO]# dd skip=104790512 count=767 iflag=direct if=/dev/sdb of=/dev/null
767+0 records in
767+0 records out
392704 bytes (393 kB, 384 KiB) copied, 0.0849093 s, 4.6 MB/s
[root@sysresccd /mnt/REPO]# echo count $((103508872-103509823))
count -951
[root@sysresccd /mnt/REPO]# echo first sector without offset $((103508872+1083392))
first sector without offset 104592264
[root@sysresccd /mnt/REPO]# dd seek=104592264 count=951 oflag=direct if=/dev/zero of=/dev/sdb
951+0 records in
951+0 records out
486912 bytes (487 kB, 476 KiB) copied, 0.464146 s, 1.0 MB/s
[root@sysresccd /mnt/REPO]# dd skip=104592264 count=951 iflag=direct if=/dev/sdb of=/dev/null
951+0 records in
951+0 records out
486912 bytes (487 kB, 476 KiB) copied, 0.10581 s, 4.6 MB/s
[root@sysresccd /mnt/REPO]# echo count $((89082000-89082175))
count -175
[root@sysresccd /mnt/REPO]# echo first sector without offset $((89082000+1083392))
first sector without offset 90165392
[root@sysresccd /mnt/REPO]# dd seek=90165392 count=175 oflag=direct if=/dev/zero of=/dev/sdb
175+0 records in
175+0 records out
89600 bytes (90 kB, 88 KiB) copied, 0.428108 s, 209 kB/s
[root@sysresccd /mnt/REPO]# dd skip=90165392 count=175 iflag=direct if=/dev/sdb of=/dev/null
175+0 records in
175+0 records out
89600 bytes (90 kB, 88 KiB) copied, 0.0196124 s, 4.6 MB/s
[root@sysresccd /mnt/REPO]# smartctl -A /dev/sdb
smartctl 7.1 2019-12-30 r5022 [x86_64-linux-5.4.32-1-lts] (local build)
Copyright (C) 2002-19, Bruce Allen, Christian Franke, www.smartmontools.org

=== START OF READ SMART DATA SECTION ===
SMART Attributes Data Structure revision number: 16
Vendor Specific SMART Attributes with Thresholds:
ID# ATTRIBUTE_NAME          FLAG     VALUE WORST THRESH TYPE      UPDATED  WHEN_FAILED RAW_VALUE
  1 Raw_Read_Error_Rate     0x002f   199   183   051    Pre-fail  Always       -       116548
  3 Spin_Up_Time            0x0027   161   125   021    Pre-fail  Always       -       2908
  4 Start_Stop_Count        0x0032   099   099   000    Old_age   Always       -       1423
  5 Reallocated_Sector_Ct   0x0033   200   200   140    Pre-fail  Always       -       0
  7 Seek_Error_Rate         0x002e   200   200   000    Old_age   Always       -       0
  9 Power_On_Hours          0x0032   086   086   000    Old_age   Always       -       10670
 10 Spin_Retry_Count        0x0032   100   100   000    Old_age   Always       -       0
 11 Calibration_Retry_Count 0x0032   100   100   000    Old_age   Always       -       0
 12 Power_Cycle_Count       0x0032   099   099   000    Old_age   Always       -       1423
192 Power-Off_Retract_Count 0x0032   200   200   000    Old_age   Always       -       83
193 Load_Cycle_Count        0x0032   177   177   000    Old_age   Always       -       71063
194 Temperature_Celsius     0x0022   112   107   000    Old_age   Always       -       31
196 Reallocated_Event_Count 0x0032   200   200   000    Old_age   Always       -       0
197 Current_Pending_Sector  0x0032   200   197   000    Old_age   Always       -       38
198 Offline_Uncorrectable   0x0030   199   198   000    Old_age   Offline      -       285
199 UDMA_CRC_Error_Count    0x0032   200   200   000    Old_age   Always       -       0
200 Multi_Zone_Error_Rate   0x0008   200   198   000    Old_age   Offline      -       289

Westerd Digital BLUE firmware plead guilty

After nuking the four bad sector ranges, Current_Pending_Sector went down to 38 from the initial 292, but the attributes counting reallocation events and the count of reallocated sectors remained 0. This is an objective hard evidence that the firmware on this disk has either a bug or a fishy built-in misbehavior.

Eventually, one could overwrite the whole disk and zero out the pending sector count, without leaving any trace of past reallocations, thereby letting the disk look much more healthy that it is in reality. Would selling this disk after zeroing out the pending sector count knowing that the reallocation counters will remain zero, be an act of fraud? What about producing and selling disks which expose such behavior?

Second round

I turned my attention back to data recovery, to see how nuking had influenced the recovery with ddrescue.


[root@sysresccd /mnt/REPO]# mv disk-sdb-to-sda.map disk-sdb-to-sda.map.20200517T1426
[root@sysresccd ~]# ddrescue --ask --verbose --binary-prefixes --idirect --retry=20 --force /dev/sdb /dev/sda disk-sdb-to-sda.map
GNU ddrescue 1.25
About to copy 953869 MiBytes
from '/dev/sdb' [UNKNOWN] (1_000_204_886_016)
  to '/dev/sda' [UNKNOWN] (1_000_204_886_016)
Proceed (y/N)? y
    Starting positions: infile = 0 B,  outfile = 0 B
    Copy block size: 128 sectors       Initial skip size: 19584 sectors
Sector size: 512 Bytes

Press Ctrl-C to interrupt
Initial status (read from mapfile)
rescued: 953868 MiB, tried: 1081 KiB, bad-sector: 1081 KiB, bad areas: 16

Current status
     ipos:   2351 MiB, non-trimmed:        0 B,  current rate:       0 B/s
     opos:   2351 MiB, non-scraped:        0 B,  average rate:      88 B/s
non-tried:        0 B,  bad-sector:    68608 B,    error rate:     128 B/s
  rescued: 953869 MiB,   bad areas:       15,        run time:  3h 15m 57s
pct rescued:   99.99%, read errors:     2550,  remaining time:         n/a
                              time since last successful read:      3h 55s
Finished

[root@sysresccd /mnt/REPO]# mkdir round-2
[root@sysresccd /mnt/REPO]# mv *.txt round-2/
[root@sysresccd /mnt/REPO]# mv disk-sdb-to-sda.map.20200517T1426 round-2/                 

It can be clearly seen in the output that bad sectors have significantly decreased (from 1081 KiB to 68608 B) and the number of bad areas decreased from 16 to 15, and execution time has drastically reduced from 40 hours to around 3. Although the results improved, it should be noted that we permanently lost the content of the four bad sector ranges which were most likely unallocated, but due to the damaged MFT, there is no hard evindence for this. We took a calculated risk in order pinpoint the firmware misbehavior.

The next post will cover a more advanced approach to progress data recovery even further, without overwriting any sector on the failing disk. Stay tuned!

Tuesday 9 June 2020

Non-bootable Windows recovery (Part 2)

Context

This is the second post in a series dedicated to documenting a systematic approach of recovering a non-bootable Windows machine with Linux and open source tools. Make sure you read the first post to familiarize yourself with the context and previous activities.

In a nutshell, the investigation was narrowed down to a disk that fails S.M.A.R.T. extended self test, and misreports Reallocated Sector Count and potentially other S.M.A.R.T attributes due to a firmware bug or intentional "vendor feature".

The LBA (logical block address) of the first read error is known from self test log, and various implications of manually overwriting bad sectors via dd have been covered.

  1. The necessity of understanding, what kind of data that particular sector stored (such as file content, directory structure, journal, superblock or unused area) is key to understand the risk of nuking that sector in order to force reallocation
  2. The chance that repetitively reading the bad sector could eventually succeed, but at the same time stressing a mechanically failing disk for a long duration might render it unusable and make further recovery impossible
  3. The risk associated with continued production use of a disk that had bad sectors fixed manually in the past but seems to be healthy, as opposed to decommissioning drives right after recovery

First round

The decision has been taken to clone the 1TB disk holding medical/business data to a new 2TB disk, and re-purposing the 1TB disk during the recovery process. Rather than working with disk images, this particular case allowed recovering data from the failing 1TB drive /dev/sdb to directly this known to be good disk. Time pressure, the lack of spare disk capacity and previous testing of the disks justified this shortcut.


[root@sysresccd ~]# ddrescue --ask --verbose --binary-prefixes --force /dev/sdb /dev/sda disk-sdb-to-sda.map
GNU ddrescue 1.25
About to copy 953869 MiBytes
from '/dev/sdb' [UNKNOWN] (1_000_204_886_016)
  to '/dev/sda' [UNKNOWN] (1_000_204_886_016)
Proceed (y/N)? y
    Starting positions: infile = 0 B,  outfile = 0 B
    Copy block size: 128 sectors       Initial skip size: 19584 sectors
Sector size: 512 Bytes

Press Ctrl-C to interrupt
     ipos:  68402 MiB, non-trimmed:        0 B,  current rate:       0 B/s
     opos:  68402 MiB, non-scraped:        0 B,  average rate: 39780 KiB/s
non-tried:        0 B,  bad-sector:   1094 KiB,    error rate:     102 B/s
  rescued: 953868 MiB,   bad areas:       25,        run time:  6h 49m 14s
pct rescued:   99.99%, read errors:     2225,  remaining time:         n/a
                              time since last successful read:  2h 44m 54s
Finished                                  

[root@sysresccd ~]# ddrescue --ask --verbose --binary-prefixes --idirect --retry=20 --force /dev/sdb /dev/sda disk-sdb-to-sda.map
GNU ddrescue 1.25
About to copy 953869 MiBytes
from '/dev/sdb' [UNKNOWN] (1_000_204_886_016)
  to '/dev/sda' [UNKNOWN] (1_000_204_886_016)
Proceed (y/N)? y
    Starting positions: infile = 0 B,  outfile = 0 B
    Copy block size: 128 sectors       Initial skip size: 19584 sectors
Sector size: 512 Bytes

Press Ctrl-C to interrupt
Initial status (read from mapfile)
rescued: 953868 MiB, tried: 1094 KiB, bad-sector: 1094 KiB, bad areas: 25

Current status
     ipos:  51070 MiB, non-trimmed:        0 B,  current rate:       0 B/s
     opos:  51070 MiB, non-scraped:        0 B,  average rate:       0 B/s
non-tried:        0 B,  bad-sector:   1081 KiB,    error rate:       0 B/s
  rescued: 953868 MiB,   bad areas:       16,        run time:  1d 17h 14m
pct rescued:   99.99%, read errors:    31116,  remaining time:         n/a
                              time since last successful read:     59m 58s
Retrying bad sectors... Retry 15 (forwards)^C  
  Interrupted by user

The first invocation of ddrescue executed a rather conservative swipe through the disk, copying as much data as possible without retrying bad sectors. It is worth to read the algorithm which defines how the disk is processed.

The second invocation reused the map file created by the first invocation, which allows focusing efforts on the failed areas only, used --idirect to bypass kernel caches, that is, force direct disk access on each attempt to read, and defined a limit of 20 retries. The execution of this second invocation was aborted after having spent a total of 48 hours with these two invocations.

Looking at the output, it can be seen that some progress was made during the second invocation, decreasing bad areas from 25 to 16, and from a total of 1094 Kilobytes of bad sectors to 1081 KiB. My expectation at this time was that any further long running process would be exponentially less and less efficient, so it is time to understand what pragmatic options we have to get the best results before the available time window closes.

Evaluating the impact of our bad sectors

As indicated above, it is key to understand what the disk area containing bad sectors is mapped to, or used by the system. This information will allow us to further reduce the scope of recovery by eliminating recovery of unallocated blocks, and prioritize used blocks based on the type of information they store.

The remaining free space on the 2TB disk was used to create an Ext4 partition to serve as an image and file repository during the recovery process, it has been mounted to /mnt/REPO.


[root@sysresccd ~]# cp disk-sdb-to-sda.map /mnt/REPO/disk-sdb-to-sda.map
[root@sysresccd ~]# cd /mnt/REPO/
[root@sysresccd /mnt/REPO]# ddrescuelog --binary-prefixes -A disk-sdb-to-sda.map | grep -
# Command line: ddrescuelog --binary-prefixes -A disk-sdb-to-sda.map
# Start time:   2020-05-17 13:35:55
0xC77EA1C00     -               15 #  51070 MiB
0x92FF0000  0x00001000  - #    2351 MiB      4096  
0x13A5A8000  0x00001000  - #    5029 MiB      4096  
0x13A72C000  0x00001000  - #    5031 MiB      4096  
0x13B0FC000  0x00001000  - #    5040 MiB      4096  
0x13D9CB000  0x00001000  - #    5081 MiB      4096  
0x1541DA000  0x00001000  - #    5441 MiB      4096  
0x22328C000  0x00001000  - #    8754 MiB      4096  
0x228D72000  0x00000400  - #    8845 MiB      1024  
0x228D76200  0x00000200  - #    8845 MiB       512  
0x228DCD000  0x00001000  - #    8845 MiB      4096  
0x5379F4000  0x00002000  - #   21369 MiB      8192  
0x5CAACA000  0x00006000  - #   23722 MiB     24576  
0xABFA12000  0x00016000  - #   44026 MiB     90112  
0xC77E71000  0x00077000  - #   51070 MiB    487424  
0xC7DF3E000  0x00060000  - #   51167 MiB    393216  
0x10B3261000  0x00011000  - #   68402 MiB     69632  

[root@sysresccd /mnt/REPO]# ddrescuelog --list-blocks=- disk-sdb-to-sda.map > bad-sectors-sdb.txt

The command ddrescuelog was used to read the map file and enumerate bad areas along with their starting position and length. It can be seen, that in most of the cases, bad areas are 4K blocks. The last 5 bad areas are much larger than others, so eliminating some of those would significantly improve the efficiency of the recovery process, and thereby our chances for a success recovery.

In addition to displaying the byte based offset and size of bad areas, the same command was used to create a simple list of bad sectors which was then used to calculate the offset of bad sector ranges within the affected partitions. In fact, a single partition as it turned out.


[root@sysresccd /mnt/REPO]# gdisk -l /dev/sda
GPT fdisk (gdisk) version 1.0.5

Partition table scan:
  MBR: protective
  BSD: not present
  APM: not present
  GPT: present

Found valid GPT with protective MBR; using GPT.
Disk /dev/sda: 1953525168 sectors, 931.5 GiB
Model: WDC WD10EFRX-68F
Sector size (logical/physical): 512/4096 bytes
Disk identifier (GUID): 848E364C-322B-45A8-8685-073A18109019
Partition table holds up to 128 entries
Main partition table begins at sector 2 and ends at sector 33
First usable sector is 34, last usable sector is 1953525134
Partitions will be aligned on 2048-sector boundaries
Total free space is 1533013357 sectors (731.0 GiB)

Number  Start (sector)    End (sector)  Size       Code  Name
   1            2048          616447   300.0 MiB   2700  Basic data partition
   2          616448          821247   100.0 MiB   EF00  EFI system partition
   3          821248         1083391   128.0 MiB   0C01  Microsoft reserved ...
   4         1083392       210798591   100.0 GiB   0700  Basic data partition
   5       210798592       420513791   100.0 GiB   0700  
[root@sysresccd /mnt/REPO]# cat bad-sectors-sdb.txt | while read lba; do echo $(($lba - 1083392)); done >> bad-sectors-sdb4.txt

As the careful reader will have noticed, partition information and data is read from the physically healthy /dev/sda.

Based on the first and last bad sector it was confirmed that bad areas are within partition /dev/sdb4, which is the "C:" partition of Windows. The last line of the command listing above shows how to translate the raw sector based disk offsets to relative offsets within the partition.

Identifying files in bad sector ranges

Identifying which files, or what part of file sysem is allocated to a given sector range could typically be done using dumpe2fs and debuge2fs in tandem in the case of Linux Ext file systems, however, in this case we are dealing with NTFS. A classic universal option would have been using ifind from The Sleuth Kit, an open source collection of forensics tools, but I decided to stick to utilities that are part of the already running SystemResqueCd as much as possible, to avoid any delay in my workflow. I ended up using ntfscluster to achieve the goal.


[root@sysresccd /mnt/REPO]# cat bad-sector-ranges-sdb4.txt 
3733376-3733383
9217344-9217351
9220448-9220455
9240544-9240551
9324120-9324127
10061520-10061527
16845920-16845927
17032080-17032081
17032113
17032808-17032815
42682272-42682287
47500880-47500927
89082000-89082175
103508872-103509823
103707120-103707887
139004680-139004815

[root@sysresccd /mnt/REPO]# ntfscluster -s 139004680-139004815 /dev/sda4
...
Inode 222099 is an extent of inode 285447.
Inode 222116 is an extent of inode 285450.
Inode 222120 is an extent of inode 285452.
Inode 222132 is an extent of inode 285454.
ntfs_mst_post_read_fixup_warn: magic: 0x788627c2  size: 1024   usa_ofs: 5592  usa_count: 63093: Invalid argument
Record 222148 has no FILE magic (0x788627c2)
ntfs_mst_post_read_fixup_warn: magic: 0x788627c2  size: 1024   usa_ofs: 5592  usa_count: 63093: Invalid argument
Record 222148 has no FILE magic (0x788627c2)
Error reading inode 222148.
ntfs_mst_post_read_fixup_warn: magic: 0x1dcddcd1  size: 1024   usa_ofs: 15035  usa_count: 45642: Invalid argument
Record 222149 has no FILE magic (0x1dcddcd1)
ntfs_mst_post_read_fixup_warn: magic: 0x1dcddcd1  size: 1024   usa_ofs: 15035  usa_count: 45642: Invalid argument
Record 222149 has no FILE magic (0x1dcddcd1)
Error reading inode 222149.
ntfs_mst_post_read_fixup_warn: magic: 0x3e9913ab  size: 1024   usa_ofs: 36947  usa_count: 6616: Invalid argument
Record 222150 has no FILE magic (0x3e9913ab)
ntfs_mst_post_read_fixup_warn: magic: 0x3e9913ab  size: 1024   usa_ofs: 36947  usa_count: 6616: Invalid argument
Record 222150 has no FILE magic (0x3e9913ab)
Error reading inode 222150.
ntfs_mst_post_read_fixup_warn: magic: 0xb9942bfd  size: 1024   usa_ofs: 52375  usa_count: 32401: Invalid argument
Record 222151 has no FILE magic (0xb9942bfd)
ntfs_mst_post_read_fixup_warn: magic: 0xb9942bfd  size: 1024   usa_ofs: 52375  usa_count: 32401: Invalid argument
Record 222151 has no FILE magic (0xb9942bfd)
Error reading inode 222151.
Inode 222177 is an extent of inode 285458.
Inode 222188 is an extent of inode 58416.
Inode 222191 is an extent of inode 241635.
...
Inode 389780 is an extent of inode 386451.
* no inode found

The command ntfscluster was run to display information on the use of the last bad sector range. According to the output, no file data stream allocation could be found within that range, however, there were errors reading 4 MFT entries 222148-222151. At this point, it is uncertain whether or not files are allocated to the disk area in question, but there is certainly an issue with file system integrity which needs to be addressed. This issue was put on the parking lane in order to assemble a list of files certainly affected by the other bad sector ranges.

Read on, and check out the next post in the series.

Monday 8 June 2020

Non-bootable Windows recovery (Part 1)

Context

A friend asked for help. A Windows box at a small medical point has become unable to boot. Unfortunately, this was the central box, serving files, storing many year's worth of email and medical data, plus running a couple of medical applications. A single point of failure, without a reasonably fresh backup: a typical real life problem of small, non-IT businesses.

The goal was to get the environment up and running. A handful of medical stations depend on the services of this central computer, and staff needs the medical data it stores. I took the box home for a weekend, to see what could be done.

This series of blog posts will give the reader a systematic approach to diagnosing and fixing this issue with open source Linux tools.

The plan

While driving home, I decided to develop an action plan rather than rushing and making mistakes with non revocable impact. Instead of a clear sequence of steps, an ever growing binary decision tree crystallized from hypothetical observations, possible causes and outcomes. A plethora of unknown variables and a time window of a bit more than a weekend.

Pragmatic time boxed problem solving can be based on the the OODA loop which promotes a calm, systematic, approach made up of iterations of absorbing information, filtering and contextualizing it, then making a reasonably sound (what seems to be best) decision, and observing the effects of the decision, which serve as input for the next iteration. This is how one adapts to changes during the problem solving process in a disciplined manner.

Symptoms

The single socket, quad core machine had Windows 8.1 installed with the Norton Security Suite, several usual and a few special medical applications. One of the two hard drives gave place to the operating system and some data, while a separate 1TB disk was dedicated for the large amount of growing business data.

A few seconds after power on, the machine got suck at a state where the boot logo of the motherboard was displayed with a spinner, then after a while went black and did not progress for hours (until forcefully powered off). The HDD led on the case indicated intense disk activity. These are the symptoms I have collected over phone.

First steps

The first decision was not to boot the operating system, as that might make the situation even worse, whether or not we are dealing with malware or "just" software or hardware failure.

The second decision was to source a 2TB disk. Any data recovery or forensic investigation shall only be performed on disk images or clones and not the disks themselves, to shield the effects of mechanically damaged disks and to retain backup of the starting of the activities. The disk would serve as storage upgrade of the machine once returned.

I entered the UEFI Firmware Setup Utility, and checked for indications of hardware failure, but did not see anything obvious.

Having booted SystemRescueCD, my preferred live Linux distribution for general system rescue, from a USB stick, I launched an extended self test on all 3 disks in parallel, along with two iterations of memtester, which is a userspace memory stress utility, that reliably works on UEFI and does not need a reboot. Running these 4 tests in parallel saved many hours of unproductive time with an acceptable risk of not being able to test the first 200MB of RAM.


smartctl -a /dev/sda | less -S
smartctl -a /dev/sdb | less -S
smartctl -a /dev/sdc | less -S
smartctl -t long /dev/sda
smartctl -t long /dev/sdb
smartctl -t long /dev/sdc
memtester 7956M 2

Findings, assumptions and decisions

The disk /dev/sdb, where Windows was installed, has failed the self test. The other two disks and also the memory have passed the test, which allowed for narrowing down the investigation, with the assumption that there is not hardware issue except the disk which failed the self test. Making assumption is fine as long as one takes note of them so they can be revisited and challenged later if needed.

The good news was that the drive /dev/sda, the one holding medical data in a single NTFS partition was fine hardware-wise as per the self test. It could me mounted read-only and the filesystem seemed to be all right. The decision was to clone this drive to the new 2TB drive, and then repurpose /dev/sda later during the process of recovering the system drive.


ddrescue --ask --verbose --binary-prefixes --idirect --force /dev/sda /dev/sdc disk.map

One could certainly use a shorter command to clone one drive to another, however, during a recover task, I recommend using ddrescue with a map file and the arguments like shown above. Copying will not be aborted on the first error like it would be when using dd. Instead, read errors are gracefully skipped, allowing one to maximize the amount of data copied before bad areas are retried. The map file captures progress and state and allows one to continue with recovery by re-running ddrescue with the same or different arguments.

The problematic disk

After re-running the self test a couple of times, I took a deeper look at the output of smartctl.


[root@sysresccd ~]# smartctl -a /dev/sdb
smartctl 7.1 2019-12-30 r5022 [x86_64-linux-5.4.32-1-lts] (local build)
Copyright (C) 2002-19, Bruce Allen, Christian Franke, www.smartmontools.org

=== START OF INFORMATION SECTION ===
Model Family:     Western Digital Blue
Device Model:     WDC WD10EZRZ-00HTKB0
Serial Number:    WD-WCC4J4APRJA4
LU WWN Device Id: 5 0014ee 261b8c4c0
Firmware Version: 01.01A01
User Capacity:    1,000,204,886,016 bytes [1.00 TB]
Sector Sizes:     512 bytes logical, 4096 bytes physical
Rotation Rate:    5400 rpm
Device is:        In smartctl database [for details use: -P show]
ATA Version is:   ACS-2, ACS-3 T13/2161-D revision 3b
SATA Version is:  SATA 3.1, 6.0 Gb/s (current: 6.0 Gb/s)
Local Time is:    Sun May 17 11:13:28 2020 UTC
SMART support is: Available - device has SMART capability.
SMART support is: Enabled

=== START OF READ SMART DATA SECTION ===
SMART overall-health self-assessment test result: PASSED

General SMART Values:
Offline data collection status:  (0x82) Offline data collection activity
     was completed without error.
     Auto Offline Data Collection: Enabled.
Self-test execution status:      ( 121) The previous self-test completed having
     the read element of the test failed.
Total time to complete Offline 
data collection:   (13440) seconds.
Offline data collection
capabilities:     (0x7b) SMART execute Offline immediate.
     Auto Offline data collection on/off support.
     Suspend Offline collection upon new
     command.
     Offline surface scan supported.
     Self-test supported.
     Conveyance Self-test supported.
     Selective Self-test supported.
SMART capabilities:            (0x0003) Saves SMART data before entering
     power-saving mode.
     Supports SMART auto save timer.
Error logging capability:        (0x01) Error logging supported.
     General Purpose Logging supported.
Short self-test routine 
recommended polling time:   (   2) minutes.
Extended self-test routine
recommended polling time:   ( 153) minutes.
Conveyance self-test routine
recommended polling time:   (   5) minutes.
SCT capabilities:         (0x3035) SCT Status supported.
     SCT Feature Control supported.
     SCT Data Table supported.

SMART Attributes Data Structure revision number: 16
Vendor Specific SMART Attributes with Thresholds:
ID# ATTRIBUTE_NAME          FLAG     VALUE WORST THRESH TYPE      UPDATED  WHEN_FAILED RAW_VALUE
  1 Raw_Read_Error_Rate     0x002f   199   183   051    Pre-fail  Always       -       115158
  3 Spin_Up_Time            0x0027   161   125   021    Pre-fail  Always       -       2908
  4 Start_Stop_Count        0x0032   099   099   000    Old_age   Always       -       1423
  5 Reallocated_Sector_Ct   0x0033   200   200   140    Pre-fail  Always       -       0
  7 Seek_Error_Rate         0x002e   200   200   000    Old_age   Always       -       0
  9 Power_On_Hours          0x0032   086   086   000    Old_age   Always       -       10667
 10 Spin_Retry_Count        0x0032   100   100   000    Old_age   Always       -       0
 11 Calibration_Retry_Count 0x0032   100   100   000    Old_age   Always       -       0
 12 Power_Cycle_Count       0x0032   099   099   000    Old_age   Always       -       1423
192 Power-Off_Retract_Count 0x0032   200   200   000    Old_age   Always       -       83
193 Load_Cycle_Count        0x0032   177   177   000    Old_age   Always       -       71057
194 Temperature_Celsius     0x0022   110   107   000    Old_age   Always       -       33
196 Reallocated_Event_Count 0x0032   200   200   000    Old_age   Always       -       0
197 Current_Pending_Sector  0x0032   199   197   000    Old_age   Always       -       292
198 Offline_Uncorrectable   0x0030   199   198   000    Old_age   Offline      -       285
199 UDMA_CRC_Error_Count    0x0032   200   200   000    Old_age   Always       -       0
200 Multi_Zone_Error_Rate   0x0008   200   198   000    Old_age   Offline      -       289

SMART Error Log Version: 1
No Errors Logged

SMART Self-test log structure revision number 1
Num  Test_Description    Status                  Remaining  LifeTime(hours)  LBA_of_first_error
# 1  Extended offline    Completed: read failure       90%     10605         10323936
# 2  Extended offline    Completed: read failure       90%     10605         10323936
# 3  Extended offline    Completed: read failure       90%     10605         10323936
# 4  Extended offline    Completed: read failure       90%     10605         10323936
# 5  Extended offline    Completed: read failure       90%     10604         10323936
# 6  Extended offline    Completed without error       00%       773         -
# 7  Extended offline    Completed: read failure       90%       770         977627520
# 8  Extended offline    Completed: read failure       90%       760         18849666
# 9  Extended offline    Completed: read failure       90%       759         18849665
#10  Extended offline    Completed: read failure       90%       757         844589
#11  Extended offline    Completed: read failure       90%       756         844584
#12  Extended offline    Completed: read failure       90%       746         844584
#13  Extended offline    Completed: read failure       90%       745         844584
#14  Extended offline    Completed: read failure       90%       744         844584
#15  Extended offline    Completed: read failure       90%       744         844588
#16  Extended offline    Completed: read failure       90%       744         844588
#17  Extended offline    Completed: read failure       90%       744         844584
11 of 16 failed self-tests are outdated by newer successful extended offline self-test # 6

SMART Selective self-test log data structure revision number 1
 SPAN  MIN_LBA  MAX_LBA  CURRENT_TEST_STATUS
    1        0        0  Not_testing
    2        0        0  Not_testing
    3        0        0  Not_testing
    4        0        0  Not_testing
    5        0        0  Not_testing
Selective self-test flags (0x0):
  After scanning selected spans, do NOT read-scan remainder of disk.
If Selective self-test is pending on power-up, resume after 0 minute delay.

The SMART attributes 5 and 197 indicate that there are 292 bad sectors pending for reallocation, and so far, this disk has not reallocated any sectors during it's lifetime. That in itself would be fine, since reallocations usually happen when the bad areas are written to. Such a write would cause the number of pending sectors to decrease, and the number of reallocation to increase.

However, looking at the log of previously run self test unveils some contradition. It seems that this disk already had multiple bad sectors years ago, which seem to have been fixed by rewriting the bad areas and forcing a reallocation. Test number 6 shows that a few hours after the supposed rewrite, the self test did not find any bad sectors. So reallocations must have happened, however, the SMART attribute showing the number of reallocated sectors is still 0. This seems to be either a firmware bug, or a fishy "feature" used by Western Digital.

The next steps

As far as the current self test results are concerned, there is a consistently reproducible read error at logical block address 10323936. Once could just fix that single sector by using dd to directly write to that sector to force a reallocation, then re-run the self test to test for further problematic sectors. I have successfully employed this practice in the past on Linux machines but there are 3 caveats.

  1. Overwriting the bad 512 bytes would permanently destroy data of that sector. One should check under what partition this sector falls, and whether or not the filesystem on that partition uses the given sector. It might be unused area (which can be safely overwritten), a 512 bytes section of a file, or part of the directory strucutre, journal, superblock, or other are of the filesystem which may or may not tolerate being overwritten. The situation has to be analysed so the impact of overwriting becomes clear.
  2. There is a realistic chance that repeatedly re-reading a failing sector would sooner or later succeed allowing us to recover that 512 bytes of data, however, the extra wear and tear this causes may kill the drive before data can be recovered, making recovery of other areas impossible, so it should only be applied on unhealthy drives after evaluating the risks.
  3. If you manually fix bad sectors on a failing drive and succeed, you end up with a drive that seems healthy but known to be prone to errors. Whether or not that disk should by used in production or not, is your choice and your liability. One might be just better off replacing it with a new disk.

Read on, proceed to the next part of the series!

Sunday 15 September 2019

Ubuntu 18.04 no DNS after VPN

Symptoms

On Ubuntu 18.04, once you connect to VPN (OpenVPN, L2TP or other point-to-point protocols), your system will use the remote peer's DNS server, unless explicitly configured not to use peer DNS. Once the VPN session is closed, local name resolution does not work.

Root cause and quickfix

Turning off and then back on the physical network interface (WiFi or wired) fixed the issue. On this version of Ubuntu, systemd-resolve is responsible for managing changes to, and configuration of domain name resolution. Running systemd-resolve --status correctly shows the original nameserver that was assigned when the connection via the physical interface was established, however this nameserver is not marked as the default and in fact there is no default nameserver once the VPN session is closed.

A quick command like the following recovers the issue: systemd-resolve --set-dns=192.168.0.1 --interface=wlp4s0 but does not resolve the root cause. Further analysis has shown that the error is caused by a file permission issue due to lacking integration of systemd, network manager and ppp. While tracking down such issues can be fun, this case was more annoying than useful

Solution candidate

As in most of the cases, a bit of googling unveils that this problem also affects others. There is a bug report in launchpad, which is marked as resolved with a fix. Unfortunately, that was not applied to 18.04 although it is a long term release. Nevertheless, one can inspect the patch and find that adding a few lines to /etc/ppp/ip-up.d/0000usepeerdns should fix the issue. The point of the patch is to prevent the misbehaving DNS configuration scripts to run when network-manager initiated VPN connections are terminated.

Applying patches directly to the local file system is not my preferred option - I would rather repackage the affected ppp deb or use dpkg-divert to apply local changes in a way that plays nicely together with the packaging system and keeps my system easily manageable in the long run. However, for a quick verification, I have applied the required modification, and found it would not work per se.

Applied solution

Switching to plan B. Upon inspecting /etc/ppp/ip-up.d/0000usepeerdns once can clearly see that if resolvconf - the traditional way how Ubuntu and most Linux distributions would manage name resolution in previous releases - is installed, the problematic part of the script is not executed. I settled with this simpler and cleaner solution, installed the resolvconf package and with that the issue was resolved.

Monday 26 August 2019

Ubuntu 18.04 on ThinkPad P50 (Part 4)

Conflict between libcurl3 and libcurl4

Ubuntu 18.04 includes libcurl4 by default which in fact is required by the packaged version of curl. Some legacy applications depend on libcurl3, which but libcurl3 conflicts with libcurl4. The steps below demonstrate how to alter the control file of such legacy packages to allow libcurl4 instead of libcurl3 and then how to repackage and install these packages.

People following these steps should test the updated legacy applications and confirm they run properly, or revert if they face any issue they cannot resolve.


tb@castor:~$ cd /tmp
tb@castor:/tmp$ mkdir dpkg
tb@castor:/tmp$ cd dpkg/
tb@castor:/tmp/dpkg$ apt download xxxsam osprules 
Get:1 http://ocdc.hursley.xxx.com/ocdc bionic-safe/XXX amd64 xxxsam amd64 3.06-4-ocdc6 [195 kB]
Get:2 http://ocdc.hursley.xxx.com/ocdc bionic-safe/XXX amd64 osprules amd64 1.00.1-2.precise-ocdc2 [34,7 kB]
Fetched 230 kB in 0s (708 kB/s)    
tb@castor:/tmp/dpkg$ ll
total 228
drwxr-xr-x  2 tb   tb       80 aug   26 17:54 ./
drwxrwxrwt 26 root root    680 aug   26 17:54 ../
-rw-r--r--  1 tb   tb   194938 márc  20  2015 xxxsam_3.06-4-ocdc6_amd64.deb
-rw-r--r--  1 tb   tb    34718 júl   13  2012 osprules_1.00.1-2.precise-ocdc2_amd64.deb
tb@castor:/tmp/dpkg$ fakeroot
root@castor:/tmp/dpkg# dpkg-deb -R xxxsam_3.06-4-ocdc6_amd64.deb xxxsam
root@castor:/tmp/dpkg# dpkg-deb -R osprules_1.00.1-2.precise-ocdc2_amd64.deb ospfules
root@castor:/tmp/dpkg# sed -i 's/libcurl3 (>= 7.16.2-1)/libcurl3 (>= 7.16.2-1) | libcurl4/' xxxsam/DEBIAN/control
root@castor:/tmp/dpkg# sed -i 's/libcurl3 (>= 7.16.2-1)/libcurl3 (>= 7.16.2-1) | libcurl4/' ospfules/DEBIAN/control
root@castor:/tmp/dpkg# sed -i 's/\(^Version:.*$\)/\1+dep1/' ospfules/DEBIAN/control
root@castor:/tmp/dpkg# sed -i 's/\(^Version:.*$\)/\1+dep1/' xxxsam/DEBIAN/control
root@castor:/tmp/dpkg# dpkg-deb -b xxxsam xxxsam_3.06-4-ocdc6+dep1_amd64.deb 
dpkg-deb: warning: conffile name '/etc/init.d/xxx-isambios' is duplicated
dpkg-deb: warning: conffile name '/etc/xdg/autostart/xxx-asset-management.desktop' is duplicated
dpkg-deb: warning: ignoring 2 warnings about the control file(s)
dpkg-deb: building package 'xxxsam' in 'xxxsam_3.06-4-ocdc6+dep1_amd64.deb'.
root@castor:/tmp/dpkg# dpkg -b ospfules osprules_1.00.1-2.precise-ocdc2+dep1_amd64.deb 
dpkg-deb: building package 'osprules' in 'osprules_1.00.1-2.precise-ocdc2+dep1_amd64.deb'.
root@castor:/tmp/dpkg# ll
total 452
drwxr-xr-x  4 root root    160 aug   26 18:06 ./
drwxrwxrwt 26 root root    680 aug   26 18:06 ../
drwxr-xr-x  7 root root    140 aug   26 18:00 xxxsam/
-rw-r--r--  1 root root 194938 márc  20  2015 xxxsam_3.06-4-ocdc6_amd64.deb
-rw-r--r--  1 root root 195024 aug   26 18:04 xxxsam_3.06-4-ocdc6+dep1_amd64.deb
drwxr-xr-x  4 root root     80 aug   26 18:00 ospfules/
-rw-r--r--  1 root root  34718 júl   13  2012 osprules_1.00.1-2.precise-ocdc2_amd64.deb
-rw-r--r--  1 root root  29128 aug   26 18:06 osprules_1.00.1-2.precise-ocdc2+dep1_amd64.deb
root@castor:/tmp/dpkg# exit
exit
tb@castor:/tmp/dpkg$ sudo apt install -f ./xxxsam_3.06-4-ocdc6+dep1_amd64.deb 
Reading package lists... Done
Building dependency tree       
Reading state information... Done
Note, selecting 'xxxsam' instead of './xxxsam_3.06-4-ocdc6+dep1_amd64.deb'
The following packages will be upgraded:
  xxxsam
1 upgraded, 0 newly installed, 0 to remove and 0 not upgraded.
Need to get 0 B/195 kB of archives.
After this operation, 0 B of additional disk space will be used.
Get:1 /tmp/dpkg/xxxsam_3.06-4-ocdc6+dep1_amd64.deb xxxsam amd64 3.06-4-ocdc6+dep1 [195 kB]
(Reading database ... 369572 files and directories currently installed.)
Preparing to unpack .../xxxsam_3.06-4-ocdc6+dep1_amd64.deb ...
Unpacking xxxsam (3.06-4-ocdc6+dep1) over (3.06-4-ocdc6) ...
Setting up xxxsam (3.06-4-ocdc6+dep1) ...
.
Processing triggers for systemd (237-3ubuntu10.25) ...
Processing triggers for ureadahead (0.100.0-21) ...
tb@castor:/tmp/dpkg$ sudo apt install -f ./osprules_1.00.1-2.precise-ocdc2+dep1_amd64.deb 
Reading package lists... Done
Building dependency tree       
Reading state information... Done
Note, selecting 'osprules' instead of './osprules_1.00.1-2.precise-ocdc2+dep1_amd64.deb'
The following packages will be upgraded:
  osprules
1 upgraded, 0 newly installed, 0 to remove and 0 not upgraded.
Need to get 0 B/29,1 kB of archives.
After this operation, 0 B of additional disk space will be used.
Get:1 /tmp/dpkg/osprules_1.00.1-2.precise-ocdc2+dep1_amd64.deb osprules amd64 1.00.1-2.precise-ocdc2+dep1 [29,1 kB]
(Reading database ... 369572 files and directories currently installed.)
Preparing to unpack .../osprules_1.00.1-2.precise-ocdc2+dep1_amd64.deb ...
Unpacking osprules (1.00.1-2.precise-ocdc2+dep1) over (1.00.1-2.precise-ocdc2) ...
Setting up osprules (1.00.1-2.precise-ocdc2+dep1) ...
Creating symbolic links ...
tb@castor:/tmp/dpkg$