Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Bug: referenced path cannot exist #7

Closed
Mek101 opened this issue Sep 12, 2021 · 17 comments
Closed

Bug: referenced path cannot exist #7

Mek101 opened this issue Sep 12, 2021 · 17 comments

Comments

@Mek101
Copy link

Mek101 commented Sep 12, 2021

time ./btrfs-diff-go /mountpoints/raid1/private/mek101/data_snapshot.20210816/ /mountpoints/raid1/private/mek101/data_snapshot.20210912/
BUG? referenced path o94102-212-0/LG_Firmware_Extract_v1.2.6.1 cannot exist

real	0m21,881s
user	0m1,695s
sys	0m13,085s

Seems like it doesn't handle newly created folders. Perhaps folders created anew start with a random name, and then are renamed like the files?

@Mek101
Copy link
Author

Mek101 commented Sep 12, 2021

I'm currently testing the sh version

@mbideau
Copy link
Owner

mbideau commented Oct 15, 2021

Hey @Mek101,
Thank you again for your feedback. That's really really appreciated 😉
I will try to reproduce the bug in a test case and fix it this weekend, or by the end of the month.
I keep you posted anyway.

@vbargsten
Copy link

Hitting the same problem. Here is some debug log with the problem node:

[DEBUG] 13:56:11.733897 BTRFS_SEND_C_UTIMES -> ignored
[DEBUG] 13:56:11.733899     ignoring (as specified in command definitions)
[DEBUG] 13:56:11.733903 command size: '43' ([43 0 0 0])
[DEBUG] 13:56:11.733906 command type: '9' ([9 0])
[DEBUG] 13:56:11.733911 BTRFS_SEND_C_RENAME -> renamed
[DEBUG] 13:56:11.733914     'renamed' operation
[DEBUG] 13:56:11.733917         reading param (C.BTRFS_SEND_A_PATH) ...
[DEBUG] 13:56:11.733920             param type: '15' (expected: 15, raw: [15 0])
[DEBUG] 13:56:11.733926             param length: '22' (raw: [22 0])
[DEBUG] 13:56:11.733931             param: 'vbargsten/texmf/source' (str:'vbargsten/texmf/source', raw: [118 98 97 114 103 115 116 101 110 47 116 101 120 109 102 47 115 111 117 114 99 101])
[DEBUG] 13:56:11.733937         from: 'vbargsten/texmf/source'
[DEBUG] 13:56:11.733942         reading param (C.BTRFS_SEND_A_PATH_TO) ...
[DEBUG] 13:56:11.733949             param type: '16' (expected: 16, raw: [16 0])
[DEBUG] 13:56:11.733954             param length: '13' (raw: [13 0])
[DEBUG] 13:56:11.733961             param: 'o559687-114-0' (str:'o559687-114-0', raw: [111 53 53 57 54 56 55 45 49 49 52 45 48])
[DEBUG] 13:56:11.733968         to: 'o559687-114-0'
[DEBUG] 13:56:11.733972         updating the diff double tree
[DEBUG] 13:56:11.733977             searching for 'from' node
[DEBUG] 13:56:11.733982                 splitted path in parts, processing each one ...
[DEBUG] 13:56:11.733988                     - vbargsten
[DEBUG] 13:56:11.733995                         parent node is _n('', St:!!!, ori:/, oriSt:!!!, child:1)
[DEBUG] 13:56:11.734001                         getting the node in the children (New tree)
[DEBUG] 13:56:11.734009                             found: _n('vbargsten', St:!!!, ori:<same>, oriSt:!!!, child:8)
[DEBUG] 13:56:11.734014                         node exists (New tree)
[DEBUG] 13:56:11.734018                     - texmf
[DEBUG] 13:56:11.734026                         parent node is _n('vbargsten', St:!!!, ori:<same>, oriSt:!!!, child:8)
[DEBUG] 13:56:11.734031                         getting the node in the children (New tree)
[DEBUG] 13:56:11.734038                             found: _n('texmf', St:!!!, ori:<same>, oriSt:!!!, child:0)
[DEBUG] 13:56:11.734044                         node exists (New tree)
[DEBUG] 13:56:11.734049                     - source
[DEBUG] 13:56:11.734055                         parent node is _n('texmf', St:!!!, ori:<same>, oriSt:!!!, child:0)
[DEBUG] 13:56:11.734061                         getting the node in the children (New tree)
[DEBUG] 13:56:11.734076                             found: <nil>
[DEBUG] 13:56:11.734081                         creating the node
[DEBUG] 13:56:11.734087                             created: _n('source', St:!!!, child:0)
[DEBUG] 13:56:11.734093                             added to its parent node (New tree)
[DEBUG] 13:56:11.734099                             the parent node have an old version (Original tree)
[DEBUG] 13:56:11.734106                                 old parent: _n('texmf', St:!!!, child:1)
[DEBUG] 13:56:11.734112                                 getting the old node (Original tree)
[DEBUG] 13:56:11.734125                                     found: <nil>
[DEBUG] 13:56:11.734131                                 isNew is 'false' or the parent part isn't the last one
[DEBUG] 13:56:11.734136                                 creating old node
[DEBUG] 13:56:11.734144                                     old node created: _n('source', St:!!!, child:0)
[DEBUG] 13:56:11.734151                                     added to old parent node 'texmf' (Original tree)
[DEBUG] 13:56:11.734158                 returning node '_n('source', St:!!!, ori:<same>, oriSt:!!!, child:0)'
[DEBUG] 13:56:11.734166             found: _n('source', St:!!!, ori:<same>, oriSt:!!!, child:0)
[DEBUG] 13:56:11.734171             it's a renaming
[DEBUG] 13:56:11.734176                 removing it from its parent node 'texmf' (New tree)
[DEBUG] 13:56:11.734180                 set old node St to 'renamed' (Original tree)
[DEBUG] 13:56:11.734186                 old node is now: _n('source', St:renamed, child:0)
[DEBUG] 13:56:11.734192             searching for 'to' node
[DEBUG] 13:56:11.734195                 splitted path in parts, processing each one ...
[DEBUG] 13:56:11.734199                     - o559687-114-0
[DEBUG] 13:56:11.734203                         parent node is _n('', St:!!!, ori:/, oriSt:!!!, child:1)
[DEBUG] 13:56:11.734206                         getting the node in the children (New tree)
[DEBUG] 13:56:11.734216                             found: <nil>
[DEBUG] 13:56:11.734219                         creating the node
[DEBUG] 13:56:11.734224                             created: _n('o559687-114-0', St:!!!, child:0)
[DEBUG] 13:56:11.734230                             added to its parent node (New tree)
[DEBUG] 13:56:11.734235                             the parent node have an old version (Original tree)
[DEBUG] 13:56:11.734242                                 old parent: _n('/', St:!!!, child:1)
[DEBUG] 13:56:11.734248                                 getting the old node (Original tree)
[DEBUG] 13:56:11.734262                                     found: <nil>
[DEBUG] 13:56:11.734267                                     not creating the old node because it is new (true)
[DEBUG] 13:56:11.734275                 returning node '_n('o559687-114-0', St:!!!, child:0)'
[DEBUG] 13:56:11.734281             found: _n('o559687-114-0', St:!!!, child:0)
[DEBUG] 13:56:11.734286             it's a renaming (bis)
[DEBUG] 13:56:11.734292                 adding the 'from' node to the 'to' node parent tree at name 'o559687-114-0' (New tree)
[DEBUG] 13:56:11.734298                 'from' node Name is replaced by the 'to' node Name 'o559687-114-0'
[DEBUG] 13:56:11.734304                 'from' node Op is set to 'added'
[DEBUG] 13:56:11.734310                 'from' node Parent is assigned the 'to' node Parent ''
[DEBUG] 13:56:11.734318                 now node is: _n('o559687-114-0', St:added, ori:source, oriSt:renamed, child:0)
[DEBUG] 13:56:11.734323         'renamed' operation processed
[DEBUG] 13:56:11.734331 command size: '67' ([67 0 0 0])
[DEBUG] 13:56:11.734335 command type: '20' ([20 0])
[DEBUG] 13:56:11.734339 BTRFS_SEND_C_UTIMES -> ignored
[DEBUG] 13:56:11.734343     ignoring (as specified in command definitions)
[DEBUG] 13:56:11.734348 command size: '42' ([42 0 0 0])
[DEBUG] 13:56:11.734352 command type: '9' ([9 0])
[DEBUG] 13:56:11.734357 BTRFS_SEND_C_RENAME -> renamed
[DEBUG] 13:56:11.734361     'renamed' operation
[DEBUG] 13:56:11.734365         reading param (C.BTRFS_SEND_A_PATH) ...
[DEBUG] 13:56:11.734370             param type: '15' (expected: 15, raw: [15 0])
[DEBUG] 13:56:11.734375             param length: '21' (raw: [21 0])
[DEBUG] 13:56:11.734402             param: 'o559687-114-0/context' (str:'o559687-114-0/context', raw: [111 53 53 57 54 56 55 45 49 49 52 45 48 47 99 111 110 116 101 120 116])
[DEBUG] 13:56:11.734407         from: 'o559687-114-0/context'
[DEBUG] 13:56:11.734411         reading param (C.BTRFS_SEND_A_PATH_TO) ...
[DEBUG] 13:56:11.734416             param type: '16' (expected: 16, raw: [16 0])
[DEBUG] 13:56:11.734421             param length: '13' (raw: [13 0])
[DEBUG] 13:56:11.734428             param: 'o559688-114-0' (str:'o559688-114-0', raw: [111 53 53 57 54 56 56 45 49 49 52 45 48])
[DEBUG] 13:56:11.734434         to: 'o559688-114-0'
[DEBUG] 13:56:11.734438         updating the diff double tree
[DEBUG] 13:56:11.734442             searching for 'from' node
[DEBUG] 13:56:11.734447                 splitted path in parts, processing each one ...
[DEBUG] 13:56:11.734454                     - o559687-114-0
[DEBUG] 13:56:11.734460                         parent node is _n('', St:!!!, ori:/, oriSt:!!!, child:2)
[DEBUG] 13:56:11.734466                         getting the node in the children (New tree)
[DEBUG] 13:56:11.734474                             found: _n('o559687-114-0', St:added, ori:source, oriSt:renamed, child:0)
[DEBUG] 13:56:11.734479                         node exists (New tree)
[DEBUG] 13:56:11.734484                     - context
[DEBUG] 13:56:11.734491                         parent node is _n('o559687-114-0', St:added, ori:source, oriSt:renamed, child:0)
[DEBUG] 13:56:11.734497                             no children: set a new empty children list/map
[DEBUG] 13:56:11.734503                         getting the node in the children (New tree)
[DEBUG] 13:56:11.734516                             found: <nil>
[DEBUG] 13:56:11.734521                         creating the node
[DEBUG] 13:56:11.734530                             created: _n('context', St:!!!, child:0)
[DEBUG] 13:56:11.734536                             added to its parent node (New tree)
[DEBUG] 13:56:11.734569                             the parent node have an old version (Original tree)
[DEBUG] 13:56:11.734576                                 old parent: _n('source', St:renamed, child:0)
[DEBUG] 13:56:11.734583                                     no children: set a new empty children list/map
[DEBUG] 13:56:11.734591                                 old parent node was renamed, not creating the old node in it
[DEBUG] 13:56:11.734598                 returning node '_n('context', St:!!!, child:0)'
[DEBUG] 13:56:11.734605             found: _n('context', St:!!!, child:0)
[DEBUG] 13:56:11.734609             it's a renaming
[DEBUG] 13:56:11.734614                 removing it from its parent node 'o559687-114-0' (New tree)
[DEBUG] 13:56:11.734618             searching for 'to' node
[DEBUG] 13:56:11.734623                 splitted path in parts, processing each one ...
[DEBUG] 13:56:11.734628                     - o559688-114-0
[DEBUG] 13:56:11.734636                         parent node is _n('', St:!!!, ori:/, oriSt:!!!, child:2)
[DEBUG] 13:56:11.734642                         getting the node in the children (New tree)
[DEBUG] 13:56:11.734657                             found: <nil>
[DEBUG] 13:56:11.734661                         creating the node
[DEBUG] 13:56:11.734668                             created: _n('o559688-114-0', St:!!!, child:0)
[DEBUG] 13:56:11.734674                             added to its parent node (New tree)
[DEBUG] 13:56:11.734679                             the parent node have an old version (Original tree)
[DEBUG] 13:56:11.734687                                 old parent: _n('/', St:!!!, child:1)
[DEBUG] 13:56:11.734697                                 getting the old node (Original tree)
[DEBUG] 13:56:11.734709                                     found: <nil>
[DEBUG] 13:56:11.734716                                     not creating the old node because it is new (true)
[DEBUG] 13:56:11.734723                 returning node '_n('o559688-114-0', St:!!!, child:0)'
[DEBUG] 13:56:11.734729             found: _n('o559688-114-0', St:!!!, child:0)
[DEBUG] 13:56:11.734734             it's a renaming (bis)
[DEBUG] 13:56:11.734739                 adding the 'from' node to the 'to' node parent tree at name 'o559688-114-0' (New tree)
[DEBUG] 13:56:11.734745                 'from' node Name is replaced by the 'to' node Name 'o559688-114-0'
[DEBUG] 13:56:11.734750                 'from' node Op is set to 'added'
[DEBUG] 13:56:11.734756                 'from' node Parent is assigned the 'to' node Parent ''
[DEBUG] 13:56:11.734763                 now node is: _n('o559688-114-0', St:added, child:0)
[DEBUG] 13:56:11.734768         'renamed' operation processed
[DEBUG] 13:56:11.734773 command size: '23' ([23 0 0 0])
[DEBUG] 13:56:11.734778 command type: '12' ([12 0])
[DEBUG] 13:56:11.734782 BTRFS_SEND_C_RMDIR -> deleted
[DEBUG] 13:56:11.734786     other operation (deleted)
[DEBUG] 13:56:11.734790         reading param (C.BTRFS_SEND_A_PATH) ...
[DEBUG] 13:56:11.734795             param type: '15' (expected: 15, raw: [15 0])
[DEBUG] 13:56:11.734800             param length: '19' (raw: [19 0])
[DEBUG] 13:56:11.734810             param: 'o559688-114-0/third' (str:'o559688-114-0/third', raw: [111 53 53 57 54 56 56 45 49 49 52 45 48 47 116 104 105 114 100])
[DEBUG] 13:56:11.734814         path: 'o559688-114-0/third'
[DEBUG] 13:56:11.734819         processing operation 'deleted'
[DEBUG] 13:56:11.734823             searching for matching node
[DEBUG] 13:56:11.734828                 is new? false (only when 'added')
[DEBUG] 13:56:11.734833                 splitted path in parts, processing each one ...
[DEBUG] 13:56:11.734839                     - o559688-114-0
[DEBUG] 13:56:11.734844                         parent node is _n('', St:!!!, ori:/, oriSt:!!!, child:3)
[DEBUG] 13:56:11.734848                         getting the node in the children (New tree)
[DEBUG] 13:56:11.734854                             found: _n('o559688-114-0', St:added, child:0)
[DEBUG] 13:56:11.734860                         node exists (New tree)
[DEBUG] 13:56:11.734864                     - third
[DEBUG] 13:56:11.734871                         parent node is _n('o559688-114-0', St:added, child:0)
[DEBUG] 13:56:11.734880                             no children: set a new empty children list/map
[DEBUG] 13:56:11.734885                         getting the node in the children (New tree)
[DEBUG] 13:56:11.734898                             found: <nil>
[DEBUG] 13:56:11.734903                         creating the node
[DEBUG] 13:56:11.734910                             created: _n('third', St:!!!, child:0)
[DEBUG] 13:56:11.734915                             added to its parent node (New tree)
[DEBUG] 13:56:11.734919                             no previous version of the parent node (Original tree)
[DEBUG] 13:56:11.734926                             isNew is 'false' or the parent part isn't the last one
BUG? referenced path o559688-114-0/third cannot exist

@mbideau
Copy link
Owner

mbideau commented Jan 15, 2023

Hi @vbargsten,
Thank you very much for the feedback, and sorry for ma late reply.
Currently I am dealing with a lot of things that are taking all my free time, but I'll dig into this issue ASAP.
First I'll need to create a test case that reproduce the bug, then a fix. I'll ping you when it's done ...
Hope you are not in a hurry 😅
In the meantime, if you wanna/can help to produce a minimal test case that cause this bug it would save me a lot of time...
Thanks again

@mbideau mbideau closed this as completed Jan 15, 2023
@mbideau
Copy link
Owner

mbideau commented Jan 15, 2023

Woops close by miss clicking

@mbideau mbideau reopened this Jan 15, 2023
@mbideau
Copy link
Owner

mbideau commented Jan 15, 2023

@vbargsten could you produce a btrfs stream file to help me produce a test case ?
You can do it with the command btrfs send (with --no-data preferably).
It would be useful to help me understand how that fiesystem situation came up.

As far as I understand (I quickly read the DEBUG you kindly provided) :
#1 vbargsten/texmf/source is renamed to object dir o559687-114-0 (existing in old and now in new tree)
#2 vbargsten/texmf/source/context is renamed to object dir o559688-114-0 (existing in old and no in new tree)
#3 vbargsten/texmf/source/context/third is deleted (not existing in old tree which causes the bug)
So it is a double renaming that leads to this bug, but I can only understand one renaming, not the two ... maybe it is the way BTRFS deletes a file tree, by renaming each folder then deleting the leaf file, and then delete the parent after each subfolder has been renamed+deleted...
I am going to dig a little bit into deleting a file tree and try to base my test case around it ...

mbideau added a commit that referenced this issue Jan 21, 2023
@mbideau
Copy link
Owner

mbideau commented Jan 21, 2023

Hi @vbargsten and @Mek101 ,
I have fixed that bug, at least for the test case I come up with.
It wasn't easy: I had to create a tool to help me debug the tree structure, then rewrite a significant part of the code. It was challenging but I liked it 😃

If, by any chance, you could checkout again the project (beware, I had to rewrite the git history, for a personal reason @Mek101 😉 ), and test it again on your case, it would be very much appreciated.
Feel free to re-open that issue if the bug occurs again.

Thanks again for your feedback.

PS: @vbargsten : do you want to appear in the contributors section ? If yes, you can tell me if you want a link to your github acount or website and if you want to use your realname or a nickname...

@vbargsten
Copy link

Hi @mbideau, thank you very much for your effort. I am glad to hear from you; I was afraid that something happened, because your activities here were a while back and your domain appeared to be unregistered.

I gave it a new try. Unfortunately the program seems to be stuck in a loop. With -d I logged the output, but stopped at 120GB file size. I greped with some random file names of the log and it seems to just repeat. Sometimes I got btrfsSendSyscall returns bad file descriptor when I kept it running without -d, also with CTRL+Z and fg. I have no idea how I could make a minimal example.

I'm not sure if this is the same bug showing differently due to the fix. If not we can close it here and open a new issue.

@mbideau
Copy link
Owner

mbideau commented Mar 5, 2023

Hi @vbargsten,
Thanks again for your feedback 🙏
I am sorry that you worried about me, actually I am just very busy (construction, family and friends, sailing, etc.) and have less and less free time to contribute to open source community/projects (to my despair).

Wow 120Gb log file ! How long did you let it ran ? A month ? 😅

I have tested it against a moderately large stream file (150Mb) and it ran 24h on a 10 year old i3 computer, generating a 150Mb output log.

Could you try to first generate a stream file and tell me about its size (and number of lines that are not metadata changes) ?

btrfs send --quiet --no-data -p /path/to/parent/snap /path/to/child/snap | LC_ALL=C btrfs receive --quiet --dump > /tmp/btrfs.dump
grep -v 'utimes\|chown\|chmod' /tmp/btrfs.dump > /tmp/btrfs.filtered.dump
du -sh /tmp/btrfs.dump /tmp/btrfs.filtered.dump
wc -l /tmp/btrfs.dump /tmp/btrfs.filtered.dump

I have added an argument to the binary to reduce the output, but I didn't had the time to commit it (and I don't have access to that code right now). I'll do it in the coming week I think.
I'll ping you when this will be done, so you could run the new binary against the stream file and better see if the algorithm is stuck or just looping over a very large file tree structure many times (as the current algorithm isn't optimized).

Thanks again in advance.
Best regards,

@vbargsten
Copy link

Thank you!
Here you go:

root@vbargsten-u:~/src/btrfs-diff-go# du -sh /tmp/btrfs.dump /tmp/btrfs.filtered.dump
107M    /tmp/btrfs.dump
73M     /tmp/btrfs.filtered.dump
root@vbargsten-u:~/src/btrfs-diff-go# wc -l /tmp/btrfs.dump /tmp/btrfs.filtered.dump
   698658 /tmp/btrfs.dump
   514743 /tmp/btrfs.filtered.dump
  1213401 insgesamt

A few minutes were enough to generate the 120 GB. I'm not sure if it really repeats or if for every event it just prints the full file tree status.

In addition, I've let it run for 2 hours without debug. In fact, the output looks ok. It lists 25000 changes ( mostly caches of MS products :/ ). So, I think it actually works but way too slow - probably a file based diff would be faster. Let me know if you have an idea.

@mbideau
Copy link
Owner

mbideau commented Mar 5, 2023

Alright, thank you @vbargsten.

The file is way smaller than I thought but bigger than my biggest test file 😃

I have taken the time to commit my code with a less verbose option --info (88e8558).
Maybe you could update your local repo to fetch this commit, and then produce a stream file and pass it to the binary with the --info option :

btrfs send --quiet --no-data -p /path/to/parent/snap /path/to/child/snap > /tmp/btrfs.stream
./btrfs-diff-go --info --file /tmp/btrfs.stream >/tmp/btrfs.out 2>&1 &
# and in another terminal, may be run: tail -f /tmp/btrfs.out

I guess it would require around 35h on a 10 years old computer to analyze and report all the changes.

If it finishes with success on your test data it would be a good sign of its stability, and then I could start to think about how to optimize it 😉

Again, thank you in advance for your well appreciated feedback 🙏

@vbargsten
Copy link

This is the outcome:

~/src/btrfs-diff-go# time ./btrfs-diff-go --info --file /tmp/btrfs.stream >/tmp/btrfs.out 2>&1

real    127m22,411s
user    183m41,462s
sys     1m41,264s

I did a quick check what's going on there with
sudo ./perf record -F 99 -p <PID> --call-graph dwarf sleep 10 (part of the kernel; https://www.brendangregg.com/perf.html) and hotspot to visualize:
Screenshot_20230306_150743

If I'm correct the tree isn't printed at all in this mode, right?. So I made the following change:

diff --git a/pkg/btrfs-diff.go b/pkg/btrfs-diff.go
index bd1db35..1da67a6 100644
--- a/pkg/btrfs-diff.go
+++ b/pkg/btrfs-diff.go
@@ -166,7 +166,7 @@ func debugInd(ind int, msg string, params ...interface{}) {
 
 // print a diff tree (only if debug mode is enabled)
 func (node *nodeInst) PrintTree(w io.Writer, root bool, padding string, lenParent int, indexParent int) {
-       if node == nil {
+       if node == nil || !debugMode {
                return
        }

Et voila, now only 3s :)

~/src/btrfs-diff-go# time ./btrfs-diff-go --info --file /tmp/btrfs.stream >/tmp/btrfs.out2 2>&1

real    0m3,208s
user    0m2,479s
sys     0m1,731s
~/src/btrfs-diff-go# ls -alh /tmp/btrfs.out2
-rw-r--r-- 1 root root 97M Mär  6 15:13 /tmp/btrfs.out2
~/src/btrfs-diff-go# wc -l /tmp/btrfs.out2
1284940 /tmp/btrfs.out2

I checked that the output is the same once we remove the timestamps from the line beginning:

~/src/btrfs-diff-go# cat /tmp/btrfs.out | grep -P -o -e '(?:(?<=\[INFO\].{17})|(?:^[^\[].*)).*$' > /tmp/btrfs.out-a
~/src/btrfs-diff-go# cat /tmp/btrfs.out2 | grep -P -o -e '(?:(?<=\[INFO\].{17})|(?:^[^\[].*)).*$' > /tmp/btrfs.out-b
~/src/btrfs-diff-go# sha1sum /tmp/btrfs.out-*
b0ed30cea73b0ea5aac73bcc6e0fd19db8423693  /tmp/btrfs.out-a
b0ed30cea73b0ea5aac73bcc6e0fd19db8423693  /tmp/btrfs.out-b

So the problem is with the tree printing only, otherwise it seems to work as intended.

@mbideau
Copy link
Owner

mbideau commented Mar 6, 2023

Awesome @vbargsten ! 🎉
I just forgot to disable the printing function when not in debug mode ! Pfff stupid me ! 🙄 😅
That's what happen when I rush in the code and commit too fast.
Thanks to you we're back to acceptable timings 🕐 and the window of usage suddenly go back to its original promises ✨
Do you want to create a PR with your patch that I would happilly accept or I patch the code myself ?
Also (you never answered previously) I would gladly add you to the contributors section (with your real name or nickname), you tell me...

One thing I want to be sure is that no operation is wrongly ignored or wrongly added, so I am going to compare the output to the regular diff binary.
If you manage to run the comparison too on your data set it would be awesome.
I mean :

./btrfs-diff-go /path/to/parent/snap /path/to/child/snap >/tmp/btrfs-diff-go.out 2>&1
LC_ALL=C diff -rq /path/to/parent/snap /path/to/child/snap >/tmp/utils.diff 2>&1
sort /tmp/btrfs-diff-go.out > /tmp/btrfs-diff-go.sorted.out
sed -e "s|/path/to/parent/snap|old|" \
       -e "s|/path/to/child/snap|new|g" -e 's|: |/|' \
       -e 's/Only in new/added: /' -e 's/Only in old/deleted: /' \
       -e 's|Files old/.* and new/\(.*\) differ|changed: /\1|' \
       -e '/File .* is a fifo while file .* is a fifo/d' /tmp/utils.diff | sort > /tmp/utils.sorted.diff
diff /tmp/utils.sorted.diff /tmp/btrfs-diff-go.sorted.out > /tmp/diff.diff
# or manually compares the diff with colors:
# diff --color=always /tmp/utils.sorted.diff /tmp/btrfs-diff-go.sorted.out | less -R

Note: I didn't ran those commands, I just adapted them from another script, may be you'll have to adjust/tweak them. I'll get back to you when I'll have a proper script that does this automatically.

You can also time both first commands to compare the time it takes to get the differences with this binary and the standard diff utility. Just if you do that, don't forget to remove the output of the time command from the files before comparing them 😅

PS: thanks also for the perf tool, I didn't know about it, very usefull 🙏

@vbargsten
Copy link

Hi @mbideau!

notes:

  • had to run diff with --no-dereference to avoid false differences due to symlinks
  • had to add spaces in front of "added:" in the sed command

Still not completely the same:

  • some changes are only in the btrfs-diff-go.sorted.out
  • in btrfs-diff-go.sorted.out sometimes only the respective parent directory is listed as changed, while in utils.sorted.diff the tree below with all files is listed as added/changed/deleted (among others, such as the texmf directory in Bug: referenced path cannot exist #7 (comment))
  • some additions (only many files below texmf directory), some deletions, some changes are only in the utils.sorted.diff

It is hard for me to conclude anything from the diff. What in particular should I look for?

I created a PR. You can add me as contributor, but I do not insist. My data is now in the git commit log of the PR :)

@mbideau
Copy link
Owner

mbideau commented Mar 8, 2023

Thanks again @vbargsten for your well appreciated contributions.

had to run diff with --no-dereference to avoid false differences due to symlinks

I ran it on my test data (using snapshots made by timeshift on a Manjaro distribution on a spare computer), but I didn't ran into the symlink issue you mention.

had to add spaces in front of "added:" in the sed command

😅

some changes are only in the btrfs-diff-go.sorted.out

Yes, I tracked down a few of those and they all are related to an UPDATE_EXTENT command that doesn't change the file content (used to send "holes"), but btrsf-diif-go always interpret it as a file change and there is no way to discriminate between real and fake change. I have prepared a mail that I will send to the btrfs mailing list to get some help on why that behavior.

in btrfs-diff-go.sorted.out sometimes only the respective parent directory is listed as changed, while in utils.sorted.diff the tree below with all files is listed as added/changed/deleted

That's not good. There is a code (https://github.com/mbideau/btrfs-diff-go/blob/master/pkg/btrfs-diff.go#L650-L654 and https://github.com/mbideau/btrfs-diff-go/blob/master/pkg/btrfs-diff.go#L721-L725) that do not prints operations on a file if one of the parent directory was renamed (because I assumed a rename precedes a deletion, and if the parent directory was deleted, operations on inner files doesn't matter)... May be I was to bold and there is a bug in there.

If by any chance, you could privately send me your test stream file and the output of the diffutility it would greatly help me debug/solve those issues. May be you could use SwissTransfer.

If I/we struggle too much to get a proper result in this golang implementation (that I improved over the basis I found), I consider re-using the btrfs-send and btrfs-receive code base to create a C implementation of this btrfs-diff as close as the source (hoping to struggle less 😅 ).
I'll hope not, for the moment... cause may be we are close to have it work as expected.

Thanks again.

@vbargsten
Copy link

I ran it on my test data (using snapshots made by timeshift on a Manjaro distribution on a spare computer), but I didn't ran into the symlink issue you mention.

It depends where the symlink points to. If it is absolute, it could point into your current root / subvolume and diff will compare that when not using --no-dereference.

some changes are only in the btrfs-diff-go.sorted.out

Yes, I tracked down a few of those

Ok, let's ignore the changed which only appear in the btrfs-diff-go output.

in btrfs-diff-go.sorted.out sometimes only the respective parent directory is listed as changed, while in utils.sorted.diff the tree below with all files is listed as added/changed/deleted

On further inspection, I can relax that a bit I'd say. diff -rq will in fact also only list the top level if it was added (so we cannot say if the tree below is really the same -- but let's also assume that for now). Temporarily, I have commented the lines you mentioned, so btrfs-diff-go won't stop at the parent dir which was added.
What I can say is that there are definitely deletions (also individual files) in utils.sorted.diff but not in the btrfs-diff-go output below my "problem directory". I found that the sort using the path is more useful here, btw (pipe through sort -t$':' -k2 -b -)

grafik

I ran with debug but disabled the PrintTree in the code. Then searched for one of the files. It is detected as deleted, but as you see no deleted: ... is printed for these files.

# grep --text -C5 /vbargsten/texmf/doc/latex/koma-script/scrguide.html /tmp/btrfs-diff-go.out
[DEBUG] 15:20:13.930052     iterating over node 0 children
[DEBUG] 15:20:13.930054 resolvePathsAndFlatten() /vbargsten/texmf/doc/latex/koma-script/scraddr.html (_n('scraddr.html', St:deleted, child:0))
[DEBUG] 15:20:13.930055     newPrefix: '/vbargsten/texmf/doc/latex/koma-script/scraddr.html'
[DEBUG] 15:20:13.930060     replacing node <nil> by _n('scraddr.html', St:deleted, child:0)
[DEBUG] 15:20:13.930063     iterating over node 0 children
[DEBUG] 15:20:13.930064 resolvePathsAndFlatten() /vbargsten/texmf/doc/latex/koma-script/scrguide.html (_n('scrguide.html', St:deleted, child:0))
[DEBUG] 15:20:13.930065     newPrefix: '/vbargsten/texmf/doc/latex/koma-script/scrguide.html'
[DEBUG] 15:20:13.930071     replacing node <nil> by _n('scrguide.html', St:deleted, child:0)
[DEBUG] 15:20:13.930073     iterating over node 0 children
[DEBUG] 15:20:13.930075 resolvePathsAndFlatten() /vbargsten/texmf/doc/latex/koma-script/INSTALL.txt (_n('INSTALL.txt', St:deleted, child:0))
[DEBUG] 15:20:13.930076     newPrefix: '/vbargsten/texmf/doc/latex/koma-script/INSTALL.txt'
[DEBUG] 15:20:13.930081     replacing node <nil> by _n('INSTALL.txt', St:deleted, child:0)
--
[DEBUG] 15:20:14.298095     - old node: _n('scrbeta.dtx', St:deleted, child:0) # /vbargsten/texmf/source/latex/koma-script/scrbeta.dtx
[DEBUG] 15:20:14.298098         new file node: <nil>
[DEBUG] 15:20:14.298101         not found in new files (<nil>) or old node St is not '!!!'
[DEBUG] 15:20:14.298102         not a changed file (deleted)
[DEBUG] 15:20:14.298103         old node St is 'deleted' and its parent too: ignoring a node deletion in a parent deleted
[DEBUG] 15:20:14.298104     - old node: _n('scrguide.html', St:deleted, child:0) # /vbargsten/texmf/doc/latex/koma-script/scrguide.html
[DEBUG] 15:20:14.298107         new file node: <nil>
[DEBUG] 15:20:14.298110         not found in new files (<nil>) or old node St is not '!!!'
[DEBUG] 15:20:14.298111         not a changed file (deleted)
[DEBUG] 15:20:14.298112         old node St is 'deleted' and its parent too: ignoring a node deletion in a parent deleted

Maybe because the parent dirs (/vbargsten/texmf/doc and below) is deleted and added?:

# grep --text -C5 /vbargsten/texmf/doc/latex/koma-script\' /tmp/btrfs-diff-go.out
[DEBUG] 15:20:13.536764 resolvePathsAndFlatten() /vbargsten/texmf/doc/latex (_n('latex', St:added, child:5))
[DEBUG] 15:20:13.536764     newPrefix: '/vbargsten/texmf/doc/latex'
[DEBUG] 15:20:13.536767     replacing node <nil> by _n('latex', St:added, child:5)
[DEBUG] 15:20:13.536768     iterating over node 5 children
[DEBUG] 15:20:13.536769 resolvePathsAndFlatten() /vbargsten/texmf/doc/latex/koma-script (_n('koma-script', St:added, child:33))
[DEBUG] 15:20:13.536770     newPrefix: '/vbargsten/texmf/doc/latex/koma-script'
[DEBUG] 15:20:13.536773     replacing node <nil> by _n('koma-script', St:added, child:33)
[DEBUG] 15:20:13.536774     iterating over node 33 children
[DEBUG] 15:20:13.536777 resolvePathsAndFlatten() /vbargsten/texmf/doc/latex/koma-script/scrextend.html (_n('scrextend.html', St:added, child:0))
[DEBUG] 15:20:13.536778     newPrefix: '/vbargsten/texmf/doc/latex/koma-script/scrextend.html'
[DEBUG] 15:20:13.536781     replacing node <nil> by _n('scrextend.html', St:added, child:0)
--
[DEBUG] 15:20:13.929965 resolvePathsAndFlatten() /vbargsten/texmf/doc/latex (_n('latex', St:deleted, child:1))
[DEBUG] 15:20:13.929966     newPrefix: '/vbargsten/texmf/doc/latex'
[DEBUG] 15:20:13.929971     replacing node <nil> by _n('latex', St:deleted, child:1)
[DEBUG] 15:20:13.929973     iterating over node 1 children
[DEBUG] 15:20:13.929975 resolvePathsAndFlatten() /vbargsten/texmf/doc/latex/koma-script (_n('koma-script', St:deleted, child:35))
[DEBUG] 15:20:13.929976     newPrefix: '/vbargsten/texmf/doc/latex/koma-script'
[DEBUG] 15:20:13.929982     replacing node <nil> by _n('koma-script', St:deleted, child:35)
[DEBUG] 15:20:13.929985     iterating over node 35 children
[DEBUG] 15:20:13.929986 resolvePathsAndFlatten() /vbargsten/texmf/doc/latex/koma-script/scrlayer-notecolumn.html (_n('scrlayer-notecolumn.html', St:deleted, child:0))
[DEBUG] 15:20:13.929987     newPrefix: '/vbargsten/texmf/doc/latex/koma-script/scrlayer-notecolumn.html'
[DEBUG] 15:20:13.929993     replacing node <nil> by _n('scrlayer-notecolumn.html', St:deleted, child:0)

I cannot share the full stream metadata, unfortunately.

@mbideau
Copy link
Owner

mbideau commented Mar 20, 2023

Hi @vbargsten,
Great feedback.
I can confirm that the deleted file are not printed because, one parent directory where detected as deleted as you find out. But may be it is a more tricky use case, because I don't see the parent directory delete in the left output.
I have to dig into that case... and other specifics of btrfs ... see #9

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants