nested query inside an iterator deadlocks the connection pool

[benedikt-bartscher]

What happened?

One of my nodes stopped syncing mid-transfer and stayed dead for 26 minutes until I restarted it. No error, no folder error, no log line — it just quietly stopped moving files.

It's a connection pool deadlock in the SQLite layer. iterStructs keeps its pooled connection for the whole iteration, and most places that iterate also query the same database from inside the loop body:

• the puller and the copier, folder_sendrecv.go:323 and :1441
• the scanner, folder.go:775
• folder_recvonly.go:93, folder_recvenc.go:54, folder_sendonly.go:48

Once maxDBConns goroutines are each holding an iterator and waiting for a second connection, nothing moves again. database/sql has no timeout on acquiring a connection, so it never recovers by itself.

I suspect this became much easier to hit with #10596, which took maxDBConns from 16 down to 6. Worth noting too that the number of goroutines which can be in this state grows with copiers and with numConnections per device, while maxDBConns is a constant.

Separately, and independently: baseDB.stmt() calls Preparex while holding the statementsMut write lock. Preparex needs a connection itself, so a single cache miss on an exhausted pool blocks every other statement lookup on that database, cached ones included.

Handy for confirming it's this one:

• /rest/system/ping and /status answer instantly, while /rest/system/connections and /rest/db/status hang forever
• the process sits at 0% CPU with no disk writes
• peer sockets pile up unread data (ss -tn, non-zero Recv-Q)
• the log goes completely silent, no "Synced file" lines at all

This hangs on current main:

func TestNestedQueryDuringIteration(t *testing.T) {
	sdb, _ := Open(t.TempDir())
	files := make([]protocol.FileInfo, 0, 100)
	for i := range 100 {
		files = append(files, genFile(fmt.Sprintf("file%03d", i), 1, 0))
	}
	sdb.Update(folderID, protocol.LocalDeviceID, files)

	var wg sync.WaitGroup
	for range 32 { // more than maxDBConns
		wg.Go(func() {
			it, errFn := sdb.AllLocalFiles(folderID, protocol.LocalDeviceID)
			for range it {
				sdb.GetDeviceSequence(folderID, protocol.LocalDeviceID)
			}
			errFn()
		})
	}
	wg.Wait() // never returns
}

Syncthing version

v2.1.2

Platform & operating system

Linux amd64

Browser version

No response

Relevant log output

From a SIGQUIT dump, 358 goroutines. Dozens waiting for a connection:

  db/sqlite.(*folderDB).GetMtime           folderdb_mtimes.go:21    [select, 26 minutes]
  db/sqlite.(*folderDB).GetDeviceSequence  folderdb_indexid.go:97   [select, 18-27 minutes]
  db/sqlite.(*folderDB).CountGlobal        folderdb_counts.go:46    [select, 22-26 minutes]

Holding a connection, blocked on a second one from inside their loop:

  model.(*sendReceiveFolder).copierRoutine    folder_sendrecv.go:1332
  model.(*sharedPullerState).addWriterLocked  sharedpullerstate.go:154
  model.(*sendReceiveFolder).processNeeded    folder_sendrecv.go:459

[benedikt-bartscher]

benedikt-bartscher@7fd3dc2

[calmh]

Full backtrace, please.

[benedikt-bartscher]

https://gist.github.com/benedikt-bartscher/49e8e377a82522a6e5409491907303a5