mautrix-discord fails to relay messages with dendrite

[kushal-kumaran]

Background information

• Dendrite version or git SHA: 0.9.5
• Monolith or Polylith?: monolith
• SQLite3 or Postgres?: postgres 13.7
• Running in Docker?: yes, docker 20.10.5+dfsg1, kubernetes 1.23.6
• go version: as shipped in official docker images
• Client used (if applicable): Element/Linux 1.11.3 on debian

Description

• What is the problem: mautrix-discord appservice does not relay messages from discord
• Who is affected: Me, as the admin and only user on my homeserver
• How is this bug manifesting: dendrite logs say time="2022-09-07T04:57:01.446203771Z" level=error msg="Failed to join room" error="r.Queryer.QueryRestrictedJoinAllowed: helpers.IsInvitePending: missing NID for user \"@discord_200047045262704640:locationd.net\" (map[])" room_id="!Q3UXWb44A9A2bR7N:locationd.net" servers="[]" user_id="@discord_200047045262704640:locationd.net"
• When did this first appear: I've started using dendrite with 0.9.4, and mautrix-discord master as of commit 92c5407359e18500d3090cbca460781e86c88726 from August 20, 2022

Steps to reproduce

• install dendrite 0.9.5 (using docker image matrixdotorg/dendrite-monolith:v0.9.5)
• install mautrix-discord (using docker image dock.mau.dev/mautrix/discord:92c5407359e18500d3090cbca460781e86c88726-amd64)
• copy registration.yaml from mautrix-discord to dendrite data directory and add to app_service_api.config_files
• using Element client, start conversation with @discordbot:<domain>
• say login and scan QR code using discord mobile app to authenticate
• say login-matrix <access-token> to enable double-puppeting
• say guilds bridge <guild-id> to bridge a guild
• wait for rooms to be created as messages come in

At this point rooms should start showing messages as received from discord, but rooms stay empty.

Excerpts from dendrite logs (filtering to messages about specific proxy user mautrix-discord created):

time="2022-09-07T04:57:01.222367605Z" level=info msg="Processing registration request" auth.type="" req.id=xezhG0QOWHbp req.method=POST req.path=/_matrix/client/v3/register session_id="" username=discord_200047045262704640
time="2022-09-07T04:57:01.419596968Z" level=info msg="Uploading file" ContentType=image/png FileSizeBytes=23366 Origin=locationd.net UploadName="" req.id=zV24CZ5ea5vZ req.method=POST req.path=/_matrix/media/v3/upload user_id="@discord_200047045262704640:locationd.net"
time="2022-09-07T04:57:01.422008197Z" level=info msg="File uploaded" Base64Hash=MLJliBF86fp3nTdT5nAbhbmytemtdh4-ypwRNoNdHIA ContentType=image/png FileSizeBytes=23366 Origin=locationd.net UploadName="" media_id=c4c925a120e48a769711d7a480518434aca082f6059c7ba518dd77aa10626159 req.id=zV24CZ5ea5vZ req.method=POST req.path=/_matrix/media/v3/upload user_id="@discord_200047045262704640:locationd.net"
time="2022-09-07T04:57:01.430298458Z" level=info msg="Generated thumbnail" ActualHeight=32 ActualWidth=32 Height=32 Origin=locationd.net ResizeMethod=crop Width=32 media_id=c4c925a120e48a769711d7a480518434aca082f6059c7ba518dd77aa10626159 processTime=1.386355ms req.id=zV24CZ5ea5vZ req.method=POST req.path=/_matrix/media/v3/upload user_id="@discord_200047045262704640:locationd.net"
time="2022-09-07T04:57:01.432871760Z" level=info msg="Signalling other goroutines waiting for this goroutine to generate the thumbnail." Height=32 Origin=locationd.net ResizeMethod=crop Width=32 media_id=c4c925a120e48a769711d7a480518434aca082f6059c7ba518dd77aa10626159 req.id=zV24CZ5ea5vZ req.method=POST req.path=/_matrix/media/v3/upload user_id="@discord_200047045262704640:locationd.net"
time="2022-09-07T04:57:01.437245104Z" level=info msg="Generated thumbnail" ActualHeight=96 ActualWidth=96 Height=96 Origin=locationd.net ResizeMethod=crop Width=96 media_id=c4c925a120e48a769711d7a480518434aca082f6059c7ba518dd77aa10626159 processTime=3.416638ms req.id=zV24CZ5ea5vZ req.method=POST req.path=/_matrix/media/v3/upload user_id="@discord_200047045262704640:locationd.net"
time="2022-09-07T04:57:01.438568193Z" level=info msg="User requested to room join" room_id="!Q3UXWb44A9A2bR7N:locationd.net" servers="[]" user_id="@discord_200047045262704640:locationd.net"
time="2022-09-07T04:57:01.439663790Z" level=info msg="Signalling other goroutines waiting for this goroutine to generate the thumbnail." Height=96 Origin=locationd.net ResizeMethod=crop Width=96 media_id=c4c925a120e48a769711d7a480518434aca082f6059c7ba518dd77aa10626159 req.id=zV24CZ5ea5vZ req.method=POST req.path=/_matrix/media/v3/upload user_id="@discord_200047045262704640:locationd.net"
time="2022-09-07T04:57:01.446203771Z" level=error msg="Failed to join room" error="r.Queryer.QueryRestrictedJoinAllowed: helpers.IsInvitePending: missing NID for user \"@discord_200047045262704640:locationd.net\" (map[])" room_id="!Q3UXWb44A9A2bR7N:locationd.net" servers="[]" user_id="@discord_200047045262704640:locationd.net"

Excerpts from mautrix-discord logs:

�[0m[Sep  7, 2022 04:57:01] [Matrix/@discord_200047045262704640:locationd.net/DEBUG] req #155: POST https://matrix.locationd.net/_matrix/client/v3/register?user_id=%40discord_200047045262704640%3Alocationd.net {"username":"discord_200047045262704640","inhibit_login":true,"type":"m.login.application_service"}
�[0m[Sep  7, 2022 04:57:01] [Matrix/@discord_200047045262704640:locationd.net/DEBUG] req #155 (/v3/register) completed in 4.486375ms with status 200 and 85 bytes of application/json body
�[0m[Sep  7, 2022 04:57:01] [Matrix/@discord_200047045262704640:locationd.net/DEBUG] req #156: GET https://matrix.locationd.net/_matrix/client/v3/profile/@discord_200047045262704640:locationd.net/displayname?user_id=%40discord_200047045262704640%3Alocationd.net
�[0m[Sep  7, 2022 04:57:01] [Matrix/@discord_200047045262704640:locationd.net/DEBUG] req #156 (/v3/profile/@discord_200047045262704640:locationd.net/displayname) completed in 617.298µs with status 200 and 44 bytes of application/json body
�[0m[Sep  7, 2022 04:57:01] [Matrix/@discord_200047045262704640:locationd.net/DEBUG] req #157: PUT https://matrix.locationd.net/_matrix/client/v3/profile/@discord_200047045262704640:locationd.net/displayname?user_id=%40discord_200047045262704640%3Alocationd.net {"displayname":"rubix#7669"}
�[0m[Sep  7, 2022 04:57:01] [Matrix/@discord_200047045262704640:locationd.net/DEBUG] req #157 (/v3/profile/@discord_200047045262704640:locationd.net/displayname) completed in 2.109004ms with status 200 and 2 bytes of application/json body
�[0m[Sep  7, 2022 04:57:01] [Matrix/@discord_200047045262704640:locationd.net/DEBUG] req #158: POST https://matrix.locationd.net/_matrix/media/v3/upload?user_id=%40discord_200047045262704640%3Alocationd.net <23366 bytes>
�[0m[Sep  7, 2022 04:57:01] [Matrix/@discord_200047045262704640:locationd.net/DEBUG] req #158 (/_matrix/media/v3/upload) completed in 6.867654ms with status 200 and 102 bytes of application/json body
�[0m[Sep  7, 2022 04:57:01] [Matrix/@discord_200047045262704640:locationd.net/DEBUG] req #159: GET https://matrix.locationd.net/_matrix/client/v3/profile/@discord_200047045262704640:locationd.net/avatar_url?user_id=%40discord_200047045262704640%3Alocationd.net
�[0m[Sep  7, 2022 04:57:01] [Matrix/@discord_200047045262704640:locationd.net/DEBUG] req #159 (/v3/profile/@discord_200047045262704640:locationd.net/avatar_url) completed in 1.626063ms with status 200 and 17 bytes of application/json body
�[0m[Sep  7, 2022 04:57:01] [Matrix/@discord_200047045262704640:locationd.net/DEBUG] req #160: PUT https://matrix.locationd.net/_matrix/client/v3/profile/@discord_200047045262704640:locationd.net/avatar_url?user_id=%40discord_200047045262704640%3Alocationd.net {"avatar_url":"mxc://locationd.net/c4c925a120e48a769711d7a480518434aca082f6059c7ba518dd77aa10626159"}
�[0m[Sep  7, 2022 04:57:01] [Matrix/@discord_200047045262704640:locationd.net/DEBUG] req #160 (/v3/profile/@discord_200047045262704640:locationd.net/avatar_url) completed in 4.403364ms with status 200 and 2 bytes of application/json body
�[0m[Sep  7, 2022 04:57:01] [Matrix/@discord_200047045262704640:locationd.net/DEBUG] req #161: POST https://matrix.locationd.net/_matrix/client/v3/rooms/%21Q3UXWb44A9A2bR7N:locationd.net/join?user_id=%40discord_200047045262704640%3Alocationd.net <default empty object>
�[0m[Sep  7, 2022 04:57:01] [Matrix/@discord_200047045262704640:locationd.net/DEBUG] req #161 (/v3/rooms/!Q3UXWb44A9A2bR7N:locationd.net/join) completed in 10.833817ms with status 500 and 155 bytes of application/json body
�[33m[Sep  7, 2022 04:57:01] [Portal/397426163649216512/WARN] Failed to send message 1016935096227483731 to matrix: failed to ensure joined: failed to POST /_matrix/client/v3/rooms/!Q3UXWb44A9A2bR7N:locationd.net/join: 500 Internal Server Error�[0m

[S7evinK]

Can you update to latest main? The appservice component was refactored in Dendrite 0.9.6 and another fix was pushed to main later.

[kushal-kumaran]

Built dendrite-monolith for commit 7e8c605. It has exactly the same issue, and the log has the same error about missing NID for user

ADD: just to clarify, this test was a fresh install with the new build. I deleted the old data directory and databases and started over.

[kushal-kumaran]

Tested v0.9.7. The issue persists with this version.

[shalzz]

Hi, I'm seeing something similar with the latest dendrite 0.10.2 release:
I see this in my logs:

Oct 11 03:03:14 ip-172-31-45-176 matrix-dendrite[998369]: time="2022-10-11T03:03:14.247052907Z" level=info msg="Processing registration request" auth.type="" req.id=yMf38XiuJx6p req.method=POST req.path=/_matrix/client/v3/register session_id="" username=discord_347113414390448138
Oct 11 03:05:37 ip-172-31-45-176 matrix-dendrite[998369]: time="2022-10-11T03:05:37.769562351Z" level=info msg="User requested to room join" room_id="!4EGEqU36OlAbwxeE:jain.sh" servers="[]" user_id="@discord_900052690187460688:jain.sh"                                                                                   Oct 11 03:05:37 ip-172-31-45-176 matrix-dendrite[998369]: time="2022-10-11T03:05:37.791088488Z" level=error msg="Failed to join room" error="r.Queryer.QueryRes
trictedJoinAllowed: helpers.IsInvitePending: missing NID for user \"@discord_900052690187460688:jain.sh\" (map[])" room_id="!4EGEqU36OlAbwxeE:jain.sh" servers="[]" user_id="@discord_900052690187460688:jain.sh"                                                                                                             Oct 11 03:07:28 ip-172-31-45-176 matrix-dendrite[998369]: time="2022-10-11T03:07:28.432017404Z" level=info msg="Uploading file" ContentType=application/json Fi
leSizeBytes=173015 Origin=jain.sh UploadName="" req.id=qLsayoZtFI4z req.method=POST req.path=/_matrix/media/v3/upload user_id="@discord_347113414390448138:jain.sh"                                                                                                                                                           Oct 11 03:07:29 ip-172-31-45-176 matrix-dendrite[998369]: time="2022-10-11T03:07:29.515503139Z" level=info msg="File uploaded" Base64Hash=3ok6NaaalY17FuD80lMAG
8-rj56BvPhVkYG2O-GpCdg ContentType=application/json FileSizeBytes=173015 Origin=jain.sh UploadName="" media_id=f5d450e3d882f4595b504792e562c7f8a49b8039ab2567bff46a51ea442a2ccf req.id=qLsayoZtFI4z req.method=POST req.path=/_matrix/media/v3/upload user_id="@discord_347113414390448138:jain.sh"                           Oct 11 03:07:30 ip-172-31-45-176 matrix-dendrite[998369]: time="2022-10-11T03:07:30.359268170Z" level=info msg="User requested to room join" room_id="!4EGEqU36
OlAbwxeE:jain.sh" servers="[]" user_id="@discord_347113414390448138:jain.sh"                                                                                   Oct 11 03:07:30 ip-172-31-45-176 matrix-dendrite[998369]: time="2022-10-11T03:07:30.385981887Z" level=error msg="Failed to join room" error="r.Queryer.QueryRes
trictedJoinAllowed: helpers.IsInvitePending: missing NID for user \"@discord_347113414390448138:jain.sh\" (map[])" room_id="!4EGEqU36OlAbwxeE:jain.sh" servers="[]" user_id="@discord_347113414390448138:jain.sh"
Oct 11 03:08:43 ip-172-31-45-176 matrix-dendrite[998369]: time="2022-10-11T03:08:43.647279570Z" level=info msg="User requested to room join" room_id="!7jii0HR8jDv3cEU2:jain.sh" servers="[]" user_id="@hbirc_oftc_mes:jain.sh"                                                                                               Oct 11 03:08:43 ip-172-31-45-176 matrix-dendrite[998369]: time="2022-10-11T03:08:43.751714804Z" level=warning msg="Event $XjcvgQhC4QWhSQllonSD1MalOhYWlugTwJcDA

mautrix-discord log:

Oct 09 00:59:27 ip-172-31-45-176 matrix-mautrix-discord\[1000124\]: \[Oct  9, 2022 00:59:27\] \[Portal/839990363258486805/WARN\] Unhandled message 1028471704411983892                                                                                                                                                              Oct 09 00:59:54 ip-172-31-45-176 matrix-mautrix-discord\[1000124\]: \[Oct  9, 2022 00:59:54\] \[Portal/839990363258486805/WARN\] Failed to send message 1028471836624818206 to matrix: failed to ensure joined: failed to POST /\_matrix/client/v3/rooms/!4EGEqU36OlAbwxeE:jain.sh/join: 500 Internal Server Error                   Oct 09 01:00:09 ip-172-31-45-176 matrix-mautrix-discord\[1000124\]: \[Oct  9, 2022 01:00:09\] \[Portal/839990363258486805/WARN\] Failed to send sticker to Matrix: failed to ensure joined: failed to POST /\_matrix/client/v3/rooms/!4EGEqU36OlAbwxeE:jain.sh/join: 500 Internal Server Error                                       Oct 09 01:00:09 ip-172-31-45-176 matrix-mautrix-discord\[1000124\]: \[Oct  9, 2022 01:00:09\] \[Portal/839990363258486805/WARN\] Unhandled message 1028471882225287238                                                                                                                                                              Oct 09 01:47:54 ip-172-31-45-176 matrix-mautrix-discord\[1000124\]: \[Oct  9, 2022 01:47:54\] \[Portal/801060727267655680/WARN\] Failed to send message 1028483901313786006 to matrix: failed to ensure joined: failed to POST /\_matrix/client/v3/rooms/!NwyUucUD5ZsTAima:jain.sh/join: 500 Internal Server Error                   Oct 09 02:53:36 ip-172-31-45-176 matrix-mautrix-discord\[1000124\]: \[Oct  9, 2022 02:53:36\] \[Portal/796423309280935976/WARN\] Can't create Matrix room from non new message event                                                                                                                                                Oct 09 03:23:38 ip-172-31-45-176 matrix-mautrix-discord\[1000124\]: \[Oct  9, 2022 03:23:38\] \[Portal/846466121888170004/WARN\] Failed to send message 1028507990803882055 to matrix: failed to ensure joined: failed to POST /\_matrix/client/v3/rooms/!Sk8EJ5BXjottRtbb:jain.sh/join: 500 Internal Server Error
Oct 09 03:25:43 ip-172-31-45-176 matrix-mautrix-discord\[1000124\]: \[Oct  9, 2022 03:25:43\] \[Portal/846466121888170004/WARN\] Failed to send message 1028508533702017134 to matrix: failed to ensure joined: failed to POST /\_matrix/client/v3/rooms/!Sk8EJ5BXjottRtbb:jain.sh/join: 500 Internal Server Error
Oct 09 03:46:21 ip-172-31-45-176 matrix-mautrix-discord\[1000124\]: \[Oct  9, 2022 03:46:21\] \[Portal/846466121888170004/WARN\] Failed to send message 1028513728167153664 to matrix: failed to ensure joined: failed to POST /\_matrix/client/v3/rooms/!Sk8EJ5BXjottRtbb:jain.sh/join: 500 Internal Server Error
Oct 09 04:27:35 ip-172-31-45-176 matrix-mautrix-discord\[1000124\]: \[Oct  9, 2022 04:27:35\] \[Portal/839990363258486805/WARN\] Failed to send message 1028524100920025108 to matrix: failed to ensure joined: failed to POST /\_matrix/client/v3/rooms/!4EGEqU36OlAbwxeE:jain.sh/join: 500 Internal Server Error

[Salastil]

\[Nov 11, 2022 02:09:30\] \[Portal/244509187063808000/WARN\] Failed to send message 1040448152437784657 to matrix: failed to ensure joined: failed to POST /\_matrix/client/v3/rooms/!Zhblablahblah:matrix.salastil.com/join: 500 Internal Server Error

I can confirm this bug is still extant in 0.10.7 and renders the bridge largely useless. A curious quirk I've noticed is that a Discord bot has managed to join one of the rooms and is acting as expected in the room which indicates that the bridge is functional and transmitting data back and forth, I can talk using Dendrite and it will show in Discord and if I talk on Discord I see my Discord account talking in the Dendrite. Its just external users are not permitted to join.

[S7evinK]

This should now be fixed on main. If it is still happening, feel free to reopen.

[squidink7]

This is still happening for me on 0.13.6+d5f4d75 2024-02-03T20:47:17+10:30 ERR Failed to send part of message to Matrix error="failed to ensure joined: failed to POST /_matrix/client/v3/rooms/!h0vO9YrfzDbUUEUO:matrix.fryer.net.au/join: HTTP 500" action="discord message create" attachment_id= author_id=1148068739380695181 channel_id=1203276285330071575 channel_receiver= message_id=1203283061295292457 message_type=0 part_index=0 room_id=!h0vO9YrfzDbUUEUO:matrix.fryer.net.au