element-hq / element-hq/dendrite
Dendrite panic on syncapi jetstream
- Dominant language
- Go
- Stars
- 965
- Forks
- 101
- PR merge metrics
- No merged PRs in 30d
Description
*This issue was originally created by [**@hdhog**](https://github.com/hdhog) at .*
### Background information
- **Dendrite version or git SHA**: 0.10.3
- **Monolith or Polylith?**: monolith
- **SQLite3 or Postgres?**: PostgreSQL
- **Running in Docker?**: yes
- **Client used (if applicable)**: server side
### Description
- **What** is the problem: panic on roomeventconsumer and restart
- **Who** is affected: all users
- **How** is this bug manifesting: server restarted
- **When** did this first appear:
last log
```
time="2022-10-16T05:36:09.361354944Z" level=error msg="Failed to acquire database snapshot for sync request" error="context canceled"
time="2022-10-16T05:36:09.361394483Z" level=error msg="Failed to acquire database snapshot for sync request" error="context canceled"
time="2022-10-16T05:36:09.360830889Z" level=error msg="GetEvent: syncDB.NewDatabaseTransaction failed" error="context canceled" event_id="$F79b7RslJn_KLnQYvq2nMH5IoInKsmi-xUimRdlijME" req.id=baXQgUAzTNUS req.method=GET req.path="/_matrix/client/v3/rooms/!KqkRjyTEzAGRiZFBYT:nixos.org/event/$F79b7RslJn_KLnQYvq2nMH5IoInKsmi-xUimRdlijME" room_id="!KqkRjyTEzAGRiZFBYT:nixos.org" user_id="@hdhog:matrix.hdhog.ru"
time="2022-10-16T05:36:11.769729776Z" level=panic msg="roomserver output log: write new event failure" add="[$YS2FFKq3PfAbm5rZsVapvQQaUOKtfs_zcKmVOIUfGlY $5is-LYQo2L0Haoh4wJ67EKsVFftU3NHqO0Z_LGUVor0 $TrcRT6hmenmTx4sXFlQdyrJPUs7j-P-G14Ta-9nXgWs $hhr7lAN-45ZVm5pOyT811j7PRBSzlVlzwI1RGFXALXM $niefVlQsLWPCmAif7xcq_B2_3VSVxvPslwuEI_H3i2o $PchbUq4ZMRxlwRJ5swdEfKAJ_82qv6cWqxLOO1xojt8 $BrrQ-dZEjblxISqA5A2p5xeY6dyeCGM0dhzahnBfc3c $U4wLJalKSW4121plydlljXuQIuGQbajJixEjTJ434CA $xOtP2LpV1G6M_oNeTTIGZRm7MDSr0iazC_lkB4kcPaQ $zvvoRHW6au4L0ULlR-h9ab91dew8mEBNwqh-kNNhiAw $G8uY3lglKCJ8pYuKiQnSb8vIKmQcDFWnInrKcs14jJw $NJl3afzuiDMrdFQQeMF2MfpO0TEUHyAUwHOxTkUwSgs $jC49UmRBEiK6eINbjZTOuK6SkdjylTEe8wL5oJaMDTc $iCP64E_d2vEiyVibAayhV02JkgXEGExZqkAEQS8PeIY $-_iX7bsQXPwB5295idBk_mHTyGtckPTeXv3kmtFUs4A $htYw1h5eSQnAyeLCX5iEvD3g8py_onUuDDtAoOcAixQ $LcGmh_WuLiRemXtxfUPmLA72PR_glrToClYcbvrOQ2A $VzR6JVw7rBOUQLKlEC5JPNDGID_B4urhFnJKnMaeurE $pzx2HKdHiKCqxoEt9R5GpiYDAHrllHE579c8OhHUKZ4 $7i5cEV5x7nZPTv441QqxKY4r-lSSnA443Hoh6lRhJdc $KjRNcuHTMcJ4XakXUEji2d9Ub6PTmD5-m2u7MCcQDXk $IZop0HSKRmJfVxbZnWzrftIHA-Y9u4YeWWscr03_3EE
*********** remove many lines ***************
$Ufq4UZ6ladgf1FqA7XVZfwBbizdhH-0Xx_ybCEBygw8 $45OF-eEYm2WWXGH3wGxz49rtVdgT1Vd-k8nxenxYA00 $p1Ci-g2ZziSjtc_Slkr5T8G49H-DTwoH3QmYSXuc1pc $ro1kl07V4kGvchP46CKuy2MRqXZT8gOG6m8u5NanTPg $jVDY1ylN7vKKRB5nHTsqQH75ciiUUUcP8F2zGyOi1r8 $m7P9jSYBAjTJYPucNSB4riJDqHH-se8qGRt870vcY_I $UxQJR2PBUr4DFe-LGio_t-YKM_rhjEWYsWBV-iP2hp8 $xykKCbew2hPcsCrQ5U17BmqphKibuem2E3N1zUGou8o $U9ty-KAq3LoWItQsneBK-cKU-O_5DUYlj8VSWE22uLw $4UYWA-gkeH6Nw__q31YetLNrqabrDOourz2wF2D_LoU $bwfQxLXwtVOzcIVqFg3C699ilRmwsCXbml97tdqnJ0A $1sbPWaxLoIyvSNze_-HTezevxzqpEMeJXqJs-cBBmKo $fyKPjuYFD9kJa5AuNCxKJU2w6jdfkDZGrNOW5Flfxu0 $PvHT3jwSVyYZarPkS8htCu8VO-9p72NHz9Vhi0XNdf4 $3VSXkMquI3Qws-OZp-EQQtCpYnHD4Z7dRDfbDH314FI $iNKlqw5Mgr7VVztgeyVfFtlzuKSHgUxHiOxqdbQv3i8 $3-JzdCPmygNacTss0Z3OCWqOqm4tsXq02ogeIaJ0z7o $K_f6OzBIMU7fZ6492-XlBxU2MbCV7_Bmo4fcM25WIdc $TZTzwyJLsBYLJtXPGUx2XLix_K99cWZUXOI-ljPk_cE $DrR6RaYk_eNKET4ZclFakjLAYQobEYUwKw7TRmHyXWk $HmDvRbETeGpn_ka7pv-ie7f6k5mKPBh1lGBT7DQWTAg $ZhQQgvz-W62kHSivJq1tntxK8RVJuudjS8MkQEMvxt0 $TnspHK9FpkAzuejtC7jGC27kQnl_X_XTGNvLJLQAFjY $KECPPOz-DNEDcKYPp7SFHXcJd8JpER9XJXI6NpTOcpI $H-PzC1Y6NtzOcTl-B55e9WFuMDkEnmj_sYyXFKpT7l4 $8-rjdtvxaTSEtKp3hyPPx3nWhitpb-qVB3uWBJO8skg $2ZsBe-u4Ijzl4yjLpM7VZX7LV-jEtG6HIpzOvNuyAYE $HO6LKWASWzvdX5b50H82hEmS-l8KRFjV2EJdXT8qpyA $iASnZDDA2HVU8JbYFIWT3bV8mZBNejEXh34bswkSqkI $lxIaVm2WPtvM6jJlLz2rPesFORyOz8XRgsoYeZ5oQow $3IiZmItu-8Vc3vqAImVcVeNLhEtrSrXiVyEwbI13FoU $JPSPp9_vXyvsFc77fHe6uB7OsTvR-iA98cza7w81iCQ $mc84WsQXmUO3mvARUMYeyBVSNZctxlduxElRWBFa5ps $U-HLCH4oORY3kjBNyPSKdcfPXELSaoTKo5Uv6VyfGQM $d6tto_Nc0lfJu61pdq7CqUMK6nU41k42pGVM2-UGwLA $LvTDk6mzTVw3556vkIZ1O294pcf0twiv3xo1wME9_6U $vtK04MbnO5ac3Z31Fk60DYSQH6wu2Ywfn-qF1YC7mtw $eSBJNfIRjqhKjhzaP6iEDMMT2hDq58E_KS7Icm_Kfq0 $Jllq1-gajPNu1H8tdPb67Zzmu2Ct8XrPdZ7FNWX8UMo $e7a6dH_yLunuKyOk_ca4Bw9gcCTz8zw1eLCP6N3359w $vlY4XIoZfHd0pVibJVrqHmPFJJoFEQjeD5r3OYN1NsY $87K12_1jJwL3YhjwfiUTsZB6ZNl4I8g7mnIXTUY8iQ4 $4L5FbL3JObcNs_8AxTfQdXpqpqsEKevyBKSJQNAl5_g $BH0zYB2Uy9vUif72qMnXRv1tiw1RGlI7A_dtSDkCthw $IYHMO4WxDsHiEwCI2RG7KiuWgtTSGmn-pzJVtcNS75w $XB8ODTGqmWue_kzaCwfZDarPETS69-P131GoLy7Yj4w $pFcpGUMoshGN5VnJSXa98WOUaFyGVWgncN16V3d1hok $TOfKRr4kXU8-siQfvcUurfALzyJZMACftTckIq7I5YI $HdwRGEaz5rYmEdc7aR1gazoGRU-ockfmJcvRVyFweIo]" del="[]" error="d.Memberships.UpsertMembership: pq: duplicate key value violates unique constraint \"syncapi_memberships_unique\"" event="{\"auth_events\":[\"$YS2FFKq3PfAbm5rZsVapvQQaUOKtfs_zcKmVOIUfGlY\",\"$LKsl93OKRQ-_S9qJcDcZZB4vpBQ9EQXRjt1HbohkYVE\",\"$TrcRT6hmenmTx4sXFlQdyrJPUs7j-P-G14Ta-9nXgWs\",\"$5is-LYQo2L0Haoh4wJ67EKsVFftU3NHqO0Z_LGUVor0\"],\"content\":{\"avatar_url\":\"mxc://lassul.us/mSBytdnmcCoAFjWHVslfgOJw\",\"displayname\":\"lassulus\",\"membership\":\"invite\"},\"depth\":7147,\"hashes\":{\"sha256\":\"VPR4Nz1glRDZNzyqxHY675lIJuPAHb8pS1J/IaVO4eQ\"},\"origin\":\"nixos.dev\",\"origin_server_ts\":1665833783154,\"prev_events\":[\"$bwfQxLXwtVOzcIVqFg3C699ilRmwsCXbml97tdqnJ0A\",\"$Hwf9cce64pn0EgrXWEuAgFRKlCw5NPKIxCkxrwyOrMw\"],\"room_id\":\"!MKvhXlSTLGJUXpYuWF:nixos.org\",\"sender\":\"@lassulus:nixos.dev\",\"signatures\":{\"lassul.us\":{\"ed25519:a_MvbO\":\"d0fWw/wLDVxlEUQsxCP/ecgchdlfsy0JpXqIhhBuiOccHg+OqYA8qRgZIAJWTcGvppj0tJlzOFNOIpY7IDfRBg\"},\"nixos.dev\":{\"ed25519:a_NQWV\":\"QRcTd1lrgb/xITfHoHTL1PdWb2J4fYz/qeHEA/FEig9rCJYY0qT9VyMz2C0AwNR+x03OXbviYqaP1vMoi/bHCg\"}},\"state_key\":\"@lassulus:lassul.us\",\"type\":\"m.room.member\"}" event_id="$_HgVf2QlLSWPB8OC49jFsGihPqb3o-Q7IV6Kz3ln9Pg"
panic: (*logrus.Entry) 0xc011f04070
goroutine 405 [running]:
github.com/sirupsen/logrus.(*Entry).log(0xc011f04000, 0x0, {0xc00b9140f0, 0x2e})
github.com/sirupsen/logrus@v1.9.0/entry.go:260 +0x4a7
github.com/sirupsen/logrus.(*Entry).Log(0xc011f04000, 0x0, {0xc011eda898?, 0xc011eda8f8?, 0x0?})
github.com/sirupsen/logrus@v1.9.0/entry.go:304 +0x4f
github.com/sirupsen/logrus.(*Entry).Panic(...)
github.com/sirupsen/logrus@v1.9.0/entry.go:342
github.com/MFAshby/stdemuxerhook.(*StdDemuxerHook).Fire(0x0?, 0xc006ac3f80)
github.com/MFAshby/stdemuxerhook@v1.0.0/stdemuxerhook.go:58 +0x19e
github.com/sirupsen/logrus.LevelHooks.Fire(0xc011eda9d8?, 0x11eda9a8?, 0x4?)
github.com/sirupsen/logrus@v1.9.0/hooks.go:28 +0x82
github.com/sirupsen/logrus.(*Entry).fireHooks(0xc006ac3f80)
github.com/sirupsen/logrus@v1.9.0/entry.go:280 +0x1dc
github.com/sirupsen/logrus.(*Entry).log(0xc006ac3f10, 0x0, {0xc00b9140c0, 0x2e})
github.com/sirupsen/logrus@v1.9.0/entry.go:242 +0x390
github.com/sirupsen/logrus.(*Entry).Log(0xc006ac3f10, 0x0, {0xc011edac98?, 0x0?, 0x0?})
github.com/sirupsen/logrus@v1.9.0/entry.go:304 +0x4f
github.com/sirupsen/logrus.(*Entry).Logf(0xc006ac3f10, 0x0, {0x187ec27?, 0x3?}, {0x0?, 0x0?, 0xc012d105c0?})
github.com/sirupsen/logrus@v1.9.0/entry.go:349 +0x85
github.com/sirupsen/logrus.(*Entry).Panicf(...)
github.com/sirupsen/logrus@v1.9.0/entry.go:387
github.com/matrix-org/dendrite/syncapi/consumers.(*OutputRoomEventConsumer).onNewRoomEvent(0xc0041e7b80, {0x1ad6ef0, 0xc0043b2720}, {0xc018f0b590, 0x1, {0xc00bd3f580, 0x1, 0x4}, {0xc016772000, 0xecf, ...}, ...})
github.com/matrix-org/dendrite/syncapi/consumers/roomserver.go:268 +0xd55
github.com/matrix-org/dendrite/syncapi/consumers.(*OutputRoomEventConsumer).onMessage(0xc0041e7b80, {0xc015bf9de0?, 0xc00f4139c0?}, {0xc012d1a4e8?, 0xc00f4139c0?, 0xc00fd97a60?})
github.com/matrix-org/dendrite/syncapi/consumers/roomserver.go:117 +0x3f8
github.com/matrix-org/dendrite/setup/jetstream.JetStreamConsumer.func2()
github.com/matrix-org/dendrite/setup/jetstream/helpers.go:91 +0x71e
created by github.com/matrix-org/dendrite/setup/jetstream.JetStreamConsumer
github.com/matrix-org/dendrite/setup/jetstream/helpers.go:43 +0x31e
```
Contributor guide
Research direction
Start in syncapi/consumers/roomserver.go around line 268, then trace the JetStream consumer through setup/jetstream/helpers.go around lines 43 and 91. Reproduce the reported panic with the PostgreSQL monolith setup and use the duplicate syncapi_memberships_unique error as the trigger. Done means the room event is handled without panicking or restarting the server.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- go, postgresql
- Domain
- backend, databases
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Mostly clear
- Newbie friendliness
- 25/100