Ignore Permissions / Different mtimes on Android Sdcard

Support
1

Hi,

I’m running the 1.1.4 version of syncthing from master on github (v1.1.4+34-g5541697d compiled locally - not the pre compiled version). One machine is a Linux desktop.

I’m sharing with Android on external, FAT formatted, SD card. The syncthing version is Catfriend’s syncthing fork, running 1.1.3.

Android has Receive Only and Ignore Permissions set.

Each time syncthing is restarted on both machines, syncthing on the Linux machine reports that syncing with the Android device has stalled. On the Android device I look in the Web GUI section and have to press “Revert Local Changes” (even though nothing has changed).

The problem is fixed if I set Ignore Permissions on the Linux box, too.

Some questions:

  • Is this normal behaviour? That is, is it normal that if both Receive Only and Ignore Permissions are set on the Android device, permission differences on the Android device show up as local changes that have to be reverted?

  • Are these two settings mutually exclusive?

  • If I set ignore permissions on a folder on one machine, do I have to set it on all machines?

It would be nice if I could leave permissions not ignored on the Linux box, so that permissions would be propagated correctly on other platforms that support permissions.

Apologies if I’m missing something obvious.

Thank you once again for this beautiful and immensely useful program.

===Rich

2

Update:

I was having the same issues on another Android phone. The sync happened, and all seemed to be up to date, but the Linux box reported that files were left to transfer.

I did:

-reset-database and -reset-deltas on the Linux side, and these problems disappeared.

Thanks,

===Rich

1 Like
3

This is unexpected.

4

Thanks for the info! After lots of resets, on many systems (files out of sync in on one machine but not others), I seem to be back in business.

Thanks again,

===Rich

5

Hello,

Forgive me for revisiting this.

It seems one of the problems I’m encountering may be to do with the fact that my files are stored on the sdcard in the …/com.github.catfriend1.syncthingandroid/… directory.

According to an discussion on github:

Specifically:

AudriusButkevicius wrote:

So this is not solved because updating mtime does not work in the sdcard, only in the built-in storage, hence the issue.

And my experience does seem to bear Audrius out.

I Revert Local Changes on the Android device, and all is good with the world. However, on restarting syncthing, some files are out of sync again, with 1 second differences in their mtimes. So I have to revert again.

From Linux Box “Out of Sync Items”:

MathJax.js 60.7 KiB 2016-09-17 14:29:09 LinuxBox

From Linux Box stat at command line:

Modify: 2016-09-17 14:29:09.441446450 +0100

From Android stat at command line:

Modify: 2016-09-17 14:29:08.000000000

Would it be possible to have an advanced setting on receive only directories that allowed for automatic Revert Local Changes, or, better still, automatic reversion of local metadata if file blobs are the same (and especially if mtime is behind change time by some largish margin)?

Thanks again,

===Rich

6

All “automatically nuke my data” options have been refused before, as they are too destructive.

There are attempts to work around the mtime android problem, but is seems not to be working (perhaps just with receive only folders).

Someone needs to debug this and potentially fix it.

7

So I observe we have a “fit” user helping us to observe code change impacts but who would be best to do the coding on the go side? I also remember this out of sync problems from my first time using Syncthing Android back in 2016 (0.14.7+). There wasn’t receive only folder so I often had to click override changes on the sendonly side (pc). I think We shouldn’t hit any override button automatically as this only cures the impact and not the root cause what is the difference in mtime. Can we maybe be more tolerant to assume mtimes < 2 sec away from each other as “virtually” the same when OS=Android detected?

8

There is already code handles this problem (same code that handles fat32 on windows having 2s precision), but for some reason it doesn’t work.

Someone needs to compile a custom version with debugging and understand whats happening.

9

  1. @AudriusButkevicius Thanks for getting back to me. I take your point about nuking data, but allowing metadata/mtime changes when file blobs haven’t been changed, esp when receive only is enforced, isn’t quite the nuking that others have requested. Ignoring mtimes within a window if and only if the blob hasn’t changed seems like a non-nuke idea, too (and may amount to the same thing). I think the rsync --modify-window option was originally meant for the same issue with FAT file systems.

  2. Is there a way to log metadata transfers only? Is there some high level traffic debugging facility? Or some way of showing what logic has been triggered?

  3. Since the file blobs don’t change and the metadata does change with this problem, is it possible/probable that on non receive only directories, the mtime metadata bounces back and forth between nodes until it reaches a stability, only, perhaps, a second out from where it started? And if that’s the case, who would notice? Only those who have set receive only on a FAT file system with dodgy granularity.

  4. @Catfriend1 Thanks for getting back to me. I can read go enough to hack a line here and there and bang in a few l.Infoln(“bingo”)‘s here and there, and I can certainly compile it, but getting to grips with the logic of the code would seem like a considerable undertaking! Audrius’ last phrase “and understand what’s happening” comment is the killer. :frowning: Perhaps just getting a reproducible test case might be an achievable baby step for me.

Thanks again,

===Rich

1 Like
10
  1. We should already handle that (yet we don’t as you are seeing issues). We try setting the time with high precision, if after setting the time and reading it back it’s different, we set the expected timestamp in the database and the actual timestamp that we’ve observed on disk. As someone does a stat call to check the mtime, we check in the database, if the time on the file matches the old observed mtime in the db, we return the high precision (expected) time stored in the db oppose to the time of the file.
  2. You can enable model logging, which will print “taking shortcut” if only metadata on the files changes, and nothing needs to be downloaded.
  3. It should not happen due to what is done in #1
  4. The relevant “lets warp the filesystem with a thing that stores stuff in the database to have better accuracy” starts here: https://github.com/syncthing/syncthing/blob/master/lib/model/model.go#L325
11

@AudriusButkevicius I enabled model logging on the main Linux box with:

STTRACE=model syncthing

But I suspect I need to do this on the Android phone. How do I do that?

Where should I paste this logging output? Here?

Are lines like the following from the sender any good at all?

[WKOOO] 2019/06/08 18:52:15.355399 model.go:727: DEBUG: model@0xc00018e840 Completion(UEMJNGF-XXXXXX... , "a2sch-pe4vv"): 0.000000 (79006867 / 79006867 = 1.000000)
[WKOOO] 2019/06/08 18:52:15.357411 model.go:727: DEBUG: model@0xc00018e840 Completion(UZIB6UE-XXXXXX... , "a2sch-pe4vv"): 100.000000 (0 / 79006867 = 0.000000)
[WKOOO] 2019/06/08 18:52:15.360209 model.go:727: DEBUG: model@0xc00018e840 Completion(WR6WMT7--XXXXXX... , "a2sch-pe4vv"): 100.000000 (0 / 79006867 = 0.000000)
[WKOOO] 2019/06/08 18:52:15.362176 model.go:727: DEBUG: model@0xc00018e840 Completion(3ABJ3OJ-XXXXXX... , "a2sch-pe4vv"): 99.964512 (28038 / 79006867 = 0.000355)
[WKOOO] 2019/06/08 18:52:41.688980 model.go:1118: INFO: Device 3ABJ3OJ-XXXXXX...  folder "dps1-distro" (a2sch-pe4vv) has mismatching index ID for us (0x2717643F1A7E646A != 0x2E4C203563E498D9)
[WKOOO] 2019/06/08 18:52:41.689010 model.go:1140: INFO: Device 3ABJ3OJ-XXXXXX...  folder "dps1-distro" (a2sch-pe4vv) has a new index ID (0x380D0EBE54AE308F)
[WKOOO] 2019/06/08 18:52:41.699983 model.go:1873: DEBUG: Starting sendIndexes for a2sch-pe4vv to 3ABJ3OJ-XXXXXX...  at 192.168.0.2:35596-94.130.123.126:22067/relay-client/TLS1.2-TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384 (slv=0)
[WKOOO] 2019/06/08 18:52:41.702997 model.go:1916: DEBUG: Sending indexes for a2sch-pe4vv to 3ABJ3OJ-XXXXXX...  at 192.168.0.2:35596-94.130.123.126:22067/relay-client/TLS1.2-TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384: 468 files (<114544 bytes)
[WKOOO] 2019/06/08 18:52:41.952375 progressemitter.go:261: DEBUG: progress emitter: bytes completed for a2sch-pe4vv: 0
[WKOOO] 2019/06/08 18:52:41.952407 model.go:805: DEBUG: model@0xc00018e840 NeedSize("a2sch-pe4vv"): {0 0 0 0 0 0 [] 0}
[WKOOO] 2019/06/08 18:52:41.958140 model.go:727: DEBUG: model@0xc00018e840 Completion(3ABJ3OJ-XXXXXX... , "a2sch-pe4vv"): 0.000000 (79006867 / 79006867 = 1.000000)
[WKOOO] 2019/06/08 18:52:42.142026 model.go:965: DEBUG: Index (in): 3ABJ3OJ-XXXXXX...  / "a2sch-pe4vv": 470 files
[WKOOO] 2019/06/08 18:52:44.217875 progressemitter.go:261: DEBUG: progress emitter: bytes completed for a2sch-pe4vv: 0
[WKOOO] 2019/06/08 18:52:44.217891 model.go:805: DEBUG: model@0xc00018e840 NeedSize("a2sch-pe4vv"): {0 0 0 0 0 0 [] 0}
[WKOOO] 2019/06/08 18:52:44.220093 model.go:727: DEBUG: model@0xc00018e840 Completion(3ABJ3OJ-XXXXXX... , "a2sch-pe4vv"): 99.964512 (28038 / 79006867 = 0.000355)
[WKOOO] 2019/06/08 18:52:44.572441 model.go:1888: DEBUG: Exiting sendIndexes for a2sch-pe4vv to 3ABJ3OJ-XXXXXX...  at 192.168.0.2:35596-94.130.123.126:22067/relay-client/TLS1.2-TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384: <nil>
[WKOOO] 2019/06/08 18:52:44.580922 model.go:1111: DEBUG: Device 3ABJ3OJ-XXXXXX...  folder "dps1-distro" (a2sch-pe4vv) is delta index compatible (mlv=1950)
[WKOOO] 2019/06/08 18:52:44.581039 model.go:1873: DEBUG: Starting sendIndexes for a2sch-pe4vv to 3ABJ3OJ-XXXXXX...  at 192.168.0.2:56482-192.168.0.51:22000/tcp-client/TLS1.2-TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384 (slv=1950)
[WKOOO] 2019/06/08 18:52:46.369105 progressemitter.go:261: DEBUG: progress emitter: bytes completed for a2sch-pe4vv: 0
[WKOOO] 2019/06/08 18:52:46.369115 model.go:805: DEBUG: model@0xc00018e840 NeedSize("a2sch-pe4vv"): {0 0 0 0 0 0 [] 0}
[WKOOO] 2019/06/08 18:52:46.372270 model.go:727: DEBUG: model@0xc00018e840 Completion(3ABJ3OJ-XXXXXX... , "a2sch-pe4vv"): 99.964512 (28038 / 79006867 = 0.000355)
[WKOOO] 2019/06/08 18:55:01.901039 model.go:965: DEBUG: Index update (in): 3ABJ3OJ-XXXXXX...  / "a2sch-pe4vv": 3 files
[WKOOO] 2019/06/08 18:55:02.155348 model.go:965: DEBUG: Index update (in): 3ABJ3OJ-XXXXXX...  / "a2sch-pe4vv": 3 files
[WKOOO] 2019/06/08 18:55:02.822199 progressemitter.go:261: DEBUG: progress emitter: bytes completed for a2sch-pe4vv: 0
[WKOOO] 2019/06/08 18:55:02.822235 model.go:805: DEBUG: model@0xc00018e840 NeedSize("a2sch-pe4vv"): {0 0 0 0 0 0 [] 0}
[WKOOO] 2019/06/08 18:55:02.825771 model.go:727: DEBUG: model@0xc00018e840 Completion(3ABJ3OJ-XXXXXX... , "a2sch-pe4vv"): 100.000000 (0 / 79006867 = 0.000000)
[WKOOO] 2019/06/08 19:02:44.572823 model.go:1888: DEBUG: Exiting sendIndexes for a2sch-pe4vv to 3ABJ3OJ-XXXXXX...  at 192.168.0.2:56482-192.168.0.51:22000/tcp-client/TLS1.2-TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384: <nil>
[WKOOO] 2019/06/08 19:02:56.907263 progressemitter.go:261: DEBUG: progress emitter: bytes completed for a2sch-pe4vv: 0
[WKOOO] 2019/06/08 19:02:56.907273 model.go:805: DEBUG: model@0xc00018e840 NeedSize("a2sch-pe4vv"): {0 0 0 0 0 0 [] 0}

I’m afraid it’ll take me a bit of time to plod along behind on the code logic! Sorry.

===R

12

@Catfriend1 To enable debugging on Android, do I have to build my own version of the apk, or can I just do something on your version?

Thanks,

===Rich

13

There are debug options on android too, somewhere in the UI .

1 Like
14

Yes, thank you, found it.

On Reverting, I get lines like these:

3ABJ3] DEBUG: receiveonly/a2sch-pe4vv@0x400018fb80 taking shortcut on books/...../MathJax.j

For each file reverted. Just chopped the path out a bit.

1 Like
15

This file had been reverted earlier, curious.

What next?

16

Instrument mtimefs, build a custom android app, understand why it doesn’t work.

17

I’d apply this

 lib/fs/mtimefs.go | 11 +++++++----
 1 file changed, 7 insertions(+), 4 deletions(-)

diff --git a/lib/fs/mtimefs.go b/lib/fs/mtimefs.go
index 3f375640..60c51250 100644
--- a/lib/fs/mtimefs.go
+++ b/lib/fs/mtimefs.go
@@ -59,6 +55,7 @@ func (f *MtimeFS) Chtimes(name string, atime, mtime time.Time) error {
 	// because it might be "does not exist" or similar.
 	info, err := f.Filesystem.Lstat(name)
 	if err != nil {
+		l.Debugln("Chtimes: Lstat:", err)
 		return err
 	}
 
@@ -69,6 +66,7 @@ func (f *MtimeFS) Chtimes(name string, atime, mtime time.Time) error {
 func (f *MtimeFS) Lstat(name string) (FileInfo, error) {
 	info, err := f.Filesystem.Lstat(name)
 	if err != nil {
+		l.Debugln("Lstat:", err)
 		return nil, err
 	}
 
@@ -94,6 +92,7 @@ func (f *MtimeFS) save(name string, real, virtual time.Time) {
 	if real.Equal(virtual) {
 		// If the virtual time and the real on disk time are equal we don't
 		// need to store anything.
+		l.Debugf("save: clearing saved for %s, time is %v", name, real)
 		f.db.Delete(name)
 		return
 	}
@@ -103,6 +102,7 @@ func (f *MtimeFS) save(name string, real, virtual time.Time) {
 		virtual: virtual,
 	}
 	bs, _ := mtime.Marshal() // Can't fail
+	l.Debugf("save: saving %v / %v for %s", real, virtual, name)
 	f.db.PutBytes(name, bs)
 }
 
@@ -113,14 +113,17 @@ func (f *MtimeFS) load(name string) (real, virtual time.Time) {
 
 	data, exists := f.db.Bytes(name)
 	if !exists {
+		l.Debugln("load: nothing for", name)
 		return
 	}
 
 	var mtime dbMtime
 	if err := mtime.Unmarshal(data); err != nil {
+		l.Debugln("load: unmarshal error for", name)
 		return
 	}
 
+	l.Debugf("load: loaded %v / %v for %s", mtime.real, mtime.virtual, name)
 	return mtime.real, mtime.virtual
 }

then reproduce the problem with STTRACE=fs

1 Like
19

… done. Link: https://drive.google.com/file/d/1SrejtTcXcCJeNSYSN3H53PF3lryvFROO/view?usp=sharing

This is the same wrapper code as from release 1.1.4.1 including SyncthingNative 1.1.4 with the above mentioned log patch from calmh.

Don’t forget to enable STTRACE in the app settings first and ticking the “fs” checkbox there to get extended log output. Running adb logcat from a computer will help getting a complete log and not missing some lines because of ring bufferness.

Windows: adb logcat | findstr /C:“SyncthingNative” Linux: adb logcat | grep “SyncthingNative”

1 Like
20

Sorry for delay on this. Real life gets in the way!

Have replied to @Catfriend1 in different thread. Should have answers today.

===Rich

21

Hi

Progress so far:

  1. Installed latest debug build as per Catfriend1’s instructions. Shared the same dirs with it (and with the some of the same devices) that were shared with the non debug version - the two builds have different names, different config files, different keys, and different databases.

  2. Whilst I had the error in the original app, I had to reboot the phone to provoke it in the debug version.

  3. Here’s the output from:

/storage/emulated/0/Android/data/com.github.catfriend1.syncthingandroid.debug/files/syncthing.log

for one file:

[XHTJH] DEBUG: mtimefs.go:71 basic /storage/B977-5AE1/Android/data/com.github.catfriend1.syncthingandroid.debug/st/dps1-distro Lstat books/mbrett_git/Deleting your master branch_files/MathJax.js {0x4001019200} <nil>
[XHTJH] DEBUG: load: loaded 2016-09-17 13:29:09 +0000 UTC / 2016-09-17 13:29:09.44144645 +0000 UTC for books/mbrett_git/Deleting your master branch_files/MathJax.js
[XHTJH] DEBUG: load: loaded 2019-04-03 15:31:38 +0000 UTC / 2019-04-03 15:31:38.460158242 +0000 UTC for dps1-distro/books/mbrett_git/Deleting your master branch_files/MathJax.js
[XHTJH] DEBUG: blockqueue.go:20 basic /storage/B977-5AE1/Android/data/com.github.catfriend1.syncthingandroid.debug/st/dps1-distro Open books/mbrett_git/Deleting your master branch_files/MathJax.js {0x400028e638 books/mbrett_git/Deleting your master branch_files/MathJax.js} <nil>
[XHTJH] DEBUG: load: loaded 2019-04-03 15:31:38 +0000 UTC / 2019-04-03 15:31:38.460158242 +0000 UTC for dps1-distro/books/mbrett_git/Deleting your master branch_files/MathJax.js
[XHTJH] DEBUG: mtimefs.go:71 basic /storage/B977-5AE1/Android/data/com.github.catfriend1.syncthingandroid.debug/st/dps1-distro Lstat books/mbrett_git/Deleting your master branch_files/MathJax.js {0x4002e28180} <nil>
[XHTJH] DEBUG: load: loaded 2016-09-17 13:29:09 +0000 UTC / 2016-09-17 13:29:09.44144645 +0000 UTC for books/mbrett_git/Deleting your master branch_files/MathJax.js
[XHTJH] DEBUG: mtimefs.go:56 basic /storage/B977-5AE1/Android/data/com.github.catfriend1.syncthingandroid.debug/st/dps1-distro Chtimes books/mbrett_git/Deleting your master branch_files/MathJax.js 2016-09-17 13:29:09.44144645 +0000 UTC 2016-09-17 13:29:09.44144645 +0000 UTC <nil>
[XHTJH] DEBUG: mtimefs.go:60 basic /storage/B977-5AE1/Android/data/com.github.catfriend1.syncthingandroid.debug/st/dps1-distro Lstat books/mbrett_git/Deleting your master branch_files/MathJax.js {0x40004ab5c0} <nil>
[XHTJH] DEBUG: save: saving 2016-09-17 13:29:09 +0000 UTC / 2016-09-17 13:29:09.44144645 +0000 UTC for books/mbrett_git/Deleting your master branch_files/MathJax.js

Can PM the whole 4MB file.

Thanks,

===Rich