Potential Deadlock

I let my computer update itself to the Windows 10 Fall Creators edition over the holidays. As expected, this broke near everything, but whilst I’ve put my development environment and VPN back together again, I’m still getting SyncThing falling over on startup.

A debug log looks like this:

2018/01/02 10:03:51.477105 debug.go:39: DEBUG: Enabling lock logging at 100ms threshold
[CIZST] 2018/01/02 10:03:51.486605 main.go:644: INFO: syncthing v0.14.43-rc.1 "Dysprosium Dragonfly" (go1.9.2 windows-amd64) teamcity@build.syncthing.net 2017-12-29 21:23:06 UTC
[CIZST] 2018/01/02 10:03:51.487605 main.go:645: INFO: My ID: redacted
[CIZST] 2018/01/02 10:03:52.388906 sha256.go:92: INFO: Single thread SHA256 performance is 396 MB/s using minio/sha256-simd (390 MB/s using crypto/sha256).
[CIZST] 2018/01/02 10:03:52.855898 main.go:702: INFO: Hashing performance with weak hash is 325.73 MB/s
[CIZST] 2018/01/02 10:03:53.315902 main.go:704: INFO: Hashing performance without weak hash is 381.58 MB/s
[CIZST] 2018/01/02 10:03:53.315902 main.go:710: INFO: Weak hash enabled, as it has an acceptable performance impact.
[CIZST] 2018/01/02 10:03:54.558891 model.go:167: INFO: Starting deadlock detector with 5m0s timeout
[CIZST] 2018/01/02 10:03:54.558891 model.go:182: INFO: Ready to synchronize FOLDERNAME readwrite
[CIZST] 2018/01/02 10:03:54.558891 model.go:182: INFO: Ready to synchronize FOLDERNAME readwrite
[CIZST] 2018/01/02 10:03:54.559898 model.go:182: INFO: Ready to synchronize FOLDERNAME readwrite
[CIZST] 2018/01/02 10:03:54.559898 model.go:182: INFO: Ready to synchronize FOLDERNAME readwrite
[CIZST] 2018/01/02 10:03:54.559898 model.go:182: INFO: Ready to synchronize FOLDERNAME readwrite
[CIZST] 2018/01/02 10:03:54.559898 model.go:182: INFO: Ready to synchronize FOLDERNAME readwrite
[CIZST] 2018/01/02 10:03:54.560891 model.go:182: INFO: Ready to synchronize FOLDERNAME readwrite
[CIZST] 2018/01/02 10:03:54.560891 model.go:182: INFO: Ready to synchronize FOLDERNAME readwrite
[CIZST] 2018/01/02 10:03:54.560891 model.go:182: INFO: Ready to synchronize FOLDERNAME readwrite
[CIZST] 2018/01/02 10:03:54.560891 model.go:182: INFO: Ready to synchronize FOLDERNAME readwrite
[CIZST] 2018/01/02 10:03:54.560891 model.go:182: INFO: Ready to synchronize FOLDERNAME readwrite
[CIZST] 2018/01/02 10:03:54.561890 model.go:182: INFO: Ready to synchronize FOLDERNAME readwrite
[CIZST] 2018/01/02 10:03:54.561890 model.go:182: INFO: Ready to synchronize FOLDERNAME readwrite
[CIZST] 2018/01/02 10:03:54.561890 model.go:182: INFO: Ready to synchronize FOLDERNAME readwrite
[CIZST] 2018/01/02 10:03:54.561890 model.go:182: INFO: Ready to synchronize FOLDERNAME readwrite
[CIZST] 2018/01/02 10:03:54.561890 model.go:182: INFO: Ready to synchronize FOLDERNAME readwrite
[CIZST] 2018/01/02 10:03:54.562890 model.go:182: INFO: Ready to synchronize FOLDERNAME readwrite
[CIZST] 2018/01/02 10:03:54.562890 model.go:182: INFO: Ready to synchronize FOLDERNAME readwrite
[CIZST] 2018/01/02 10:03:54.562890 model.go:182: INFO: Ready to synchronize FOLDERNAME readwrite
[CIZST] 2018/01/02 10:03:54.562890 model.go:182: INFO: Ready to synchronize FOLDERNAME readwrite
[CIZST] 2018/01/02 10:03:54.562890 model.go:182: INFO: Ready to synchronize FOLDERNAME readwrite
[CIZST] 2018/01/02 10:03:54.563890 model.go:182: INFO: Ready to synchronize FOLDERNAME readwrite
[CIZST] 2018/01/02 10:03:54.563890 model.go:182: INFO: Ready to synchronize FOLDERNAME readwrite
[CIZST] 2018/01/02 10:03:54.563890 model.go:182: INFO: Ready to synchronize FOLDERNAME readwrite
[CIZST] 2018/01/02 10:03:54.563890 model.go:182: INFO: Ready to synchronize FOLDERNAME readwrite
[CIZST] 2018/01/02 10:03:54.563890 model.go:182: INFO: Ready to synchronize FOLDERNAME readwrite
[CIZST] 2018/01/02 10:03:54.563890 model.go:182: INFO: Ready to synchronize FOLDERNAME readwrite
[CIZST] 2018/01/02 10:03:54.564891 model.go:182: INFO: Ready to synchronize FOLDERNAME readwrite
[CIZST] 2018/01/02 10:03:54.564891 model.go:182: INFO: Ready to synchronize FOLDERNAME readwrite
[CIZST] 2018/01/02 10:03:54.564891 model.go:182: INFO: Ready to synchronize FOLDERNAME readwrite
[CIZST] 2018/01/02 10:03:54.564891 model.go:182: INFO: Ready to synchronize FOLDERNAME readwrite
[CIZST] 2018/01/02 10:03:54.564891 model.go:182: INFO: Ready to synchronize FOLDERNAME readwrite
[CIZST] 2018/01/02 10:03:54.565891 model.go:182: INFO: Ready to synchronize FOLDERNAME readwrite
[CIZST] 2018/01/02 10:03:54.565891 model.go:182: INFO: Ready to synchronize FOLDERNAME readwrite
[CIZST] 2018/01/02 10:03:54.565891 model.go:182: INFO: Ready to synchronize FOLDERNAME readwrite
[CIZST] 2018/01/02 10:03:54.565891 model.go:182: INFO: Ready to synchronize FOLDERNAME readwrite
[CIZST] 2018/01/02 10:03:54.565891 limiter.go:84: INFO: Send rate is unlimited, receive rate is unlimited
[CIZST] 2018/01/02 10:03:54.565891 limiter.go:89: INFO: Rate limits do not apply to LAN connections
[CIZST] 2018/01/02 10:03:54.567891 tcp_listen.go:69: INFO: TCP listener ([::]:22000) starting
[CIZST] 2018/01/02 10:03:54.567891 relay_listen.go:65: INFO: Relay listener (dynamic+https://relays.syncthing.net/endpoint) starting
[CIZST] 2018/01/02 10:03:54.567891 kcp_listen.go:91: INFO: KCP listener ([::]:22020) starting
[CIZST] 2018/01/02 10:03:54.572892 main.go:812: INFO: Using discovery server https://discovery-v4-2.syncthing.net/v2/?id=DVU36WY-H3LVZHW-E6LLFRE-YAFN5EL-HILWRYP-OC2M47J-Z4PE62Y-ADIBDQC
[CIZST] 2018/01/02 10:03:54.572892 main.go:812: INFO: Using discovery server https://discovery-v4-3.syncthing.net/v2/?id=VK6HNJ3-VVMM66S-HRVWSCR-IXEHL2H-U4AQ4MW-UCPQBWX-J2L2UBK-NVZRDQZ
[CIZST] 2018/01/02 10:03:54.572892 main.go:812: INFO: Using discovery server https://discovery-v4-4.syncthing.net/v2/?id=LYXKCHX-VI3NYZR-ALCJBHF-WMZYSPK-QG6QJA3-MPFYMSO-U56GTUK-NA2MIAW
[CIZST] 2018/01/02 10:03:54.572892 main.go:812: INFO: Using discovery server https://discovery-v6-2.syncthing.net/v2/?id=DVU36WY-H3LVZHW-E6LLFRE-YAFN5EL-HILWRYP-OC2M47J-Z4PE62Y-ADIBDQC
[CIZST] 2018/01/02 10:03:54.572892 main.go:812: INFO: Using discovery server https://discovery-v6-3.syncthing.net/v2/?id=VK6HNJ3-VVMM66S-HRVWSCR-IXEHL2H-U4AQ4MW-UCPQBWX-J2L2UBK-NVZRDQZ
[CIZST] 2018/01/02 10:03:54.572892 main.go:812: INFO: Using discovery server https://discovery-v6-4.syncthing.net/v2/?id=LYXKCHX-VI3NYZR-ALCJBHF-WMZYSPK-QG6QJA3-MPFYMSO-U56GTUK-NA2MIAW
[CIZST] 2018/01/02 10:03:54.593891 main.go:857: INFO: Device redacted is "Ben's Desktop" at [dynamic]
[CIZST] 2018/01/02 10:03:54.593891 main.go:857: INFO: Device redacted is "SqlServer2" at [dynamic]
[CIZST] 2018/01/02 10:03:54.593891 main.go:857: INFO: Device redacted is "WebServer5" at [dynamic]
[CIZST] 2018/01/02 10:03:54.593891 main.go:857: INFO: Device redacted is "WebServer6" at [dynamic]
[CIZST] 2018/01/02 10:03:54.593891 main.go:857: INFO: Device redacted is "DevServer1" at [dynamic]
[CIZST] 2018/01/02 10:03:54.593891 main.go:857: INFO: Device redacted is "LILITH" at [dynamic]
[CIZST] 2018/01/02 10:03:54.593891 main.go:857: INFO: Device redacted is "Development in EC2" at [dynamic]
[CIZST] 2018/01/02 10:03:54.593891 main.go:857: INFO: Device redacted is "Backup-Bytemark" at [dynamic]
[CIZST] 2018/01/02 10:03:54.593891 main.go:857: INFO: Device redacted is "WebServer3" at [dynamic]
[CIZST] 2018/01/02 10:03:54.593891 main.go:857: INFO: Device redacted is "WIN-AJ99CJD26IA" at [dynamic]
[CIZST] 2018/01/02 10:03:54.593891 main.go:857: INFO: Device redacted is "Andrew's New Laptop" at [dynamic]
[CIZST] 2018/01/02 10:03:54.593891 main.go:864: INFO: Anonymous usage reporting is always enabled for candidate releases.
[CIZST] 2018/01/02 10:03:54.605892 main.go:889: INFO: Automatic upgrade is always enabled for candidate releases.
[CIZST] 2018/01/02 10:03:54.613891 gui.go:365: INFO: GUI and API listening on 127.0.0.1:8384
[CIZST] 2018/01/02 10:03:54.613891 gui.go:366: INFO: Access the GUI via the following URL: http://127.0.0.1:8384/
[CIZST] 2018/01/02 10:03:54.631399 folder.go:123: INFO: Completed initial scan of readwrite folder Transfer-Ben
[CIZST] 2018/01/02 10:03:54.656406 folder.go:123: INFO: Completed initial scan of readwrite folder "Database-Lima" (Database-Lima)
[CIZST] 2018/01/02 10:03:54.659409 folder.go:123: INFO: Completed initial scan of readwrite folder "Database-RAMSRO" (Database-RAMSRO)
[CIZST] 2018/01/02 10:03:54.659409 folder.go:123: INFO: Completed initial scan of readwrite folder Database-Empty
[CIZST] 2018/01/02 10:03:54.664406 folder.go:123: INFO: Completed initial scan of readwrite folder Transfer-Alex
[CIZST] 2018/01/02 10:03:54.664406 folder.go:123: INFO: Completed initial scan of readwrite folder "Database-OldCourt" (Database-OldCourt)
[CIZST] 2018/01/02 10:03:54.716913 folder.go:123: INFO: Completed initial scan of readwrite folder Database-Postcodes
[CIZST] 2018/01/02 10:03:54.716913 folder.go:123: INFO: Completed initial scan of readwrite folder Database-UKHMA
[CIZST] 2018/01/02 10:03:54.753418 folder.go:123: INFO: Completed initial scan of readwrite folder "DeveloperUtility" (DeveloperUtility)
[CIZST] 2018/01/02 10:03:54.766419 folder.go:123: INFO: Completed initial scan of readwrite folder Database-TwoMoorsFestival
[CIZST] 2018/01/02 10:03:54.769420 folder.go:123: INFO: Completed initial scan of readwrite folder Database-Elmhurst
[CIZST] 2018/01/02 10:03:54.813419 folder.go:123: INFO: Completed initial scan of readwrite folder "Database-StarkAdder" (Database-StarkAdder)
[CIZST] 2018/01/02 10:03:54.851428 folder.go:123: INFO: Completed initial scan of readwrite folder Database-SterlingHay
[CIZST] 2018/01/02 10:03:54.853429 folder.go:123: INFO: Completed initial scan of readwrite folder Database-ScottAndRobson
[CIZST] 2018/01/02 10:03:54.874429 folder.go:123: INFO: Completed initial scan of readwrite folder Database-LondonKayakTours
[CIZST] 2018/01/02 10:03:54.998444 folder.go:123: INFO: Completed initial scan of readwrite folder "Database-ETicketMe" (Database-ETicketMe)
[CIZST] 2018/01/02 10:03:54.999444 folder.go:123: INFO: Completed initial scan of readwrite folder Database-BlueCoatSchool
[CIZST] 2018/01/02 10:03:55.079458 folder.go:123: INFO: Completed initial scan of readwrite folder Database-Cockpit
[CIZST] 2018/01/02 10:03:55.096459 folder.go:123: INFO: Completed initial scan of readwrite folder Database-WindsorDuckTours
[CIZST] 2018/01/02 10:03:55.098459 folder.go:123: INFO: Completed initial scan of readwrite folder Database-WindsorFirestation
[CIZST] 2018/01/02 10:03:55.106459 folder.go:123: INFO: Completed initial scan of readwrite folder "Database-RAM" (Database-RAM)
[CIZST] 2018/01/02 10:03:55.113459 folder.go:123: INFO: Completed initial scan of readwrite folder Database-HobbsOfHenley
[CIZST] 2018/01/02 10:03:55.131466 folder.go:123: INFO: Completed initial scan of readwrite folder Database-WindsorFestival
[CIZST] 2018/01/02 10:03:55.141473 folder.go:123: INFO: Completed initial scan of readwrite folder Database-RuddockPAC
[CIZST] 2018/01/02 10:03:55.201472 folder.go:123: INFO: Completed initial scan of readwrite folder Database-Localizations
[CIZST] 2018/01/02 10:03:55.264485 folder.go:123: INFO: Completed initial scan of readwrite folder Database-Comar
[CIZST] 2018/01/02 10:03:55.407499 folder.go:123: INFO: Completed initial scan of readwrite folder "Database-SomersetHouse" (Database-SomersetHouse)
[CIZST] 2018/01/02 10:03:55.444004 folder.go:123: INFO: Completed initial scan of readwrite folder Database-BroadwayBarking
[CIZST] 2018/01/02 10:03:55.559003 folder.go:123: INFO: Completed initial scan of readwrite folder Database-AnLanntair
[CIZST] 2018/01/02 10:03:55.560004 folder.go:123: INFO: Completed initial scan of readwrite folder Database-HaslemereHall
[CIZST] 2018/01/02 10:03:55.562505 folder.go:123: INFO: Completed initial scan of readwrite folder Database-BattleOfFlowers
[CIZST] 2018/01/02 10:03:55.612503 folder.go:123: INFO: Completed initial scan of readwrite folder "Database-ShetlandArts" (Database-ShetlandArts)
[CIZST] 2018/01/02 10:03:55.613003 folder.go:123: INFO: Completed initial scan of readwrite folder Database-WindsorTIC
[CIZST] 2018/01/02 10:03:55.798004 folder.go:123: INFO: Completed initial scan of readwrite folder SqlServerUtility
[CIZST] 2018/01/02 10:03:55.801504 folder.go:123: INFO: Completed initial scan of readwrite folder WebServerUtility
[CIZST] 2018/01/02 10:03:55.972505 folder.go:123: INFO: Completed initial scan of readwrite folder MonadBuilds
[CIZST] 2018/01/02 10:04:04.277293 static.go:93: INFO: Joined relay relay://31.220.45.3:22067
POTENTIAL DEADLOCK: Duplicate locking, saw callers this locks in one goroutine:[CIZST] 2018/01/02 10:04:04.949037 structs.go:32: INFO: New NAT port mapping: external TCP address 109.151.148.102:48962 to local address 0.0.0.0:22000.

current goroutine 227533 lock &{{{0 0} 0 0 1 0}} 
all callers to this lock in the goroutine
C:/Temp/syncthing-d3d5715d/src/github.com/syncthing/syncthing/lib/nat/structs.go:64 nat.(*Mapping).notify ??? <<<<<
C:/Temp/syncthing-d3d5715d/src/github.com/syncthing/syncthing/lib/nat/service.go:196 nat.(*Service).updateMapping ???
C:/Temp/syncthing-d3d5715d/src/github.com/syncthing/syncthing/lib/nat/service.go:121 nat.(*Service).process ???
C:/Temp/syncthing-d3d5715d/src/github.com/syncthing/syncthing/lib/nat/service.go:55 nat.(*Service).Serve ???
C:/Temp/syncthing-d3d5715d/src/github.com/syncthing/syncthing/vendor/github.com/thejerf/suture/supervisor.go:525 suture.(*Supervisor).runService.func1 ???

C:/Temp/syncthing-d3d5715d/src/github.com/syncthing/syncthing/lib/nat/structs.go:87 nat.(*Mapping).ExternalAddresses ??? <<<<<
C:/Temp/syncthing-d3d5715d/src/github.com/syncthing/syncthing/lib/connections/tcp_listen.go:138 connections.(*tcpListener).WANAddresses ???
C:/Temp/syncthing-d3d5715d/src/github.com/syncthing/syncthing/lib/connections/service.go:498 connections.(*Service).logListenAddressesChangedEvent ???
C:/Temp/syncthing-d3d5715d/src/github.com/syncthing/syncthing/lib/connections/service.go:488 connections.logListenAddressesChangedEvent)-fm ???
C:/Temp/syncthing-d3d5715d/src/github.com/syncthing/syncthing/lib/connections/structs.go:183 connections.(*onAddressesChangedNotifier).notifyAddressesChanged ???
C:/Temp/syncthing-d3d5715d/src/github.com/syncthing/syncthing/lib/connections/tcp_listen.go:74 connections.(*tcpListener).Serve.func1 ???
C:/Temp/syncthing-d3d5715d/src/github.com/syncthing/syncthing/lib/nat/structs.go:66 nat.(*Mapping).notify ???
C:/Temp/syncthing-d3d5715d/src/github.com/syncthing/syncthing/lib/nat/service.go:196 nat.(*Service).updateMapping ???
C:/Temp/syncthing-d3d5715d/src/github.com/syncthing/syncthing/lib/nat/service.go:121 nat.(*Service).process ???
C:/Temp/syncthing-d3d5715d/src/github.com/syncthing/syncthing/lib/nat/service.go:55 nat.(*Service).Serve ???
C:/Temp/syncthing-d3d5715d/src/github.com/syncthing/syncthing/vendor/github.com/thejerf/suture/supervisor.go:525 suture.(*Supervisor).runService.func1 ???


Other goroutines holding locks:
goroutine 227534 lock 0xc042ebf900
C:/Temp/syncthing-d3d5715d/src/github.com/syncthing/syncthing/lib/discover/cache.go:74 discover.(*cachingMux).Lookup ??? <<<<<
C:/Temp/syncthing-d3d5715d/src/github.com/syncthing/syncthing/lib/connections/service.go:331 connections.(*Service).connect ???
C:/Temp/syncthing-d3d5715d/src/github.com/syncthing/syncthing/lib/connections/service.go:145 connections.connect)-fm ???
C:/Temp/syncthing-d3d5715d/src/github.com/syncthing/syncthing/lib/connections/structs.go:170 connections.serviceFunc.Serve ???
C:/Temp/syncthing-d3d5715d/src/github.com/syncthing/syncthing/vendor/github.com/thejerf/suture/supervisor.go:525 suture.(*Supervisor).runService.func1 ???

It is possible there’s something wrong with my disk (see Panic Dump) but I still haven’t found anything despite doing all the diagnostics.

I’m going to try removing my config, and adding folders back in one at a time next.

1 Like

Do you have lock debugging environment variables set?

I have STDEADLOCKTIMEOUT set to 300 and STTRACE set to sync:

<service>
  <id>SyncThing</id>
  <name>SyncThing</name>
  <description>This service runs SyncThing</description>
  <env name="STDEADLOCKTIMEOUT" value="300"/>
  <env name="STTRACE" value="sync"/>
  <executable>syncthing.exe</executable>
  <arguments>-home .\ServiceHome -no-console -no-browser</arguments>
  <logmode>rotate</logmode>
</service>

You should unset that as it triggers a few false positives.

Ok!

I have also narrowed down the setting that makes the problem go away: If I set

<natEnabled>false</natEnabled>

Then it stays up, if NAT traversal is enabled, then it falls over. Even with 9/10 of the folders and half the devices removed.

But I’ll turn the lock debugging off anyway.

There are other cases where it can fall over, so disabling random settings is not the right way to fix this. Right way to fix this is to remove the deadlock env var.

Done. Thanks!

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