btrfs icon indicating copy to clipboard operation
btrfs copied to clipboard

Published 20 hours ago • verified publisher icon maharmstone

Snapshot from the «send» features are incompatible with Linux's «btrfs receive»

Open ticpu opened this issue 2 years ago • 6 comments

When trying to import the image, I get this error:

jerome in p4 in /mnt/btrfs/snapshots🔒 
❯ sudo btrfs receive -v -f ../stream/bs.btrfs --dump
subvol          ./Snapshot\ of\ Beat\ Saber\ (2022-04-30) uuid=677dc0d6-dd1b-d309-f15b-b603f09dabe1 transid=88588
set_xattr       ./Snapshot\ of\ Beat\ Saber\ (2022-04-30)/ name=security.NTACL data= len=280
chown           ./Snapshot\ of\ Beat\ Saber\ (2022-04-30)/ gid=100 uid=65534
chmod           ./Snapshot\ of\ Beat\ Saber\ (2022-04-30)/ mode=755
utimes          ./Snapshot\ of\ Beat\ Saber\ (2022-04-30)/ atime=2021-09-15T00:39:32-0400 mtime=2022-04-12T21:40:26-0400 ctime=2022-04-30T15:09:01-0400
mkdir           ./Snapshot\ of\ Beat\ Saber\ (2022-04-30)/o257-245-0
rename          ./Snapshot\ of\ Beat\ Saber\ (2022-04-30)/o257-245-0 dest=./Snapshot of Beat Saber (2022-04-30)/Beat Saber_Data
utimes          ./Snapshot\ of\ Beat\ Saber\ (2022-04-30)/ atime=2021-09-15T00:39:32-0400 mtime=2022-04-12T21:40:26-0400 ctime=2022-04-30T15:09:01-0400
set_xattr       ./Snapshot\ of\ Beat\ Saber\ (2022-04-30)/Beat\ Saber_Data name=security.NTACL data= len=280
chown           ./Snapshot\ of\ Beat\ Saber\ (2022-04-30)/Beat\ Saber_Data gid=100 uid=65534
chmod           ./Snapshot\ of\ Beat\ Saber\ (2022-04-30)/Beat\ Saber_Data mode=755
utimes          ./Snapshot\ of\ Beat\ Saber\ (2022-04-30)/Beat\ Saber_Data atime=2021-09-15T00:50:21-0400 mtime=2022-03-31T23:47:33-0400 ctime=2022-03-31T23:47:33-0400
mkfile          ./Snapshot\ of\ Beat\ Saber\ (2022-04-30)/o258-245-0
rename          ./Snapshot\ of\ Beat\ Saber\ (2022-04-30)/o258-245-0 dest=./Snapshot of Beat Saber (2022-04-30)/Beat Saber_Data/app.info
ERROR: failed to convert time -5166429213304716051.3401201028 to local time
ERROR: failed to dump the send stream: Invalid argument

ticpu avatar Apr 30 '22 19:04 ticpu

Interesting. What does stat say for this file? And what does Windows give as its file times - something nonsensical?

maharmstone avatar May 01 '22 16:05 maharmstone

On Windows, it appears as an inline file with the following dates: 2022-05-02 01_44_49-Window

On Linux:

# stat app.info 
  File: app.info
  Size: 31        	Blocks: 8          IO Block: 4096   regular file
Device: 200074h/2097268d	Inode: 258         Links: 1
Access: (0644/-rw-r--r--)  Uid: (65534/  nobody)   Gid: (  100/   users)
Access: 2021-09-15 00:50:21.951835400 -0400
Modify: 2021-09-15 00:00:17.391920500 -0400
Change: 2021-12-10 20:01:22.891444600 -0500
 Birth: 2021-09-15 00:50:21.951835400 -0400

btrfs send | receive seems to be doing fine on Linux too:

# btrfs send "Snapshot of Beat Saber (2022-04-30)" | btrfs receive --dump | head -n 100
At subvol Snapshot of Beat Saber (2022-04-30)
subvol          ./Snapshot\ of\ Beat\ Saber\ (2022-04-30) uuid=677dc0d6-dd1b-d309-f15b-b603f09dabe1 transid=88588
set_xattr       ./Snapshot\ of\ Beat\ Saber\ (2022-04-30)/ name=security.NTACL data= len=280
chown           ./Snapshot\ of\ Beat\ Saber\ (2022-04-30)/ gid=100 uid=65534
chmod           ./Snapshot\ of\ Beat\ Saber\ (2022-04-30)/ mode=755
utimes          ./Snapshot\ of\ Beat\ Saber\ (2022-04-30)/ atime=2021-09-15T00:39:32-0400 mtime=2022-04-12T21:40:26-0400 ctime=2022-04-30T15:09:01-0400
mkdir           ./Snapshot\ of\ Beat\ Saber\ (2022-04-30)/o257-245-0
rename          ./Snapshot\ of\ Beat\ Saber\ (2022-04-30)/o257-245-0 dest=./Snapshot of Beat Saber (2022-04-30)/Beat Saber_Data
utimes          ./Snapshot\ of\ Beat\ Saber\ (2022-04-30)/ atime=2021-09-15T00:39:32-0400 mtime=2022-04-12T21:40:26-0400 ctime=2022-04-30T15:09:01-0400
set_xattr       ./Snapshot\ of\ Beat\ Saber\ (2022-04-30)/Beat\ Saber_Data name=security.NTACL data= len=280
chown           ./Snapshot\ of\ Beat\ Saber\ (2022-04-30)/Beat\ Saber_Data gid=100 uid=65534
chmod           ./Snapshot\ of\ Beat\ Saber\ (2022-04-30)/Beat\ Saber_Data mode=755
utimes          ./Snapshot\ of\ Beat\ Saber\ (2022-04-30)/Beat\ Saber_Data atime=2021-09-15T00:50:21-0400 mtime=2022-03-31T23:47:33-0400 ctime=2022-03-31T23:47:33-0400
mkfile          ./Snapshot\ of\ Beat\ Saber\ (2022-04-30)/o258-245-0
rename          ./Snapshot\ of\ Beat\ Saber\ (2022-04-30)/o258-245-0 dest=./Snapshot of Beat Saber (2022-04-30)/Beat Saber_Data/app.info
utimes          ./Snapshot\ of\ Beat\ Saber\ (2022-04-30)/Beat\ Saber_Data atime=2021-09-15T00:50:21-0400 mtime=2022-03-31T23:47:33-0400 ctime=2022-03-31T23:47:33-0400
set_xattr       ./Snapshot\ of\ Beat\ Saber\ (2022-04-30)/Beat\ Saber_Data/app.info name=security.NTACL data= len=192
write           ./Snapshot\ of\ Beat\ Saber\ (2022-04-30)/Beat\ Saber_Data/app.info offset=0 len=31
chown           ./Snapshot\ of\ Beat\ Saber\ (2022-04-30)/Beat\ Saber_Data/app.info gid=100 uid=65534
chmod           ./Snapshot\ of\ Beat\ Saber\ (2022-04-30)/Beat\ Saber_Data/app.info mode=644
utimes          ./Snapshot\ of\ Beat\ Saber\ (2022-04-30)/Beat\ Saber_Data/app.info atime=2021-09-15T00:50:21-0400 mtime=2021-09-15T00:00:17-0400 ctime=2021-12-10T20:01:22-0500
mkfile          ./Snapshot\ of\ Beat\ Saber\ (2022-04-30)/o259-245-0
rename          ./Snapshot\ of\ Beat\ Saber\ (2022-04-30)/o259-245-0 dest=./Snapshot of Beat Saber (2022-04-30)/Beat Saber_Data/boot.config
utimes          ./Snapshot\ of\ Beat\ Saber\ (2022-04-30)/Beat\ Saber_Data atime=2021-09-15T00:50:21-0400 mtime=2022-03-31T23:47:33-0400 ctime=2022-03-31T23:47:33-0400
set_xattr       ./Snapshot\ of\ Beat\ Saber\ (2022-04-30)/Beat\ Saber_Data/boot.config name=security.NTACL data= len=192
write           ./Snapshot\ of\ Beat\ Saber\ (2022-04-30)/Beat\ Saber_Data/boot.config offset=0 len=142
chown           ./Snapshot\ of\ Beat\ Saber\ (2022-04-30)/Beat\ Saber_Data/boot.config gid=100 uid=65534
chmod           ./Snapshot\ of\ Beat\ Saber\ (2022-04-30)/Beat\ Saber_Data/boot.config mode=644
utimes          ./Snapshot\ of\ Beat\ Saber\ (2022-04-30)/Beat\ Saber_Data/boot.config atime=2021-09-15T00:50:21-0400 mtime=2021-09-15T00:00:17-0400 ctime=2021-12-10T20:01:22-0500
[...]

ticpu avatar May 02 '22 05:05 ticpu

I also noticed that it doesn't happen to be the same file every time a send/receive operation is attempted.

At subvol Snapshot of Beat Saber (2022-06-07)
ERROR: utimes o269-150798-0/142e6 (DRUM GO DUM - Sotarks) failed: Invalid argument
...
At subvol Snapshot of Beat Saber (2022-06-07)
ERROR: utimes o269-150798-0/11a7c (Dokidoki Parirarura - nsenuesu) failed: Invalid argument
...
At subvol Snapshot of Beat Saber (2022-06-07)
ERROR: utimes o269-150798-0/12240 (Game Over - Joshabi) failed: Invalid argument
...
At subvol Snapshot of Beat Saber (2022-06-07)
ERROR: utimes o269-150798-0/1059c (MORE - Dack) failed: Invalid argument

It seems to be random.

Cheating btrfs receive by patching the code to ignore wrong utimes, the rest seems to be doing ok.

Chroot to /mnt/btrfs/snapshots/fuse
At subvol Snapshot of Beat Saber (2022-06-07)
ERROR: utimes o269-150798-0/1657f (Ubi - Swifter1243) failed: Invalid argument
ERROR: utimes o269-150798-0/1657f (Ubi - Swifter1243) failed: Invalid argument
ERROR: utimes o269-150798-0/1657f (Ubi - Swifter1243) failed: Invalid argument
ERROR: utimes o269-150798-0/1657f (Ubi - Swifter1243) failed: Invalid argument
ERROR: utimes o269-150798-0/4d44 (Lean On - Funrankable) failed: Invalid argument
ERROR: utimes o269-150798-0/4d44 (Lean On - Funrankable) failed: Invalid argument
ERROR: utimes o269-150798-0/4d44 (Lean On - Funrankable) failed: Invalid argument
ERROR: utimes o269-150798-0/4d44 (Lean On - Funrankable) failed: Invalid argument
ERROR: utimes o269-150798-0/4d44 (Lean On - Funrankable) failed: Invalid argument
ERROR: utimes o269-150798-0/4d44 (Lean On - Funrankable) failed: Invalid argument
ERROR: utimes o269-150798-0/4d44 (Lean On - Funrankable) failed: Invalid argument
ERROR: utimes o269-150798-0/4d44 (Lean On - Funrankable) failed: Invalid argument
ERROR: utimes o269-150798-0/4d44 (Lean On - Funrankable) failed: Invalid argument
ERROR: utimes o269-150798-0/4d44 (Lean On - Funrankable) failed: Invalid argument
ERROR: utimes o269-150798-0/4d44 (Lean On - Funrankable) failed: Invalid argument
ERROR: utimes o269-150798-0/4d44 (Lean On - Funrankable) failed: Invalid argument
ERROR: utimes o269-150798-0/4d44 (Lean On - Funrankable) failed: Invalid argument
ERROR: utimes o269-150798-0/4d44 (Lean On - Funrankable) failed: Invalid argument
ERROR: utimes o269-150798-0/4d44 (Lean On - Funrankable) failed: Invalid argument
ERROR: utimes o269-150798-0/4d44 (Lean On - Funrankable) failed: Invalid argument
ERROR: utimes o269-150798-0/55a0 (Blow - HelenCarnate) failed: Invalid argument
ERROR: utimes o269-150798-0/55a0 (Blow - HelenCarnate) failed: Invalid argument
...
#ls -l Snapshot\ of\ Beat\ Saber\ \(2022-06-07\)/
total 27216
drwxr-xr-x 1 nobody users      202 370299041679933440 'Beat Saber_Data'
-rw-r--r-- 1 nobody users   650752 sep 14  2021 'Beat Saber.exe'
-rw-r--r-- 1 nobody users        6 avr 12 21:37  BeatSaberVersion.txt
-rw-r--r-- 1 nobody users      656 mar 19 22:00  beatsaber.vrmanifest
drwxr-xr-x 1 nobody users      780 3906933362199101440  CustomAvatars
drwxr-xr-x 1 nobody users      324 3760850048309526528  CustomNotes
drwxr-xr-x 1 nobody users     1456 4049361899437948928  CustomSabers
...
drwx------ 1 root   root       188 jun  8 03:26  o1742-150798-0
drwx------ 1 root   root        32 jun  8 03:25  o1752-150798-0
drwx------ 1 root   root        94 jun  8 03:26  o1753-150798-0
drwx------ 1 root   root        16 jun  8 03:26  o1755-150798-0
...

So, other than that, it seems that folders aren't renamed correctly when the dates are wrong and some folders have dates completely wrong but since they weren't negative, didn't give any errors for receive.

File presents seems to be intact, even those in o- folders.

#file IPA.exe 
IPA.exe: PE32 executable (console) Intel 80386 Mono/.Net assembly, for MS Windows

#gzip -dc ./o2368-150798-0/2022.05.19.00.05.47.log.gz | tail -n4
[DEBUG @ 02:00:00 | BeatSaberMarkupLanguage] NotifyUpdater destroyed.
[DEBUG @ 02:00:00 | BeatSaberMarkupLanguage] NotifyUpdater destroyed.
[DEBUG @ 02:00:00 | FasterScroll] FasterScrollController: OnDestroy()
[DEBUG @ 02:00:00 | PerformanceMeter] PerformanceMeterController: OnDestroy()

ticpu avatar Jun 08 '22 07:06 ticpu

Closing old issues

maharmstone avatar Nov 30 '23 01:11 maharmstone

@maharmstone I believe this problem is still present. I just tried with WinBtrfs 1.8.2 with the same kind of procedure and receiving the snapshots ends with: ERROR: utimes o274-553457-0/256b4 (Inu no outa - fqrb) failed: Invalid argument

It seems the send operation on WinBtrfs is seldomly saving wrong utime values.

ticpu avatar Dec 11 '23 00:12 ticpu

Thanks, I'll re-examine it

maharmstone avatar Dec 11 '23 01:12 maharmstone