Files Seemingly Not Completing As Expected?

[Moisie]

Hello:

I’ve got some files which don’t seem to be completing as expected.

Running Syncthing 1.1.3 on a mixture of macOS and Synology machines (totalling about 10 machines signed into this folder), I’m seeing the following in the logs on one of the NASes (filtered to only show the lines relevant to one of the un-finished files):

2019-05-28 13:10:02 sharedPullerState y9qce-***** File/Path/Here pullNeeded start -> 1
2019-05-28 13:10:02 model@0xc0000c8b00 REQ(out): NN3I4DJ-*******-*******-*******-*******-*******-*******-*******: "y9qce-*****" / "File/Path/Here" o=1230897152 s=131072 h=7ba181c06bf243fae7bae65415fdb8b4d60d9aee326ab635b7b722ac88c71e9e wh=774194cf ft=false
2019-05-28 13:10:02 sharedPullerState y9qce-***** File/Path/Here pullNeeded done -> 0
2019-05-28 13:10:04 sharedPullerState y9qce-***** File/Path/Here pullNeeded start -> 1
2019-05-28 13:10:04 model@0xc0000c8b00 REQ(out): NN3I4DJ-*******-*******-*******-*******-*******-*******-*******: "y9qce-*****" / "File/Path/Here" o=1205993472 s=131072 h=e60601ebd926e6cb0f9b68f7444eba6429fd9518d1b17a006a3f1c0bbdf101e3 wh=81875888 ft=false
2019-05-28 13:10:04 sharedPullerState y9qce-***** File/Path/Here pullNeeded done -> 0
2019-05-28 13:10:04 progress emitter: emitting map[string]map[string]*model.pullerProgress{"czphw-*****":map[string]*model.pullerProgress{"File 2/Path/Here":(*model.pullerProgress)(0xc00119c960), "File 3/Path/Here":(*model.pullerProgress)(0xc00119ca00)}, "xns9m-*****":map[string]*model.pullerProgress{"File 4/Path/Here":(*model.pullerProgress)(0xc00119cb40)}, "y9qce-*****":map[string]*model.pullerProgress{"File/Path/Here":(*model.pullerProgress)(0xc00119caa0), "File 5/Path Here":(*model.pullerProgress)(0xc00119caf0)}}
2019-05-28 13:10:05 sharedPullerState y9qce-***** File/Path/Here pullNeeded start -> 1
2019-05-28 13:10:05 model@0xc0000c8b00 REQ(out): NN3I4DJ-*******-*******-*******-*******-*******-*******-*******: "y9qce-*****" / "File/Path/Here" o=406061056 s=131072 h=81e93c28e233012fc7c2070d6e8256bdf804aa176811ed5a17ef6f7c7b3ca692 wh=b3e1012d ft=false
2019-05-28 13:10:05 sharedPullerState y9qce-***** File/Path/Here pullNeeded done -> 0
2019-05-28 13:10:08 sharedPullerState y9qce-***** File/Path/Here pullNeeded start -> 1
2019-05-28 13:10:08 model@0xc0000c8b00 REQ(out): NN3I4DJ-*******-*******-*******-*******-*******-*******-*******: "y9qce-*****" / "File/Path/Here" o=1288044544 s=131072 h=c232588905424e25289c2b6d708f5305711217aebdb8c5fbc47b5dfd5b3b3cae wh=fbbcd1b8 ft=false
2019-05-28 13:10:08 sharedPullerState y9qce-***** File/Path/Here pullNeeded done -> 0
2019-05-28 13:10:11 sharedPullerState y9qce-***** File/Path/Here pullNeeded start -> 1
2019-05-28 13:10:11 model@0xc0000c8b00 REQ(out): NN3I4DJ-*******-*******-*******-*******-*******-*******-*******: "y9qce-*****" / "File/Path/Here" o=43909120 s=131072 h=838f83f3f48727bcee72126e0981692eb6e9de8467708378f49b60429cb6835a wh=d9326b99 ft=false
...

Looking at the file in the API, I see the following:

curl -k -X GET -H "X-API-Key: ******" 'http://192.168.1.4:7070/rest/db/file?folder=y9qce-*****&file=File/Path/Here'

{
  "availability": [
    {
      "id": "NN3I4DJ-*******-*******-*******-*******-*******-*******-*******",
      "fromTemporary": false
    },
    {
      "id": "LM7BDG6-*******-*******-*******-*******-*******-*******-*******",
      "fromTemporary": false
    },
    {
      "id": "SEPDJWL-*******-*******-*******-*******-*******-*******-*******",
      "fromTemporary": false
    },
    {
      "id": "UD7AGR2-*******-*******-*******-*******-*******-*******-*******",
      "fromTemporary": false
    }
  ],
  "global": {
    "deleted": false,
    "ignored": false,
    "invalid": false,
    "localFlags": 0,
    "modified": "2019-05-24T20:18:12+01:00",
    "modifiedBy": "UD7AGR2",
    "mustRescan": false,
    "name": "File/Path/Here",
    "noPermissions": true,
    "numBlocks": 20276,
    "permissions": "0644",
    "sequence": 2579466,
    "size": 2657557427,
    "type": 0,
    "version": [
      "QMA6DXE:1",
      "UD7AGR2:2"
    ]
  },
  "local": {
    "deleted": true,
    "ignored": false,
    "invalid": false,
    "localFlags": 0,
    "modified": "2019-05-06T23:59:20+01:00",
    "modifiedBy": "UD7AGR2",
    "mustRescan": false,
    "name": "File/Path/Here",
    "noPermissions": false,
    "numBlocks": 0,
    "permissions": "0",
    "sequence": 2195854,
    "size": 0,
    "type": 0,
    "version": [
      "QMA6DXE:1",
      "UD7AGR2:1"
    ]
  }
}

Am I seeing something unexpected? Pretty much every machine in the cluster is switched on every day (the NAS units 24/7), so I would have expected the file to have propagated to more machines by now… though admittedly, the cluster is large and busy. But seeing those repeated lines in the log, I’m wondering if there’s something preventing files from completing successfully…

Any input much appreciated!

[calmh (Jakob Borg)]

You’re seeing it download the file. This is not unexpected. If it’s not syncing you should be looking for complaints at the info or warning levels, not usually debugging/trace.

[Moisie]

Hi Jakob:

Thanks for the quick response - and sorry for the noise. I see this file is now reported as being in sync (though I still have 7k failed items that I’m trying to track down…).

It was the repeated 1/0/1/0 that threw me off - I normally expect to see it counting down to zero and then finishing for a file - but I’m presumably mis-reading the log file!

[AudriusButkevicius]

You still need to look at the failed items (not the debug traces) if you want progress as it indicates there might be an issue.

[imsodin (Simon)]

That’s the thing about debug log entries: Those aren’t meant for user readability, some might be cryptic to the point of being misleading. I still need to lookup the context of these lines in code when debugging something from time to time. In this case it just means that for that specific file only one (or no) block is being pulled at the time of the log. Just look at UI/info logging for your debugging and only consider more than that if something isn’t clear.