Too Many Open Files

calmh · December 26, 2017, 7:16am

Thanks. I’ve been staring at it for a while, and it’s still not obvious. I made a build with some further debugging output - can we repeat the same operation again?

https://build.syncthing.net/viewLog.html?buildId=14413&buildTypeId=Syncthing_BuildLinuxCross&tab=artifacts

export STDEADLOCKTIMEOUT=7200
export STTRACE=model

The log was good otherwise, i.e., enough. If you get the final panic trace when it runs out of fd:s, that might be helpful as well…

Mostly what it shows is many files being synced half way but never finished, and this should be limited to 2+64 open files (copiers+pullers) potentially times two for when reading/copying… It’s not clear how more files than this escape while still open.

Moisie · December 28, 2017, 11:11pm

Hi Jakob:

Many thanks for looking at this so quickly - very much appreciated.

I’ve tried the build you suggested - but I don’t think it’s necessarily working as you expected. I’ve uploaded the trace file for your consideration.

Best wishes,

Pants.

calmh · December 29, 2017, 8:04am

Yeah there’s some deadlock detector chatter that I think is false, but no syncing activity.

Moisie · December 29, 2017, 9:21am

Well - Syncthing is restarting itself every hour (or thereabouts), before the syncing gets going. Note - I’m not doing anything to cause this behaviour…

calmh · December 29, 2017, 9:24am

Syncthing does not typically restart itself, and the logs contains nothing about that (but it’s clear that it does restart). I think your system may have other problems. Maybe you’re running out of memory. Maybe there’s a hardware problem.

Moisie · December 29, 2017, 3:07pm

Hmmmm… does that seem likely, considering I haven’t seen this issue with any other builds?

Moisie · January 3, 2018, 10:33am

Hello again:

As I didn’t get anywhere with the suggested build, I’ve been running v0.14.43-rc.1 (with none of the deadlock problems) and looking through the trace file - I’ve just uploaded it again to your SFTP.

Of course, I don’t have an intimate knowledge of what the expected output should be - but I am seeing some odd things, which might be related to files being left open: there’s a number of instances where I’m seeing a file being transferred - I’m seeing the ‘copyNeeded’ counter count down - but then it just stops, with no apparent explanation.

e.g. here’s one from the trace I’ve just uploaded:

[OVPYX] 2018/01/03 09:15:24.742108 rwfolder.go:1101: DEBUG: sendReceiveFolder/bvkmk-*****@0xc4200ba480 need file file/path/1/here.doc; copy 91, reused 0
[OVPYX] 2018/01/03 09:15:24.742166 verboseservice.go:48: VERBOSE: Started syncing "bvkmk-*****" / "file/path/1/here.doc" (update file)
[OVPYX] 2018/01/03 09:15:37.460032 progressemitter.go:211: DEBUG: progress emitter: registering bvkmk-***** file/path/1/here.doc
[OVPYX] 2018/01/03 09:33:11.374700 sharedpullerstate.go:222: DEBUG: sharedPullerState bvkmk-***** file/path/1/here.doc copyNeeded -> 90
[OVPYX] 2018/01/03 09:33:11.490782 sharedpullerstate.go:222: DEBUG: sharedPullerState bvkmk-***** file/path/1/here.doc copyNeeded -> 89
...
[OVPYX] 2018/01/03 09:33:18.356313 sharedpullerstate.go:222: DEBUG: sharedPullerState bvkmk-***** file/path/1/here.doc copyNeeded -> 10
[OVPYX] 2018/01/03 09:33:18.418396 sharedpullerstate.go:222: DEBUG: sharedPullerState bvkmk-***** file/path/1/here.doc copyNeeded -> 9
[OVPYX] 2018/01/03 09:33:18.592313 sharedpullerstate.go:222: DEBUG: sharedPullerState bvkmk-***** file/path/1/here.doc copyNeeded -> 8
[OVPYX] 2018/01/03 09:33:18.698237 sharedpullerstate.go:222: DEBUG: sharedPullerState bvkmk-***** file/path/1/here.doc copyNeeded -> 7
[OVPYX] 2018/01/03 09:33:18.759148 sharedpullerstate.go:222: DEBUG: sharedPullerState bvkmk-***** file/path/1/here.doc copyNeeded -> 6

This is then the last reference to file/path/1/here.doc in the trace; I’m not seeing any further copyNeeded entries, or references to closing, deregistering or Finished syncing for these files (though many files are being completed as expected).

Any thoughts?

Many thanks,

Pants.

calmh · January 3, 2018, 7:40pm

Yeah debugging that requires additional output, which is what is the extra addition in the build linked above.

Moisie · January 4, 2018, 9:35am

Hello:

Yep - I’ve just tried the build with additional debugging again - and the same problem’s happening (even with a 4hr deadlock timeout):

[OVPYX] 2018/01/04 09:17:46.139715 main.go:644: INFO: syncthing v0.14.42+18-ge7a8f95 "Dysprosium Dragonfly" (go1.9.2 linux-amd64) teamcity@build.syncthing.net 2017-12-26 07:14:37 UTC
[OVPYX] 2018/01/04 09:17:46.139875 main.go:645: INFO: My ID: OVPYXBH-*******-*******-*******-*******-*******-*******-*******
[OVPYX] 2018/01/04 09:17:47.203130 sha256.go:92: INFO: Single thread SHA256 performance is 93 MB/s using minio/sha256-simd (68 MB/s using crypto/sha256).
[OVPYX] 2018/01/04 09:17:47.203475 verboseservice.go:48: VERBOSE: Starting up (/usr/local/syncthing/var)
[OVPYX] 2018/01/04 09:17:48.271357 main.go:702: INFO: Hashing performance with weak hash is 81.00 MB/s
[OVPYX] 2018/01/04 09:17:49.278564 main.go:704: INFO: Hashing performance without weak hash is 91.40 MB/s
[OVPYX] 2018/01/04 09:17:49.278611 main.go:710: INFO: Weak hash enabled, as it has an acceptable performance impact.
[OVPYX] 2018/01/04 09:25:09.906853 progressemitter.go:196: DEBUG: progress emitter: updated interval 1s
[OVPYX] 2018/01/04 09:25:09.907038 model.go:167: INFO: Starting deadlock detector with 4h0m0s timeout
[OVPYX] 2018/01/04 09:25:09.914049 model.go:182: INFO: Ready to synchronize "NAS" (bvkmk-*****) (readwrite)
[OVPYX] 2018/01/04 09:25:09.914228 limiter.go:84: INFO: Send rate is unlimited, receive rate is unlimited
[OVPYX] 2018/01/04 09:25:09.914253 limiter.go:89: INFO: Rate limits do not apply to LAN connections
[OVPYX] 2018/01/04 09:25:09.914561 main.go:812: INFO: Using discovery server https://discovery-v4-2.syncthing.net/v2/?id=DVU36WY-H3LVZHW-E6LLFRE-YAFN5EL-HILWRYP-OC2M47J-Z4PE62Y-ADIBDQC
[OVPYX] 2018/01/04 09:25:09.914680 main.go:812: INFO: Using discovery server https://discovery-v4-3.syncthing.net/v2/?id=VK6HNJ3-VVMM66S-HRVWSCR-IXEHL2H-U4AQ4MW-UCPQBWX-J2L2UBK-NVZRDQZ
[OVPYX] 2018/01/04 09:25:09.914754 main.go:812: INFO: Using discovery server https://discovery-v4-4.syncthing.net/v2/?id=LYXKCHX-VI3NYZR-ALCJBHF-WMZYSPK-QG6QJA3-MPFYMSO-U56GTUK-NA2MIAW
[OVPYX] 2018/01/04 09:25:09.914818 main.go:812: INFO: Using discovery server https://discovery-v6-2.syncthing.net/v2/?id=DVU36WY-H3LVZHW-E6LLFRE-YAFN5EL-HILWRYP-OC2M47J-Z4PE62Y-ADIBDQC
[OVPYX] 2018/01/04 09:25:09.914883 main.go:812: INFO: Using discovery server https://discovery-v6-3.syncthing.net/v2/?id=VK6HNJ3-VVMM66S-HRVWSCR-IXEHL2H-U4AQ4MW-UCPQBWX-J2L2UBK-NVZRDQZ
[OVPYX] 2018/01/04 09:25:09.914948 main.go:812: INFO: Using discovery server https://discovery-v6-4.syncthing.net/v2/?id=LYXKCHX-VI3NYZR-ALCJBHF-WMZYSPK-QG6QJA3-MPFYMSO-U56GTUK-NA2MIAW
POTENTIAL DEADLOCK: Inconsistent locking. saw this ordering in one goroutine:
happened before
/tmp/syncthing-e02d0de3/src/github.com/syncthing/syncthing/lib/config/wrapper.go:295 config.(*Wrapper).Options ??? <<<<<
/tmp/syncthing-e02d0de3/src/github.com/syncthing/syncthing/cmd/syncthing/main.go:826 main.syncthingMain ???
/tmp/syncthing-e02d0de3/src/github.com/syncthing/syncthing/cmd/syncthing/main.go:440 main.main ???
[OVPYX] 2018/01/04 09:25:09.915161 rwfolder.go:143: DEBUG: sendReceiveFolder/bvkmk-wxrz3@0xc420092480 starting
[OVPYX] 2018/01/04 09:25:09.915259 tcp_listen.go:69: INFO: TCP listener ([::]:22000) starting
[OVPYX] 2018/01/04 09:25:09.915366 rwfolder.go:202: DEBUG: sendReceiveFolder/bvkmk-wxrz3@0xc420092480 Scanning subdirectories
[OVPYX] 2018/01/04 09:25:09.915600 kcp_listen.go:91: INFO: KCP listener ([::]:22020) starting
../../go/src/runtime/proc.go:195 runtime.main ???

happened after
/tmp/syncthing-e02d0de3/src/github.com/syncthing/syncthing/lib/nat/service.go:148 nat.(*Service).NewMapping ??? <<<<<
/tmp/syncthing-e02d0de3/src/github.com/syncthing/syncthing/lib/connections/tcp_listen.go:72 connections.(*tcpListener).Serve ???
/tmp/syncthing-e02d0de3/src/github.com/syncthing/syncthing/vendor/github.com/thejerf/suture/supervisor.go:454 suture.(*Supervisor).runService.func1 ???

in another goroutine: happened before
/tmp/syncthing-e02d0de3/src/github.com/syncthing/syncthing/lib/nat/service.go:148 nat.(*Service).NewMapping ??? <<<<<
/tmp/syncthing-e02d0de3/src/github.com/syncthing/syncthing/lib/connections/tcp_listen.go:72 connections.(*tcpListener).Serve ???
/tmp/syncthing-e02d0de3/src/github.com/syncthing/syncthing/vendor/github.com/thejerf/suture/supervisor.go:454 suture.(*Supervisor).runService.func1 ???

happend after
/tmp/syncthing-e02d0de3/src/github.com/syncthing/syncthing/lib/config/wrapper.go:295 config.(*Wrapper).Options ??? <<<<<
/tmp/syncthing-e02d0de3/src/github.com/syncthing/syncthing/cmd/syncthing/main.go:828 main.syncthingMain ???
/tmp/syncthing-e02d0de3/src/github.com/syncthing/syncthing/cmd/syncthing/main.go:440 main.main ???
../../go/src/runtime/proc.go:195 runtime.main ???


Other goroutines holding locks:
goroutine 16777216 lock 0xc42347c380
/tmp/syncthing-e02d0de3/src/github.com/syncthing/syncthing/lib/connections/service.go:594 connections.(*Service).ExternalAddresses ??? <<<<<
/tmp/syncthing-e02d0de3/src/github.com/syncthing/syncthing/lib/discover/global.go:207 discover.(*globalClient).sendAnnouncement ???
/tmp/syncthing-e02d0de3/src/github.com/syncthing/syncthing/lib/discover/global.go:195 discover.(*globalClient).Serve ???
/tmp/syncthing-e02d0de3/src/github.com/syncthing/syncthing/vendor/github.com/thejerf/suture/supervisor.go:454 suture.(*Supervisor).runService.func1 ???

goroutine 16777216 lock 0xc4200100d8
/tmp/syncthing-e02d0de3/src/github.com/syncthing/syncthing/lib/events/events.go:280 events.(*Logger).Subscribe ??? <<<<<
/tmp/syncthing-e02d0de3/src/github.com/syncthing/syncthing/lib/discover/global.go:184 discover.(*globalClient).Serve ???
/tmp/syncthing-e02d0de3/src/github.com/syncthing/syncthing/vendor/github.com/thejerf/suture/supervisor.go:454 suture.(*Supervisor).runService.func1 ???

goroutine 72057594054705152 lock 0xc42347c360
/tmp/syncthing-e02d0de3/src/github.com/syncthing/syncthing/lib/nat/service.go:148 nat.(*Service).NewMapping ??? <<<<<
/tmp/syncthing-e02d0de3/src/github.com/syncthing/syncthing/lib/connections/tcp_listen.go:72 connections.(*tcpListener).Serve ???
/tmp/syncthing-e02d0de3/src/github.com/syncthing/syncthing/vendor/github.com/thejerf/suture/supervisor.go:454 suture.(*Supervisor).runService.func1 ???


[OVPYX] 2018/01/04 09:25:10.964637 main.go:644: INFO: syncthing v0.14.42+18-ge7a8f95 "Dysprosium Dragonfly" (go1.9.2 linux-amd64) teamcity@build.syncthing.net 2017-12-26 07:14:37 UTC
[OVPYX] 2018/01/04 09:25:10.964782 main.go:645: INFO: My ID: OVPYXBH-*******-*******-*******-*******-*******-*******-*******
[OVPYX] 2018/01/04 09:25:12.028760 sha256.go:92: INFO: Single thread SHA256 performance is 93 MB/s using minio/sha256-simd (68 MB/s using crypto/sha256).
[OVPYX] 2018/01/04 09:25:12.029043 verboseservice.go:48: VERBOSE: Starting up (/usr/local/syncthing/var)
[OVPYX] 2018/01/04 09:25:13.098011 main.go:702: INFO: Hashing performance with weak hash is 81.02 MB/s
[OVPYX] 2018/01/04 09:25:14.104832 main.go:704: INFO: Hashing performance without weak hash is 91.45 MB/s
[OVPYX] 2018/01/04 09:25:14.104882 main.go:710: INFO: Weak hash enabled, as it has an acceptable performance impact.
...

I was watching Resource Monitoring whilst this was happening, and it didn’t run out of CPU or RAM when the restart happened (which was only a few minutes after starting it going).

Best wishes,

Pants.

AudriusButkevicius · January 4, 2018, 10:53am

You have some environment variable set which enables the deadlock timeout monitor (starts with STDEADLOCK), you should unset that and try again.

calmh · January 4, 2018, 2:32pm

I can ignore the deadlock chatter. It’s more curios that it’s not doing it’s thing.

Moisie · January 4, 2018, 3:10pm

Hi:

Without the STDEADLOCKTIMEOUT variable, the process is restarting after 20mins:

[OVPYX] 2018/01/04 13:13:09.819891 main.go:644: INFO: syncthing v0.14.42+18-ge7a8f95 "Dysprosium Dragonfly" (go1.9.2 linux-amd64) teamcity@build.syncthing.net 2017-12-26 07:14:37 UTC
[OVPYX] 2018/01/04 13:13:09.820070 main.go:645: INFO: My ID: OVPYXBH-*******-*******-*******-*******-*******-*******-*******
[OVPYX] 2018/01/04 13:13:10.884248 sha256.go:92: INFO: Single thread SHA256 performance is 93 MB/s using minio/sha256-simd (68 MB/s using crypto/sha256).
[OVPYX] 2018/01/04 13:13:10.884501 verboseservice.go:48: VERBOSE: Starting up (/usr/local/syncthing/var)
[OVPYX] 2018/01/04 13:13:11.951905 main.go:702: INFO: Hashing performance with weak hash is 80.99 MB/s
[OVPYX] 2018/01/04 13:13:12.958441 main.go:704: INFO: Hashing performance without weak hash is 91.54 MB/s
[OVPYX] 2018/01/04 13:13:12.958488 main.go:710: INFO: Weak hash enabled, as it has an acceptable performance impact.
[OVPYX] 2018/01/04 13:13:32.114089 progressemitter.go:196: DEBUG: progress emitter: updated interval 1s
[OVPYX] 2018/01/04 13:13:32.114152 model.go:167: INFO: Starting deadlock detector with 20m0s timeout
[OVPYX] 2018/01/04 13:13:32.114679 model.go:182: INFO: Ready to synchronize "NAS" (bvkmk-*****) (readwrite)
[OVPYX] 2018/01/04 13:13:32.114794 limiter.go:84: INFO: Send rate is unlimited, receive rate is unlimited
[OVPYX] 2018/01/04 13:13:32.114829 limiter.go:89: INFO: Rate limits do not apply to LAN connections
[OVPYX] 2018/01/04 13:13:32.114935 rwfolder.go:143: DEBUG: sendReceiveFolder/bvkmk-*****@0xc420094480 starting
[OVPYX] 2018/01/04 13:13:32.115196 main.go:812: INFO: Using discovery server https://discovery-v4-2.syncthing.net/v2/?id=DVU36WY-H3LVZHW-E6LLFRE-YAFN5EL-HILWRYP-OC2M47J-Z4PE62Y-ADIBDQC
[OVPYX] 2018/01/04 13:13:32.115297 main.go:812: INFO: Using discovery server https://discovery-v4-3.syncthing.net/v2/?id=VK6HNJ3-VVMM66S-HRVWSCR-IXEHL2H-U4AQ4MW-UCPQBWX-J2L2UBK-NVZRDQZ
[OVPYX] 2018/01/04 13:13:32.115371 relay_listen.go:65: INFO: Relay listener (dynamic+https://relays.syncthing.net/endpoint) starting
[OVPYX] 2018/01/04 13:13:32.115421 main.go:812: INFO: Using discovery server https://discovery-v4-4.syncthing.net/v2/?id=LYXKCHX-VI3NYZR-ALCJBHF-WMZYSPK-QG6QJA3-MPFYMSO-U56GTUK-NA2MIAW
[OVPYX] 2018/01/04 13:13:32.115484 tcp_listen.go:69: INFO: TCP listener ([::]:22000) starting
[OVPYX] 2018/01/04 13:13:32.115540 kcp_listen.go:91: INFO: KCP listener ([::]:22020) starting
[OVPYX] 2018/01/04 13:13:32.116227 rwfolder.go:202: DEBUG: sendReceiveFolder/bvkmk-*****@0xc420094480 Scanning subdirectories
[OVPYX] 2018/01/04 13:13:32.117714 verboseservice.go:48: VERBOSE: Folder "bvkmk-*****" is now scanning
[OVPYX] 2018/01/04 13:13:35.569972 main.go:812: INFO: Using discovery server https://discovery-v6-2.syncthing.net/v2/?id=DVU36WY-H3LVZHW-E6LLFRE-YAFN5EL-HILWRYP-OC2M47J-Z4PE62Y-ADIBDQC
[OVPYX] 2018/01/04 13:13:35.570073 main.go:812: INFO: Using discovery server https://discovery-v6-3.syncthing.net/v2/?id=VK6HNJ3-VVMM66S-HRVWSCR-IXEHL2H-U4AQ4MW-UCPQBWX-J2L2UBK-NVZRDQZ
[OVPYX] 2018/01/04 13:13:35.570134 main.go:812: INFO: Using discovery server https://discovery-v6-4.syncthing.net/v2/?id=LYXKCHX-VI3NYZR-ALCJBHF-WMZYSPK-QG6QJA3-MPFYMSO-U56GTUK-NA2MIAW
[OVPYX] 2018/01/04 13:13:35.607291 main.go:857: INFO: Device GSXHK4J-*******-*******-*******-*******-*******-*******-******* is "NAS01" at [dynamic]
[OVPYX] 2018/01/04 13:13:35.607350 main.go:857: INFO: Device OVPYXBH-*******-*******-*******-*******-*******-*******-******* is "NAS02" at [dynamic]
[OVPYX] 2018/01/04 13:13:35.607882 main.go:1289: INFO: Cleaned away old file panic-20171228-111040.log
[OVPYX] 2018/01/04 13:13:35.608065 verboseservice.go:48: VERBOSE: Startup complete
[OVPYX] 2018/01/04 13:13:35.608981 gui.go:365: INFO: GUI and API listening on [::]:7070
[OVPYX] 2018/01/04 13:13:35.609024 gui.go:366: INFO: Access the GUI via the following URL: http://127.0.0.1:7070/
[OVPYX] 2018/01/04 13:13:52.030641 kcp_listen.go:249: INFO: kcp://0.0.0.0:22020 detected NAT type: Port restricted NAT
[OVPYX] 2018/01/04 13:13:52.030699 kcp_listen.go:269: INFO: kcp://0.0.0.0:22020 resolved external address kcp://81.135.129.1:1055 (via stun.voip.aebc.com:3478)
[OVPYX] 2018/01/04 13:13:52.030880 verboseservice.go:48: VERBOSE: Listen address kcp://0.0.0.0:22020 resolution has changed: lan addresses: [kcp://0.0.0.0:22020] wan addresses: [kcp://0.0.0.0:22020 kcp://81.135.129.1:1055]
[OVPYX] 2018/01/04 13:13:57.830886 service.go:275: INFO: Established secure connection to GSXHK4J-*******-*******-*******-*******-*******-*******-******* at [::]:22020-192.168.1.2:22020 (kcp-server) (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
[OVPYX] 2018/01/04 13:13:57.831011 model.go:1571: INFO: Device GSXHK4J-*******-*******-*******-*******-*******-*******-******* client is "syncthing v0.14.42" named "NAS01"
[OVPYX] 2018/01/04 13:13:57.831122 verboseservice.go:48: VERBOSE: Connected to device GSXHK4J-*******-*******-*******-*******-*******-*******-******* at 192.168.1.2:22020 (type kcp-server)
[OVPYX] 2018/01/04 13:13:57.858751 model.go:1033: INFO: Device GSXHK4J-*******-*******-*******-*******-*******-*******-******* folder "NAS" (bvkmk-*****) has a new index ID (0x9284D5EE182F4D15)
[OVPYX] 2018/01/04 13:13:57.860181 service.go:61: INFO: Detected 2 NAT devices
[OVPYX] 2018/01/04 13:14:08.292499 static.go:93: INFO: Joined relay relay://149.202.52.153:22067
[OVPYX] 2018/01/04 13:14:12.116124 verboseservice.go:48: VERBOSE: Listen address dynamic+https://relays.syncthing.net/endpoint resolution has changed: lan addresses: [relay://149.202.52.153:22067/?id=G35VE6F-HCHOFGZ-ZGBYREQ-YJ37265-2FSXDSF-4N54JE3-IPB6MYA-TM7FKQE&pingInterval=1m0s&networkTimeout=2m0s&sessionLimitBps=0&globalLimitBps=500000&statusAddr=:22070&providedBy=dopsi.ch] wan addresses: [relay://149.202.52.153:22067/?id=G35VE6F-HCHOFGZ-ZGBYREQ-YJ37265-2FSXDSF-4N54JE3-IPB6MYA-TM7FKQE&pingInterval=1m0s&networkTimeout=2m0s&sessionLimitBps=0&globalLimitBps=500000&statusAddr=:22070&providedBy=dopsi.ch]
[OVPYX] 2018/01/04 13:14:55.264435 main.go:1289: INFO: Cleaned away old file tmp-index-sorter.243952741
[OVPYX] 2018/01/04 13:15:27.831503 model.go:1296: INFO: Connection to GSXHK4J-*******-*******-*******-*******-*******-*******-******* closed: writing message: broken pipe
[OVPYX] 2018/01/04 13:15:27.831573 verboseservice.go:48: VERBOSE: Disconnected from device GSXHK4J-*******-*******-*******-*******-*******-*******-*******
[OVPYX] 2018/01/04 13:15:38.982228 main.go:1289: INFO: Cleaned away old file tmp-index-sorter.436118144
panic: deadlock detected at fmut
[OVPYX] 2018/01/04 13:38:33.435246 main.go:644: INFO: syncthing v0.14.42+18-ge7a8f95 "Dysprosium Dragonfly" (go1.9.2 linux-amd64) teamcity@build.syncthing.net 2017-12-26 07:14:37 UTC
[OVPYX] 2018/01/04 13:38:33.435444 main.go:645: INFO: My ID: OVPYXBH-*******-*******-*******-*******-*******-*******-*******
[OVPYX] 2018/01/04 13:38:34.499903 sha256.go:92: INFO: Single thread SHA256 performance is 93 MB/s using minio/sha256-simd (68 MB/s using crypto/sha256).
[OVPYX] 2018/01/04 13:38:34.500170 verboseservice.go:48: VERBOSE: Starting up (/usr/local/syncthing/var)
[OVPYX] 2018/01/04 13:38:35.568471 main.go:702: INFO: Hashing performance with weak hash is 81.03 MB/s
[OVPYX] 2018/01/04 13:38:36.574898 main.go:704: INFO: Hashing performance without weak hash is 91.45 MB/s
[OVPYX] 2018/01/04 13:38:36.574948 main.go:710: INFO: Weak hash enabled, as it has an acceptable performance impact.
[OVPYX] 2018/01/04 13:39:14.234952 progressemitter.go:196: DEBUG: progress emitter: updated interval 1s
[OVPYX] 2018/01/04 13:39:14.235034 model.go:167: INFO: Starting deadlock detector with 20m0s timeout
[OVPYX] 2018/01/04 13:39:14.249946 model.go:182: INFO: Ready to synchronize "NAS" (bvkmk-*****) (readwrite)
[OVPYX] 2018/01/04 13:39:14.250153 rwfolder.go:143: DEBUG: sendReceiveFolder/bvkmk-*****@0xc4201f4240 starting
[OVPYX] 2018/01/04 13:39:14.250217 limiter.go:84: INFO: Send rate is unlimited, receive rate is unlimited
[OVPYX] 2018/01/04 13:39:14.250255 limiter.go:89: INFO: Rate limits do not apply to LAN connections
[OVPYX] 2018/01/04 13:39:14.250493 main.go:812: INFO: Using discovery server https://discovery-v4-2.syncthing.net/v2/?id=DVU36WY-H3LVZHW-E6LLFRE-YAFN5EL-HILWRYP-OC2M47J-Z4PE62Y-ADIBDQC
[OVPYX] 2018/01/04 13:39:14.250592 main.go:812: INFO: Using discovery server https://discovery-v4-3.syncthing.net/v2/?id=VK6HNJ3-VVMM66S-HRVWSCR-IXEHL2H-U4AQ4MW-UCPQBWX-J2L2UBK-NVZRDQZ
[OVPYX] 2018/01/04 13:39:14.250650 main.go:812: INFO: Using discovery server https://discovery-v4-4.syncthing.net/v2/?id=LYXKCHX-VI3NYZR-ALCJBHF-WMZYSPK-QG6QJA3-MPFYMSO-U56GTUK-NA2MIAW
[OVPYX] 2018/01/04 13:39:14.250707 main.go:812: INFO: Using discovery server https://discovery-v6-2.syncthing.net/v2/?id=DVU36WY-H3LVZHW-E6LLFRE-YAFN5EL-HILWRYP-OC2M47J-Z4PE62Y-ADIBDQC
[OVPYX] 2018/01/04 13:39:14.251333 tcp_listen.go:69: INFO: TCP listener ([::]:22000) starting
[OVPYX] 2018/01/04 13:39:14.251730 main.go:812: INFO: Using discovery server https://discovery-v6-3.syncthing.net/v2/?id=VK6HNJ3-VVMM66S-HRVWSCR-IXEHL2H-U4AQ4MW-UCPQBWX-J2L2UBK-NVZRDQZ
[OVPYX] 2018/01/04 13:39:14.251885 main.go:812: INFO: Using discovery server https://discovery-v6-4.syncthing.net/v2/?id=LYXKCHX-VI3NYZR-ALCJBHF-WMZYSPK-QG6QJA3-MPFYMSO-U56GTUK-NA2MIAW
[OVPYX] 2018/01/04 13:39:14.252314 kcp_listen.go:91: INFO: KCP listener ([::]:22020) starting
[OVPYX] 2018/01/04 13:39:14.254567 relay_listen.go:65: INFO: Relay listener (dynamic+https://relays.syncthing.net/endpoint) starting
[OVPYX] 2018/01/04 13:39:14.259752 rwfolder.go:202: DEBUG: sendReceiveFolder/bvkmk-*****@0xc4201f4240 Scanning subdirectories
[OVPYX] 2018/01/04 13:39:14.261295 verboseservice.go:48: VERBOSE: Folder "bvkmk-*****" is now scanning
[OVPYX] 2018/01/04 13:39:15.884770 main.go:857: INFO: Device GSXHK4J-*******-*******-*******-*******-*******-*******-******* is "NAS01" at [dynamic]
[OVPYX] 2018/01/04 13:39:15.884820 main.go:857: INFO: Device OVPYXBH-*******-*******-*******-*******-*******-*******-******* is "NAS02" at [dynamic]
[OVPYX] 2018/01/04 13:39:15.885088 verboseservice.go:48: VERBOSE: Startup complete
[OVPYX] 2018/01/04 13:39:15.886487 gui.go:365: INFO: GUI and API listening on [::]:7070
[OVPYX] 2018/01/04 13:39:15.886528 gui.go:366: INFO: Access the GUI via the following URL: http://127.0.0.1:7070/
[OVPYX] 2018/01/04 13:39:25.020270 static.go:93: INFO: Joined relay relay://83.240.51.14:443
[OVPYX] 2018/01/04 13:39:33.334515 kcp_listen.go:249: INFO: kcp://0.0.0.0:22020 detected NAT type: Port restricted NAT
[OVPYX] 2018/01/04 13:39:33.334572 kcp_listen.go:269: INFO: kcp://0.0.0.0:22020 resolved external address kcp://81.135.129.1:1055 (via stun.ekiga.net:3478)
[OVPYX] 2018/01/04 13:39:33.334731 verboseservice.go:48: VERBOSE: Listen address kcp://0.0.0.0:22020 resolution has changed: lan addresses: [kcp://0.0.0.0:22020] wan addresses: [kcp://0.0.0.0:22020 kcp://81.135.129.1:1055]
[OVPYX] 2018/01/04 13:39:34.254977 verboseservice.go:48: VERBOSE: Listen address dynamic+https://relays.syncthing.net/endpoint resolution has changed: lan addresses: [relay://83.240.51.14:443/?id=NCIJELL-4BNAKN3-GABVCNA-VNEFTM2-M5ELGSD-CNNOZQV-DFXPZ2B-LSKM3QA&pingInterval=1m0s&networkTimeout=2m0s&sessionLimitBps=0&globalLimitBps=20000000&statusAddr=:22070&providedBy=chucic] wan addresses: [relay://83.240.51.14:443/?id=NCIJELL-4BNAKN3-GABVCNA-VNEFTM2-M5ELGSD-CNNOZQV-DFXPZ2B-LSKM3QA&pingInterval=1m0s&networkTimeout=2m0s&sessionLimitBps=0&globalLimitBps=20000000&statusAddr=:22070&providedBy=chucic]
[OVPYX] 2018/01/04 13:39:36.338604 service.go:61: INFO: Detected 2 NAT devices
[OVPYX] 2018/01/04 14:01:34.984777 verboseservice.go:48: VERBOSE: Discovered device GSXHK4J-*******-*******-*******-*******-*******-*******-******* at [kcp://192.168.1.2:22020 tcp://192.168.1.2:22000]
[OVPYX] 2018/01/04 14:01:46.098420 service.go:275: INFO: Established secure connection to GSXHK4J-*******-*******-*******-*******-*******-*******-******* at 192.168.1.3:49363-83.240.51.14:443 (relay-server) (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
[OVPYX] 2018/01/04 14:01:46.098536 model.go:1571: INFO: Device GSXHK4J-*******-*******-*******-*******-*******-*******-******* client is "syncthing v0.14.42" named "NAS01"
[OVPYX] 2018/01/04 14:01:46.098617 verboseservice.go:48: VERBOSE: Connected to device GSXHK4J-*******-*******-*******-*******-*******-*******-******* at 83.240.51.14:443 (type relay-server)
[OVPYX] 2018/01/04 14:01:46.141751 model.go:1033: INFO: Device GSXHK4J-*******-*******-*******-*******-*******-*******-******* folder "NAS" (bvkmk-*****) has a new index ID (0x9284D5EE182F4D15)
[OVPYX] 2018/01/04 14:04:46.099148 model.go:1296: INFO: Connection to GSXHK4J-*******-*******-*******-*******-*******-*******-******* closed: writing message: write tcp 192.168.1.3:49363->83.240.51.14:443: write: broken pipe
[OVPYX] 2018/01/04 14:04:46.099226 verboseservice.go:48: VERBOSE: Disconnected from device GSXHK4J-*******-*******-*******-*******-*******-*******-*******
panic: deadlock detected at fmut
[OVPYX] 2018/01/04 14:24:15.558965 main.go:644: INFO: syncthing v0.14.42+18-ge7a8f95 "Dysprosium Dragonfly" (go1.9.2 linux-amd64) teamcity@build.syncthing.net 2017-12-26 07:14:37 UTC
[OVPYX] 2018/01/04 14:24:15.559105 main.go:645: INFO: My ID: OVPYXBH-*******-*******-*******-*******-*******-*******-*******
[OVPYX] 2018/01/04 14:24:16.623704 sha256.go:92: INFO: Single thread SHA256 performance is 93 MB/s using minio/sha256-simd (68 MB/s using crypto/sha256).
[OVPYX] 2018/01/04 14:24:16.623972 verboseservice.go:48: VERBOSE: Starting up (/usr/local/syncthing/var)
[OVPYX] 2018/01/04 14:24:17.721471 main.go:702: INFO: Hashing performance with weak hash is 81.01 MB/s
[OVPYX] 2018/01/04 14:24:18.727376 main.go:704: INFO: Hashing performance without weak hash is 91.52 MB/s
[OVPYX] 2018/01/04 14:24:18.727424 main.go:710: INFO: Weak hash enabled, as it has an acceptable performance impact.
[OVPYX] 2018/01/04 14:25:08.252643 progressemitter.go:196: DEBUG: progress emitter: updated interval 1s
[OVPYX] 2018/01/04 14:25:08.252711 model.go:167: INFO: Starting deadlock detector with 20m0s timeout
[OVPYX] 2018/01/04 14:25:08.282886 model.go:182: INFO: Ready to synchronize "NAS" (bvkmk-*****) (readwrite)
[OVPYX] 2018/01/04 14:25:08.283042 rwfolder.go:143: DEBUG: sendReceiveFolder/bvkmk-*****@0xc4200a2480 starting
[OVPYX] 2018/01/04 14:25:08.283081 limiter.go:84: INFO: Send rate is unlimited, receive rate is unlimited
[OVPYX] 2018/01/04 14:25:08.283107 limiter.go:89: INFO: Rate limits do not apply to LAN connections
[OVPYX] 2018/01/04 14:25:08.283330 main.go:812: INFO: Using discovery server https://discovery-v4-2.syncthing.net/v2/?id=DVU36WY-H3LVZHW-E6LLFRE-YAFN5EL-HILWRYP-OC2M47J-Z4PE62Y-ADIBDQC
[OVPYX] 2018/01/04 14:25:08.283423 main.go:812: INFO: Using discovery server https://discovery-v4-3.syncthing.net/v2/?id=VK6HNJ3-VVMM66S-HRVWSCR-IXEHL2H-U4AQ4MW-UCPQBWX-J2L2UBK-NVZRDQZ
[OVPYX] 2018/01/04 14:25:08.283489 main.go:812: INFO: Using discovery server https://discovery-v4-4.syncthing.net/v2/?id=LYXKCHX-VI3NYZR-ALCJBHF-WMZYSPK-QG6QJA3-MPFYMSO-U56GTUK-NA2MIAW
[OVPYX] 2018/01/04 14:25:08.283557 relay_listen.go:65: INFO: Relay listener (dynamic+https://relays.syncthing.net/endpoint) starting
[OVPYX] 2018/01/04 14:25:08.283931 rwfolder.go:202: DEBUG: sendReceiveFolder/bvkmk-*****@0xc4200a2480 Scanning subdirectories
[OVPYX] 2018/01/04 14:25:08.285147 tcp_listen.go:69: INFO: TCP listener ([::]:22000) starting
[OVPYX] 2018/01/04 14:25:08.285265 verboseservice.go:48: VERBOSE: Folder "bvkmk-*****" is now scanning
[OVPYX] 2018/01/04 14:25:08.285326 kcp_listen.go:91: INFO: KCP listener ([::]:22020) starting
[OVPYX] 2018/01/04 14:25:10.715172 main.go:812: INFO: Using discovery server https://discovery-v6-2.syncthing.net/v2/?id=DVU36WY-H3LVZHW-E6LLFRE-YAFN5EL-HILWRYP-OC2M47J-Z4PE62Y-ADIBDQC
[OVPYX] 2018/01/04 14:25:10.715267 main.go:812: INFO: Using discovery server https://discovery-v6-3.syncthing.net/v2/?id=VK6HNJ3-VVMM66S-HRVWSCR-IXEHL2H-U4AQ4MW-UCPQBWX-J2L2UBK-NVZRDQZ
[OVPYX] 2018/01/04 14:25:10.715323 main.go:812: INFO: Using discovery server https://discovery-v6-4.syncthing.net/v2/?id=LYXKCHX-VI3NYZR-ALCJBHF-WMZYSPK-QG6QJA3-MPFYMSO-U56GTUK-NA2MIAW
[OVPYX] 2018/01/04 14:25:10.717993 verboseservice.go:48: VERBOSE: Discovered device GSXHK4J-*******-*******-*******-*******-*******-*******-******* at [kcp://192.168.1.2:22020 kcp://81.135.129.1:22020 relay://213.124.171.119:22067/?id=7XFGH4B-GJZ7EHK-NSP5UWE-YK6PTYZ-EPVZ2W2-6ZOXVXK-67DGS66-7BP3IA6&pingInterval=1m0s&networkTimeout=2m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=:22070&providedBy=@Frituurpanda - Nijmegen, NL tcp://192.168.1.2:22000]
[OVPYX] 2018/01/04 14:25:10.754544 main.go:857: INFO: Device OVPYXBH-*******-*******-*******-*******-*******-*******-******* is "NAS02" at [dynamic]
[OVPYX] 2018/01/04 14:25:10.754688 main.go:857: INFO: Device GSXHK4J-*******-*******-*******-*******-*******-*******-******* is "NAS01" at [dynamic]
[OVPYX] 2018/01/04 14:25:10.762831 verboseservice.go:48: VERBOSE: Startup complete
[OVPYX] 2018/01/04 14:25:10.779015 gui.go:365: INFO: GUI and API listening on [::]:7070
[OVPYX] 2018/01/04 14:25:10.779063 gui.go:366: INFO: Access the GUI via the following URL: http://127.0.0.1:7070/
[OVPYX] 2018/01/04 14:25:20.716303 static.go:93: INFO: Joined relay relay://51.15.73.128:22067
[OVPYX] 2018/01/04 14:25:22.001756 service.go:275: INFO: Established secure connection to GSXHK4J-*******-*******-*******-*******-*******-*******-******* at 192.168.1.3:42599-213.124.171.119:22067 (relay-client) (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
[OVPYX] 2018/01/04 14:25:22.001871 model.go:1571: INFO: Device GSXHK4J-*******-*******-*******-*******-*******-*******-******* client is "syncthing v0.14.42" named "NAS01"
[OVPYX] 2018/01/04 14:25:22.002058 verboseservice.go:48: VERBOSE: Connected to device GSXHK4J-*******-*******-*******-*******-*******-*******-******* at 213.124.171.119:22067 (type relay-client)
[OVPYX] 2018/01/04 14:25:22.044744 model.go:1033: INFO: Device GSXHK4J-*******-*******-*******-*******-*******-*******-******* folder "NAS" (bvkmk-*****) has a new index ID (0x9284D5EE182F4D15)
[OVPYX] 2018/01/04 14:25:27.360667 kcp_listen.go:249: INFO: kcp://0.0.0.0:22020 detected NAT type: Port restricted NAT
[OVPYX] 2018/01/04 14:25:27.360734 kcp_listen.go:269: INFO: kcp://0.0.0.0:22020 resolved external address kcp://81.135.129.1:22020 (via stun.schlund.de:3478)
[OVPYX] 2018/01/04 14:25:27.360899 verboseservice.go:48: VERBOSE: Listen address kcp://0.0.0.0:22020 resolution has changed: lan addresses: [kcp://0.0.0.0:22020] wan addresses: [kcp://0.0.0.0:22020 kcp://81.135.129.1:22020]
[OVPYX] 2018/01/04 14:25:28.284087 verboseservice.go:48: VERBOSE: Listen address dynamic+https://relays.syncthing.net/endpoint resolution has changed: lan addresses: [relay://51.15.73.128:22067/?id=4WRQN2E-L3CK5CD-3IQLQX7-GFKJSGY-QQ4LK6D-LCKE6YO-RUYBXLD-LZHWJQH&pingInterval=1m0s&networkTimeout=2m0s&sessionLimitBps=0&globalLimitBps=100000000&statusAddr=:22070&providedBy=relay.cccp.io] wan addresses: [relay://51.15.73.128:22067/?id=4WRQN2E-L3CK5CD-3IQLQX7-GFKJSGY-QQ4LK6D-LCKE6YO-RUYBXLD-LZHWJQH&pingInterval=1m0s&networkTimeout=2m0s&sessionLimitBps=0&globalLimitBps=100000000&statusAddr=:22070&providedBy=relay.cccp.io]
[OVPYX] 2018/01/04 14:25:35.601756 service.go:61: INFO: Detected 2 NAT devices
[OVPYX] 2018/01/04 14:29:52.002311 model.go:1296: INFO: Connection to GSXHK4J-*******-*******-*******-*******-*******-*******-******* closed: writing message: write tcp 192.168.1.3:42599->213.124.171.119:22067: write: broken pipe
[OVPYX] 2018/01/04 14:29:52.002378 verboseservice.go:48: VERBOSE: Disconnected from device GSXHK4J-*******-*******-*******-*******-*******-*******-*******
panic: deadlock detected at fmut
[OVPYX] 2018/01/04 14:50:09.477291 main.go:644: INFO: syncthing v0.14.42+18-ge7a8f95 "Dysprosium Dragonfly" (go1.9.2 linux-amd64) teamcity@build.syncthing.net 2017-12-26 07:14:37 UTC
[OVPYX] 2018/01/04 14:50:09.477470 main.go:645: INFO: My ID: OVPYXBH-*******-*******-*******-*******-*******-*******-*******
[OVPYX] 2018/01/04 14:50:10.540904 sha256.go:92: INFO: Single thread SHA256 performance is 93 MB/s using minio/sha256-simd (68 MB/s using crypto/sha256).
[OVPYX] 2018/01/04 14:50:10.541204 verboseservice.go:48: VERBOSE: Starting up (/usr/local/syncthing/var)
[OVPYX] 2018/01/04 14:50:11.647858 main.go:702: INFO: Hashing performance with weak hash is 81.13 MB/s
[OVPYX] 2018/01/04 14:50:12.654271 main.go:704: INFO: Hashing performance without weak hash is 91.42 MB/s
[OVPYX] 2018/01/04 14:50:12.654321 main.go:710: INFO: Weak hash enabled, as it has an acceptable performance impact.
[OVPYX] 2018/01/04 14:52:51.817604 progressemitter.go:196: DEBUG: progress emitter: updated interval 1s
[OVPYX] 2018/01/04 14:52:51.817672 model.go:167: INFO: Starting deadlock detector with 20m0s timeout
[OVPYX] 2018/01/04 14:52:51.835971 model.go:182: INFO: Ready to synchronize "NAS" (bvkmk-*****) (readwrite)
[OVPYX] 2018/01/04 14:52:51.836119 limiter.go:84: INFO: Send rate is unlimited, receive rate is unlimited
[OVPYX] 2018/01/04 14:52:51.836152 limiter.go:89: INFO: Rate limits do not apply to LAN connections
[OVPYX] 2018/01/04 14:52:51.836258 rwfolder.go:143: DEBUG: sendReceiveFolder/bvkmk-*****@0xc4201f8240 starting
[OVPYX] 2018/01/04 14:52:51.836493 main.go:812: INFO: Using discovery server https://discovery-v4-2.syncthing.net/v2/?id=DVU36WY-H3LVZHW-E6LLFRE-YAFN5EL-HILWRYP-OC2M47J-Z4PE62Y-ADIBDQC
[OVPYX] 2018/01/04 14:52:51.836638 main.go:812: INFO: Using discovery server https://discovery-v4-3.syncthing.net/v2/?id=VK6HNJ3-VVMM66S-HRVWSCR-IXEHL2H-U4AQ4MW-UCPQBWX-J2L2UBK-NVZRDQZ
[OVPYX] 2018/01/04 14:52:51.836742 tcp_listen.go:69: INFO: TCP listener ([::]:22000) starting
[OVPYX] 2018/01/04 14:52:51.836800 kcp_listen.go:91: INFO: KCP listener ([::]:22020) starting
[OVPYX] 2018/01/04 14:52:51.836893 relay_listen.go:65: INFO: Relay listener (dynamic+https://relays.syncthing.net/endpoint) starting
[OVPYX] 2018/01/04 14:52:51.837009 rwfolder.go:202: DEBUG: sendReceiveFolder/bvkmk-*****@0xc4201f8240 Scanning subdirectories
[OVPYX] 2018/01/04 14:52:51.837216 main.go:812: INFO: Using discovery server https://discovery-v4-4.syncthing.net/v2/?id=LYXKCHX-VI3NYZR-ALCJBHF-WMZYSPK-QG6QJA3-MPFYMSO-U56GTUK-NA2MIAW
[OVPYX] 2018/01/04 14:52:51.837319 main.go:812: INFO: Using discovery server https://discovery-v6-2.syncthing.net/v2/?id=DVU36WY-H3LVZHW-E6LLFRE-YAFN5EL-HILWRYP-OC2M47J-Z4PE62Y-ADIBDQC
[OVPYX] 2018/01/04 14:52:51.837375 main.go:812: INFO: Using discovery server https://discovery-v6-3.syncthing.net/v2/?id=VK6HNJ3-VVMM66S-HRVWSCR-IXEHL2H-U4AQ4MW-UCPQBWX-J2L2UBK-NVZRDQZ
[OVPYX] 2018/01/04 14:52:51.837432 main.go:812: INFO: Using discovery server https://discovery-v6-4.syncthing.net/v2/?id=LYXKCHX-VI3NYZR-ALCJBHF-WMZYSPK-QG6QJA3-MPFYMSO-U56GTUK-NA2MIAW
[OVPYX] 2018/01/04 14:52:51.838905 verboseservice.go:48: VERBOSE: Folder "bvkmk-*****" is now scanning
[OVPYX] 2018/01/04 14:52:51.841642 verboseservice.go:48: VERBOSE: Discovered device GSXHK4J-*******-*******-*******-*******-*******-*******-******* at [kcp://192.168.1.2:22020 kcp://81.135.129.1:22020 relay://213.124.171.119:22067/?id=7XFGH4B-GJZ7EHK-NSP5UWE-YK6PTYZ-EPVZ2W2-6ZOXVXK-67DGS66-7BP3IA6&pingInterval=1m0s&networkTimeout=2m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=:22070&providedBy=@Frituurpanda - Nijmegen, NL tcp://192.168.1.2:22000]
[OVPYX] 2018/01/04 14:52:51.873709 main.go:857: INFO: Device GSXHK4J-*******-*******-*******-*******-*******-*******-******* is "NAS01" at [dynamic]
[OVPYX] 2018/01/04 14:52:51.873757 main.go:857: INFO: Device OVPYXBH-*******-*******-*******-*******-*******-*******-******* is "NAS02" at [dynamic]
[OVPYX] 2018/01/04 14:52:51.874401 verboseservice.go:48: VERBOSE: Startup complete
[OVPYX] 2018/01/04 14:52:51.875389 gui.go:365: INFO: GUI and API listening on [::]:7070
[OVPYX] 2018/01/04 14:52:51.875431 gui.go:366: INFO: Access the GUI via the following URL: http://127.0.0.1:7070/
[OVPYX] 2018/01/04 14:52:52.413339 service.go:275: INFO: Established secure connection to GSXHK4J-*******-*******-*******-*******-*******-*******-******* at 192.168.1.3:22000-192.168.1.2:44582 (tcp-server) (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
[OVPYX] 2018/01/04 14:52:52.413461 model.go:1571: INFO: Device GSXHK4J-*******-*******-*******-*******-*******-*******-******* client is "syncthing v0.14.42" named "NAS01"
[OVPYX] 2018/01/04 14:52:52.413554 verboseservice.go:48: VERBOSE: Connected to device GSXHK4J-*******-*******-*******-*******-*******-*******-******* at 192.168.1.2:44582 (type tcp-server)
[OVPYX] 2018/01/04 14:52:52.414815 model.go:1033: INFO: Device GSXHK4J-*******-*******-*******-*******-*******-*******-******* folder "NAS" (bvkmk-*****) has a new index ID (0x9284D5EE182F4D15)
[OVPYX] 2018/01/04 14:53:01.837221 verboseservice.go:48: VERBOSE: Listen address dynamic+https://relays.syncthing.net/endpoint resolution has changed: lan addresses: [relay://163.172.179.61:8443/?id=FU55S7D-DO2JQEP-DYE6SLV-UKU4FS2-BMDTHUE-L5633N2-CIFX32Y-QQUVQAC&pingInterval=1m0s&networkTimeout=2m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=:22070&providedBy=harry.lu - Paris2, FR] wan addresses: [relay://163.172.179.61:8443/?id=FU55S7D-DO2JQEP-DYE6SLV-UKU4FS2-BMDTHUE-L5633N2-CIFX32Y-QQUVQAC&pingInterval=1m0s&networkTimeout=2m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=:22070&providedBy=harry.lu - Paris2, FR]
[OVPYX] 2018/01/04 14:53:01.887603 static.go:93: INFO: Joined relay relay://163.172.179.61:8443
[OVPYX] 2018/01/04 14:53:11.285066 kcp_listen.go:249: INFO: kcp://0.0.0.0:22020 detected NAT type: Port restricted NAT
[OVPYX] 2018/01/04 14:53:11.285124 kcp_listen.go:269: INFO: kcp://0.0.0.0:22020 resolved external address kcp://81.135.129.1:22020 (via stun.voip.aebc.com:3478)
[OVPYX] 2018/01/04 14:53:11.285314 verboseservice.go:48: VERBOSE: Listen address kcp://0.0.0.0:22020 resolution has changed: lan addresses: [kcp://0.0.0.0:22020] wan addresses: [kcp://0.0.0.0:22020 kcp://81.135.129.1:22020]
[OVPYX] 2018/01/04 14:53:14.921524 service.go:61: INFO: Detected 2 NAT devices

I’ve previously used the STDEADLOCKTIMEOUT=7200 as expected - but it doesn’t seem to be happy with this build (i.e. with the STDEADLOCKTIMEOUT variable in place, the process is restarting after a very short time).

Thanks,

Pants.

AudriusButkevicius · January 4, 2018, 3:28pm

There should be panic logs in syncthings config dir or next to the binary, providing those would be useful. I suspect you have bad disk or something like that which makes writes hang, hence we end up leaking fds.

Moisie · January 4, 2018, 5:02pm

Hi Audrius:

Here’s the first panic log from when I was running without any STDEADLOCKTIMEOUT variable today: https://pastebin.com/4pWFWUzK

I would be surprised about this - Syncthing is running on a Synology NAS, with 2-disk redundancy; the Synologies are pretty good at reporting storage errors - and this unit is not showing any evidence of any disk errors.

Hope that’s helpful,

Pants.

AudriusButkevicius · January 4, 2018, 5:42pm

So everything is mostly stuck on database operations, and I suspect the database is stuck on this:

goroutine 35 [syscall]:
syscall.Syscall(0x4a, 0x12, 0x0, 0x0, 0x4a6f22, 0xc423913228, 0xc423913230)
    /usr/local/go/src/syscall/asm_linux_amd64.s:18 +0x5
syscall.Fsync(0x12, 0xd49338, 0xc424280000)
    /usr/local/go/src/syscall/zsyscall_linux_amd64.go:473 +0x4a
internal/poll.(*FD).Fsync(0xc424280000, 0x0, 0x0)
    /usr/local/go/src/internal/poll/fd_posix.go:56 +0x88

It doesn’t say that it was stuck on fsync for a long time, so perhaps the fsync is returning fine, but perhaps the database is in a bad state where it must do a lot of compaction, and the compaction is taking a while, triggering the deadlock timeout. Is the database on some network share or something like that? If it’s not a lot of data you have there, perhaps you can try resetting the database.

The fact you are getting deadlock timeouts is just a side effect of running a development build. I am on the phone and can’t check if there is a way to disable it.

Moisie · January 4, 2018, 5:59pm

Hi Audrius:

Many thanks for your input on this.

The database is on the same RAID set as the data files themselves - so I would expect it to be solid, but not necessarily very fast. Unfortunately I have a very large data set, so resetting the database is not an ideal option… And putting the database on a separate, fast, drive is not going to be easy either.

Indeed - and giving the STDEADLOCKTIMEOUT=7200 variable has been good on previous builds to work around the slow database response - but for some reason, this time it’s kicking off this deadlock problem and prompting syncthing to restart (and not write a panic log, IIRC).

I’ll try running this build with the STDEADLOCKTIMEOUT variable on another system, and see if I get the same result. At least I can eliminate the hardware as a factor then…

Thanks,

Pants.

AudriusButkevicius · January 4, 2018, 6:33pm

Yeah, I suspect @calmh’s recent env var cleanup made it so that non-release builds always run either with 20min deadlock timeout, or lock order deadlock detector.

I don’t know how calmh produced the build for you, but he potentially needs to remove the deadlock detector on it.

calmh · January 4, 2018, 9:40pm

I’ll make a new one tomorrow on the current master. It’s just a few extra debug prints to hopefully figure out where those stopped syncs stop.

Moisie · January 5, 2018, 9:00am

Thanks Jakob - that would be really appreciated!

calmh · January 5, 2018, 2:34pm

Here’s a new build:

https://build.syncthing.net/viewLog.html?buildId=15155&buildTypeId=Syncthing_BuildLinuxCross&tab=artifacts

It has the automatic deadlock detector thing disabled. Do not set any deadlock related envvars (or you will wake it again). Do set STTRACE=model though.