gitfs icon indicating copy to clipboard operation
gitfs copied to clipboard
verified publisher icon presslabs

Simultaneous changes on different instances cause incorrect merge

Open gp42 opened this issue 5 years ago • 0 comments

It looks like there is a problem in merging files if different changes happen to the same file on different instances of gitfs.

Here are the steps to recreate:

  • Create 3 VMs with gitfs mounted to same repo.
  • Simultaneously (i used tmux + synchronize-panes) add a new file with different content on each vm: echo $(hostname) > /mnt/zpool/gitfs/current/foosync.file
  • Waited for sync. This generated 6 commits.
  • Initial 3 commits show expected behaviour (racing to merge changes), but the next 3 commits perform merges and corrupt initial data: b"b'dev-rackly-zfstest-1\\n'" instead of dev-rackly-zfstest-1 - this looks like python formatting
  • logs show conflict-solving
Gitfs log 
...
July-06-2020 07:05:02 Dummy-4: Router: Cache key for /current: /current
July-06-2020 07:05:02 Dummy-4: Router: Serving /current from cache
July-06-2020 07:05:02 Dummy-4: Call getattr CurrentView with ('/', None)
July-06-2020 07:05:02 Dummy-4: CurrentView: Get attributes {'st_atime': 1594018097.080711, 'st_ctime': 1594018096.2087092, 'st_gid': 0, 'st_mode': 16832, 'st_mtime': 1594018096.2087092, 'st_nlink': 5, 'st_size': 4096, 'st_uid': 0} for /
July-06-2020 07:05:02 Dummy-3: Router: Cache key for /current/foosync.file: /current
July-06-2020 07:05:02 Dummy-3: Router: Serving /current/foosync.file from cache
July-06-2020 07:05:02 Dummy-3: Call getattr CurrentView with ('/foosync.file', None)
July-06-2020 07:05:02 Dummy-4: Router: Cache key for /current/foosync.file: /current
July-06-2020 07:05:02 Dummy-4: Router: Serving /current/foosync.file from cache
July-06-2020 07:05:02 Dummy-4: Call create CurrentView with ('/foosync.file', 33188)
July-06-2020 07:05:02 Dummy-4: CurrentView: Open /foosync.file for read
July-06-2020 07:05:02 Dummy-4: CurrentView: Open /foosync.file for write
July-06-2020 07:05:02 Dummy-4: CurrentView: Created /foosync.file
July-06-2020 07:05:02 Dummy-4: Router: Cache key for /current/foosync.file: /current
July-06-2020 07:05:02 Dummy-4: Router: Serving /current/foosync.file from cache
July-06-2020 07:05:02 Dummy-4: Call getattr CurrentView with ('/foosync.file', 6)
July-06-2020 07:05:02 Dummy-4: CurrentView: Get attributes {'st_atime': 1594019102.8608754, 'st_ctime': 1594019102.8608754, 'st_gid': 0, 'st_mode': 33188, 'st_mtime': 1594019102.8608754, 'st_nlink': 1, 'st_size': 0, 'st_uid': 0} for /foosync.file
July-06-2020 07:05:02 Dummy-3: Router: Cache key for /current/foosync.file: /current
July-06-2020 07:05:02 Dummy-3: Router: Serving /current/foosync.file from cache
July-06-2020 07:05:02 Dummy-3: Call flush CurrentView with ('/foosync.file', 6)
July-06-2020 07:05:02 Dummy-3: Router: Cache key for /current/foosync.file: /current
July-06-2020 07:05:02 Dummy-3: Router: Serving /current/foosync.file from cache
July-06-2020 07:05:02 Dummy-3: Call lock CurrentView with ('/foosync.file', 6, 6, 140202101849024)
July-06-2020 07:05:02 Dummy-4: Router: Cache key for /current/foosync.file: /current
July-06-2020 07:05:02 Dummy-4: Router: Serving /current/foosync.file from cache
July-06-2020 07:05:02 Dummy-4: Call getxattr CurrentView with ('/foosync.file', 'security.capability')
July-06-2020 07:05:02 Dummy-4: Router: Cache key for /current/foosync.file: /current
July-06-2020 07:05:02 Dummy-4: Router: Serving /current/foosync.file from cache
July-06-2020 07:05:02 Dummy-4: Call write CurrentView with ('/foosync.file', b'dev-rackly-zfstest-0\n', 0, 6)
July-06-2020 07:05:02 Dummy-4: CurrentView: Wrote 21 to /foosync.file
July-06-2020 07:05:02 Dummy-3: Router: Cache key for /current/foosync.file: /current
July-06-2020 07:05:02 Dummy-3: Router: Serving /current/foosync.file from cache
July-06-2020 07:05:02 Dummy-3: Call flush CurrentView with ('/foosync.file', 6)
July-06-2020 07:05:02 Dummy-3: Router: Cache key for /current/foosync.file: /current
July-06-2020 07:05:02 Dummy-3: Router: Serving /current/foosync.file from cache
July-06-2020 07:05:02 Dummy-3: Call lock CurrentView with ('/foosync.file', 6, 6, 140202101849024)
July-06-2020 07:05:02 Dummy-3: Router: Cache key for /current/foosync.file: /current
July-06-2020 07:05:02 Dummy-3: Router: Serving /current/foosync.file from cache
July-06-2020 07:05:02 Dummy-3: Call release CurrentView with ('/foosync.file', 6)
July-06-2020 07:05:02 Dummy-3: CurrentView: Staged /foosync.file for commit
July-06-2020 07:05:02 Dummy-3: Got a new commit job on queue
July-06-2020 07:05:02 SyncWorker: Got a commit job
July-06-2020 07:05:02 Dummy-3: CurrentView: Release /foosync.file
July-06-2020 07:05:07 SyncWorker: Nothing to do right now, going idle
July-06-2020 07:05:07 SyncWorker: Set syncing event (0 pending writes)
July-06-2020 07:05:07 SyncWorker: Get some commits
July-06-2020 07:05:07 SyncWorker: Commit Update /foosync.file with ('dev-rackly-zfstest-0', 'root@dev-rackly-zfstest-0') as author and ('dev-rackly-zfstest-0', 'root@dev-rackly-zfstest-0') as commiter
July-06-2020 07:05:07 SyncWorker: Update commits cache
July-06-2020 07:05:07 SyncWorker: Checkout to HEAD
July-06-2020 07:05:07 SyncWorker: Start syncing, first attempt.
July-06-2020 07:05:07 SyncWorker: Check if I'm ahead
July-06-2020 07:05:07 SyncWorker: Start pushing
July-06-2020 07:05:10 SyncWorker: Push done
July-06-2020 07:05:10 SyncWorker: Clear syncing
July-06-2020 07:05:10 SyncWorker: Set sync_done
July-06-2020 07:05:10 SyncWorker: Set push_successful
July-06-2020 07:05:15 SyncWorker: Nothing to do right now, going idle
July-06-2020 07:05:15 SyncWorker: Set syncing event (0 pending writes)
July-06-2020 07:05:15 SyncWorker: Start syncing, first attempt.
July-06-2020 07:05:15 SyncWorker: Check if I'm ahead
July-06-2020 07:05:15 SyncWorker: Start pushing
July-06-2020 07:05:16 SyncWorker: Push failed because of cannot push because a reference that you are trying to update on the remote contains commits that are not present locally.
July-06-2020 07:05:16 FetchWorker: Lock fetching operation
July-06-2020 07:05:16 FetchWorker: Start fetching
July-06-2020 07:05:16 SyncWorker: Failed to sync. Going to sleep for 1 seconds
July-06-2020 07:05:16 FetchWorker: Fetch done
July-06-2020 07:05:16 FetchWorker: Wait for 30
July-06-2020 07:05:17 SyncWorker: Retry-ing to sync with remote. Attempt #1
July-06-2020 07:05:17 SyncWorker: Check if I'm ahead
July-06-2020 07:05:17 SyncWorker: I'm behind so I start merging
July-06-2020 07:05:17 SyncWorker: Start fetching
July-06-2020 07:05:17 SyncWorker: Done fetching
July-06-2020 07:05:17 SyncWorker: Start merging
July-06-2020 07:05:17 SyncWorker: Start merging
July-06-2020 07:05:17 SyncWorker: AcceptMine: Copy local branch to merging_local
July-06-2020 07:05:17 SyncWorker: AcceptMine: Copy remote branch to merging_remote
July-06-2020 07:05:17 SyncWorker: AcceptMine: Find diverge commis
July-06-2020 07:05:17 SyncWorker: AcceptMine: Checkout to refs/heads/merging_remote
July-06-2020 07:05:17 SyncWorker: AcceptMine: Merging 66dd9e4c66747dc8f4e985df0a74465bcd298a54
July-06-2020 07:05:17 SyncWorker: AcceptMine: Solving conflicts
July-06-2020 07:05:17 SyncWorker: AcceptMine: overwrite all file with our content
July-06-2020 07:05:17 SyncWorker: AcceptMine: Commiting changes
July-06-2020 07:05:17 SyncWorker: AcceptMine: We have a non-empty commit
July-06-2020 07:05:17 SyncWorker: AcceptMine: Checkout to refs/heads/merging_remote
July-06-2020 07:05:17 SyncWorker: AcceptMine: Clean the state
July-06-2020 07:05:17 SyncWorker: AcceptMine: Checkout to master
July-06-2020 07:05:17 SyncWorker: AcceptMine: Checkout force to branch master
July-06-2020 07:05:17 SyncWorker: AcceptMine: Delete merging_local
July-06-2020 07:05:17 SyncWorker: AcceptMine: Delete merging_remote
July-06-2020 07:05:17 SyncWorker: Update commits cache
July-06-2020 07:05:17 SyncWorker: Update ignore list
July-06-2020 07:05:17 SyncWorker: Merge done with success, ready to push
July-06-2020 07:05:17 SyncWorker: Start pushing
July-06-2020 07:05:20 SyncWorker: Push done
July-06-2020 07:05:20 SyncWorker: Clear syncing
July-06-2020 07:05:20 SyncWorker: Set sync_done
July-06-2020 07:05:20 SyncWorker: Set push_successful
July-06-2020 07:05:25 SyncWorker: Nothing to do right now, going idle
July-06-2020 07:05:25 SyncWorker: Set syncing event (0 pending writes)
July-06-2020 07:05:25 SyncWorker: Start syncing, first attempt.
July-06-2020 07:05:25 SyncWorker: Check if I'm ahead
July-06-2020 07:05:25 SyncWorker: Sync done, clearing
July-06-2020 07:05:30 SyncWorker: Nothing to do right now, going idle
July-06-2020 07:05:30 SyncWorker: Set syncing event (0 pending writes)
July-06-2020 07:05:30 SyncWorker: Start syncing, first attempt.
July-06-2020 07:05:31 SyncWorker: Check if I'm ahead
July-06-2020 07:05:31 SyncWorker: Sync done, clearing
July-06-2020 07:05:36 SyncWorker: Nothing to do right now, going idle
July-06-2020 07:05:36 SyncWorker: Set syncing event (0 pending writes)
July-06-2020 07:05:36 SyncWorker: Start syncing, first attempt.
July-06-2020 07:05:36 SyncWorker: Check if I'm ahead
July-06-2020 07:05:36 SyncWorker: Sync done, clearing
July-06-2020 07:05:41 SyncWorker: Nothing to do right now, going idle
July-06-2020 07:05:41 SyncWorker: Set syncing event (0 pending writes)
July-06-2020 07:05:41 SyncWorker: Start syncing, first attempt.
July-06-2020 07:05:41 SyncWorker: Check if I'm ahead
July-06-2020 07:05:41 SyncWorker: Sync done, clearing
July-06-2020 07:05:46 SyncWorker: Nothing to do right now, going idle
July-06-2020 07:05:46 SyncWorker: Set syncing event (0 pending writes)
July-06-2020 07:05:46 SyncWorker: Start syncing, first attempt.
July-06-2020 07:05:46 SyncWorker: Check if I'm ahead
July-06-2020 07:05:46 SyncWorker: Sync done, clearing
July-06-2020 07:05:46 FetchWorker: Lock fetching operation
July-06-2020 07:05:46 FetchWorker: Start fetching
July-06-2020 07:05:47 FetchWorker: Fetch done
July-06-2020 07:05:47 FetchWorker: Wait for 30
July-06-2020 07:05:51 SyncWorker: Nothing to do right now, going idle
July-06-2020 07:05:51 SyncWorker: Set syncing event (0 pending writes)
July-06-2020 07:05:51 SyncWorker: Start syncing, first attempt.
July-06-2020 07:05:51 SyncWorker: Check if I'm ahead
July-06-2020 07:05:51 SyncWorker: I'm behind so I start merging
July-06-2020 07:05:51 SyncWorker: Start fetching
July-06-2020 07:05:51 SyncWorker: Done fetching
July-06-2020 07:05:51 SyncWorker: Start merging
July-06-2020 07:05:51 SyncWorker: Start merging
July-06-2020 07:05:51 SyncWorker: AcceptMine: Copy local branch to merging_local
July-06-2020 07:05:51 SyncWorker: AcceptMine: Copy remote branch to merging_remote
July-06-2020 07:05:51 SyncWorker: AcceptMine: Find diverge commis
July-06-2020 07:05:51 SyncWorker: AcceptMine: Checkout to refs/heads/merging_remote
July-06-2020 07:05:51 SyncWorker: AcceptMine: Checkout to master
July-06-2020 07:05:51 SyncWorker: AcceptMine: Checkout force to branch master
July-06-2020 07:05:51 SyncWorker: AcceptMine: Delete merging_local
July-06-2020 07:05:51 SyncWorker: AcceptMine: Delete merging_remote
July-06-2020 07:05:51 SyncWorker: Update commits cache
July-06-2020 07:05:51 SyncWorker: Update ignore list
July-06-2020 07:05:51 SyncWorker: Merge done with success, ready to push
July-06-2020 07:05:51 SyncWorker: Start pushing
July-06-2020 07:05:54 SyncWorker: Push done
July-06-2020 07:05:54 SyncWorker: Clear syncing
July-06-2020 07:05:54 SyncWorker: Set sync_done
July-06-2020 07:05:54 SyncWorker: Set push_successful
...
Last 3 git commits in sequential order (last one below) 
commit 301c4d1d09fd87cbfb7a039400dc0d5b698d0042
Merge: 1ae8492 66dd9e4
Author: dev-rackly-zfstest-0 <root@dev-rackly-zfstest-0>
Date:   Mon Jul 6 07:05:17 2020 +0000

    merging: Update /foosync.file

diff --cc foosync.file
index 5cbab9a,88ab997..de6283d
--- a/foosync.file
+++ b/foosync.file
@@@ -1,1 -1,1 +1,1 @@@
- dev-rackly-zfstest-2
 -dev-rackly-zfstest-0
++b'dev-rackly-zfstest-0\n'

commit 77711a2d34e5ccfcbd4514eeefe7970638ce6f32
Merge: 1ae8492 47dd0d6
Author: dev-rackly-zfstest-1 <root@dev-rackly-zfstest-1>
Date:   Mon Jul 6 07:05:18 2020 +0000

    merging: Update /foosync.file

diff --cc foosync.file
index 5cbab9a,12413e6..6afe446
--- a/foosync.file
+++ b/foosync.file
@@@ -1,1 -1,1 +1,1 @@@
- dev-rackly-zfstest-2
 -dev-rackly-zfstest-1
++b'dev-rackly-zfstest-1\n'

commit 2638ddef97f42c74f009deeb8f277bd394e6d2fb (HEAD -> master, origin/master)
Merge: 301c4d1 77711a2
Author: dev-rackly-zfstest-1 <root@dev-rackly-zfstest-1>
Date:   Mon Jul 6 07:05:29 2020 +0000

    merging: merging: Update /foosync.file

diff --cc foosync.file
index de6283d,6afe446..20b0403
--- a/foosync.file
+++ b/foosync.file
@@@ -1,1 -1,1 +1,1 @@@
- b'dev-rackly-zfstest-0\n'
 -b'dev-rackly-zfstest-1\n'
++b"b'dev-rackly-zfstest-1\\n'"

Please help me to understand, maybe I am just confused and gitfs was not designed to work with multiple mounts simultaniously.

gp42 avatar Jul 06 '20 08:07 gp42