Troubleshoot a few items not syncing

Support
21

Hmmm, thinking further, it is deterministic, the same 791 files are not synced, so it can’t really be a race condition or something else random.

22

It uses the device ID as a tie-breaker, which should provide consistent ordering on all devices.

This is nice - as in it’s reproducible so there’s a chance at finding the cause :slight_smile:

Can you run syncthing with -reset-deltas and STTRACE=model,db env var set and save the logging output. The output will be huge, so don’t run it as a system service, just redirect stdout to a file.

23

Each log file is 1.5GB. Probably best I pull stuff out at this end. I will pick a file that hasn’t synced and post relevant sections. Is there anything specific to look out for?

24

Ideally if you don’t mind make the entire thing available. Otherwise if I don’t mess it up the following grep should contain the info I want (or at least a good starting point): grep -P '(*nameOfAnOutOfSyncFile*|INFO)' (obviously replacing the parts within asterisks) and have a more sensible size (still large though).

25

I cut these from the logs. I will have a go with the grep command in a moment. If we can work it out without the whole log I would prefer, but if we can’t then I will look to share them

From dirac 

[O3ET7] 2020/01/13 16:45:07.945348 lowlevel.go:548: DEBUG: need folder="cmpcj-twatt" device=DZGK2SA-3E7QVQM-GPUIX7Y-AFFZMWU-WE
O53Q5-2FLBZRL-MCEUDBA-YNFLDAF name="20-29_Interests/21_Art/21.03_Flowers/Daffodil.ai" have=false invalid=false haveV={[]} glob
alV={[{O3ET7QT 1}]} globalDev=7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4
...
[O3ET7] 2020/01/13 16:45:08.973715 lowlevel.go:548: DEBUG: need folder="cmpcj-twatt" device=DZGK2SA-3E7QVQM-GPUIX7Y-AFFZMWU-WEO53Q5-2FLBZRL-MCEUDBA-YNFLDAF name="20-29_Interests/21_Art/21.03_Flowers/Daffodil.ai" have=false invalid=false haveV={[]} globalV={[{O3ET7QT 1}]} globalDev=7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4
...
[O3ET7] 2020/01/13 16:46:08.537569 lowlevel.go:548: DEBUG: need folder="cmpcj-twatt" device=DZGK2SA-3E7QVQM-GPUIX7Y-AFFZMWU-WEO53Q5-2FLBZRL-MCEUDBA-YNFLDAF name="20-29_Interests/21_Art/21.03_Flowers/Daffodil.ai" have=false invalid=false haveV={[]} globalV={[{O3ET7QT 1}]} globalDev=7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4
...
[O3ET7] 2020/01/13 16:48:47.577064 lowlevel.go:548: DEBUG: need folder="cmpcj-twatt" device=DZGK2SA-3E7QVQM-GPUIX7Y-AFFZMWU-WEO53Q5-2FLBZRL-MCEUDBA-YNFLDAF name="20-29_Interests/21_Art/21.03_Flowers/Daffodil.ai" have=false invalid=false haveV={[]} globalV={[{O3ET7QT 1}]} globalDev=7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4
...
[O3ET7] 2020/01/13 16:51:58.522881 lowlevel.go:548: DEBUG: need folder="cmpcj-twatt" device=DZGK2SA-3E7QVQM-GPUIX7Y-AFFZMWU-WEO53Q5-2FLBZRL-MCEUDBA-YNFLDAF name="20-29_Interests/21_Art/21.03_Flowers/Daffodil.ai" have=false invalid=false haveV={[]} globalV={[{O3ET7QT 1}]} globalDev=7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4
...
[O3ET7] 2020/01/13 16:55:24.806060 lowlevel.go:548: DEBUG: need folder="cmpcj-twatt" device=DZGK2SA-3E7QVQM-GPUIX7Y-AFFZMWU-WEO53Q5-2FLBZRL-MCEUDBA-YNFLDAF name="20-29_Interests/21_Art/21.03_Flowers/Daffodil.ai" have=false invalid=false haveV={[]} globalV={[{O3ET7QT 1}]} globalDev=7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4

From geo-fun 

[DZGK2] 2020/01/13 16:46:01.054449 lowlevel.go:548: DEBUG: need folder="cmpcj-twatt" device=O3ET7QT-RNUQHPX-APW6PNS-QPAVQWY-PU43DGW-CG455OH-XWBVLQB-NLDTSAA name="20-29_Interests/21_Art/21.03_Flowers/Daffodil.ai" have=true invalid=false haveV={[{O3ET7QT 1}]} globalV={[{BGRPGB2 1}]} globalDev=7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4
...
[DZGK2] 2020/01/13 16:46:06.823728 transactions.go:267: DEBUG: remove from global; folder="cmpcj-twatt" device=O3ET7QT-RNUQHPX-APW6PNS-QPAVQWY-PU43DGW-CG455OH-XWBVLQB-NLDTSAA file="20-29_Interests/21_Art/21.03_Flowers/Daffodil.ai"
...
[DZGK2] 2020/01/13 16:46:07.996147 lowlevel.go:548: DEBUG: need folder="cmpcj-twatt" device=O3ET7QT-RNUQHPX-APW6PNS-QPAVQWY-PU43DGW-CG455OH-XWBVLQB-NLDTSAA name="20-29_Interests/21_Art/21.03_Flowers/Daffodil.ai" have=false invalid=false haveV={[]} globalV={[{BGRPGB2 1}]} globalDev=7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4
...
[DZGK2] 2020/01/13 16:48:47.743876 lowlevel.go:75: DEBUG: insert; folder="cmpcj-twatt" device=O3ET7QT-RNUQHPX-APW6PNS-QPAVQWY-PU43DGW-CG455OH-XWBVLQB-NLDTSAA File{Name:"20-29_Interests/21_Art/21.03_Flowers/Daffodil.ai", Sequence:632068, Permissions:0644, ModTime:2009-03-08 17:23:26 +0000 GMT, Version:{[{O3ET7QT 1}]}, Length:1300419, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:false, BlockSize:131072, Blocks:[Block{0/131072/3987058061/17b4374edae4abb683d8b56a4a3c0dd63a463d63bc23b2fa215571b08107d0e3} Block{131072/131072/3501716483/36a714145f5211f9bc38f9c4964e4108b4c898d46cdf338248fa96477f6a0cf4} Block{262144/131072/41453113/cee5e9e56e7e722b6090732142f1c84e00682ff2e539b1fcf966f80071095194} Block{393216/131072/3755594029/f3a418fb094538821c5e3f74cc2d4e5f08ba0097ae452875781fd025b669cfac} Block{524288/131072/985730212/52d4be8a0257f454c4ecce3121507b622340e71276e3b80f763bb5e4918b0165} Block{655360/131072/853818378/23e9b5dc8413a03bba4979bb1d62563dbf3332e06be6b1e94a7ebe8d760755f1} Block{786432/131072/999585817/7c087a5c9137cf76c842220f6a254e1966e6b730ea34ca8e19d8d87da66681f2} Block{917504/131072/1633936707/316d3dc7358210d9562d70c818dc43e22ecd2103c4e28b608244f5ec6a037eb9} Block{1048576/131072/588696647/649a73dc56f4f2c8f09af063e1f97c3041fe9e939e8cc500c225e3f02b869908} Block{1179648/120771/1384364102/34a61b3f75811733163cc6fbffd9c557688f6ee7d83074ef49e79bcbd6deb113}]}
[DZGK2] 2020/01/13 16:48:47.743927 transactions.go:133: DEBUG: update global; folder="cmpcj-twatt" device=O3ET7QT-RNUQHPX-APW6PNS-QPAVQWY-PU43DGW-CG455OH-XWBVLQB-NLDTSAA file="20-29_Interests/21_Art/21.03_Flowers/Daffodil.ai" version={[{O3ET7QT 1}]} invalid=false
[DZGK2] 2020/01/13 16:48:47.744120 transactions.go:177: DEBUG: new global for "20-29_Interests/21_Art/21.03_Flowers/Daffodil.ai" after update: {{{[{BGRPGB2 1}]}, 7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4}, {{[{O3ET7QT 1}]}, O3ET7QT-RNUQHPX-APW6PNS-QPAVQWY-PU43DGW-CG455OH-XWBVLQB-NLDTSAA}}
...
[DZGK2] 2020/01/13 16:48:49.524230 lowlevel.go:548: DEBUG: need folder="cmpcj-twatt" device=O3ET7QT-RNUQHPX-APW6PNS-QPAVQWY-PU43DGW-CG455OH-XWBVLQB-NLDTSAA name="20-29_Interests/21_Art/21.03_Flowers/Daffodil.ai" have=true invalid=false haveV={[{O3ET7QT 1}]} globalV={[{BGRPGB2 1}]} globalDev=7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4
...
[DZGK2] 2020/01/13 16:55:09.698525 lowlevel.go:548: DEBUG: need folder="cmpcj-twatt" device=O3ET7QT-RNUQHPX-APW6PNS-QPAVQWY-PU43DGW-CG455OH-XWBVLQB-NLDTSAA name="20-29_Interests/21_Art/21.03_Flowers/Daffodil.ai" have=true invalid=false haveV={[{O3ET7QT 1}]} globalV={[{BGRPGB2 1}]} globalDev=7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4
...
[DZGK2] 2020/01/13 16:55:18.079197 lowlevel.go:548: DEBUG: need folder="cmpcj-twatt" device=O3ET7QT-RNUQHPX-APW6PNS-QPAVQWY-PU43DGW-CG455OH-XWBVLQB-NLDTSAA name="20-29_Interests/21_Art/21.03_Flowers/Daffodil.ai" have=true invalid=false haveV={[{O3ET7QT 1}]} globalV={[{BGRPGB2 1}]} globalDev=7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4
...
[DZGK2] 2020/01/13 16:55:45.126982 lowlevel.go:548: DEBUG: need folder="cmpcj-twatt" device=O3ET7QT-RNUQHPX-APW6PNS-QPAVQWY-PU43DGW-CG455OH-XWBVLQB-NLDTSAA name="20-29_Interests/21_Art/21.03_Flowers/Daffodil.ai" have=true invalid=false haveV={[{O3ET7QT 1}]} globalV={[{BGRPGB2 1}]} globalDev=7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4
26

My version of grep doesn’t have -P. Using -E gives lines with the file as well as any line containing INFO, and there is a lot of noise in the files with filenames containing INFO. This is only 27k though…

27 
grep -E '(*Daffodil.ai*|INFO)' st_dirac.txt| tee st_dirac_daffodil.txt

Log entries for a single unsynced file uploaded here - Will remove in 30 mins

28

What’s missing in dirac is any mention of an index for that file from geo-fun. To check that this is indeed the case (though it’s likely given the repeoted need folder ... lines run grep -E 'insert;.+DZGK2SA.+20-29_Interests/21_Art/21.03_Flowers/Daffodil.ai.

On geo-fun, please grep for missing file for sequence number.

If that doesn’t yield anything we are in a bit of pickle because there is no file level logging when sending indexes, so you’d have to run a custom binary for further debugging. Would you be ok with that? It can be built on official CI from an official github branch to increase the thrustworthiness :slight_smile:

I’ll do it myself, thanks for sharing!

29

These greps return nothing from the 1.5GB file on either machine

I have hit the “new user” limits, couldn’t post…

I can run a custom build, but would like a more private way of sharing the logs

30

It looks like on dirac the file is present in the db but not in the sequence “bucket”, which is used for sending indexes. Can you build

Upgraded your trust level.

Doable, would per PM here on the forum be ok? Also can you build go binaries? We have a tool to check database integrity, but unfortunately it’s not part of release bundles. If yes, could you build https://github.com/syncthing/syncthing/tree/master/cmd/stindex and run it like stindex -mode idxck *pathToYourConfig* please.

31

I haven’t built anything with go yet, but can have a go (excuse the pun). Won’t be until tomorrow afternoon though.

32

Then only if you want to, otherwise you can use this: stindex (9.8 MB)

33

on dirac 

./stindex -mode idxck .config/syncthing/index-v0.14.0.db

no output

on geo-fun

Lots of output… (Removed)

34

Ok, confirmed, the issue is a missing sequence entry in the db, i.e. the error occurred earlier. Meaning unfortunately new logs can’t tell us how it happened.

Do you have past logs? And if so, can you check if there was ever a panic.

Other than that I am out of ideas…

If you don’t want to touch the files, to get rid of this you’d have to remove and readd that folder (i.e. hash everything anew).

35

Sorry I was not following debugging, but are they missing locally or remotely?

36

I am not sure where the logs would be. They are not in /var/log or ~/.config/syncthing

I am running it using:

sudo systemctl start syncthing@vance.service
37

to remove and re-add I presume I need to do this at both ends? i.e. give it a new folder id pointing at the same location on disk?

38

No just on geo-fun where the db errors are.

journalctl -u syncthing@vances | grep panic

The sequence entries in the db are missing on geo-fun for reasons unknown. Therefore they are not sent in indexes which then causes the remote out-of-sync display (being out of sync on both devices is a red herring, that’s because it’s a conflict that would be resolved if the index was sent).

39

How does it know it’s a conflict if it lost it’s own entries? Or are you saying they exist locally, but weren’t sent or sent but lost on the receiving side?

40

In Troubleshoot a few items not syncing the db was checked, and it was confirmed that on device geo-fun for the files out of sync the sequence entry in the db is missing (the “normal” fileinfo entry is there). Therefore it doesn’t send these files to dirac. Dirac has the loosing conflict copy. So now dirac thinks geo-fun is out of date because it doesn’t have the file at all (no index sent) and geo-fun correctly reports dirac as out of sync because it has the loosing conflict. Now if the index were sent, geo-fun would pull the file and resolve the conflict.

How it ended up in this situation is a complete mystery to me (except for an unlikely panic or whatever that left the db in an inconsistent state, but that’s pretty unlikely for ~700 files I’d say).