Analyze nodes loop

[Vallefor]

I use this doc to setup nginx+cells: https://github.com/pydio/cells-sync/files/3784576/nginx_reverse_proxy.pdf

Once per 1-5 minutes i see in log this:

2019-10-30T11:56:42.542+0300    ERROR   endpoint.cells.remote   Stopping watcher on errorrpc error: code = Internal desc = stream terminated by RST_STREAM with error code: PROTOCOL_ERROR
2019-10-30T11:56:42.542+0300    INFO    endpoint.cells.remote   Connection finished rpc error: code = Internal desc = stream terminated by RST_STREAM with error code: PROTOCOL_ERROR
2019-10-30T11:56:42.542+0300    INFO    sync-task       https://cells.example.com:8002/personal-files/personal is currently disconnected
2019-10-30T11:56:47.543+0300    INFO    endpoint.cells.remote   Restarting events watcher after 5s
2019-10-30T11:56:47.568+0300    INFO    sync-task       https://cells.example.com:8002/personal-files/personal is now connected
2019-10-30T11:56:47.568+0300    INFO    sync-task       Both sides are connected, now launching a sync loop
2019-10-30T11:56:47.619+0300    INFO    sync-task       Got Stats for fs:///home/vallefor/Cells {"stats": {"HasChildrenInfo":true,"HasSizeInfo":true,"Size":36246115,"Children":0,"Folders":1016,"Files":8740}}
2019-10-30T11:56:47.656+0300    INFO    sync-task       Got Stats for https://cells.example.com:8002/personal-files/personal   {"stats": {"HasChildrenInfo":false,"HasSizeInfo":true,"Size":26526479,"Children":0,"Folders":0,"Files":0}}
2019-10-30T11:56:47.681+0300    INFO    sync-task       Analyzed 506 nodes (5%)
2019-10-30T11:56:47.716+0300    INFO    sync-task       Analyzed 1340 nodes (10%)
2019-10-30T11:56:47.750+0300    INFO    sync-task       Analyzed 2257 nodes (15%)
2019-10-30T11:56:47.775+0300    INFO    sync-task       Analyzed 2877 nodes (20%)
2019-10-30T11:56:47.816+0300    INFO    sync-task       Analyzed 4320 nodes (25%)
2019-10-30T11:56:47.848+0300    INFO    sync-task       Analyzed 5105 nodes (33%)
2019-10-30T11:56:47.853+0300    INFO    sync-task       Analyzed 5262 nodes (38%)
2019-10-30T11:56:47.875+0300    INFO    sync-task       Analyzed 5863 nodes (43%)
2019-10-30T11:56:47.886+0300    INFO    sync-task       Analyzed 6195 nodes (48%)
2019-10-30T11:56:47.894+0300    INFO    sync-task       Analyzed 561 nodes (5%)
2019-10-30T11:56:47.912+0300    INFO    sync-task       Analyzed 6836 nodes (53%)
2019-10-30T11:56:47.924+0300    INFO    sync-task       Analyzed 7235 nodes (59%)
2019-10-30T11:56:47.931+0300    INFO    sync-task       Analyzed 7438 nodes (64%)
2019-10-30T11:56:47.951+0300    INFO    sync-task       Analyzed 8010 nodes (70%)
2019-10-30T11:56:47.973+0300    INFO    sync-task       Analyzed 8677 nodes (75%)
2019-10-30T11:56:47.988+0300    INFO    sync-task       Analyzed 9091 nodes (80%)
2019-10-30T11:56:47.989+0300    INFO    sync-task       Analyzed 9126 nodes (86%)
2019-10-30T11:56:48.000+0300    INFO    sync-task       Analyzed 9390 nodes (91%)
2019-10-30T11:56:48.007+0300    INFO    sync-task       Analyzed 1055 nodes (10%)
2019-10-30T11:56:48.010+0300    INFO    sync-task       Analyzed 9696 nodes (96%)
2019-10-30T11:56:48.019+0300    INFO    sync-task       Diff Stats      {"s": {"EndpointLeft":"fs:///home/vallefor/Cells","EndpointRight":"snapshot://right","conflicts":0,"missingLeft":0,"missingRight":0}}
2019-10-30T11:56:48.019+0300    INFO    sync-task       Finished analyzing nodes        {"i": 10834}
2019-10-30T11:56:48.019+0300    INFO    sync-task       Sending unidirectional patch    {"patch": {"Source":"fs:///home/vallefor/Cells","Target":"snapshot://right","Type":"TreePatch"}}
2019-10-30T11:56:48.069+0300    INFO    sync-task       Analyzed 1338 nodes (16%)
2019-10-30T11:56:48.069+0300    INFO    sync-task       Analyzed 1339 nodes (22%)
2019-10-30T11:56:48.150+0300    INFO    sync-task       Analyzed 1800 nodes (27%)
2019-10-30T11:56:48.214+0300    INFO    sync-task       Analyzed 2197 nodes (32%)
2019-10-30T11:56:48.299+0300    INFO    sync-task       Analyzed 2484 nodes (37%)
2019-10-30T11:56:48.426+0300    INFO    sync-task       Analyzed 2965 nodes (42%)
2019-10-30T11:56:48.497+0300    INFO    sync-task       Analyzed 3201 nodes (47%)
2019-10-30T11:56:48.708+0300    INFO    sync-task       Analyzed 3521 nodes (54%)
2019-10-30T11:56:48.752+0300    INFO    sync-task       Analyzed 3688 nodes (59%)
2019-10-30T11:56:48.826+0300    INFO    sync-task       Analyzed 3995 nodes (64%)
2019-10-30T11:56:49.025+0300    INFO    sync-task       Analyzed 4458 nodes (69%)
2019-10-30T11:56:49.080+0300    INFO    sync-task       Analyzed 4584 nodes (76%)
2019-10-30T11:56:49.093+0300    INFO    sync-task       Analyzed 4629 nodes (81%)
2019-10-30T11:56:49.147+0300    INFO    sync-task       Analyzed 4843 nodes (86%)
2019-10-30T11:56:49.189+0300    INFO    sync-task       Analyzed 5127 nodes (91%)
2019-10-30T11:56:49.259+0300    INFO    sync-task       Analyzed 5261 nodes (96%)
2019-10-30T11:56:49.275+0300    INFO    sync-task       Diff Stats      {"s": {"EndpointLeft":"https://cells.example.com:8002/personal-files/personal","EndpointRight":"snapshot://left","conflicts":0,"missingLeft":0,"missingRight":0}}
2019-10-30T11:56:49.275+0300    INFO    sync-task       Finished analyzing nodes        {"i": 15044}
2019-10-30T11:56:49.275+0300    INFO    sync-task       Sending unidirectional patch    {"patch": {"Source":"https://cells.example.com:8002/personal-files/personal","Target":"snapshot://left","Type":"TreePatch"}}
2019-10-30T11:56:50.419+0300    INFO    sync-task       Computing patches from Snapshots
2019-10-30T11:56:50.419+0300    INFO    sync-task       Filtering TreePatch took        {"time": "8.608µs", "source": "https://cells.example.com:8002/personal-files/personal", "target": "snapshot://left"}
2019-10-30T11:56:50.419+0300    INFO    sync-task       Filtering TreePatch took        {"time": "3.946µs", "source": "fs:///home/vallefor/Cells", "target": "snapshot://right"}
2019-10-30T11:56:50.419+0300    INFO    sync-task       Merged Patch    {"stats": {"Source":"https://cells.example.com:8002/personal-files/personal","Target":"fs:///home/vallefor/Cells","Type":"TreePatch"}}
2019-10-30T11:56:50.419+0300    INFO    sync-task       Empty Patch : nothing to do

[cdujeu]

is it 1 or is 5 (minutes) ?

[Vallefor]

@cdujeu
I thought that cycle have a random seconds. But then I noted that it is exactly 65 seconds.

I change my nginx config to:

...
location / {
    grpc_pass grpcs://192.168.1.49:8013;
    client_body_timeout 600s;
}
...

http {
    ...
    keepalive_timeout 600s;
    ...
}

And cycle become 10 minutes.

If I increase timeouts more than 600s it have no effect.

[cdujeu]

ha ha interesting
the grpc connection does have an inherent 10mn timeout, so the regular loop is normal. But your proxy in-between would shorten this connection. I'll ping @jthabet to update the upcoming docs on that subject
thanks for reporting

[Vallefor]

@cdujeu I mistaken in second option name:
Here right one:

http {
   keepalive_timeout 600s;
}

[Vallefor]

Btw its strange that once per 10 minutes this error will be appearing and in tray all users see " ! " sign.

[cdujeu]

i agree, i guess we should "debounce" events to make sure they do not switch the status too quick