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

Re\scan bug, some regular files treated as "local additions" (different), but they not. #8636

Closed
5x3 opened this issue Nov 2, 2022 · 18 comments
Labels
bug A problem with current functionality, as opposed to missing functionality (enhancement) frozen-due-to-age Issues closed and untouched for a long time, together with being locked for discussion needs-triage New issues needed to be validated

Comments

@5x3
Copy link

5x3 commented Nov 2, 2022

on Linux OS, last syncthing,

On
pc-sender, add any linux ext4 folder here with send only and share with pc-receiver,
copy shaded folder content with tar -p\rsync -a\cp -a (with maximum preserve) from pc-sender to pc-receiver
unpack data with preservation on pc-receiver, use md5sum\sha1sum\sha512sum or mtree to validate all files checksum on both pc-sender and pc-receiver - all should be equal.

On
pc-receiver, accept incoming folder request and add folder to copyed dir (already with data transferred), as receive only folder .

data have files that equal with sha512sum , both pc-sender and pc-receiver -- all files have same checksum on both PCs.

Look at web GUI - you will see "local additions" that will re-appears after rescan folder even after "Revert local changes".

I tested it with 250GiB folder and 2GiB folder, same result.

P.S. If you don't transfer data to pc-receiver and let syncthing to sync it from scratch - everyting would be fine - NO "local additions" will appear.

click "Revert local changes" - "local additions" disappears.
click Rescan on folder - "local additions" appears again, same file.
click rescan on pc-sender or turning on\off Ignore Permissions does not solve problem.
+
sha512 sum of every file on "local additions" show same checksum on both pc-sender and pc-receiver, what was expected.

this is Re\scan bug.

@5x3 5x3 added bug A problem with current functionality, as opposed to missing functionality (enhancement) needs-triage New issues needed to be validated labels Nov 2, 2022
@calmh
Copy link
Member

calmh commented Nov 2, 2022

Different doesn't just mean different in content, it also relates to timestamps and permissions. That may still be a bug, but we could use some more information. Can you grab debug output for an affected file and paste here?

syncthing cli debug file $folder-id $path-to-file

@acolomb
Copy link
Member

acolomb commented Nov 2, 2022

And please do include the Syncthing version. "Last" doesn't mean much, as just today a new release came out.

@5x3
Copy link
Author

5x3 commented Nov 2, 2022

"Last" doesn't mean much, .. new release came out.
new release means nothing there since there is no difference in this release in code regarding bug nature and re\sync process in common.
but ok, I have v1.22.1, Linux (64-bit Intel/AMD) on both PCs.

it also relates to timestamps and permissions.

timestamp ? MTIME? mtime the same since it was preserved on transfer. I re\check it twice with stat (man 1 stat).

Selinux disabled on both ends. permission is exactly the same, uid\gid also, both PCs have same users with the same UID\GID settings exactly the same.

No extended attributes defined, I re\check it also twice with lsattr (man 1 lsattr)

That may still be a bug,

This is bug since out from 250 GiB files 54 GiB is stacked in "local additions", and "pc-sender" now have ethernal
"Syncing (67%, 54.8 GiB)" against device name in "Remote Devices", this is NOT normal state of syncing.

You can reproduce this by yourself, it reproduces easily.
you can tar files on pc-sender and transfer to pc-receiver with\via USB flash drive or via network like this
pc-receiver# ssh root@pc-sender 'cd /datadir && tar --numeric-owner -jcp manyfilesdir' | tar --numeric-owner -jvxp
*Make SURE you define -p (preserve) attribute on both tar end as well as --numeric-owner

syncthing cli debug file $folder-id $path-to-file

this don't work as described,
but I start syncthing with STRACE=all and grep some lines regarding "/dir/file.data"
don't sure what this can show to you since it is better to reproduce this by yourself, it's pretty easy and fast than collect my private data I can't post here.

orig IDs in output obfuscated.

[ABC0A] 2022/11/02 16:20:23.260261 set.go:281: DEBUG: 4meff-xxx1r GetGlobal(/dir/file.data)
[ABC0A] 2022/11/02 16:20:23.273990 lowlevel.go:378: DEBUG: removing sequence; folder="4meff-xxx1r" sequence=1679 /dir/file.data
[ABC0A] 2022/11/02 16:20:23.274212 lowlevel.go:239: DEBUG: insert (local); folder="4meff-xxx1r" File{Name:"/dir/file.data", Sequence:1682, Permissions:0600, ModTime:2018-08-11 20:09:18 +0300 MSK, Version:{[]}, VersionHash:, Length:10264, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:true, BlockSize:131072, NumBlocks:1, BlocksHash:35f5a03331e207c371279877ad17b2276a7a3a8e00d1cbbcb220cba0045c2acc, Platform:{owner_name:"w_live" group_name:"clients" uid:1012 gid:1000  <nil> <nil> <nil> <nil> <nil>}, InodeChangeTime:2022-11-02 15:24:37.338281884 +0300 MSK}
[ABC0A] 2022/11/02 16:20:23.274315 transactions.go:635: DEBUG: update global; folder="4meff-xxx1r" device=7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4 file="/dir/file.data" version={[]} invalid=false
[ABC0A] 2022/11/02 16:20:23.274369 transactions.go:649: DEBUG: new global for "/dir/file.data" after update: {{Version:{[{ABC0AHA 1665942349} {0A1ON9V 1665944789}]}, Deleted:false, Devices:{0A1ON9V}, Invalid:{}}, {Version:{[]}, Deleted:false, Devices:{7777777}, Invalid:{}}}
[ABC0A] 2022/11/02 16:20:23.274652 transactions.go:772: DEBUG: local need insert; folder="4meff-xxx1r", name="/dir/file.data"
[ABC0A] 2022/11/02 16:20:23.274720 lowlevel.go:260: DEBUG: adding sequence; folder="4meff-xxx1r" sequence=1682 /dir/file.data
[ABC0A] 2022/11/02 16:20:23.278230 events.go:334: DEBUG: log 25 LocalIndexUpdated map[filenames:[/dir /dir/file.data /dir/file2 /dir/file3] folder:4meff-xxx1r items:5 sequence:1685 version:1685]
[ABC0A] 2022/11/02 16:20:23.278619 events.go:334: DEBUG: log 27 LocalChangeDetected map[action:modified folder:4meff-xxx1r folderID:4meff-xxx1r label:/usb/ modifiedBy:ABC0AHA path:/dir/file.data type:file]
[ABC0A] 2022/11/02 16:20:23.281266 set.go:268: DEBUG: 4meff-xxx1r Get(/dir/file.data)
[ABC0A] 2022/11/02 16:20:23.281387 folder_sendrecv.go:1209: DEBUG: receiveonly/4meff-xxx1r@0xc000066c00 taking shortcut on /dir/file.data
[ABC0A] 2022/11/02 16:20:23.281496 events.go:334: DEBUG: log 36 ItemStarted map[action:metadata folder:4meff-xxx1r item:/dir/file.data type:file]
[ABC0A] 2022/11/02 16:20:23.281616 logfs.go:37: DEBUG: folder_sendrecv.go:1270 basic /usb Chtimes /dir/file.data 2018-08-11 20:09:18 +0300 MSK 2018-08-11 20:09:18 +0300 MSK <nil>
[ABC0A] 2022/11/02 16:20:23.281699 logfs.go:61: DEBUG: folder_sendrecv.go:2185 basic /usb Lstat /dir/file.data {0xc00db04dd0} <nil>
[ABC0A] 2022/11/02 16:20:23.281735 events.go:334: DEBUG: log 37 ItemFinished map[action:metadata error:<nil> folder:4meff-xxx1r item:/dir/file.data type:file]
[ABC0A] 2022/11/02 16:20:23.312121 lowlevel.go:378: DEBUG: removing sequence; folder="4meff-xxx1r" sequence=1682 /dir/file.data
[ABC0A] 2022/11/02 16:20:23.312195 lowlevel.go:239: DEBUG: insert (local); folder="4meff-xxx1r" File{Name:"/dir/file.data", Sequence:1687, Permissions:0600, ModTime:2018-08-11 20:09:18 +0300 MSK, Version:{[{ABC0AHA 1665942349} {0A1ON9V 1665944789}]}, VersionHash:, Length:10264, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:true, BlockSize:131072, NumBlocks:1, BlocksHash:35f5a03331e207c371279877ad17b2276a7a3a8e00d1cbbcb220cba0045c2acc, Platform:{group_name:"clients" uid:1012 gid:1000  <nil> <nil> <nil> <nil> <nil>}, InodeChangeTime:2022-11-02 16:20:23.280804481 +0300 MSK}
[ABC0A] 2022/11/02 16:20:23.312230 transactions.go:635: DEBUG: update global; folder="4meff-xxx1r" device=7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4 file="/dir/file.data" version={[{ABC0AHA 1665942349} {0A1ON9V 1665944789}]} invalid=false
[ABC0A] 2022/11/02 16:20:23.312242 transactions.go:649: DEBUG: new global for "/dir/file.data" after update: {{Version:{[{ABC0AHA 1665942349} {0A1ON9V 1665944789}]}, Deleted:false, Devices:{0A1ON9V, 7777777}, Invalid:{}}}
[ABC0A] 2022/11/02 16:20:23.312345 transactions.go:775: DEBUG: local need delete; folder="4meff-xxx1r", name="/dir/file.data"
[ABC0A] 2022/11/02 16:20:23.312369 lowlevel.go:260: DEBUG: adding sequence; folder="4meff-xxx1r" sequence=1687 /dir/file.data
[ABC0A] 2022/11/02 16:20:23.313593 events.go:334: DEBUG: log 44 LocalIndexUpdated map[filenames:[/dir /dir/file.data /dir/file2 /dir/file3] folder:4meff-xxx1r items:5 sequence:1690 version:1690]
[ABC0A] 2022/11/02 16:20:23.313906 events.go:334: DEBUG: log 46 RemoteChangeDetected map[action:modified folder:4meff-xxx1r folderID:4meff-xxx1r label:/usb/ modifiedBy:0A1ON9V path:/dir/file.data type:file]
[ABC0A] 2022/11/02 16:20:23.260261 set.go:281: DEBUG: 4meff-xxx1r GetGlobal(/dir/file.data)
[ABC0A] 2022/11/02 16:20:23.273990 lowlevel.go:378: DEBUG: removing sequence; folder="4meff-xxx1r" sequence=1679 /dir/file.data
[ABC0A] 2022/11/02 16:20:23.274212 lowlevel.go:239: DEBUG: insert (local); folder="4meff-xxx1r" File{Name:"/dir/file.data", Sequence:1682, Permissions:0600, ModTime:2018-08-11 20:09:18 +0300 MSK, Version:{[]}, VersionHash:, Length:10264, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:true, BlockSize:131072, NumBlocks:1, BlocksHash:35f5a03331e207c371279877ad17b2276a7a3a8e00d1cbbcb220cba0045c2acc, Platform:{owner_name:"w_live" group_name:"clients" uid:1012 gid:1000  <nil> <nil> <nil> <nil> <nil>}, InodeChangeTime:2022-11-02 15:24:37.338281884 +0300 MSK}
[ABC0A] 2022/11/02 16:20:23.274315 transactions.go:635: DEBUG: update global; folder="4meff-xxx1r" device=7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4 file="/dir/file.data" version={[]} invalid=false
[ABC0A] 2022/11/02 16:20:23.274369 transactions.go:649: DEBUG: new global for "/dir/file.data" after update: {{Version:{[{ABC0AHA 1665942349} {0A1ON9V 1665944789}]}, Deleted:false, Devices:{0A1ON9V}, Invalid:{}}, {Version:{[]}, Deleted:false, Devices:{7777777}, Invalid:{}}}
[ABC0A] 2022/11/02 16:20:23.274652 transactions.go:772: DEBUG: local need insert; folder="4meff-xxx1r", name="/dir/file.data"
[ABC0A] 2022/11/02 16:20:23.274720 lowlevel.go:260: DEBUG: adding sequence; folder="4meff-xxx1r" sequence=1682 /dir/file.data
[ABC0A] 2022/11/02 16:20:23.278230 events.go:334: DEBUG: log 25 LocalIndexUpdated map[filenames:[/dir /dir/file.data /dir/file2 /dir/file3] folder:4meff-xxx1r items:5 sequence:1685 version:1685]
[ABC0A] 2022/11/02 16:20:23.278619 events.go:334: DEBUG: log 27 LocalChangeDetected map[action:modified folder:4meff-xxx1r folderID:4meff-xxx1r label:/usb/ modifiedBy:ABC0AHA path:/dir/file.data type:file]
[ABC0A] 2022/11/02 16:20:23.281266 set.go:268: DEBUG: 4meff-xxx1r Get(/dir/file.data)
[ABC0A] 2022/11/02 16:20:23.281387 folder_sendrecv.go:1209: DEBUG: receiveonly/4meff-xxx1r@0xc000066c00 taking shortcut on /dir/file.data
[ABC0A] 2022/11/02 16:20:23.281496 events.go:334: DEBUG: log 36 ItemStarted map[action:metadata folder:4meff-xxx1r item:/dir/file.data type:file]
[ABC0A] 2022/11/02 16:20:23.281616 logfs.go:37: DEBUG: folder_sendrecv.go:1270 basic /usb Chtimes /dir/file.data 2018-08-11 20:09:18 +0300 MSK 2018-08-11 20:09:18 +0300 MSK <nil>
[ABC0A] 2022/11/02 16:20:23.281699 logfs.go:61: DEBUG: folder_sendrecv.go:2185 basic /usb Lstat /dir/file.data {0xc00db04dd0} <nil>
[ABC0A] 2022/11/02 16:20:23.281735 events.go:334: DEBUG: log 37 ItemFinished map[action:metadata error:<nil> folder:4meff-xxx1r item:/dir/file.data type:file]
[ABC0A] 2022/11/02 16:20:23.312121 lowlevel.go:378: DEBUG: removing sequence; folder="4meff-xxx1r" sequence=1682 /dir/file.data
[ABC0A] 2022/11/02 16:20:23.312195 lowlevel.go:239: DEBUG: insert (local); folder="4meff-xxx1r" File{Name:"/dir/file.data", Sequence:1687, Permissions:0600, ModTime:2018-08-11 20:09:18 +0300 MSK, Version:{[{ABC0AHA 1665942349} {0A1ON9V 1665944789}]}, VersionHash:, Length:10264, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:true, BlockSize:131072, NumBlocks:1, BlocksHash:35f5a03331e207c371279877ad17b2276a7a3a8e00d1cbbcb220cba0045c2acc, Platform:{group_name:"clients" uid:1012 gid:1000  <nil> <nil> <nil> <nil> <nil>}, InodeChangeTime:2022-11-02 16:20:23.280804481 +0300 MSK}
[ABC0A] 2022/11/02 16:20:23.312230 transactions.go:635: DEBUG: update global; folder="4meff-xxx1r" device=7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4 file="/dir/file.data" version={[{ABC0AHA 1665942349} {0A1ON9V 1665944789}]} invalid=false
[ABC0A] 2022/11/02 16:20:23.312242 transactions.go:649: DEBUG: new global for "/dir/file.data" after update: {{Version:{[{ABC0AHA 1665942349} {0A1ON9V 1665944789}]}, Deleted:false, Devices:{0A1ON9V, 7777777}, Invalid:{}}}
[ABC0A] 2022/11/02 16:20:23.312345 transactions.go:775: DEBUG: local need delete; folder="4meff-xxx1r", name="/dir/file.data"
[ABC0A] 2022/11/02 16:20:23.312369 lowlevel.go:260: DEBUG: adding sequence; folder="4meff-xxx1r" sequence=1687 /dir/file.data
[ABC0A] 2022/11/02 16:20:23.313593 events.go:334: DEBUG: log 44 LocalIndexUpdated map[filenames:[/dir /dir/file.data /dir/file2 /dir/file3] folder:4meff-xxx1r items:5 sequence:1690 version:1690]
[ABC0A] 2022/11/02 16:20:23.313906 events.go:334: DEBUG: log 46 RemoteChangeDetected map[action:modified folder:4meff-xxx1r folderID:4meff-xxx1r label:/usb/ modifiedBy:0A1ON9V path:/dir/file.data type:file]

please forward this to beta testers to confirm the bug for the future resolve.

@5x3
Copy link
Author

5x3 commented Nov 3, 2022

even send only + revert local changes is possible, gree.

dear testers, use 250 GiB test dir with Linux OS data on ext4 as a test directory and many files with code and os data including many files 2M+, symlinks, hardlinks, device files, to test core re\sync functions, they broken, possibly by the design.

@5x3
Copy link
Author

5x3 commented Nov 4, 2022

I continue to dig into the problem
on of the possible , I repeat, possible cause of the problem
same file but different mtime see .723820588 after dot
pc-sender:
TZ=C stat --format '%y' some.txt
2020-09-17 20:00:19.723820588 +0000
pc-reciever:
TZ=c stat --format '%y' some.txt
2020-09-17 20:00:19.000000000 +0000

this is same second, but looks like tar not supported this .723820588 appendix , what is this nanoseconds? no matter.

I believe syncthing SHOUD round all MTIME (if MTIME involved to detecting change even if Ignore permission set) to
begin of the second 20:00:19.723820588 -> 20:00:19.000000000 before comparing MTIMEes

who can check this in code and possibly fix ?

P.S. much better behavior if MTIME different on a fractions of a second - compare checksum of file content, and if they just the same - do not treat as different file, not sure what is better by the code.

will continue my finding since i am not shure that exactly this cause of the problem.

@5x3
Copy link
Author

5x3 commented Nov 7, 2022

also I found that it uses CTIME not the MTIME, which is totally wrong approach.

@tomasz1986
Copy link
Contributor

also I found that it uses CTIME not the MTIME, which is totally wrong approach.

This is probably related to the newly added support for syncing extended attributes. There are some issues with it currently (e.g. see my problem with conflicted copies at https://forum.syncthing.net/t/keep-getting-conflicts-generated-on-android-device-for-files-modified-only-on-a-desktop-pc/19060, and also https://forum.syncthing.net/t/conflicts-after-saving-a-file-from-a-single-machine/19265). The overall root of the problem here sounds similar to me, although in your case there is no Android involved. For now, I think the only solution/workaround will likely be to downgrade to v1.21.0 🙁.

@calmh
Copy link
Member

calmh commented Nov 7, 2022

Yeah that discussion isn't really useful without the requested debug info, unfortunately.

@5x3
Copy link
Author

5x3 commented Nov 7, 2022

without the requested debug info

provided early here.
Also timestamp nanoseconds issue not required some additional info to fix.

@calmh
Copy link
Member

calmh commented Nov 7, 2022

^ #8636 (comment)

@mattelacchiato
Copy link

mattelacchiato commented Nov 8, 2022

Hi! I have the same issue: Android (1.22.1) and a Linux PC (1.22.1). Both nodes have "Ignore Permissions" set.

This is the debug output for the file, executed from the PC:

{
  "availability": [
    "7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4",
    "XGZYEOG-GBQ4WSE-WXRGBW2-YK7EOOO-HEM42J5-XAQXUNG-NOLXNAD-L4CVFAY"
  ],
  "global": {
    "deleted": false,
    "ignored": false,
    "inodeChange": "2022-11-08T15:50:50.90502759+01:00",
    "invalid": false,
    "localFlags": 0,
    "modified": "2022-11-08T15:50:50.895027722+01:00",
    "modifiedBy": "KMSTLY5",
    "mustRescan": false,
    "name": "Daily/2022-11-08.md",
    "noPermissions": true,
    "numBlocks": 1,
    "platform": {
      "darwin": null,
      "freebsd": null,
      "linux": null,
      "netbsd": null,
      "unix": null,
      "windows": null
    },
    "sequence": 1278,
    "size": 147,
    "type": "FILE_INFO_TYPE_FILE",
    "version": [
      "KMSTLY5:1667919060"
    ]
  },
  "globalVersions": "{{Version:{[{KMSTLY5 1667919060}]}, Deleted:false, Devices:{7777777, XGZYEOG}, Invalid:{}}}",
  "local": {
    "deleted": false,
    "ignored": false,
    "inodeChange": "2022-11-08T15:50:50.90502759+01:00",
    "invalid": false,
    "localFlags": 0,
    "modified": "2022-11-08T15:50:50.895027722+01:00",
    "modifiedBy": "KMSTLY5",
    "mustRescan": false,
    "name": "Daily/2022-11-08.md",
    "noPermissions": true,
    "numBlocks": 1,
    "platform": {
      "darwin": null,
      "freebsd": null,
      "linux": null,
      "netbsd": null,
      "unix": null,
      "windows": null
    },
    "sequence": 1278,
    "size": 147,
    "type": "FILE_INFO_TYPE_FILE",
    "version": [
      "KMSTLY5:1667919060"
    ]
  },
  "mtime": {
    "err": null,
    "value": {
      "real": "0001-01-01T00:00:00Z",
      "virtual": "0001-01-01T00:00:00Z"
    }
  }
}

@calmh
Copy link
Member

calmh commented Nov 8, 2022

@mattelacchiato thanks for the debug output, but that doesn't appear to be a "local addition". Is it taken from the device that actually shows the problem?

@mattelacchiato
Copy link

@calmh Yes: I have the file Daily/2022-11-08.md on both devices. I make a change on the PC (and no changes on the Android device) and 5 seconds later I see a sync-conflict file next to it.

@calmh
Copy link
Member

calmh commented Nov 8, 2022

Right. That's not a local addition, that's a conflict, caused by our current issue with Android, which there are a myriad threads about.

@mattelacchiato
Copy link

Oh, okay... Sorry for bothering :-)

@5x3
Copy link
Author

5x3 commented Nov 13, 2022

other test shows some files are copyed to receiver-pc after rescan folder on sender-pc, and then copyed back to sender-pc after rescan folder on receiver-pc. ctime updating each time file writes on both pc - insanity, syncthing completely broken, at least on ext4, tested with ignore permission set and both with send&receive.

you can test it easly, see "recent changes" on 1st pc, click rescan all folders, see "recent changes" again.
and repeat it on 2nd pc - see "recent changes" on 2nd pc, click rescan all folders, see "recent changes" again.
btw, 2nd pc received those files with regular directory sync with syncthing itself.
use LInux PC.

another possilbe confirmation that if syncthing should fix bug with nanosecond part of timestamp on resync (explained early) and switch from CTIME to MTIME.

if you have many files on Linux - you will get all this kind of mess - permission mess on folders while sync, rescan mess.
too much bugs for debug.

@acolomb
Copy link
Member

acolomb commented Nov 13, 2022

You could help by providing the debug info requested earlier. We are still waiting on that from you. It does not help to claim "too much bugs", but please do help in debugging.

There have been some recent fixes that might affect this. If you could collect the debug info for how it currently fails, please update to the latest release candidate version and see if it helps.

@imsodin
Copy link
Member

imsodin commented Nov 16, 2022

I am closing this bug. Without the requested information there's nothing actionable here. Please open a topic on https://forum.syncthing.net for further assistance to debug this problem. Once a bug is identified, a targeted issue here on github can be opened.

@imsodin imsodin closed this as completed Nov 16, 2022
@st-review st-review added the frozen-due-to-age Issues closed and untouched for a long time, together with being locked for discussion label Nov 16, 2023
@syncthing syncthing locked and limited conversation to collaborators Nov 16, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
bug A problem with current functionality, as opposed to missing functionality (enhancement) frozen-due-to-age Issues closed and untouched for a long time, together with being locked for discussion needs-triage New issues needed to be validated
Projects
None yet
Development

No branches or pull requests

7 participants