`reference_sha256` broke my server.

[matrixbot]

This issue was originally created by @IngwiePhoenix at matrix-org/dendrite#3091.

Background information

• Dendrite version or git SHA: 0.12.0+5d6221d1
• SQLite3 or Postgres?: Postgres
• Running in Docker?: No
• go version: go version go1.19.3 linux/amd64
• Client used (if applicable): Technically Element - but the server is down.

Description

• What is the problem: After upgrading Dendrite, I noticed that the server wasn't coming back online. It turns out that one of the migrations is not, or can not, be applied. I even tried to reset to a few commits earlier, but the problem persists.
• Who is affected: Me, I use Dendrite mainly as an old-fashioned "everything messenger" with appservices and bridges.
• How is this bug manifesting: Immediately on startup
• When did this first appear: Today after git pull.

This is what journalctl shows me.

May 28 14:58:49 birb.it dendrite[40838]: time="2023-05-28T19:58:49.475696978Z" level=info msg="Dendrite version 0.12.0+5d6221d1"
May 28 14:58:49 birb.it dendrite[40838]: time="2023-05-28T19:58:49.477771180Z" level=info msg="DNS cache enabled (size 256, lifetime 5m0s)"
May 28 14:58:49 birb.it dendrite[40838]: time="2023-05-28T19:58:49.515920674Z" level=panic msg="failed to connect to room server db" error="Error \"pq: column \\\"reference_sha256\\\" of relation \\\"roomserver_events\\\" does not exist\" while preparing statement: INSERT INTO roomserver_events AS e (room_nid, event_type_nid, event_state_key_nid, event_id, reference_sha256, auth_event_nids, depth, is_rejected) VALUES ($1, $2, $3, $4, $5, $6, $7, $8) ON CONFLICT ON CONSTRAINT roomserver_event_id_unique DO UPDATE SET is_rejected = $8 WHERE e.event_id = $4 AND e.is_rejected = TRUE RETURNING event_nid, state_snapshot_nid"
May 28 14:58:49 birb.it dendrite[40838]: panic: (*logrus.Entry) 0xc000222230
May 28 14:58:49 birb.it dendrite[40838]: goroutine 1 [running]:
May 28 14:58:49 birb.it dendrite[40838]: github.com/sirupsen/logrus.(*Entry).log(0xc0002221c0, 0x0, {0xc00004a390, 0x23})
May 28 14:58:49 birb.it dendrite[40838]:         github.com/sirupsen/logrus@v1.9.2/entry.go:260 +0x4a7
May 28 14:58:49 birb.it dendrite[40838]: github.com/sirupsen/logrus.(*Entry).Log(0xc0002221c0, 0x0, {0xc0000e9358?, 0xc0000e93b8?, 0x4615c9?})
May 28 14:58:49 birb.it dendrite[40838]:         github.com/sirupsen/logrus@v1.9.2/entry.go:304 +0x4f
May 28 14:58:49 birb.it dendrite[40838]: github.com/sirupsen/logrus.(*Entry).Panic(...)
May 28 14:58:49 birb.it dendrite[40838]:         github.com/sirupsen/logrus@v1.9.2/entry.go:342
May 28 14:58:49 birb.it dendrite[40838]: github.com/MFAshby/stdemuxerhook.(*StdDemuxerHook).Fire(0x0?, 0xc0002220e0)
May 28 14:58:49 birb.it dendrite[40838]:         github.com/MFAshby/stdemuxerhook@v1.0.0/stdemuxerhook.go:58 +0x19e
May 28 14:58:49 birb.it dendrite[40838]: github.com/sirupsen/logrus.LevelHooks.Fire(0xc0000e9498?, 0xe9468?, 0x4?)
May 28 14:58:49 birb.it dendrite[40838]:         github.com/sirupsen/logrus@v1.9.2/hooks.go:28 +0x82
May 28 14:58:49 birb.it dendrite[40838]: github.com/sirupsen/logrus.(*Entry).fireHooks(0xc0002220e0)
May 28 14:58:49 birb.it dendrite[40838]:         github.com/sirupsen/logrus@v1.9.2/entry.go:280 +0x1dc
May 28 14:58:49 birb.it dendrite[40838]: github.com/sirupsen/logrus.(*Entry).log(0xc000222070, 0x0, {0xc00004a360, 0x23})
May 28 14:58:49 birb.it dendrite[40838]:         github.com/sirupsen/logrus@v1.9.2/entry.go:242 +0x390
May 28 14:58:49 birb.it dendrite[40838]: github.com/sirupsen/logrus.(*Entry).Log(0xc000222070, 0x0, {0xc0000e9758?, 0x0?, 0x0?})
May 28 14:58:49 birb.it dendrite[40838]:         github.com/sirupsen/logrus@v1.9.2/entry.go:304 +0x4f
May 28 14:58:49 birb.it dendrite[40838]: github.com/sirupsen/logrus.(*Entry).Logf(0xc000222070, 0x0, {0x176d95a?, 0x151e560?}, {0x0?, 0x5a?, 0x5?})
May 28 14:58:49 birb.it dendrite[40838]:         github.com/sirupsen/logrus@v1.9.2/entry.go:349 +0x85
May 28 14:58:49 birb.it dendrite[40838]: github.com/sirupsen/logrus.(*Entry).Panicf(...)
May 28 14:58:49 birb.it dendrite[40838]:         github.com/sirupsen/logrus@v1.9.2/entry.go:387
May 28 14:58:49 birb.it dendrite[40838]: github.com/matrix-org/dendrite/roomserver.NewInternalAPI(0xc000277950, 0xc000347c00, {0x0, {0x0, 0x0}, {{0xc00015bc80, 0x3d}, 0x5a, 0x5, 0xffffffffffffffff}, ...}, ...)
May 28 14:58:49 birb.it dendrite[40838]:         github.com/matrix-org/dendrite/roomserver/roomserver.go:41 +0x145
May 28 14:58:49 birb.it dendrite[40838]: main.main()
May 28 14:58:49 birb.it dendrite[40838]:         github.com/matrix-org/dendrite/cmd/dendrite/main.go:152 +0xc25
May 28 14:58:49 birb.it systemd[1]: matrix-dendrite.service: Main process exited, code=exited, status=2/INVALIDARGUMENT
May 28 14:58:49 birb.it systemd[1]: matrix-dendrite.service: Failed with result 'exit-code'.

Steps to reproduce

Because I haven't found a solid way to update only to specific tags, I have been pulling from master since a long time now instead. Usually when I felt like it - no fixed schedule. After that, I'd just run ./build.sh to have all the binaries built and I have a SystemD unit pointing at it.

The SystemD unit:

# /opt/systemd-units/matrix-dendrite.service
[Unit]
Description=Dendrite (Matrix Homeserver)
After=syslog.target
After=network.target
After=postgresql.service

[Service]
#Environment=GODEBUG=madvdontneed=1
#Environment="PPROFLISTEN=localhost:65432"
RestartSec=2s
Type=simple
User=dendrite
Group=dendrite
WorkingDirectory=/srv/matrix-dendrite/
ExecStart=/opt/matrix-dendrite/bin/dendrite -config /srv/matrix-dendrite/dendrite.yaml
Restart=always
LimitNOFILE=65535

[Install]
WantedBy=multi-user.target

I have always done the exact order of commands:

git pull
./build.sh
systemctl restart matrix-dendrite

So it should have ran migrations - but maybe I somehow mised one?

Thanks and kind regards,
Ingwie

[matrixbot]

This comment was originally posted by @S7evinK at matrix-org/dendrite#3091 (comment).

Would be interesting to know the error, if any, when actually running the latest commit. (yours is from one commit earlier)
The error seems plausible, since the column was dropped in the latest commit and we don't have downgrade migrations for this :)

If one of the migrations failed on the latest commit, there is a possible fix in matrix-org/dendrite#3087

(oh, sorry, somehow missed that one of the migrations failed, only on mobile. #3087 should fix that)

[matrixbot]

This comment was originally posted by @IngwiePhoenix at matrix-org/dendrite#3091 (comment).

It's exactly the same. But, just to be sure:

root@birb:/opt/matrix-dendrite# git reset --hard HEAD
HEAD is now at 76db8e90 Dendrite Documentation Fix (#2913)
root@birb:/opt/matrix-dendrite# ./build.sh
go: downloading (... snip ...)
root@birb:/opt/matrix-dendrite# ls -l bin
total 344812
drwxr-xr-x  2 root root     4096 May 28 16:08 .
drwxr-xr-x 19 root root     4096 May 28 16:06 ..
-rwxr-xr-x  1 root root 30492096 May 28 16:08 create-account
-rwxr-xr-x  1 root root 48520976 May 28 15:04 dendrite
-rwxr-xr-x  1 root root 54232984 May 28 16:08 dendrite-demo-pinecone
-rwxr-xr-x  1 root root 52198256 May 28 16:08 dendrite-demo-yggdrasil
-rwxr-xr-x  1 root root 51516200 May 28 16:08 dendrite-monolith-server
-rwxr-xr-x  1 root root 51232976 May 28 16:08 dendrite-polylith-multi
-rwxr-xr-x  1 root root 11131253 May 28 16:07 dendrite-upgrade-tests
-rwxr-xr-x  1 root root  7751407 May 28 16:07 furl
-rwxr-xr-x  1 root root  5705096 May 28 16:07 generate-config
-rwxr-xr-x  1 root root  5861706 May 28 16:07 generate-keys
-rwxr-xr-x  1 root root 34386520 May 28 16:08 resolve-state

After then starting the service, I can see this:

May 28 16:09:20 birb.it dendrite[66792]: time="2023-05-28T21:09:20.215772737Z" level=info msg="Dendrite version 0.12.0+9b98e5a1.latest"
May 28 16:09:20 birb.it dendrite[66792]: time="2023-05-28T21:09:20.215849522Z" level=info msg="DNS cache enabled (size 256, lifetime 5m0s)"
May 28 16:09:20 birb.it dendrite[66792]: time="2023-05-28T21:09:20.244981908Z" level=panic msg="failed to connect to room server db" error="Error \"pq: column \\\"reference_sha256\\\" of relation \\\"roomserver_events\\\" does not exist\" while preparing statement: INSERT INTO roomserver_events AS e (room_nid, event_type_nid, event_state_key_nid, event_id, reference_sha256, auth_event_nids, depth, is_rejected) VALUES ($1, $2, $3, $4, $5, $6, $7, $8) ON CONFLICT ON CONSTRAINT roomserver_event_id_unique DO UPDATE SET is_rejected = $8 WHERE e.event_id = $4 AND e.is_rejected = TRUE RETURNING event_nid, state_snapshot_nid"
May 28 16:09:20 birb.it dendrite[66792]: panic: (*logrus.Entry) 0xc000178230
May 28 16:09:20 birb.it dendrite[66792]: goroutine 1 [running]:
May 28 16:09:20 birb.it dendrite[66792]: github.com/sirupsen/logrus.(*Entry).log(0xc0001781c0, 0x0, {0xc000238150, 0x23})
May 28 16:09:20 birb.it dendrite[66792]:         github.com/sirupsen/logrus@v1.9.0/entry.go:260 +0x4a7
May 28 16:09:20 birb.it dendrite[66792]: github.com/sirupsen/logrus.(*Entry).Log(0xc0001781c0, 0x0, {0xc0001d1368?, 0xc0001d13c8?, 0x4615c9?})
May 28 16:09:20 birb.it dendrite[66792]:         github.com/sirupsen/logrus@v1.9.0/entry.go:304 +0x4f
May 28 16:09:20 birb.it dendrite[66792]: github.com/sirupsen/logrus.(*Entry).Panic(...)
May 28 16:09:20 birb.it dendrite[66792]:         github.com/sirupsen/logrus@v1.9.0/entry.go:342
May 28 16:09:20 birb.it dendrite[66792]: github.com/MFAshby/stdemuxerhook.(*StdDemuxerHook).Fire(0x0?, 0xc0001780e0)
May 28 16:09:20 birb.it dendrite[66792]:         github.com/MFAshby/stdemuxerhook@v1.0.0/stdemuxerhook.go:58 +0x19e
May 28 16:09:20 birb.it dendrite[66792]: github.com/sirupsen/logrus.LevelHooks.Fire(0xc0001d14a8?, 0x1d1478?, 0x3?)
May 28 16:09:20 birb.it dendrite[66792]:         github.com/sirupsen/logrus@v1.9.0/hooks.go:28 +0x82
May 28 16:09:20 birb.it dendrite[66792]: github.com/sirupsen/logrus.(*Entry).fireHooks(0xc0001780e0)
May 28 16:09:20 birb.it dendrite[66792]:         github.com/sirupsen/logrus@v1.9.0/entry.go:280 +0x1dc
May 28 16:09:20 birb.it dendrite[66792]: github.com/sirupsen/logrus.(*Entry).log(0xc000178070, 0x0, {0xc0002380f0, 0x23})
May 28 16:09:20 birb.it dendrite[66792]:         github.com/sirupsen/logrus@v1.9.0/entry.go:242 +0x390
May 28 16:09:20 birb.it dendrite[66792]: github.com/sirupsen/logrus.(*Entry).Log(0xc000178070, 0x0, {0xc0001d1768?, 0x0?, 0x0?})
May 28 16:09:20 birb.it dendrite[66792]:         github.com/sirupsen/logrus@v1.9.0/entry.go:304 +0x4f
May 28 16:09:20 birb.it dendrite[66792]: github.com/sirupsen/logrus.(*Entry).Logf(0xc000178070, 0x0, {0x17658f2?, 0x1516f60?}, {0x0?, 0x5a?, 0x5?})
May 28 16:09:20 birb.it dendrite[66792]:         github.com/sirupsen/logrus@v1.9.0/entry.go:349 +0x85
May 28 16:09:20 birb.it dendrite[66792]: github.com/sirupsen/logrus.(*Entry).Panicf(...)
May 28 16:09:20 birb.it dendrite[66792]:         github.com/sirupsen/logrus@v1.9.0/entry.go:387
May 28 16:09:20 birb.it dendrite[66792]: github.com/matrix-org/dendrite/roomserver.NewInternalAPI(0xc0002bb200, 0xc0001bc000, {0x0, {0x0, 0x0}, {{0xc000242200, 0x3d}, 0x5a, 0x5, 0xffffffffffffffff}, ...}, ...)
May 28 16:09:20 birb.it dendrite[66792]:         github.com/matrix-org/dendrite/roomserver/roomserver.go:41 +0x145
May 28 16:09:20 birb.it dendrite[66792]: main.main()
May 28 16:09:20 birb.it dendrite[66792]:         github.com/matrix-org/dendrite/cmd/dendrite/main.go:152 +0xba5
May 28 16:09:20 birb.it systemd[1]: matrix-dendrite.service: Main process exited, code=exited, status=2/INVALIDARGUMENT
May 28 16:09:20 birb.it systemd[1]: matrix-dendrite.service: Failed with result 'exit-code'.