{"action":"created","issue":{"url":"https://api.github.com/repos/syncthing/syncthing/issues/2994","repository_url":"https://api.github.com/repos/syncthing/syncthing","labels_url":"https://api.github.com/repos/syncthing/syncthing/issues/2994/labels{/name}","comments_url":"https://api.github.com/repos/syncthing/syncthing/issues/2994/comments","events_url":"https://api.github.com/repos/syncthing/syncthing/issues/2994/events","html_url":"https://github.com/syncthing/syncthing/pull/2994","id":149602670,"number":2994,"title":"lib/osutil: Try very hard to preserve mtimes when renaming","user":{"login":"AudriusButkevicius","id":1144861,"avatar_url":"https://avatars.githubusercontent.com/u/1144861?v=3","gravatar_id":"","url":"https://api.github.com/users/AudriusButkevicius","html_url":"https://github.com/AudriusButkevicius","followers_url":"https://api.github.com/users/AudriusButkevicius/followers","following_url":"https://api.github.com/users/AudriusButkevicius/following{/other_user}","gists_url":"https://api.github.com/users/AudriusButkevicius/gists{/gist_id}","starred_url":"https://api.github.com/users/AudriusButkevicius/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/AudriusButkevicius/subscriptions","organizations_url":"https://api.github.com/users/AudriusButkevicius/orgs","repos_url":"https://api.github.com/users/AudriusButkevicius/repos","events_url":"https://api.github.com/users/AudriusButkevicius/events{/privacy}","received_events_url":"https://api.github.com/users/AudriusButkevicius/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":14,"created_at":"2016-04-19T22:34:18Z","updated_at":"2016-04-21T06:04:35Z","closed_at":null,"pull_request":{"url":"https://api.github.com/repos/syncthing/syncthing/pulls/2994","html_url":"https://github.com/syncthing/syncthing/pull/2994","diff_url":"https://github.com/syncthing/syncthing/pull/2994.diff","patch_url":"https://github.com/syncthing/syncthing/pull/2994.patch"},"body":"### Purpose\r\n\r\nWorked this one out on a test setup provided by @cmarsura.\r\n\r\nVery nice debugging procedures:\r\n\r\n```diff\r\ndiff --git a/lib/model/rwfolder.go b/lib/model/rwfolder.go\r\nindex ab384d4..3e29672 100644\r\n--- a/lib/model/rwfolder.go\r\n+++ b/lib/model/rwfolder.go\r\n@@ -494,7 +490,7 @@ func (p *rwFolder) pullerIteration(ignores *ignore.Matcher) int {\r\n                        return true\r\n                }\r\n\r\n-               l.Debugln(p, \"handling\", file.Name)\r\n+               l.Debugln(p, \"handling\", file.Name, file.Modified)\r\n\r\n                if !handleFile(file) {\r\n                        // A new or changed file or symlink. This is the only case where we\r\n\r\ndiff --git a/lib/model/rwfolder.go b/lib/model/rwfolder.go\r\nindex ab384d4..3e29672 100644\r\n--- a/lib/model/rwfolder.go\r\n+++ b/lib/model/rwfolder.go\r\n@@ -1283,6 +1284,16 @@ func (p *rwFolder) pullerRoutine(in <-chan pullBlockState, out chan<- *sharedPul\r\n        }\r\n }\r\n\r\n+func dumpDebug(msg, path string) {\r\n+       stat, err := os.Stat(path)\r\n+       if err != nil {\r\n+               l.Infoln(\"FAILED\", msg, path)\r\n+               return\r\n+       }\r\n+\r\n+       l.Infoln(\"XXXXXXXXXXXXXXXXXXXX\", msg, path, stat.ModTime().Unix())\r\n+}\r\n+\r\n func (p *rwFolder) performFinish(state *sharedPullerState) error {\r\n        // Set the correct permission bits on the new file\r\n        if !p.ignorePermissions(state.file) {\r\n@@ -1290,10 +1301,14 @@ func (p *rwFolder) performFinish(state *sharedPullerState) error {\r\n                        return err\r\n                }\r\n        }\r\n+\r\n+       dumpDebug(\"EXPECTED\", state.file.Name)\r\n+       dumpDebug(\"TEMP\", state.tempName)\r\n\r\n        // Set the correct timestamp on the new file\r\n        t := time.Unix(state.file.Modified, 0)\r\n        if err := os.Chtimes(state.tempName, t, t); err != nil {\r\n+               l.Infoln(\"CHTIMES FAILED\")\r\n                // Try using virtual mtimes instead\r\n                info, err := os.Stat(state.tempName)\r\n                if err != nil {\r\n@@ -1301,6 +1316,8 @@ func (p *rwFolder) performFinish(state *sharedPullerState) error {\r\n                }\r\n                p.virtualMtimeRepo.UpdateMtime(state.file.Name, info.ModTime(), t)\r\n        }\r\n+\r\n+       dumpDebug(\"TEMP AFTER CHTIMES\", state.tempName)\r\n\r\n        if stat, err := osutil.Lstat(state.realName); err == nil {\r\n                // There is an old file or directory already in place. We need to\r\n@@ -1346,6 +1363,8 @@ func (p *rwFolder) performFinish(state *sharedPullerState) error {\r\n        if err := osutil.Rename(state.tempName, state.realName); err != nil {\r\n                return err\r\n        }\r\n+\r\n+       dumpDebug(\"REAL AFTER RENAME\", state.realName)\r\n\r\n        // If it's a symlink, the target of the symlink is inside the file.\r\n        if state.file.IsSymlink() {\r\n```\r\n\r\nYields:\r\n\r\n```\r\n[4M335] 2016/04/20 00:18:59.495218 rwfolder.go:493: DEBUG: rwFolder/TestSmbBug@0x112d80c0 handling incr.txt 1461104338\r\n...\r\n[4M335] 2016/04/20 00:18:59.631937 rwfolder.go:1290: INFO: FAILED EXPECTED incr.txt\r\n[4M335] 2016/04/20 00:18:59.631937 rwfolder.go:1294: INFO: XXXXXXXXXXXXXXXXXXXX TEMP \\\\storagevm\\RemoteStorage\\~syncthing~incr.txt.tmp 1461104340\r\n[4M335] 2016/04/20 00:18:59.835062 rwfolder.go:1294: INFO: XXXXXXXXXXXXXXXXXXXX TEMP AFTER CHTIMES \\\\storagevm\\RemoteStorage\\~syncthing~incr.txt.tmp 1461104338\r\n[4M335] 2016/04/20 00:18:59.835062 rwfolder.go:1294: INFO: XXXXXXXXXXXXXXXXXXXX REAL AFTER RENAME \\\\storagevm\\RemoteStorage\\incr.txt 1461104341\r\n```\r\n\r\n### Testing\r\n\r\nNone at all, but it's for the reviewer to verify."},"comment":{"url":"https://api.github.com/repos/syncthing/syncthing/issues/comments/212757392","html_url":"https://github.com/syncthing/syncthing/pull/2994#issuecomment-212757392","issue_url":"https://api.github.com/repos/syncthing/syncthing/issues/2994","id":212757392,"user":{"login":"calmh","id":125426,"avatar_url":"https://avatars.githubusercontent.com/u/125426?v=3","gravatar_id":"","url":"https://api.github.com/users/calmh","html_url":"https://github.com/calmh","followers_url":"https://api.github.com/users/calmh/followers","following_url":"https://api.github.com/users/calmh/following{/other_user}","gists_url":"https://api.github.com/users/calmh/gists{/gist_id}","starred_url":"https://api.github.com/users/calmh/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/calmh/subscriptions","organizations_url":"https://api.github.com/users/calmh/orgs","repos_url":"https://api.github.com/users/calmh/repos","events_url":"https://api.github.com/users/calmh/events{/privacy}","received_events_url":"https://api.github.com/users/calmh/received_events","type":"User","site_admin":false},"created_at":"2016-04-21T06:04:35Z","updated_at":"2016-04-21T06:04:35Z","body":"That's really quite interesting. Any funky \"options\" enabled on the server side, like deduplication or shadow copies (not that the latter should have any effect)? For what it's worth I don't see the same with SMB on Mac to Unix, but of course nothing is the same in that setup as in yours. I guess this is good to merge, at least we know when it happens. We get a couple of extra stat calls per rename, but we don't do that many renames anyway..."}}