canonical / canonical/dqlite

`src/vfs.c:1271: vfsMainFileClose: Assertion '(f->database->shm.lock[0] == 0)'`

Open
#855 4 comments 0 reactions 0 assignees View on GitHub
Dominant language
C
Stars
4.4k
Forks
254
PR merge metrics
No merged PRs in 30d

Description

In the LXD test suite, during the `clustering_handover`, an assertion failure in `dqlite` [was found](https://github.com/simondeziel/lxd/actions/runs/18391256026/job/52401997054#step:17:32583):

```
2025-10-09T23:08:03.9744500Z + lxd shutdown
2025-10-09T23:08:03.9761816Z time="2025-10-09T23:08:03Z" level=info msg="Found cluster member whose role needs to be changed" candidateAddress="100.64.1.103:8443" local="100.64.1.101:8443" newRole=spare
2025-10-09T23:08:03.9765596Z time="2025-10-09T23:08:03Z" level=info msg="Demoting offline member during rebalance" candidateAddress="100.64.1.103:8443"
2025-10-09T23:08:03.9890740Z time="2025-10-09T23:08:03Z" level=info msg="Completed heartbeat round" duration=142.222769ms local="100.64.1.101:8443"
2025-10-09T23:08:03.9943000Z time="2025-10-09T23:08:03Z" level=info msg="Starting heartbeat round" local="100.64.1.101:8443" mode=initial
2025-10-09T23:08:03.9952887Z time="2025-10-09T23:08:03Z" level=warning msg="Failed heartbeat" err="Failed to send heartbeat request: Put \"https://100.64.1.103:8443/internal/database\": dial tcp 100.64.1.103:8443: connect: connection refused" remote="100.64.1.103:8443"
2025-10-09T23:08:04.0008186Z time="2025-10-09T23:08:04Z" level=info msg="Partial heartbeat received" local="100.64.1.104:8443"
2025-10-09T23:08:04.0011674Z time="2025-10-09T23:08:04Z" level=info msg="Partial heartbeat received" local="100.64.1.102:8443"
2025-10-09T23:08:04.0025965Z time="2025-10-09T23:08:04Z" level=info msg="Asked to shutdown by API" force=false
2025-10-09T23:08:04.0029878Z time="2025-10-09T23:08:04Z" level=info msg="Starting shutdown sequence" signal="power failure"
2025-10-09T23:08:04.0031115Z time="2025-10-09T23:08:04Z" level=info msg="Unwatching path" driver=inotify path=/var/lib/ubuntu-advantage/interfaces/lxd-config.json
2025-10-09T23:08:04.0032123Z time="2025-10-09T23:08:04Z" level=info msg="Transferring leadership" address="100.64.1.101:8443"
2025-10-09T23:08:04.0050157Z time="2025-10-09T23:08:04Z" level=warning msg="Failed heartbeat" err="Failed to send heartbeat request: Put \"https://100.64.1.103:8443/internal/database\": dial tcp 100.64.1.103:8443: connect: connection refused" remote="100.64.1.103:8443"
2025-10-09T23:08:04.0089964Z lxd: src/vfs.c:1271: vfsMainFileClose: Assertion `(f->database->shm.lock[0] == 0)' failed.
2025-10-09T23:08:04.0119308Z time="2025-10-09T23:08:04Z" level=warning msg="Failed adding member event listener client" err="dial tcp 100.64.1.103:8443: connect: connection refused" local="100.64.1.104:8443" remote="100.64.1.103:8443"
2025-10-09T23:08:04.0123219Z time="2025-10-09T23:08:04Z" level=warning msg="Failed adding member event listener client" err="dial tcp 100.64.1.103:8443: connect: connection refused" local="100.64.1.102:8443" remote="100.64.1.103:8443"
2025-10-09T23:08:04.0125165Z time="2025-10-09T23:08:04Z" level=info msg="Dqlite connected outbound" local="100.64.1.102:40880" name=raft remote="100.64.1.104:8443"
2025-10-09T23:08:04.0140110Z time="2025-10-09T23:08:04Z" level=info msg="Dqlite proxy started" local="100.64.1.104:8443" name=dqlite remote="100.64.1.1:40880"
2025-10-09T23:08:04.0143688Z time="2025-10-09T23:08:04Z" level=info msg="Dqlite proxy started" local="100.64.1.102:40880" name=raft remote="100.64.1.104:8443"
2025-10-09T23:08:04.0172181Z time="2025-10-09T23:08:04Z" level=info msg="Dqlite connected outbound" local="100.64.1.104:33382" name=raft remote="100.64.1.102:8443"
2025-10-09T23:08:04.0187323Z time="2025-10-09T23:08:04Z" level=info msg="Dqlite proxy started" local="100.64.1.102:8443" name=dqlite remote="100.64.1.1:33382"
2025-10-09T23:08:04.0191223Z time="2025-10-09T23:08:04Z" level=info msg="Dqlite proxy started" local="100.64.1.104:33382" name=raft remote="100.64.1.102:8443"
2025-10-09T23:08:05.2390792Z Error: Put "http://unix.socket/internal/shutdown?force=false": EOF
2025-10-09T23:08:05.2392846Z time="2025-10-09T23:08:05Z" level=info msg="Dqlite proxy stopped" local="100.64.1.104:8443" name=dqlite remote="100.64.1.1:52886"
2025-10-09T23:08:05.2394393Z time="2025-10-09T23:08:05Z" level=info msg="Dqlite proxy stopped" local="100.64.1.102:8443" name=dqlite remote="100.64.1.1:40832"
2025-10-09T23:08:05.2395726Z time="2025-10-09T23:08:05Z" level=warning msg="Dqlite proxy failed" err="first: remote -> local: read tcp 100.64.1.102:42778->100.64.1.101:8443: read: connection reset by peer" local="100.64.1.102:42778" name=raft remote="100.64.1.101:8443"
2025-10-09T23:08:05.2396937Z time="2025-10-09T23:08:05Z" level=info msg="Dqlite proxy stopped" local="100.64.1.102:42778" name=raft remote="100.64.1.101:8443"
2025-10-09T23:08:05.2397788Z time="2025-10-09T23:08:05Z" level=info msg="Dqlite proxy stopped" local="100.64.1.104:33280" name=raft remote="100.64.1.101:8443"
2025-10-09T23:08:05.2404614Z suites/clustering.sh: line 2820: 32574 Aborted (core dumped) nsenter -n -m -t "${pid}" lxd --logfile "${LXD_DIR}/lxd.log" "${SERVER_DEBUG-}" "$@" 2>&1
2025-10-09T23:08:05.2405206Z + cleanup
```

There are many failures in the other tests ran with that PR but they are unrelated to this rare `dqlite` issue.

Contributor guide

Open the contributing guide

Research direction

Start with the assertion at src/vfs.c:1271 and the clustering_handover failure in the LXD test suite. Trace why the shared-memory lock remains set during vfsMainFileClose, then reproduce the rare shutdown failure and verify that the assertion no longer occurs.

Written by the indexing model from the issue text.

Assessment

Tech stack
c, sqlite
Domain
databases, distributed-systems
Issue type
Bug
Difficulty
5/5
Estimated time
Over a week
Activity status
Stale
Clarity
Needs clarification
Newbie friendliness
25/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.