I have a weird problem with Syncthing and don’t know how to solve it, so I want to ask for help in this forum.
In short, the cornerstones:
2 Node Setup for simplification (Ubuntu 16.04 Server, ext4 – send only --> Android 8.0.0, ext4 + f2fs)
both nodes are running v0.14.49
no general problem with the setup, I have already transfered thousands of files between the nodes
NOT the known “Syncthing cannot write to Android SD Card” Problem. I am aware of the Options (internal Memory, App Folder or SD Card as internal memory) and Limitations (no write access outside the Syncthing App folder) and based on https://github.com/syncthing/syncthing-android/wiki/Frequently-Asked-Questions it
should work.
no problem with the Android Energy Settings / Options
Problem description:
It is not possible to sync to the SD Card of my phone. I have tried different configurations, in every case I am able to sync to the internal storage but not (same shared folder and other configs) to the SD card. The selected folder is within …/…/com.nutomic.syncthingandroid/files/. If the synchronization process is started, everything seems to be normal. Between nothing and some gigabytes are transfered. After that, everything dies. First, the copy-process slows down / stops. After that the app itself is getting slow (while overall RAM and CPU usage are ok) and finally my Wifi Connection dies (no longer connected, reconnect not possible with “authentication error”). So something seems to pull down the whole network stack. After some fligh mode changes / wifi on/offs the wifi is connected again, but breaks as soons as I start Syncthing again or unpause the folder.
Has anyone a idea what can be the root cause of this or seen this behavior before?
If needed please tell me what log is necessary, if I enable all debug options within the described time frame it grows over 50 Mb.
Well generic log without any options should not grow to 50mb, if that is happening, it’s most likely printing errors of not being able to sync things, so you should address those first.
[AV32Y] INFO: Unexpected folder "video-2017" (xqgqc-rtdwv) sent from device "VHVOSYQ-ME4URR4-4IG4SWY-MG6FQPO-CJZDPU7-K6VNQSZ-TV3O2EW-5GFM6A7"; ensure that the folder exists and that this device is selected under "Share With" in the folder configuration.
[AV32Y] INFO: Puller (folder "video-2018" (grzpf-owxvw), file "02/08/Sophie-Wickelkommode/original/mp4/20180208-06-26-50-Sophie-Wickelkommode-13.mp4"): finisher: pull: peers who had this file went away, or the file has changed while syncing. will retry later
[AV32Y] INFO: Puller (folder "video-2018" (grzpf-owxvw), file "02/17/Sophie-singt-lautstark/original/mp4/20180217-07-07-08-Sophie-singt-lautstark-9.mp4"): finisher: pull: peers who had this file went away, or the file has changed while syncing. will retry later
Did you try rescanning the folder on the other side?
What version is being used on the other side?
Rescan doesn’t change anything, same behavior. Also my test setup is always “clean”, I delete the folder on the receiver and accept the introduction from the “master” some time later.
An addition regarding the difference to the working folders: the only real difference are the file sizes. In the working folder there are ~30Gb of smaller files between 1 and 4Mb. In the failing folder they are between 100 and 400Mb. In both folder types there are many directories.
If also tried the “Large Blocks” option, but it seems to change nothing in the behavior.
How much memory does your android have? (RAM)
On my samsung phone with 512 mb ram my folder got stuck when the bigger files should be pulled by the phone and leaving .tmp files behind. Maybe the sync folder is too big so the index doesn’t fit in memory? How did you check RAM usage?
What do you mean with sort out? Make it two way sync? Whats the benefit if the receiver is empty at the start?
The failing files are not the same if I try it again, so I have to touch all. But I think thats not the reason. I’ve tried it again with different video folders (other years) and its the same behavior.
Well you are sharing a folder from A to B, but not from B to A, so A thinks all files on B are missing. You should fix that as this is never the desired behaviour. This does not transfer files in any direction in the setup you have now.
I feel we are discussing in a circle. For sure I can create a two way setup.
But whats wrong or not desired on the above setup? The Folder on A is send only and A invites B. B accepts and starts syncing. At this point in time it has no files, yes, but isn’t this normal at a first sync? Or argumented in the other directio: in a two way setup its the same. A will send everything to B in the first place.
Btw 4 gb of ram should be enough to sync a lot of files, I cannot calculate the exact point when failure will occur. Just wanted to make sure not being to low
The missing time stamps may be deceiving, but in those logs I just see one problem: The connection fails
[AV32Y] INFO: Established secure connection to VHVOSYQ-ME4URR4-4IG4SWY-MG6FQPO-CJZDPU7-K6VNQSZ-TV3O2EW-5GFM6A7 at 192.168.10.110:22000-192.168.10.15:54418/tcp-server (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
[...]
[AV32Y] INFO: Connection to O6SZYRG-OIE47HB-HQM7KEQ-J3TMPFI-LFTF7HB-BG4HOUI-WP7LGB7-WNLVNQB at 192.168.10.110:22000-192.168.10.115:34216/tcp-server closed: reading length: read tcp 192.168.10.110:22000->192.168.10.115:34216: read: software caused connection abort
That there are some puller errors after the connection fails isn’t very surprising.
From your description I wouldn’t be surprised about the slowing down, a first sync with lots of data can be a lengthy process - as long as RAM usage is not growing out of bounds things should be fine and waiting will “solve” it. The dying wifi suggests that’s not the case here, unfortunately I have no idea what that might be and how one could investigate something like this on android.
How would you track it down on a none android host?
It must be something in combination with the SD card and it’s performance/filesystem(f2fs)/android behavior with SD cards in general.
The SD Card itself is very fast (200Gb San Disk) in general. But if I start the sync with the same folder on the internal memory, I have download rates between 25 and 40Mb/s over the wifi connection, constant, for 20Gb or more of data. If I do the same on the SD Card it never reaches this transfer rates and its a less constant transfer from the beginning of the sync. And after some time (as stated above maybe gigabytes of data) it breaks.
Unfortunately the logcat doesn’t show anything respective I need root rights to read the log for other apps.
I raised the Syncthing Log Level a little bit, maybe it helps to clear things up?
There are some repeating Runlockers Entries. I am not sure if they are normal.
Best regards
Robert
Syncthing Debug Log
[AV32Y] DEBUG: sharedPullerState grzpf-owxvw 02/08/Sophie-Wickelkommode/original/mp4/20180208-06-26-50-Sophie-Wickelkommode-13.mp4 pullNeeded start -> 130
[AV32Y] DEBUG: model@0x44221d4480 REQ(out): VHVOSYQ-ME4URR4-4IG4SWY-MG6FQPO-CJZDPU7-K6VNQSZ-TV3O2EW-5GFM6A7: “grzpf-owxvw” / “02/08/Robert-Sophie-Fruehstueck-nach-Friseur/original/mp4/20180208-06-13-07-Robert-Sophie-Fruehstueck-nach-Friseur-15.mp4” o=155582464 s=131072 h=11d78833fbf1dab34acc090364ee53e56460ef2f3ca37bfdd547aab77c53b644 wh=860c262b ft=false
[AV32Y] DEBUG: sharedPullerState grzpf-owxvw 02/08/Robert-Sophie-Fruehstueck-nach-Friseur/original/mp4/20180208-06-13-07-Robert-Sophie-Fruehstueck-nach-Friseur-15.mp4 pullNeeded done -> 128
[AV32Y] DEBUG: basic /storage/B180-F925/Android/data/com.nutomic.syncthingandroid/Video/2018/ Watch: Ignoring 02/08/Robert-Sophie-Fruehstueck-nach-Friseur/original/mp4/.syncthing.20180208-06-13-07-Robert-Sophie-Fruehstueck-nach-Friseur-15.mp4.tmp
[AV32Y] DEBUG: basic /storage/B180-F925/Android/data/com.nutomic.syncthingandroid/Video/2018/ Watch: Ignoring 02/08/Robert-Sophie-Fruehstueck-nach-Friseur/original/mp4/.syncthing.20180208-06-13-07-Robert-Sophie-Fruehstueck-nach-Friseur-15.mp4.tmp
[AV32Y] DEBUG: basic /storage/B180-F925/Android/data/com.nutomic.syncthingandroid/Video/2018/ Watch: Ignoring 02/08/Robert-Sophie-Fruehstueck-nach-Friseur/original/mp4/.syncthing.20180208-06-13-07-Robert-Sophie-Fruehstueck-nach-Friseur-15.mp4.tmp
[AV32Y] DEBUG: RWMutex held for 111.166923ms. Locked at model/sharedpullerstate.go:73 unlocked at model/sharedpullerstate.go:75
[AV32Y] DEBUG: sharedPullerState grzpf-owxvw 02/08/Sophie-Wickelkommode/original/mp4/20180208-06-26-50-Sophie-Wickelkommode-13.mp4 pullNeeded done -> 129
[AV32Y] DEBUG: basic /storage/B180-F925/Android/data/com.nutomic.syncthingandroid/Video/2018/ Watch: Ignoring 02/08/Sophie-Wickelkommode/original/mp4/.syncthing.20180208-06-26-50-Sophie-Wickelkommode-13.mp4.tmp
[AV32Y] DEBUG: RWMutex took 101.221693ms to lock. Locked at model/sharedpullerstate.go:73. RUnlockers while locking:
at model/sharedpullerstate.go:334 goid: 14 for 1m31.432781088s
at model/sharedpullerstate.go:211 goid: 1585 for 1m31.42547705s
at model/sharedpullerstate.go:211 goid: 1683 for 1m31.425099204s
at model/sharedpullerstate.go:211 goid: 1585 for 1m31.40932055s
at model/sharedpullerstate.go:211 goid: 1683 for 2.819337883s
at model/sharedpullerstate.go:211 goid: 1683 for 2.731857345s
… ~50 lines removed
at model/sharedpullerstate.go:211 goid: 1683 for 512.242807ms
at model/sharedpullerstate.go:211 goid: 1683 for 495.265923ms
at model/sharedpullerstate.go:211 goid: 1683 for 339.773077ms
at model/sharedpullerstate.go:211 goid: 1683 for 188.936269ms
[AV32Y] DEBUG: basic /storage/B180-F925/Android/data/com.nutomic.syncthingandroid/Video/2018/ Watch: Ignoring 02/08/Robert-Sophie-Fruehstueck-nach-Friseur/original/mp4/.syncthing.20180208-06-13-07-Robert-Sophie-Fruehstueck-nach-Friseur-15.mp4.tmp
[AV32Y] DEBUG: RWMutex took 128.193807ms to lock. Locked at model/sharedpullerstate.go:73. RUnlockers while locking:
at model/sharedpullerstate.go:211 goid: 1683 for 1m31.469005627s
at model/sharedpullerstate.go:211 goid: 1683 for 1m31.46616155s
at model/sharedpullerstate.go:211 goid: 1683 for 2.90093919s
at model/sharedpullerstate.go:211 goid: 1683 for 2.803005614s
at model/sharedpullerstate.go:211 goid: 1683 for 2.533314536s
at model/sharedpullerstate.go:211 goid: 1683 for 2.409266768s
at model/sharedpullerstate.go:211 goid: 1683 for 2.278790576s
… ~50 lines removed
at model/sharedpullerstate.go:211 goid: 1683 for 285.887692ms
at model/sharedpullerstate.go:211 goid: 1683 for 255.611616ms
at model/sharedpullerstate.go:211 goid: 1683 for 242.65723ms
at model/sharedpullerstate.go:211 goid: 1683 for 88.045192ms
at model/sharedpullerstate.go:211 goid: 1682 for 87.33627ms
[AV32Y] DEBUG: RWMutex held for 132.087615ms. Locked at model/sharedpullerstate.go:73 unlocked at model/sharedpullerstate.go:75
[AV32Y] DEBUG: sharedPullerState grzpf-owxvw 02/08/Sophie-Wickelkommode/original/mp4/20180208-06-26-50-Sophie-Wickelkommode-13.mp4 pullNeeded done -> 128
[AV32Y] DEBUG: basic /storage/B180-F925/Android/data/com.nutomic.syncthingandroid/Video/2018/ Watch: Ignoring 02/08/Sophie-Wickelkommode/original/mp4/.syncthing.20180208-06-26-50-Sophie-Wickelkommode-13.mp4.tmp
[AV32Y] DEBUG: RWMutex took 224.646346ms to lock. Locked at model/sharedpullerstate.go:73. RUnlockers while locking:
[AV32Y] DEBUG: RWMutex held for 132.085346ms. Locked at model/sharedpullerstate.go:73 unlocked at model/sharedpullerstate.go:75
[AV32Y] DEBUG: RWMutex took 251.303ms to lock. Locked at model/sharedpullerstate.go:73. RUnlockers while locking:
[AV32Y] DEBUG: basic /storage/B180-F925/Android/data/com.nutomic.syncthingandroid/Video/2018/ Watch: Ignoring 02/08/Robert-Sophie-Fruehstueck-nach-Friseur/original/mp4/.syncthing.20180208-06-13-07-Robert-Sophie-Fruehstueck-nach-Friseur-15.mp4.tmp
[AV32Y] DEBUG: RWMutex held for 131.210884ms. Locked at model/sharedpullerstate.go:73 unlocked at model/sharedpullerstate.go:75
[AV32Y] DEBUG: basic /storage/B180-F925/Android/data/com.nutomic.syncthingandroid/Video/2018/ Watch: Ignoring 02/08/Sophie-Wickelkommode/original/mp4/.syncthing.20180208-06-26-50-Sophie-Wickelkommode-13.mp4.tmp
[AV32Y] DEBUG: sharedPullerState grzpf-owxvw 02/08/Sophie-Wickelkommode/original/mp4/20180208-06-26-50-Sophie-Wickelkommode-13.mp4 pullNeeded done -> 127
[AV32Y] DEBUG: RWMutex took 347.776461ms to lock. Locked at model/sharedpullerstate.go:73. RUnlockers while locking:
[AV32Y] DEBUG: http: GET “/rest/system/connections”: status 200, 1486 bytes in 2.70 ms
[AV32Y] DEBUG: http: GET “/rest/system/connections”: status 200, 1486 bytes in 3.23 ms
[AV32Y] DEBUG: progress emitter: bytes completed for a9xhj-uquzp: 0
[AV32Y] DEBUG: model@0x44221d4480 NeedSize(“a9xhj-uquzp”): {0 0 0 0 0 0 []}
[AV32Y] DEBUG: http: GET “/rest/system/connections”: status 200, 1486 bytes in 2.50 ms
[AV32Y] DEBUG: RWMutex held for 132.906577ms. Locked at model/sharedpullerstate.go:73 unlocked at model/sharedpullerstate.go:75
[AV32Y] DEBUG: RWMutex took 375.753962ms to lock. Locked at model/sharedpullerstate.go:73. RUnlockers while locking:
[AV32Y] DEBUG: basic /storage/B180-F925/Android/data/com.nutomic.syncthingandroid/Video/2018/ Watch: Ignoring 02/08/Robert-Sophie-Fruehstueck-nach-Friseur/original/mp4/.syncthing.20180208-06-13-07-Robert-Sophie-Fruehstueck-nach-Friseur-15.mp4.tmp
… only (repeating) entry regarding not working Folder until connection abort
[AV32Y] DEBUG: :1 basic /storage/B180-F925/Android/data/com.nutomic.syncthingandroid/Video/2018/ Stat . {0x44210c6180}
[AV32Y] DEBUG: :1 basic /storage/B180-F925/Android/data/com.nutomic.syncthingandroid/Video/2018/ Stat .stfolder {0x44210c6240}
[AV32Y] DEBUG: :1 basic /storage/B180-F925/Android/data/com.nutomic.syncthingandroid/Video/2018/ Open .stignore open /storage/B180-F925/Android/data/com.nutomic.syncthingandroid/Video/2018/.stignore: no such file or directory
For sure I can create a two way setup.