Files are not shared... (folder with many files and subfolders)

habakuk007 · April 7, 2015, 10:59am

I’m currently testing syncthing in my local network with a file server on hyper-v as source and a NAS (Synologie DS215j with 2 cores á 800 Mhz and 512 GB RAM).

I want to sync a folder (Readonly) with 369 GB and about 1.200.000 files in 12.300 subfolders.

The NAS is up since 18 days and only 632670 Entries, ~4.43 GiB are transfered yet.

The source server tells me most of the time that the NAS is “current” and the folder to share is “unknown”. The syncthing process uses 96 % of the CPU and slows down everything else.

The NAS tells me that the source server is “disconnected” (last online about 20 minutes ago) and the folder is “searching”.

The version is v0.10.30.

Can I do anything to “fix” this?

Best regards! Stefan Wagner

Screenshots: WeitWeitWeg is the NAS (target) and Versenkung is the fileserver (source).

AudriusButkevicius · April 7, 2015, 11:14am

Can we have some screenshots?

habakuk007 · April 7, 2015, 11:26am

Thanks for your answer, I updated the question.

AudriusButkevicius · April 7, 2015, 12:10pm

So is there anything in the logs of VERSENKUNG? Also, I assume Unbekannt means unknown? Are there any errors in the javascript log?

habakuk007 · April 7, 2015, 3:59pm

Yes, unbekannt is unknown.

In the browser’s js log there are several issues like this:

Fehler: versenkung : server does not support RFC 5746, see CVE-2009-3555
Fehler: 192.168.178.66 : server does not support RFC 5746, see CVE-2009-3555

And this one:

Fehler: downloadable font: rejected by sanitizer (font-family: "Raleway" style:normal weight:500 stretch:normal src index:1) source: https://192.168.178.66:7070/assets/font/raleway-500.woff
Quelldatei: https://192.168.178.66:7070/assets/font/raleway.css

The error log of syncthing on versenkung is empty.

AudriusButkevicius · April 7, 2015, 4:12pm

I think there is some javascript error here, but without being able to reproduce this it will be very hard for me to help you debug this. Also, you can try running the latest beta, perhaps that will help as it had changes in that department.

habakuk007 · April 8, 2015, 8:19am

Can I do anything to provide you with more informations (other logs, …)?

AudriusButkevicius · April 8, 2015, 9:06am

Did you try the beta?

I guess I would be interested in seeing the JSON returned by GET /rest/config call.

habakuk007 · April 8, 2015, 9:37am

Here is the output from Get /rest/config for the version 0.10.30 (I deleted IDs, password, api key and public url and formatted it “nice”). I’ll update to the beta later and send you the “new” json.:

    {
       "Version":10,
       "Folders":[
          {
             "ID":"LogimaDatenVersenkung",
             "Path":"e:\\",
             "Devices":[
                {
                   "DeviceID":"X"
                },
                {
                   "DeviceID":"Y"
                }
             ],
             "ReadOnly":true,
             "RescanIntervalS":60,
             "IgnorePerms":true,
             "AutoNormalize":true,
             "Versioning":{
                "Type":"",
                "Params":{

                }
             },
             "LenientMtimes":false,
             "Copiers":1,
             "Pullers":16,
             "Hashers":0,
             "Invalid":""
          }
       ],
       "Devices":[
          {
             "DeviceID":"X",
             "Name":"VERSENKUNG",
             "Addresses":[
                "dynamic"
             ],
             "Compression":"metadata",
             "CertName":"",
             "Introducer":false
          },
          {
             "DeviceID":"Y",
             "Name":"Weit Weit Weg",
             "Addresses":[
                "dynamic",
                "weitweitweg.invalid:22000"
             ],
             "Compression":"always",
             "CertName":"",
             "Introducer":false
          }
       ],
       "GUI":{
          "Enabled":true,
          "Address":"192.168.178.188:8080",
          "User":"syncVersenkung",
          "Password":"xxxx",
          "UseTLS":true,
          "APIKey":"yyyy"
       },
       "Options":{
          "ListenAddress":[
             "0.0.0.0:22000"
          ],
          "GlobalAnnServers":[
             "udp4://announce.syncthing.net:22026",
             "udp6://announce-v6.syncthing.net:22026"
          ],
          "GlobalAnnEnabled":true,
          "LocalAnnEnabled":true,
          "LocalAnnPort":21025,
          "LocalAnnMCAddr":"[ff32::5222]:21026",
          "MaxSendKbps":0,
          "MaxRecvKbps":0,
          "ReconnectIntervalS":60,
          "StartBrowser":false,
          "UPnPEnabled":true,
          "UPnPLease":0,
          "UPnPRenewal":30,
          "URAccepted":1,
          "URUniqueID":"7X00-Mib",
          "RestartOnWakeup":true,
          "AutoUpgradeIntervalH":12,
          "KeepTemporariesH":24,
          "CacheIgnoredFiles":true,
          "ProgressUpdateIntervalS":5,
          "SymlinksEnabled":true,
          "LimitBandwidthInLan":false
       },
       "IgnoredDevices":[

       ]
    }

AudriusButkevicius · April 8, 2015, 9:43am

I think you should add a breakpoint where the source code classifies the folder as Unknown and see why the status becomes unknown.

Alex · April 8, 2015, 12:02pm

the “unknown” status maybe could also be slow loading, at least this is what I observer on my raspberry pi (gui is pretty unusable there, let’s hope v0.11 makes it usable). Maybe try if rest/model?folder=LogimaDatenVersenkung returns the correct state and the gui just fails to load it.

habakuk007 · April 8, 2015, 3:33pm

I tried to open this path in my browser but didn’t get data… The waiting donut came forever. Oh wait, some minutes later came this (it took about 5 Minutes) - the machine should have a little more power than a raspberry (I’m still on 0.10.30.):

{"globalBytes":454967851465,"globalDeleted":235,"globalFiles":1379100,"ignorePatterns":false,"inSyncBytes":454967851465,"inSyncFiles":1379100,"invalid":"","localBytes":454967851465,"localDeleted":235,"localFiles":1379100,"needBytes":0,"needFiles":0,"state":"scanning","stateChanged":"2015-04-08T11:13:37.8264003+02:00","version":1379654}

Another thing: Is it normal, that there are about 21.800 Logfiles (oldest from 2015-03-17) in the ProgramData/syncthing folder?

And in the output.log are mainly entries like this:

[HIGPN] 16:46:40 INFO: Device Y name is "WeitWeitWeg"
[HIGPN] 17:12:10 INFO: Connection to Y closed: ping timeout
[HIGPN] 17:14:20 INFO: Established secure connection to Y at 192.168.178.188:61137-192.168.178.66:22000
[HIGPN] 17:15:58 INFO: Connection to Y closed: ping timeout
[HIGPN] 17:18:25 INFO: Established secure connection to Y at 192.168.178.188:61138-192.168.178.66:22000
[HIGPN] 17:20:03 INFO: Connection to Y closed: ping timeout
[HIGPN] 17:21:27 INFO: Device Y client is "syncthing v0.10.30"
[HIGPN] 17:21:27 INFO: Device Y name is "WeitWeitWeg"
[HIGPN] 17:21:48 INFO: Established secure connection to Y at 192.168.178.188:61139-192.168.178.66:22000
[HIGPN] 17:23:32 INFO: Device Y client is "syncthing v0.10.30"
[HIGPN] 17:23:32 INFO: Device Y name is "WeitWeitWeg"
[HIGPN] 17:23:54 INFO: Connection to Y closed: ping timeout
[HIGPN] 17:24:34 INFO: Established secure connection to Y at 192.168.178.188:61141-192.168.178.66:22000
[HIGPN] 17:25:38 INFO: Connection to Y closed: ping timeout

AudriusButkevicius · April 8, 2015, 3:46pm

The timeouts imply that the device is under heavy load. I think the device is just too weak, has it actually finished indexing?

calmh · April 8, 2015, 3:47pm

Possibly the database scan for this actually takes five minutes, on a not so fast box… Well, it’s something we’re working on improving.

We only create one, syncthing.log by default, which is overwritten on startup. So, no, something else going on here. Unless you mean in the index directory, in which case that’s database files and not logs.

habakuk007 · April 8, 2015, 3:51pm

No I mean the logs (error which are always empty and output).

habakuk007 · April 8, 2015, 3:56pm

What is “not so fast”? It is currently running on Hyper-V with a demand of about 5 GB Ram and it is set up to use one cpu - the cpu load on the hyper-v server is currently about 3% to 7%.

calmh · April 9, 2015, 6:35am

You have some custom setup here, we don’t create files called “error” or “output”.

I don’t know, you haven’t told us before this what kind of box it was. Five minutes sounds a bit excessive for a “real computer” here, but I’m not sure, I haven’t tested or benchmarked with as many files as you have.

calmh · April 9, 2015, 8:17am

jb@syno:~ $ time curl http://anto-syncer.int.nym.se:8080/rest/db/status?folder=foto
{"globalBytes":526070945094,"globalDeleted":0,"globalFiles":103454,"ignorePatterns":true,"inSyncBytes":526070945094,"inSyncFiles":103454,"invalid":"","localBytes":526070945094,"localDeleted":0,"localFiles":103454,"needBytes":0,"needFiles":0,"state":"idle","stateChanged":"2015-04-09T02:00:38.666765177+02:00","version":434915}

real	0m6.945s
user	0m0.005s
sys	0m0.004s
jb@syno:~ $

That’s seven seconds for 100k files on my side, so ~100 seconds expected for you with linear extrapolation and assuming everything else is equal (which it apparently isn’t, but that’s the lower bound). That’s still a long, long, time. Well, work is being done to fix it in the long term.

habakuk007 · April 9, 2015, 9:33am

Ah, ok - this are the logfiles that are generated by nssm (Non Sucking Service Manager). It redirects the output from the console to the files “output.log” and “error.log”.

And now I found some panic logs where the “real” logs where. About 50 logs all similiar to this: syncthingPanicLog.txt (86.4 KB)

AudriusButkevicius · April 9, 2015, 9:36am

It seems that whatever is causing the slowness holds the lock for too long and technically causes a deadlock which we panic about.