extractTarFork() process ended with ERROR: 255

[dexbyte]

E: ADB Restore Failed.
I had the same problem with TWRP 3.1.0 and TWRP 3.1.1 didn't fix this bug either. I am trying to restore the backup created via adb to pc. Restore always fails.

[tjanez]

I've probably encountered the same issue on my Nexus 4 with TWRP 3.1.1.

Restoring the System partition succeeds, however restoring the Data partition fails with:

I:Unable to extract tar archive '/data/media/0/TWRP/BACKUPS/00867e6ad793a5eb/2017-05-21--08-51-47_LMY48T/data.ext4.win000'
Error during restore process.
I:Error extracting '/data/media/0/TWRP/BACKUPS/00867e6ad793a5eb/2017-05-21--08-51-47_LMY48T/data.ext4.win000' in thread ID 0
I:Error extracting split archive.
Error during restore process.
extractTarFork() process ended with ERROR: 255

Here is the complete log output:

I:operation_start: 'Nandroid'
[RESTORE STARTED]
Restore folder: '/data/media/0/TWRP/BACKUPS/00867e6ad793a5eb/2017-05-21--08-51-47_LMY48T'
Verifying MD5
Calculating restore details...
MD5 matched for '/data/media/0/TWRP/BACKUPS/00867e6ad793a5eb/2017-05-21--08-51-47_LMY48T/system.ext4.win'.
I:InfoManager loading from '/data/media/0/TWRP/BACKUPS/00867e6ad793a5eb/2017-05-21--08-51-47_LMY48T/system.info'.
I:Read info file, restore size is 838259712
I:split_filename: /data/media/0/TWRP/BACKUPS/00867e6ad793a5eb/2017-05-21--08-51-47_LMY48T/data.ext4.win000
MD5 matched for '/data/media/0/TWRP/BACKUPS/00867e6ad793a5eb/2017-05-21--08-51-47_LMY48T/data.ext4.win000'.
I:split_filename: /data/media/0/TWRP/BACKUPS/00867e6ad793a5eb/2017-05-21--08-51-47_LMY48T/data.ext4.win001
MD5 matched for '/data/media/0/TWRP/BACKUPS/00867e6ad793a5eb/2017-05-21--08-51-47_LMY48T/data.ext4.win001'.
I:split_filename: /data/media/0/TWRP/BACKUPS/00867e6ad793a5eb/2017-05-21--08-51-47_LMY48T/data.ext4.win002
I:TWFunc::Set_Brightness: Setting brightness control to 5
MD5 matched for '/data/media/0/TWRP/BACKUPS/00867e6ad793a5eb/2017-05-21--08-51-47_LMY48T/data.ext4.win002'.
I:InfoManager loading from '/data/media/0/TWRP/BACKUPS/00867e6ad793a5eb/2017-05-21--08-51-47_LMY48T/data.info'.
I:Read info file, restore size is 3867481600
MD5 matched for '/data/media/0/TWRP/BACKUPS/00867e6ad793a5eb/2017-05-21--08-51-47_LMY48T/boot.emmc.win'.
I:InfoManager file '/data/media/0/TWRP/BACKUPS/00867e6ad793a5eb/2017-05-21--08-51-47_LMY48T/boot.info' not found.
I:Restore file system is: 'emmc'.
Restoring 3 partitions...
Total restore size is 4509MB
I:Restore filename is: /data/media/0/TWRP/BACKUPS/00867e6ad793a5eb/2017-05-21--08-51-47_LMY48T/system.ext4.win
I:Restore file system is: 'ext4'.
I:Restore file system is: 'ext4'.
Wiping System
Formatting system using make_ext4fs...
Creating filesystem with parameters:
    Size: 880803840
    Block size: 4096
    Blocks per group: 32768
    Inodes per group: 7680
    Inode size: 256
    Journal blocks: 3360
    Label: 
    Blocks: 215040
    Block groups: 7
    Reserved block group size: 55
Created filesystem with 11/53760 inodes and 6965/215040 blocks
I:TWFunc::Set_Brightness: Setting brightness control to 0
Restoring System...
I:InfoManager loading from '/data/media/0/TWRP/BACKUPS/00867e6ad793a5eb/2017-05-21--08-51-47_LMY48T/system.info'.
I:Read info file, restore size is 838259712
I:Single archive
I:Setting archive type
I:Extracting uncompressed tar
  ==> extracting: /system//app/ (mode 40755, directory)
  [ ... output trimmed ... ]
  ==> extracting: /system//recovery-from-boot.bak (file size 83495 bytes)
I:extractTarFork() process ended with RC=0
I:Reset capabilities of /system/bin/run-as binary successful.
[System done (83 seconds)]
I:Restore filename is: /data/media/0/TWRP/BACKUPS/00867e6ad793a5eb/2017-05-21--08-51-47_LMY48T/data.ext4.win
I:Restore file system is: 'ext4'.
I:Restore file system is: 'ext4'.
Wiping Data (excl. storage)
Wiping data without wiping /data/media ...
I:skipped '/data/lost+found'
I:skipped '/data/media'
I:skipped '/data/.layout_version'
Done.
I:sending message to add 65537 '/data/media/0' 'Internal Storage'
I:[MTP] mtppipe add storage 65537 '/data/media/0'
I:[MTP] MtpStorage id: 65537 path: /data/media/0
E:[MTP] MtpServer::addStorage Storage for storage ID 65537 already exists.
I:Message sent, add storage ID: 65537
Restoring Data (excl. storage)...
I:InfoManager loading from '/data/media/0/TWRP/BACKUPS/00867e6ad793a5eb/2017-05-21--08-51-47_LMY48T/data.info'.
I:Read info file, restore size is 3867481600
I:Multiple archives
I:First tar file '/data/media/0/TWRP/BACKUPS/00867e6ad793a5eb/2017-05-21--08-51-47_LMY48T/data.ext4.win000' not encrypted
I:Setting archive type
I:Extracting uncompressed tar
  ==> extracting: //data/dontpanic/ (mode 40750, directory)
  ==> extracting: //data/misc/ (mode 41771, directory)
  ==> extracting: //data/misc/adb/ (mode 42750, directory)
  ==> extracting: //data/misc/adb/adb_keys (file size 2147 bytes)
  [ ... output trimmed ... ]
  ==> extracting: //data/data/com.google.android.gms/app_webview/Cache/6288c862ae5df182_0 (file size 3859 bytes)
  ==> extracting: //data/data/com.google.android.gms/app_webview/Cache/cd33a17aa6ec6eb7_0 (file size 89037 bytes)
I:Unable to extract tar archive '/data/media/0/TWRP/BACKUPS/00867e6ad793a5eb/2017-05-21--08-51-47_LMY48T/data.ext4.win000'
Error during restore process.
I:Error extracting '/data/media/0/TWRP/BACKUPS/00867e6ad793a5eb/2017-05-21--08-51-47_LMY48T/data.ext4.win000' in thread ID 0
I:Error extracting split archive.
Error during restore process.
extractTarFork() process ended with ERROR: 255
I:Set page: 'action_complete'
I:TWFunc::Set_Brightness: Setting brightness control to 114
I:operation_end - status=1
I:Set overlay: ''
I:TWFunc::Set_Brightness: Setting brightness control to 5
I:TWFunc::Set_Brightness: Setting brightness control to 0
I:TWFunc::Set_Brightness: Setting brightness control to 114
I:Set overlay: ''
I:Set page: 'clear_vars'
I:Set page: 'restore_select'
I:Set page: 'restore'
I:Set page: 'main'
I:Set page: 'clear_vars'
I:Set page: 'main2'
I:Set page: 'advanced'
I:Set page: 'copylog'
I:Set page: 'action_page'
I:operation_start: 'Copy Log'
I:Copying file /tmp/recovery.log to /data/media/0/recovery.log

[dexbyte]

@tjanez Go to Mount and unmount the data partition then try to restore the backup, it might work. In my case, it doesn't even pass restoring the System partition.

[CP-4]

@dexbyte

[RESTORE STARTED]
Restore folder: '/data/media/0/TWRP/BACKUP/ff04fa7a/2017-........'
Skipping MD5 check based on user setting.
Calculating restore details...
Restoring 3 partitions...
Total restore size is 5746MB
Restoring Boot...
[Boot done (1 second)]
Wiping Data
Wiping data without wiping /data/media ...
Done.
Restoring Data...
extractTarFork() process ended with ERROR: 255

If i go to Mount and untick Data partition, the restore is no longer shown. It is only shown when data is mounted.

[nkk71]

@tjanez
Can you hexdump the last 2048 bytes of your '/2017-05-21--08-51-47_LMY48T/data.ext4.win000' file

[CaptainThrowback]

I believe there's a fix for this issue on Gerrit, pending review: https://gerrit.omnirom.org/24146

[crok]

It has been committed at Jul 21, 2017 8:37 PM - do you know when it will be released to us?

[BuildingAtom]

I'm not sure if this is the same exact issue, but I just got back from repairing my data backup for my phone. I went through the backup with a hex editor, and it seems like information that's supposed to go to the recovery log sometimes ends up in the tar file instead. This offsets the blocks in the tar and renders it unreadable since tar expects everything to line up along 512 byte blocks.

I found the line storing xattr user.default. (hex 73 74 6F 72 69 6E 67 20 78 61 74 74 72 20 75 73 65 72 2E 64 65 66 61 75 6C 74 0A) between random blocks multiple times, and I:Closing tar. (hex 49 3A 43 6C 6F 73 69 6E 67 20 74 61 72 0A) somewhere between the last few blocks. Once I removed these with a hex editor and made sure all the tar headers lined up along the blocks, I was able to use the backup again.

I think the Gerrit fixed a different problem that could also cause the same error.

Also, when I was making this backup, I was also using MTP at the same time. Not sure if that matters.

[nkk71]

@BuildingAtom
I can't say 100%, but I'm pretty sure the commit https://gerrit.omnirom.org/#/c/24146/ (merged) will fix it. I can only replicate the leaked strings if I force closing stdout, at which point the backup will show the same corruption you mentioned, and as per my initial repair commit https://gerrit.omnirom.org/#/c/23866/
Which I stopped because I didn't think it's worth updating for the extra leaked strings (as mentioned in the comments of the patchset), which cannot (easily) be done during the restore, so it would have to "clean" the file prior to restoring it. I could update it, but really don't think it's worth it, for the few corrupt backups we've seen.
I did trace the error and usually the random close(fd) mentioned in the commit closes 0 (in my tests), but if it were to close(1), then you'd get the corrupt backup you mentioned.
As to why only certain strings are getting leaked, it's a wild guess, but I'm thinking that the puts() are getting leaked into the tar, but the printf() are just going to nowhere instead of the tar, strange, but that's my only thought.

[BuildingAtom]

@nkk71
Ah, I see. I didn't get how the commit fixed the leaked strings at first. If puts() and printf() are doing that, that's definitely strange since afaik they should both go to the same output. Imo, adding a repair function is not worth it regardless. If the issue was fixed (which it probably was), then the corrupted backups should be cleaned outside of the recovery environment.

Also, even though the repair commit is abandoned, I can verify that storing xattr user.default. (and I assume the other strings as well) can find itself in the middle of a file, although for me it was near the end of the file, which makes some sense. I've also seen the line repeated 3 times in a row between blocks, which doesn't make sense.

I'm thinking that I might try making a separate tool to clean these files. At the very least, I'll get some more experience trying.

[nkk71]

@BuildingAtom
Though all the commands are printf's, from my understanding, those will get optimized into 2 types:

1. puts when it's a simple string
2. the full printf() when there are actual variables

the latter doesn't seem to get leaked into the tar, we can confirm that from the recovery.log taken in the backup folder, all information stops after the 1st tar, and we don't even see the ending:
"Thread ID %i finished successfully."
in the recovery.log

I can confirm the following strings are leaked:
const char *leaked_strings[] = { "I:Closing tar\n", "storing xattr user.default\n", "storing xattr user.inode_cache\n", "storing xattr user.inode_code_cache\n", NULL };
(excluding the trailing null of course)

The "Closing Tar" will be found just before the last 2x512bytes of EOF null chars (so EOF-1024-14), but the others will be randomly inserted somewhere (including possibly the file contents themselves), so stripping them isn't easy during a live restore, it can however be done for the entire file.

[BuildingAtom]

My friend and I both created our own external tools to "clean" these "corrupted" backups and tackled the problem in slightly different ways. You can find my tool CleanTwrpTar here, and my friend's tool TarCleaner here. He should be coming on relatively soon to post his tool and info.

While the tool I made is technically incomplete, it should be capable of cleaning these leaked strings from the backup files. I did make a few assumptions based on data I had such as the appearance of leaked strings occurring only along block boundaries, but I think they were relatively safe assumptions.

[venerjoel99]

@BuildingAtom has showed me this thread, and in response to this thread, he and I created our own separate tar file cleaner tools that takes out the specified leaked strings from them and produces a new clean copy of the corrupted tar file. Here is @BuildingAtom 's tool, and here is mine. For my project, I have several releases, with the newest one being the most optimized. However, some optimizations are based on assumptions that the leaked strings are between 512-byte blocks, so the first release does the most thorough search but with the slowest runtime. The runtime of the program will mostly depend on the sizes of the files these leaked strings take place at

[crok]

Thank you, @BuildingAtom and @venerjoel99! Will try the scripts!

[nkk71]

@venerjoel99 @BuildingAtom
Though I haven't looked at your tools (my bad) you cannot make the assumption of the leaked strings are contained in a 512byte block, they are not, otherwise I would have pushed PS3 and be done with it a long time ago ;)
(actually I do have a working version (PS4) of inline fixes but it's messy and I wouldn't push that kinda code into twrp)

You'll just need to go over the entire file in whatever block size you choose, but you'll need to overlap, ie rewind enough to make sure the lengthiest string will be properly detected.

[BuildingAtom]

@nkk71
I'm sorry, could you elaborate a bit more on that last part? From what I found, the only reason a leaked string would be within a 512 byte block and not between two blocks would be if there was already a leaked string before that string.

Because I was concerned about the rare off chance that the leaked strings might be a legitimate part of files, I tried to limit the areas where the program searched for the strings. Although I haven't exactly written it in my readme yet, my program looks for the next header location (it assumes that there's always added data) and based off of that offset, it first searches the area directly before the header, then it searches the file content of the previous header, skipping 512-byte chunks of data at a time.

Also, sorry if this is a dumb question, but what do PS3 and PS4 stand for?