Hi,
since a 0.14 version (don’t really know which one) I have a very strange problem: everytime a file with a local change gets synced the file gets a remote change as well and gets overwritten. It has no changes, the file contents don’t change, but the last modification timestamp changes. And this is very bad for my workflow, my editor whines after each and every save - argh!
Technically my cluster consists of three nodes: node1 is a Linux workstation, node2 is a Linux laptop and node3 is a macOS laptop. A change on node1 gets replicated to node2 and node3 and then overwrites node1. It doesn’t matter if only node2 or only node3 is running.
I did a trace with STTRACE="events" and this is the log output (IDs changed):
[node1] 2016/08/18 10:07:30.966530 events.go:154: DEBUG: log 80 StateChanged map[duration:24.602619765 folder:zm9sv-cngzc to:scanning from:idle]
[node1] 2016/08/18 10:07:30.966569 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:30.967068 events.go:154: DEBUG: log 81 LocalIndexUpdated map[folder:zm9sv-cngzc items:1 filenames:[noodles/Gemfile] version:79308]
[node1] 2016/08/18 10:07:30.967084 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:30.967098 events.go:154: DEBUG: log 82 LocalChangeDetected map[folder:zm9sv-cngzc action:modified type:file path:/home/ckruse/sites/noodles/Gemfile]
[node1] 2016/08/18 10:07:30.967204 events.go:154: DEBUG: log 83 StateChanged map[from:scanning duration:0.0006777910000000001 folder:zm9sv-cngzc to:idle]
[node1] 2016/08/18 10:07:30.967234 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:30.967264 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:30.967282 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:30.967292 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:30.967304 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:30.967312 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:30.967483 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:31.259131 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:31.259676 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:31.382163 events.go:154: DEBUG: log 84 RemoteIndexUpdated map[folder:zm9sv-cngzc items:1 version:52989 device:node3]
[node1] 2016/08/18 10:07:31.382222 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:31.382358 events.go:154: DEBUG: log 85 StateChanged map[folder:zm9sv-cngzc to:syncing from:idle duration:0.415093154]
[node1] 2016/08/18 10:07:31.382426 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:31.390660 events.go:154: DEBUG: log 86 RemoteIndexUpdated map[items:1 version:59795 device:node2 folder:zm9sv-cngzc]
[node1] 2016/08/18 10:07:31.390678 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:31.448095 events.go:154: DEBUG: log 87 StateChanged map[folder:zm9sv-cngzc to:idle from:syncing duration:0.065785936]
[node1] 2016/08/18 10:07:31.448179 events.go:154: DEBUG: log 88 StateChanged map[folder:zm9sv-cngzc to:syncing from:idle duration:9.082900000000001e-05]
[node1] 2016/08/18 10:07:31.448293 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:31.448301 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:31.519874 events.go:154: DEBUG: log 89 StateChanged map[from:syncing duration:0.071688176 folder:zm9sv-cngzc to:idle]
[node1] 2016/08/18 10:07:31.519972 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:31.520088 events.go:154: DEBUG: log 90 FolderSummary map[folder:zm9sv-cngzc summary:map[globalFiles:28743 localFiles:28743 sequence:267457 ignorePatterns:true globalDeleted:230 needFiles:0 inSyncFiles:28743 invalid: state:idle version:267457 globalBytes:638158203 localDeleted:228 localBytes:638157947 needBytes:0 inSyncBytes:638158203 stateChanged:2016-08-18 10:07:31.51985451 +0200 CEST]]
[node1] 2016/08/18 10:07:31.520099 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:31.520538 events.go:154: DEBUG: log 91 StateChanged map[folder:zm9sv-cngzc to:scanning from:idle duration:0.000676712]
[node1] 2016/08/18 10:07:31.520578 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:31.521663 events.go:154: DEBUG: log 92 LocalIndexUpdated map[folder:zm9sv-cngzc items:1 filenames:[noodles/.git/index] version:79309]
[node1] 2016/08/18 10:07:31.521682 events.go:154: DEBUG: log 93 LocalChangeDetected map[folder:zm9sv-cngzc action:modified type:file path:/home/ckruse/sites/noodles/.git/index]
[node1] 2016/08/18 10:07:31.521766 events.go:154: DEBUG: log 94 StateChanged map[folder:zm9sv-cngzc to:idle from:scanning duration:0.001228275]
[node1] 2016/08/18 10:07:31.523245 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:31.523257 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:31.523264 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:31.523527 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:31.523661 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:31.523681 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:31.523694 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:31.526678 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:31.602391 events.go:154: DEBUG: log 95 FolderCompletion map[folder:zm9sv-cngzc device:node2 completion:100]
[node1] 2016/08/18 10:07:31.602584 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:31.667527 events.go:154: DEBUG: log 96 FolderCompletion map[folder:zm9sv-cngzc device:node3 completion:99.97884114011772]
[node1] 2016/08/18 10:07:31.667552 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:31.822368 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:31.824180 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:31.831813 events.go:154: DEBUG: log 97 RemoteIndexUpdated map[device:node2 folder:zm9sv-cngzc items:1 version:59796]
[node1] 2016/08/18 10:07:31.831837 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:31.831904 events.go:154: DEBUG: log 98 StateChanged map[folder:zm9sv-cngzc to:syncing from:idle duration:0.310111799]
[node1] 2016/08/18 10:07:31.831940 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:31.895765 events.go:154: DEBUG: log 99 StateChanged map[folder:zm9sv-cngzc to:idle from:syncing duration:0.063873278]
[node1] 2016/08/18 10:07:31.895812 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:31.961069 events.go:154: DEBUG: log 100 FolderSummary map[folder:zm9sv-cngzc summary:map[needBytes:0 state:idle invalid: globalFiles:28743 sequence:267459 inSyncBytes:638158203 stateChanged:2016-08-18 10:07:31.895746045 +0200 CEST needFiles:0 inSyncFiles:28743 version:267459 globalBytes:638158203 localDeleted:228 localBytes:638157947 ignorePatterns:true globalDeleted:230 localFiles:28743]]
[node1] 2016/08/18 10:07:31.961268 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:32.030263 events.go:154: DEBUG: log 101 FolderCompletion map[folder:zm9sv-cngzc device:node2 completion:100]
[node1] 2016/08/18 10:07:32.030470 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:32.099501 events.go:154: DEBUG: log 102 FolderCompletion map[folder:zm9sv-cngzc device:node3 completion:99.97884114011772]
[node1] 2016/08/18 10:07:32.099528 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:32.263872 events.go:154: DEBUG: log 103 RemoteIndexUpdated map[device:node3 folder:zm9sv-cngzc items:1 version:52990]
[node1] 2016/08/18 10:07:32.263909 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:32.264009 events.go:154: DEBUG: log 104 StateChanged map[folder:zm9sv-cngzc to:syncing from:idle duration:0.368213707]
[node1] 2016/08/18 10:07:32.264043 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:32.332797 events.go:154: DEBUG: log 105 StateChanged map[folder:zm9sv-cngzc to:idle from:syncing duration:0.068815631]
[node1] 2016/08/18 10:07:32.332936 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:32.395458 events.go:154: DEBUG: log 106 FolderSummary map[folder:zm9sv-cngzc summary:map[localBytes:638157947 sequence:267460 globalFiles:28743 needFiles:0 inSyncFiles:28743 inSyncBytes:638158203 version:267460 ignorePatterns:true globalDeleted:230 localFiles:28743 localDeleted:228 needBytes:0 state:idle invalid: stateChanged:2016-08-18 10:07:32.33277654 +0200 CEST globalBytes:638158203]]
[node1] 2016/08/18 10:07:32.395665 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:32.459819 events.go:154: DEBUG: log 107 FolderCompletion map[folder:zm9sv-cngzc device:node2 completion:100]
[node1] 2016/08/18 10:07:32.460037 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:32.528033 events.go:154: DEBUG: log 108 FolderCompletion map[completion:100 folder:zm9sv-cngzc device:node3]
[node1] 2016/08/18 10:07:32.528054 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:32.728082 events.go:154: DEBUG: log 109 RemoteIndexUpdated map[device:node3 folder:zm9sv-cngzc items:1 version:52991]
[node1] 2016/08/18 10:07:32.728119 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:32.728195 events.go:154: DEBUG: log 110 StateChanged map[folder:zm9sv-cngzc to:syncing from:idle duration:0.395384008]
[node1] 2016/08/18 10:07:32.728285 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:32.795530 events.go:154: DEBUG: log 111 ItemStarted map[type:file action:metadata folder:zm9sv-cngzc item:noodles/Gemfile]
[node1] 2016/08/18 10:07:32.795604 events.go:154: DEBUG: log 112 ItemFinished map[folder:zm9sv-cngzc item:noodles/Gemfile error:<nil> type:file action:metadata]
[node1] 2016/08/18 10:07:32.795622 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:32.795626 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:32.795837 events.go:154: DEBUG: log 113 LocalIndexUpdated map[version:79310 folder:zm9sv-cngzc items:1 filenames:[noodles/Gemfile]]
[node1] 2016/08/18 10:07:32.795862 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:32.795883 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:32.795911 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:32.795942 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:32.795961 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:32.795978 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:32.796013 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:32.877033 events.go:154: DEBUG: log 114 StateChanged map[folder:zm9sv-cngzc to:idle from:syncing duration:0.14885156000000002]
[node1] 2016/08/18 10:07:32.877082 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:32.941150 events.go:154: DEBUG: log 115 FolderSummary map[folder:zm9sv-cngzc summary:map[state:idle sequence:267462 ignorePatterns:true globalFiles:28743 needFiles:0 inSyncBytes:638158203 needBytes:0 stateChanged:2016-08-18 10:07:32.877013091 +0200 CEST localDeleted:228 localBytes:638157947 localFiles:28743 inSyncFiles:28743 version:267462 invalid: globalDeleted:230 globalBytes:638158203]]
[node1] 2016/08/18 10:07:32.941362 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:33.006090 events.go:154: DEBUG: log 116 FolderCompletion map[completion:99.99979957947825 folder:zm9sv-cngzc device:node2]
[node1] 2016/08/18 10:07:33.006275 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:33.025548 events.go:154: DEBUG: log 117 RemoteIndexUpdated map[device:node2 folder:zm9sv-cngzc items:1 version:59797]
[node1] 2016/08/18 10:07:33.025589 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:33.025668 events.go:154: DEBUG: log 118 StateChanged map[folder:zm9sv-cngzc to:syncing from:idle duration:0.148620576]
[node1] 2016/08/18 10:07:33.025767 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:33.075750 events.go:154: DEBUG: log 119 FolderCompletion map[folder:zm9sv-cngzc device:node3 completion:100]
[node1] 2016/08/18 10:07:33.075777 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:33.088937 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:33.090199 events.go:154: DEBUG: log 120 StateChanged map[to:idle from:syncing duration:0.064548094 folder:zm9sv-cngzc]
[node1] 2016/08/18 10:07:33.090322 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:33.093982 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:33.155229 events.go:154: DEBUG: log 121 FolderSummary map[folder:zm9sv-cngzc summary:map[globalBytes:638158203 sequence:267463 globalDeleted:230 localBytes:638157947 stateChanged:2016-08-18 10:07:33.090182835 +0200 CEST invalid: needBytes:0 version:267463 ignorePatterns:true globalFiles:28743 localDeleted:228 needFiles:0 inSyncFiles:28743 inSyncBytes:638158203 state:idle localFiles:28743]]
[node1] 2016/08/18 10:07:33.155431 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:33.219874 events.go:154: DEBUG: log 122 FolderCompletion map[folder:zm9sv-cngzc device:node2 completion:100]
[node1] 2016/08/18 10:07:33.220080 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:33.268002 events.go:154: DEBUG: log 123 RemoteIndexUpdated map[folder:zm9sv-cngzc items:1 version:52992 device:node3]
[node1] 2016/08/18 10:07:33.268059 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:33.268128 events.go:154: DEBUG: log 124 StateChanged map[folder:zm9sv-cngzc to:syncing from:idle duration:0.177914969]
[node1] 2016/08/18 10:07:33.268250 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:33.288660 events.go:154: DEBUG: log 125 FolderCompletion map[folder:zm9sv-cngzc device:node3 completion:100]
[node1] 2016/08/18 10:07:33.288690 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:33.334395 events.go:154: DEBUG: log 126 ItemStarted map[type:file action:metadata folder:zm9sv-cngzc item:noodles/.git/index]
[node1] 2016/08/18 10:07:33.334476 events.go:154: DEBUG: log 127 ItemFinished map[folder:zm9sv-cngzc item:noodles/.git/index error:<nil> type:file action:metadata]
[node1] 2016/08/18 10:07:33.334499 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:33.334506 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:33.334706 events.go:154: DEBUG: log 128 LocalIndexUpdated map[version:79311 folder:zm9sv-cngzc items:1 filenames:[noodles/.git/index]]
[node1] 2016/08/18 10:07:33.334740 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:33.334850 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:33.334865 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:33.334889 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:33.334905 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:33.334919 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:33.334926 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:33.409868 events.go:154: DEBUG: log 129 StateChanged map[folder:zm9sv-cngzc to:idle from:syncing duration:0.141750077]
[node1] 2016/08/18 10:07:33.409912 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:33.475777 events.go:154: DEBUG: log 130 FolderSummary map[summary:map[localDeleted:228 state:idle version:267465 ignorePatterns:true inSyncBytes:638158203 invalid: globalDeleted:230 localFiles:28743 inSyncFiles:28743 globalBytes:638158203 needFiles:0 needBytes:0 globalFiles:28743 localBytes:638157947 stateChanged:2016-08-18 10:07:33.409849114 +0200 CEST sequence:267465] folder:zm9sv-cngzc]
[node1] 2016/08/18 10:07:33.475978 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:33.521420 events.go:154: DEBUG: log 131 RemoteIndexUpdated map[folder:zm9sv-cngzc items:1 version:59798 device:node2]
[node1] 2016/08/18 10:07:33.521472 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:33.521562 events.go:154: DEBUG: log 132 StateChanged map[folder:zm9sv-cngzc to:syncing from:idle duration:0.111667685]
[node1] 2016/08/18 10:07:33.521638 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:33.550957 events.go:154: DEBUG: log 133 FolderCompletion map[completion:99.97884114011772 folder:zm9sv-cngzc device:node2]
[node1] 2016/08/18 10:07:33.551482 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:33.596059 events.go:154: DEBUG: log 134 StateChanged map[folder:zm9sv-cngzc to:idle from:syncing duration:0.07452051900000001]
[node1] 2016/08/18 10:07:33.596085 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:33.622276 events.go:154: DEBUG: log 135 FolderCompletion map[folder:zm9sv-cngzc device:node3 completion:100]
[node1] 2016/08/18 10:07:33.622300 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:33.625920 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:33.629246 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:34.164150 events.go:154: DEBUG: log 136 FolderSummary map[folder:zm9sv-cngzc summary:map[ignorePatterns:true sequence:267466 localFiles:28743 localDeleted:228 localBytes:638157947 needBytes:0 invalid: inSyncFiles:28743 needFiles:0 globalDeleted:230 globalBytes:638158203 inSyncBytes:638158203 state:idle stateChanged:2016-08-18 10:07:33.596038286 +0200 CEST version:267466 globalFiles:28743]]
[node1] 2016/08/18 10:07:34.164350 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:34.230358 events.go:154: DEBUG: log 137 FolderCompletion map[folder:zm9sv-cngzc device:node2 completion:100]
[node1] 2016/08/18 10:07:34.230575 events.go:235: DEBUG: poll 1m0s
[node1] 2016/08/18 10:07:34.297298 events.go:154: DEBUG: log 138 FolderCompletion map[completion:100 folder:zm9sv-cngzc device:node3]
[node1] 2016/08/18 10:07:34.297324 events.go:235: DEBUG: poll 1m0s
Am I doing something wrong?
Best regards, CK