GUI: One file displayd many times

imsodin · February 11, 2017, 3:21pm

I just noticed something weird in the GUI. While one biggish file was pulled this item appears many times in the “Out of Sync Items” list (screenshot). Also the percentage is not adjusted to the actual progress of the file (screenshot), but that might be intentional. There is nothing in the log.

This change originates on a windows 7 device with synctrayzor and are received on linux. I cannot reproduce the same behaviour when syncing from a linux device to the same device, that’s why I am not opening a bug report.

Does anyone have a clue what might be going on or instructions how to get more information about what is happening?

AudriusButkevicius · February 11, 2017, 4:25pm

Run with -audit -verbose to see the content of the event we are firing off, or use web developer tools to see what events we actually get. It might get registered client side multiple times if the file fails and retries for some reason I suspect.

It does however sound like a bug worth opening, ideally with an explanation why it happens or a repro.

imsodin · February 11, 2017, 4:30pm

The missing explanation and repro are the reasons I didn’t open a bug. I will do as soon as I investigated it as you proposed.

AudriusButkevicius · February 11, 2017, 4:49pm

I suspect it might happen if the file fails to sync for example, and gets restarted.

imsodin · February 11, 2017, 10:45pm

Well, I tried to do the troubleshooting, found some “peer who had this file went away” errors. But now that I run it built from master with audit, verbose and STTRACE=protocol,model a new problem surfaces: It never starts syncing.

I tried to debug this, so there are some non-standard debug messages in there. However I didn’t find anything more specific than the generic errors

[BPDFD] 2017/02/11 23:27:57.911744 rwfolder.go:1400: DEBUG: request: email-UrsiPeter Outlook_PeterUrsi.pst 0 131072 returned error: generic error

So the log from the receiving side where the problem is:

[BPDFD] 2017/02/11 23:27:32.277721 rwfolder.go:220: DEBUG: sendReceiveFolder/email-UrsiPeter@0xc4202d6600 pulling 0 1445
[BPDFD] 2017/02/11 23:27:32.278119 rwfolder.go:330: DEBUG: sendReceiveFolder/email-UrsiPeter@0xc4202d6600 c 2 p 64
[BPDFD] 2017/02/11 23:27:32.278319 verboseservice.go:48: VERBOSE: Folder "email-UrsiPeter" is now syncing
[BPDFD] 2017/02/11 23:27:32.390109 service.go:221: INFO: Connection from CBBHGDL-33SPQV2-CB3CTA4-LS3SMK3-3MVPTMW-TKHJUXR-RHQMMA3-BDDI5AE at [fe80::110e:6cd:a4d7:e420%eth0]:57908 (tcp-server) rejected: device is paused
[BPDFD] 2017/02/11 23:27:37.355900 service.go:221: INFO: Connection from CBBHGDL-33SPQV2-CB3CTA4-LS3SMK3-3MVPTMW-TKHJUXR-RHQMMA3-BDDI5AE at 10.0.0.1:40894 (tcp-server) rejected: device is paused
[BPDFD] 2017/02/11 23:27:39.254421 protocol.go:354: DEBUG: read Ping message
[BPDFD] 2017/02/11 23:27:39.303609 protocol.go:773: DEBUG: 2KSY4GG-2YOY4TU-TSCDB2E-BFPINVK-36WTRF2-2FOMUQ3-JXE4Z2D-JMOWFQQ ping -> after 1m7.028609424s
[BPDFD] 2017/02/11 23:27:39.303958 protocol.go:665: DEBUG: wrote 8 bytes on the wire (2 bytes length, 2 bytes header, 4 bytes message length, 0 bytes message), err=<nil>
[BPDFD] 2017/02/11 23:27:57.906944 rwfolder.go:1154: DEBUG: sendReceiveFolder/email-UrsiPeter@0xc4202d6600 need file Outlook_PeterUrsi.pst; copy 1, reused 32641
[BPDFD] 2017/02/11 23:27:57.907101 verboseservice.go:48: VERBOSE: Started syncing "email-UrsiPeter" / "Outlook_PeterUrsi.pst" (update file)
[BPDFD] 2017/02/11 23:27:57.907276 progressemitter.go:211: DEBUG: progress emitter: registering email-UrsiPeter Outlook_PeterUrsi.pst
[BPDFD] 2017/02/11 23:27:57.907320 rwfolder.go:1242: DEBUG: not weak hashing Outlook_PeterUrsi.pst. not enough changed %!f(int=00) < 25
[BPDFD] 2017/02/11 23:27:57.907431 sharedpullerstate.go:261: DEBUG: sharedPullerState email-UrsiPeter Outlook_PeterUrsi.pst pullNeeded start -> 1
[BPDFD] 2017/02/11 23:27:57.907852 rwfolder.go:1377: DEBUG: sendReceiveFolder/email-UrsiPeter@0xc4202d6600 indaforloop
[BPDFD] 2017/02/11 23:27:57.908200 deviceactivity.go:35: DEBUG: devAct: leastBusy: 2KSY4GG-2YOY4TU-TSCDB2E-BFPINVK-36WTRF2-2FOMUQ3-JXE4Z2D-JMOWFQQ usage: 0
[BPDFD] 2017/02/11 23:27:57.908475 model.go:1665: DEBUG: model@0xc420098b40 REQ(out): 2KSY4GG-2YOY4TU-TSCDB2E-BFPINVK-36WTRF2-2FOMUQ3-JXE4Z2D-JMOWFQQ: "email-UrsiPeter" / "Outlook_PeterUrsi.pst" o=0 s=131072 h=6e1e38ebc2c1cc80b7ad8d19cd48ac47517184933b2805462b1a3b6da5455ac1 ft=false
[BPDFD] 2017/02/11 23:27:57.908822 protocol.go:665: DEBUG: wrote 88 bytes on the wire (2 bytes length, 2 bytes header, 4 bytes message length, 80 bytes message), err=<nil>
[BPDFD] 2017/02/11 23:27:57.911689 protocol.go:340: DEBUG: read Response message
[BPDFD] 2017/02/11 23:27:57.911744 rwfolder.go:1400: DEBUG: request: email-UrsiPeter Outlook_PeterUrsi.pst 0 131072 returned error: generic error
[BPDFD] 2017/02/11 23:27:57.911760 rwfolder.go:1377: DEBUG: sendReceiveFolder/email-UrsiPeter@0xc4202d6600 indaforloop
[BPDFD] 2017/02/11 23:27:57.911770 rwfolder.go:1386: DEBUG: sendReceiveFolder/email-UrsiPeter@0xc4202d6600 origin of errNoDevice
[BPDFD] 2017/02/11 23:27:57.911788 sharedpullerstate.go:217: INFO: Puller (folder "email-UrsiPeter", file "Outlook_PeterUrsi.pst"): pull: peers who had this file went away, or the file has changed while syncing. will retry later
[BPDFD] 2017/02/11 23:27:57.911839 rwfolder.go:1490: DEBUG: sendReceiveFolder/email-UrsiPeter@0xc4202d6600 closing Outlook_PeterUrsi.pst
[BPDFD] 2017/02/11 23:27:57.911955 rwfolder.go:1499: INFO: Puller: final: peers who had this file went away, or the file has changed while syncing. will retry later
[BPDFD] 2017/02/11 23:27:57.912032 progressemitter.go:225: DEBUG: progress emitter: deregistering email-UrsiPeter Outlook_PeterUrsi.pst
[BPDFD] 2017/02/11 23:27:57.912058 rwfolder.go:230: DEBUG: sendReceiveFolder/email-UrsiPeter@0xc4202d6600 changed 1
[BPDFD] 2017/02/11 23:27:57.912080 rwfolder.go:330: DEBUG: sendReceiveFolder/email-UrsiPeter@0xc4202d6600 c 2 p 64
[BPDFD] 2017/02/11 23:27:57.912132 verboseservice.go:48: VERBOSE: Finished syncing "email-UrsiPeter" / "Outlook_PeterUrsi.pst" (update file): peers who had this file went away, or the file has changed while syncing. will retry later
[BPDFD] 2017/02/11 23:28:02.907540 progressemitter.go:62: DEBUG: progress emitter: timer - looking after 0
[BPDFD] 2017/02/11 23:28:02.907718 progressemitter.go:81: DEBUG: progress emitter: nothing new
[BPDFD] 2017/02/11 23:28:16.262250 service.go:221: INFO: Connection from CBBHGDL-33SPQV2-CB3CTA4-LS3SMK3-3MVPTMW-TKHJUXR-RHQMMA3-BDDI5AE at 10.0.0.116:36214 (tcp-server) rejected: device is paused
[BPDFD] 2017/02/11 23:28:23.496383 service.go:221: INFO: Connection from NGW62IP-O37KSJN-W7RIJ6H-GHTURXV-S3LL2IK-J6SW35D-OBFFT4A-QYVLVQL at 10.0.0.13:55605 (tcp-server) rejected: device is paused
[BPDFD] 2017/02/11 23:28:23.544246 rwfolder.go:1154: DEBUG: sendReceiveFolder/email-UrsiPeter@0xc4202d6600 need file Outlook_PeterUrsi.pst; copy 1, reused 32641
[BPDFD] 2017/02/11 23:28:23.544633 progressemitter.go:211: DEBUG: progress emitter: registering email-UrsiPeter Outlook_PeterUrsi.pst
[BPDFD] 2017/02/11 23:28:23.544761 rwfolder.go:1242: DEBUG: not weak hashing Outlook_PeterUrsi.pst. not enough changed %!f(int=00) < 25
[BPDFD] 2017/02/11 23:28:23.545013 sharedpullerstate.go:261: DEBUG: sharedPullerState email-UrsiPeter Outlook_PeterUrsi.pst pullNeeded start -> 1
[BPDFD] 2017/02/11 23:28:23.545235 rwfolder.go:1377: DEBUG: sendReceiveFolder/email-UrsiPeter@0xc4202d6600 indaforloop
[BPDFD] 2017/02/11 23:28:23.545360 deviceactivity.go:35: DEBUG: devAct: leastBusy: 2KSY4GG-2YOY4TU-TSCDB2E-BFPINVK-36WTRF2-2FOMUQ3-JXE4Z2D-JMOWFQQ usage: 0
[BPDFD] 2017/02/11 23:28:23.545438 model.go:1665: DEBUG: model@0xc420098b40 REQ(out): 2KSY4GG-2YOY4TU-TSCDB2E-BFPINVK-36WTRF2-2FOMUQ3-JXE4Z2D-JMOWFQQ: "email-UrsiPeter" / "Outlook_PeterUrsi.pst" o=0 s=131072 h=6e1e38ebc2c1cc80b7ad8d19cd48ac47517184933b2805462b1a3b6da5455ac1 ft=false
[BPDFD] 2017/02/11 23:28:23.545504 verboseservice.go:48: VERBOSE: Started syncing "email-UrsiPeter" / "Outlook_PeterUrsi.pst" (update file)
[BPDFD] 2017/02/11 23:28:23.545597 protocol.go:665: DEBUG: wrote 88 bytes on the wire (2 bytes length, 2 bytes header, 4 bytes message length, 80 bytes message), err=<nil>
[BPDFD] 2017/02/11 23:28:23.548281 protocol.go:340: DEBUG: read Response message
[BPDFD] 2017/02/11 23:28:23.548395 rwfolder.go:1400: DEBUG: request: email-UrsiPeter Outlook_PeterUrsi.pst 0 131072 returned error: generic error
[BPDFD] 2017/02/11 23:28:23.548434 rwfolder.go:1377: DEBUG: sendReceiveFolder/email-UrsiPeter@0xc4202d6600 indaforloop
[BPDFD] 2017/02/11 23:28:23.548463 rwfolder.go:1386: DEBUG: sendReceiveFolder/email-UrsiPeter@0xc4202d6600 origin of errNoDevice
[BPDFD] 2017/02/11 23:28:23.548534 sharedpullerstate.go:217: INFO: Puller (folder "email-UrsiPeter", file "Outlook_PeterUrsi.pst"): pull: peers who had this file went away, or the file has changed while syncing. will retry later
[BPDFD] 2017/02/11 23:28:23.548650 rwfolder.go:1490: DEBUG: sendReceiveFolder/email-UrsiPeter@0xc4202d6600 closing Outlook_PeterUrsi.pst
[BPDFD] 2017/02/11 23:28:23.548687 rwfolder.go:1499: INFO: Puller: final: peers who had this file went away, or the file has changed while syncing. will retry later
[BPDFD] 2017/02/11 23:28:23.548844 progressemitter.go:225: DEBUG: progress emitter: deregistering email-UrsiPeter Outlook_PeterUrsi.pst
[BPDFD] 2017/02/11 23:28:23.548903 rwfolder.go:230: DEBUG: sendReceiveFolder/email-UrsiPeter@0xc4202d6600 changed 1
[BPDFD] 2017/02/11 23:28:23.548964 rwfolder.go:330: DEBUG: sendReceiveFolder/email-UrsiPeter@0xc4202d6600 c 2 p 64
[BPDFD] 2017/02/11 23:28:23.549053 verboseservice.go:48: VERBOSE: Finished syncing "email-UrsiPeter" / "Outlook_PeterUrsi.pst" (update file): peers who had this file went away, or the file has changed while syncing. will retry later
[BPDFD] 2017/02/11 23:28:24.303478 protocol.go:769: DEBUG: 2KSY4GG-2YOY4TU-TSCDB2E-BFPINVK-36WTRF2-2FOMUQ3-JXE4Z2D-JMOWFQQ ping skipped after wr 757.525388ms
[BPDFD] 2017/02/11 23:28:28.544909 progressemitter.go:62: DEBUG: progress emitter: timer - looking after 0
[BPDFD] 2017/02/11 23:28:28.544997 progressemitter.go:81: DEBUG: progress emitter: nothing new

On the sending side

[2KSY4] 23:27:50 DEBUG: BPDFDTU ping -> after 1m6.9788309s
[2KSY4] 23:27:50 DEBUG: wrote 8 bytes on the wire (2 bytes length, 2 bytes header, 4 bytes message length, 0 bytes message), err=<nil>
[2KSY4] 23:27:50 DEBUG: read Ping message
[2KSY4] 23:28:09 DEBUG: read Request message
[2KSY4] 23:28:09 DEBUG: wrote 12 bytes on the wire (2 bytes length, 2 bytes header, 4 bytes message length, 4 bytes message), err=<nil>
[2KSY4] 23:28:35 DEBUG: read Request message
[2KSY4] 23:28:35 DEBUG: wrote 12 bytes on the wire (2 bytes length, 2 bytes header, 4 bytes message length, 4 bytes message), err=<nil>

I still didn’t put it on github as I can’t reproduce it (and the problem changed…), but if you rather want it there just say so.

Edit: The file in question being a database file should be nothing to be worried about: I scan only hourly and currently, outlook is not running.

AudriusButkevicius · February 12, 2017, 12:50am

I think “generic error” implies we can’t open the file for reading because Outlook is a bastard. Try closing outlook and see if you can repro then.

imsodin · February 12, 2017, 9:37am

That is the weird thing: Outlook wasn’t running. Now this morning I am no longer able to reproduce this (even while evil outlook is running), while yesterday evening it persisted between restarts of syncthing. Neither does the original issue of duplicate entries in the “Out of Sync Items” come up any more. I will keep an eye out for this, but as it is nothing critical, stop looking for it.

canton7 · February 12, 2017, 11:00am

Bear in mind that other applications, like Lync, can also lock various Outlook files.

system · March 14, 2017, 11:10am

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.