matrix-org / matrix-appservice-irc

Node.js IRC bridge for Matrix
Apache License 2.0
465 stars 150 forks source link

Bridge is unable to accept DM invites #1270

Open jkhsjdhjs opened 3 years ago

jkhsjdhjs commented 3 years ago

Describe the bug When inviting the IRC bridge to a DM it attempts to accept the invitation, but is unable to because of a 404 - Profile was not found error. I'm not sure whether this is actually a bug of this bridge of a bug/misconfiguration of my synapse instance, so I asked on #synapse:matrix.org first. However, no one was able to help me there and since the configuration of my synapse instance is mostly vanilla, I decided to create an issue here.

To Reproduce Steps to reproduce the behavior:

  1. Invite the IRC Bridge to a DM room

Expected behavior The bridge joins the room.

Log

Mar 17 06:14:16 synapse node[16387]: 2021-03-17 06:14:16 INFO:IrcBridge 192.168.0.6 - - [17/Mar/2021:06:14:16 +0000] "PUT /transactions/1532?access_token=<REDACTED> HTTP/1.1" 200 2 "-" "Synapse/1.28.0"
Mar 17 06:14:16 synapse node[16387]: 2021-03-17 06:14:16 INFO:req [2kwddvzbq2i00] [[M->I]] onInvite: from=@jkhsjdhjs:matrix.org to=@irc:example.com rm=!zPtGChNuntQMiqhJoG:matrix.org id=$KC9gvEiIX5t3cLRyCE8j7O9CnQQ-2kNOzALd_07Adeo
Mar 17 06:14:16 synapse node[16387]: 2021-03-17 06:14:16 INFO:req [2kwddvzbq2i00] [[M->I]] Handling invite from @jkhsjdhjs:matrix.org directed to bot.
Mar 17 06:14:16 synapse node[16387]: Mar-17 06:14:16.040 DEBUG MembershipQueue [2kwddvzbq2i00] @irc:example.com@!zPtGChNuntQMiqhJoG:matrix.org -> join (reason: none, kicker: undefined)
Mar 17 06:14:16 synapse node[16387]: Mar-17 06:14:16.040 DEBUG Intent Checking if user @irc:example.com is registered
Mar 17 06:14:16 synapse node[16387]: Mar-17 06:14:16.040 DEBUG Intent ensureRegistered: Registered, and not encrypted
Mar 17 06:14:16 synapse node[16387]: 2021-03-17 06:14:16 INFO:IrcBridge [-] POST http://192.168.0.6:8008/_matrix/client/r0/join/!zPtGChNuntQMiqhJoG%3Amatrix.org (AS) Body: "{}"
Mar 17 06:14:16 synapse node[16387]: 2021-03-17 06:14:16 ERROR:IrcBridge [-] POST http://192.168.0.6:8008/_matrix/client/r0/join/!zPtGChNuntQMiqhJoG%3Amatrix.org (AS) HTTP 404 Error: "{\"errcode\":\"M_NOT_FOUND\",\"error\":\"Profile was not found\"}"
Mar 17 06:14:16 synapse node[16387]: Mar-17 06:14:16.050 WARN MembershipQueue [2kwddvzbq2i00] Failed to join !zPtGChNuntQMiqhJoG:matrix.org, delaying for 61.90264450694605ms
Mar 17 06:14:16 synapse node[16387]: Mar-17 06:14:16.050 DEBUG MembershipQueue [2kwddvzbq2i00] Failed with: undefined Failed to join room
Mar 17 06:14:16 synapse node[16387]: Mar-17 06:14:16.125 DEBUG MembershipQueue [2kwddvzbq2i00] @irc:example.com@!zPtGChNuntQMiqhJoG:matrix.org -> join (reason: none, kicker: undefined)
Mar 17 06:14:16 synapse node[16387]: Mar-17 06:14:16.125 DEBUG Intent Checking if user @irc:example.com is registered
Mar 17 06:14:16 synapse node[16387]: Mar-17 06:14:16.126 DEBUG Intent ensureRegistered: Registered, and not encrypted
Mar 17 06:14:16 synapse node[16387]: 2021-03-17 06:14:16 INFO:IrcBridge [-] POST http://192.168.0.6:8008/_matrix/client/r0/join/!zPtGChNuntQMiqhJoG%3Amatrix.org (AS) Body: "{}"
Mar 17 06:14:16 synapse node[16387]: Mar-17 06:14:16.127 DEBUG Intent Checking if user @irc:example.com is registered
Mar 17 06:14:16 synapse node[16387]: Mar-17 06:14:16.127 DEBUG Intent ensureRegistered: Registered, and not encrypted
Mar 17 06:14:16 synapse node[16387]: 2021-03-17 06:14:16 INFO:IrcBridge [-] POST http://192.168.0.6:8008/_matrix/client/r0/join/!zPtGChNuntQMiqhJoG%3Amatrix.org (AS) Body: "{}"
Mar 17 06:14:16 synapse node[16387]: 2021-03-17 06:14:16 ERROR:IrcBridge [-] POST http://192.168.0.6:8008/_matrix/client/r0/join/!zPtGChNuntQMiqhJoG%3Amatrix.org (AS) HTTP 404 Error: "{\"errcode\":\"M_NOT_FOUND\",\"error\":\"Profile was not found\"}"
Mar 17 06:14:16 synapse node[16387]: Mar-17 06:14:16.134 WARN MembershipQueue [2kwddvzbq2i00] Failed to join !zPtGChNuntQMiqhJoG:matrix.org, delaying for 500ms
Mar 17 06:14:16 synapse node[16387]: Mar-17 06:14:16.134 DEBUG MembershipQueue [2kwddvzbq2i00] Failed with: undefined Failed to join room
Mar 17 06:14:16 synapse node[16387]: 2021-03-17 06:14:16 ERROR:IrcBridge [-] POST http://192.168.0.6:8008/_matrix/client/r0/join/!zPtGChNuntQMiqhJoG%3Amatrix.org (AS) HTTP 404 Error: "{\"errcode\":\"M_NOT_FOUND\",\"error\":\"Profile was not found\"}"
Mar 17 06:14:16 synapse node[16387]: 2021-03-17 06:14:16 INFO:IrcBridge [2kwddvzbq2i00] [M->I] FAILED  (106ms)
Mar 17 06:14:16 synapse node[16387]: 2021-03-17 06:14:16 ERROR:main TypeError: Cannot read property 'error' of undefined
Mar 17 06:14:16 synapse node[16387]:     at MatrixHandler.handleAdminRoomInvite (/opt/matrix-appservice-irc/lib/bridge/MatrixHandler.js:69:93)
Mar 17 06:14:16 synapse node[16387]:     at processTicksAndRejections (node:internal/process/task_queues:94:5)
Mar 17 06:14:16 synapse node[16387]:     at async MatrixHandler._onInvite (/opt/matrix-appservice-irc/lib/bridge/MatrixHandler.js:296:17)
Mar 17 06:14:16 synapse node[16387]:     at async reqHandler (/opt/matrix-appservice-irc/lib/bridge/MatrixHandler.js:14:21)
Mar 17 06:14:16 synapse node[16387]:     at async IrcBridge._onEvent (/opt/matrix-appservice-irc/lib/bridge/IrcBridge.js:757:17)
Mar 17 06:14:16 synapse node[16387]: 2021-03-17 06:14:16 ERROR:main TypeError: Cannot read property 'error' of undefined
Mar 17 06:14:16 synapse node[16387]:     at MatrixHandler.handleAdminRoomInvite (/opt/matrix-appservice-irc/lib/bridge/MatrixHandler.js:69:93)
Mar 17 06:14:16 synapse node[16387]:     at processTicksAndRejections (node:internal/process/task_queues:94:5)
Mar 17 06:14:16 synapse node[16387]:     at async MatrixHandler._onInvite (/opt/matrix-appservice-irc/lib/bridge/MatrixHandler.js:296:17)
Mar 17 06:14:16 synapse node[16387]:     at async reqHandler (/opt/matrix-appservice-irc/lib/bridge/MatrixHandler.js:14:21)
Mar 17 06:14:16 synapse node[16387]:     at async IrcBridge._onEvent (/opt/matrix-appservice-irc/lib/bridge/IrcBridge.js:757:17)
Mar 17 06:14:16 synapse node[16387]: Mar-17 06:14:16.637 DEBUG MembershipQueue [2kwddvzbq2i00] @irc:example.com@!zPtGChNuntQMiqhJoG:matrix.org -> join (reason: none, kicker: undefined)
Mar 17 06:14:16 synapse node[16387]: Mar-17 06:14:16.637 DEBUG Intent Checking if user @irc:example.com is registered
Mar 17 06:14:16 synapse node[16387]: Mar-17 06:14:16.637 DEBUG Intent ensureRegistered: Registered, and not encrypted
Mar 17 06:14:16 synapse node[16387]: 2021-03-17 06:14:16 INFO:IrcBridge [-] POST http://192.168.0.6:8008/_matrix/client/r0/join/!zPtGChNuntQMiqhJoG%3Amatrix.org (AS) Body: "{}"
Mar 17 06:14:16 synapse node[16387]: 2021-03-17 06:14:16 ERROR:IrcBridge [-] POST http://192.168.0.6:8008/_matrix/client/r0/join/!zPtGChNuntQMiqhJoG%3Amatrix.org (AS) HTTP 404 Error: "{\"errcode\":\"M_NOT_FOUND\",\"error\":\"Profile was not found\"}"
Mar 17 06:14:16 synapse node[16387]: Mar-17 06:14:16.645 WARN MembershipQueue [2kwddvzbq2i00] Failed to join !zPtGChNuntQMiqhJoG:matrix.org, delaying for 500ms
Mar 17 06:14:16 synapse node[16387]: Mar-17 06:14:16.645 DEBUG MembershipQueue [2kwddvzbq2i00] Failed with: undefined Failed to join room
Mar 17 06:14:17 synapse node[16387]: Mar-17 06:14:17.145 DEBUG MembershipQueue [2kwddvzbq2i00] @irc:example.com@!zPtGChNuntQMiqhJoG:matrix.org -> join (reason: none, kicker: undefined)
Mar 17 06:14:17 synapse node[16387]: Mar-17 06:14:17.146 DEBUG Intent Checking if user @irc:example.com is registered
Mar 17 06:14:17 synapse node[16387]: Mar-17 06:14:17.146 DEBUG Intent ensureRegistered: Registered, and not encrypted
Mar 17 06:14:17 synapse node[16387]: 2021-03-17 06:14:17 INFO:IrcBridge [-] POST http://192.168.0.6:8008/_matrix/client/r0/join/!zPtGChNuntQMiqhJoG%3Amatrix.org (AS) Body: "{}"
Mar 17 06:14:17 synapse node[16387]: 2021-03-17 06:14:17 ERROR:IrcBridge [-] POST http://192.168.0.6:8008/_matrix/client/r0/join/!zPtGChNuntQMiqhJoG%3Amatrix.org (AS) HTTP 404 Error: "{\"errcode\":\"M_NOT_FOUND\",\"error\":\"Profile was not found\"}"
Mar 17 06:14:17 synapse node[16387]: Mar-17 06:14:17.153 WARN MembershipQueue [2kwddvzbq2i00] Failed to join !zPtGChNuntQMiqhJoG:matrix.org, delaying for 500ms
Mar 17 06:14:17 synapse node[16387]: Mar-17 06:14:17.154 DEBUG MembershipQueue [2kwddvzbq2i00] Failed with: undefined Failed to join room
Mar 17 06:14:17 synapse node[16387]: Mar-17 06:14:17.657 DEBUG MembershipQueue [2kwddvzbq2i00] @irc:example.com@!zPtGChNuntQMiqhJoG:matrix.org -> join (reason: none, kicker: undefined)
Mar 17 06:14:17 synapse node[16387]: Mar-17 06:14:17.657 DEBUG Intent Checking if user @irc:example.com is registered
Mar 17 06:14:17 synapse node[16387]: Mar-17 06:14:17.657 DEBUG Intent ensureRegistered: Registered, and not encrypted
Mar 17 06:14:17 synapse node[16387]: 2021-03-17 06:14:17 INFO:IrcBridge [-] POST http://192.168.0.6:8008/_matrix/client/r0/join/!zPtGChNuntQMiqhJoG%3Amatrix.org (AS) Body: "{}"
Mar 17 06:14:17 synapse node[16387]: 2021-03-17 06:14:17 ERROR:IrcBridge [-] POST http://192.168.0.6:8008/_matrix/client/r0/join/!zPtGChNuntQMiqhJoG%3Amatrix.org (AS) HTTP 404 Error: "{\"errcode\":\"M_NOT_FOUND\",\"error\":\"Profile was not found\"}"
Mar 17 06:14:17 synapse node[16387]: Mar-17 06:14:17.664 WARN MembershipQueue [2kwddvzbq2i00] Failed to join !zPtGChNuntQMiqhJoG:matrix.org, delaying for 500ms
Mar 17 06:14:17 synapse node[16387]: Mar-17 06:14:17.664 DEBUG MembershipQueue [2kwddvzbq2i00] Failed with: undefined Failed to join room

Desktop (please complete the following information):

Rodrigo-Barros commented 3 years ago

I don't know if helps but you can try run npm test inside bridge folder just to you gather more info about the problem you are facing, maybe this way some developers can help you better.

mweinelt commented 3 years ago

Trying to invite the appservice, this is whats happening for us.

May 27 02:37:11 matrix synapse[3908]: synapse.access.http.8008: [GET-0] 2001:67c:2ed8::666:1 - 8008 - {lossy.network} Processed request: 0.022sec/-0.000sec (0.006sec, 0.001sec) (0.002sec/0.012sec/4) 111B 200 "GET /_matrix/federation/v1/user/devices/%40appservice-irc%3Ahackint.org HTTP/1.0" "Synapse/1.34.0" [0 dbevts]
May 27 02:37:12 matrix synapse[3908]: synapse.http.server: [GET-1] <XForwardedForRequest at 0x7f47741b3b50 method='GET' uri='/_matrix/federation/v1/query/profile?user_id=%40appservice-irc%3Ahackint.org&field=displayname' clientproto='HTTP/1.0' site='8008'> SynapseError: 404 - Profile was not found
May 27 02:37:12 matrix synapse[3908]: synapse.access.http.8008: [GET-1] 2001:67c:2ed8::666:1 - 8008 - {lossy.network} Processed request: 0.011sec/-0.000sec (0.002sec, 0.002sec) (0.000sec/0.005sec/1) 57B 404 "GET /_matrix/federation/v1/query/profile?user_id=%40appservice-irc%3Ahackint.org&field=displayname HTTP/1.0" "Synapse/1.34.0" [0 dbevts]
May 27 02:37:12 matrix synapse[3908]: synapse.access.http.8008: [PUT-2] 2001:67c:2ed8::666:1 - 8008 - {lossy.network} Processed request: 0.090sec/-0.000sec (0.009sec, 0.001sec) (0.002sec/0.017sec/5) 1237B 200 "PUT /_matrix/federation/v2/invite/%21PZwRnxCHGkegUXtiUP%3Alossy.network/%24p8xCQtktawjLI24AKSlrq0VEuMjWwI9WF4Uu07o9jaM HTTP/1.0" "Synapse/1.34.0" [0 dbevts]
May 27 02:37:12 matrix synapse[3908]: synapse.appservice.scheduler: [as_scheduler-0] Starting appservice scheduler
May 27 02:37:12 matrix matrix-appservice-irc[3817]: 2021-05-27 02:37:12 INFO:IrcBridge 127.0.0.1 - - [27/May/2021:00:37:12 +0000] "PUT /transactions/219?access_token=<REDACTED> HTTP/1.1" 200 2 "-" "Synapse/1.34.0"
May 27 02:37:12 matrix matrix-appservice-irc[3817]: 2021-05-27 02:37:12 INFO:req [3xw9sgrrguu00] [[M->I]] onInvite: from=@hexa:lossy.network to=@appservice-irc:hackint.org rm=!PZwRnxCHGkegUXtiUP:lossy.network id=$p8xCQtktawjLI24AKSlrq0VEuMjWwI9WF4Uu07o9jaM
May 27 02:37:12 matrix matrix-appservice-irc[3817]: 2021-05-27 02:37:12 INFO:req [3xw9sgrrguu00] [[M->I]] Handling invite from @hexa:lossy.network directed to bot.
May 27 02:37:12 matrix matrix-appservice-irc[3817]: May-27 02:37:12.598 DEBUG MembershipQueue [3xw9sgrrguu00] @appservice-irc:hackint.org@!PZwRnxCHGkegUXtiUP:lossy.network -> join (reason: none, kicker: undefined)
May 27 02:37:12 matrix matrix-appservice-irc[3817]: May-27 02:37:12.598 DEBUG Intent Checking if user @appservice-irc:hackint.org is registered
May 27 02:37:12 matrix matrix-appservice-irc[3817]: May-27 02:37:12.599 DEBUG Intent ensureRegistered: Registered, and not encrypted
May 27 02:37:12 matrix matrix-appservice-irc[3817]: 2021-05-27 02:37:12 INFO:IrcBridge [-] POST https://matrix.hackint.org/_matrix/client/r0/join/!PZwRnxCHGkegUXtiUP%3Alossy.network (AS) Body: "{}"
May 27 02:37:12 matrix synapse[3908]: synapse.http.client: [as-sender-df621695152f1092fb1a7309a14676fe86c49a3ebc0cd50ee2b526accf53f09a-0] Received response to PUT http://127.0.0.1:8009/transactions/219?access_token=<redacted>: 200
May 27 02:37:12 matrix synapse[3908]: synapse.http.server: [POST-3] <XForwardedForRequest at 0x7f4774211a90 method='POST' uri='/_matrix/client/r0/join/!PZwRnxCHGkegUXtiUP%3Alossy.network?access_token=<redacted>' clientproto='HTTP/1.0' site='8008'> SynapseError: 404 - Profile was not found
May 27 02:37:12 matrix synapse[3908]: synapse.access.http.8008: [POST-3] 127.0.0.1 - 8008 - {@appservice-irc:hackint.org} Processed request: 0.019sec/-0.000sec (0.003sec, 0.002sec) (0.003sec/0.009sec/4) 57B 404 "POST /_matrix/client/r0/join/!PZwRnxCHGkegUXtiUP%3Alossy.network?access_token=<redacted> HTTP/1.0" "-" [0 dbevts]
May 27 02:37:12 matrix matrix-appservice-irc[3817]: 2021-05-27 02:37:12 ERROR:IrcBridge [-] POST https://matrix.hackint.org/_matrix/client/r0/join/!PZwRnxCHGkegUXtiUP%3Alossy.network (AS) HTTP 404 Error: "{\"errcode\":\"M_NOT_FOUND\",\"error\":\"Profile was not found\"}"
May 27 02:37:12 matrix matrix-appservice-irc[3817]: May-27 02:37:12.636 WARN MembershipQueue [3xw9sgrrguu00] Failed to join !PZwRnxCHGkegUXtiUP:lossy.network, delaying for 49.979099480444766ms
May 27 02:37:12 matrix matrix-appservice-irc[3817]: May-27 02:37:12.636 DEBUG MembershipQueue [3xw9sgrrguu00] Failed with: undefined Failed to join room
May 27 02:37:12 matrix matrix-appservice-irc[3817]: May-27 02:37:12.685 DEBUG MembershipQueue [3xw9sgrrguu00] @appservice-irc:hackint.org@!PZwRnxCHGkegUXtiUP:lossy.network -> join (reason: none, kicker: undefined)
May 27 02:37:12 matrix matrix-appservice-irc[3817]: May-27 02:37:12.688 DEBUG Intent Checking if user @appservice-irc:hackint.org is registered
May 27 02:37:12 matrix matrix-appservice-irc[3817]: May-27 02:37:12.688 DEBUG Intent ensureRegistered: Registered, and not encrypted
May 27 02:37:12 matrix matrix-appservice-irc[3817]: 2021-05-27 02:37:12 INFO:IrcBridge [-] POST https://matrix.hackint.org/_matrix/client/r0/join/!PZwRnxCHGkegUXtiUP%3Alossy.network (AS) Body: "{}"
May 27 02:37:12 matrix matrix-appservice-irc[3817]: May-27 02:37:12.689 DEBUG Intent Checking if user @appservice-irc:hackint.org is registered
May 27 02:37:12 matrix matrix-appservice-irc[3817]: May-27 02:37:12.689 DEBUG Intent ensureRegistered: Registered, and not encrypted
May 27 02:37:12 matrix matrix-appservice-irc[3817]: 2021-05-27 02:37:12 INFO:IrcBridge [-] POST https://matrix.hackint.org/_matrix/client/r0/join/!PZwRnxCHGkegUXtiUP%3Alossy.network (AS) Body: "{}"
May 27 02:37:12 matrix synapse[3908]: synapse.http.server: [POST-4] <XForwardedForRequest at 0x7f477122fbe0 method='POST' uri='/_matrix/client/r0/join/!PZwRnxCHGkegUXtiUP%3Alossy.network?access_token=<redacted>' clientproto='HTTP/1.0' site='8008'> SynapseError: 404 - Profile was not found
May 27 02:37:12 matrix synapse[3908]: synapse.access.http.8008: [POST-4] 127.0.0.1 - 8008 - {@appservice-irc:hackint.org} Processed request: 0.007sec/-0.000sec (0.003sec, 0.000sec) (0.001sec/0.003sec/2) 57B 404 "POST /_matrix/client/r0/join/!PZwRnxCHGkegUXtiUP%3Alossy.network?access_token=<redacted> HTTP/1.0" "-" [0 dbevts]
May 27 02:37:12 matrix matrix-appservice-irc[3817]: 2021-05-27 02:37:12 ERROR:IrcBridge [-] POST https://matrix.hackint.org/_matrix/client/r0/join/!PZwRnxCHGkegUXtiUP%3Alossy.network (AS) HTTP 404 Error: "{\"errcode\":\"M_NOT_FOUND\",\"error\":\"Profile was not found\"}"
May 27 02:37:12 matrix matrix-appservice-irc[3817]: May-27 02:37:12.725 WARN MembershipQueue [3xw9sgrrguu00] Failed to join !PZwRnxCHGkegUXtiUP:lossy.network, delaying for 500ms
May 27 02:37:12 matrix matrix-appservice-irc[3817]: May-27 02:37:12.725 DEBUG MembershipQueue [3xw9sgrrguu00] Failed with: undefined Failed to join room
May 27 02:37:12 matrix synapse[3908]: synapse.http.server: [POST-5] <XForwardedForRequest at 0x7f4771258dc0 method='POST' uri='/_matrix/client/r0/join/!PZwRnxCHGkegUXtiUP%3Alossy.network?access_token=<redacted>' clientproto='HTTP/1.0' site='8008'> SynapseError: 404 - Profile was not found
May 27 02:37:12 matrix synapse[3908]: synapse.access.http.8008: [POST-5] 127.0.0.1 - 8008 - {@appservice-irc:hackint.org} Processed request: 0.009sec/-0.000sec (0.002sec, 0.001sec) (0.001sec/0.004sec/2) 57B 404 "POST /_matrix/client/r0/join/!PZwRnxCHGkegUXtiUP%3Alossy.network?access_token=<redacted> HTTP/1.0" "-" [0 dbevts]
May 27 02:37:12 matrix matrix-appservice-irc[3817]: 2021-05-27 02:37:12 ERROR:IrcBridge [-] POST https://matrix.hackint.org/_matrix/client/r0/join/!PZwRnxCHGkegUXtiUP%3Alossy.network (AS) HTTP 404 Error: "{\"errcode\":\"M_NOT_FOUND\",\"error\":\"Profile was not found\"}"
May 27 02:37:12 matrix matrix-appservice-irc[3817]: 2021-05-27 02:37:12 DEBUG:req [3xw9sgrrguu00] [[M->I]] Not a plumbed room: Error retrieving m.room.plumbing
May 27 02:37:12 matrix matrix-appservice-irc[3817]: 2021-05-27 02:37:12 INFO:NeDBDataStore storeAdminRoom (id=!PZwRnxCHGkegUXtiUP:lossy.network, user_id=@hexa:lossy.network)
May 27 02:37:12 matrix matrix-appservice-irc[3817]: 2021-05-27 02:37:12 INFO:IrcBridge [3xw9sgrrguu00] [M->I] SUCCESS  (144ms)
May 27 02:37:13 matrix matrix-appservice-irc[3817]: May-27 02:37:13.225 DEBUG MembershipQueue [3xw9sgrrguu00] @appservice-irc:hackint.org@!PZwRnxCHGkegUXtiUP:lossy.network -> join (reason: none, kicker: undefined)
May 27 02:37:13 matrix matrix-appservice-irc[3817]: May-27 02:37:13.226 DEBUG Intent Checking if user @appservice-irc:hackint.org is registered
May 27 02:37:13 matrix matrix-appservice-irc[3817]: May-27 02:37:13.227 DEBUG Intent ensureRegistered: Registered, and not encrypted
May 27 02:37:13 matrix matrix-appservice-irc[3817]: 2021-05-27 02:37:13 INFO:IrcBridge [-] POST https://matrix.hackint.org/_matrix/client/r0/join/!PZwRnxCHGkegUXtiUP%3Alossy.network (AS) Body: "{}"
May 27 02:37:13 matrix synapse[3908]: synapse.http.server: [POST-6] <XForwardedForRequest at 0x7f4771258ee0 method='POST' uri='/_matrix/client/r0/join/!PZwRnxCHGkegUXtiUP%3Alossy.network?access_token=<redacted>' clientproto='HTTP/1.0' site='8008'> SynapseError: 404 - Profile was not found
May 27 02:37:13 matrix synapse[3908]: synapse.access.http.8008: [POST-6] 127.0.0.1 - 8008 - {@appservice-irc:hackint.org} Processed request: 0.014sec/-0.000sec (0.003sec, 0.000sec) (0.001sec/0.008sec/2) 57B 404 "POST /_matrix/client/r0/join/!PZwRnxCHGkegUXtiUP%3Alossy.network?access_token=<redacted> HTTP/1.0" "-" [0 dbevts]
May 27 02:37:13 matrix matrix-appservice-irc[3817]: 2021-05-27 02:37:13 ERROR:IrcBridge [-] POST https://matrix.hackint.org/_matrix/client/r0/join/!PZwRnxCHGkegUXtiUP%3Alossy.network (AS) HTTP 404 Error: "{\"errcode\":\"M_NOT_FOUND\",\"error\":\"Profile was not found\"}"
May 27 02:37:13 matrix matrix-appservice-irc[3817]: May-27 02:37:13.252 WARN MembershipQueue [3xw9sgrrguu00] Failed to join !PZwRnxCHGkegUXtiUP:lossy.network, delaying for 500ms
May 27 02:37:13 matrix matrix-appservice-irc[3817]: May-27 02:37:13.252 DEBUG MembershipQueue [3xw9sgrrguu00] Failed with: undefined Failed to join room
May 27 02:37:13 matrix matrix-appservice-irc[3817]: May-27 02:37:13.753 DEBUG MembershipQueue [3xw9sgrrguu00] @appservice-irc:hackint.org@!PZwRnxCHGkegUXtiUP:lossy.network -> join (reason: none, kicker: undefined)
May 27 02:37:13 matrix matrix-appservice-irc[3817]: May-27 02:37:13.753 DEBUG Intent Checking if user @appservice-irc:hackint.org is registered
May 27 02:37:13 matrix matrix-appservice-irc[3817]: May-27 02:37:13.753 DEBUG Intent ensureRegistered: Registered, and not encrypted
May 27 02:37:13 matrix matrix-appservice-irc[3817]: 2021-05-27 02:37:13 INFO:IrcBridge [-] POST https://matrix.hackint.org/_matrix/client/r0/join/!PZwRnxCHGkegUXtiUP%3Alossy.network (AS) Body: "{}"
May 27 02:37:13 matrix synapse[3908]: synapse.http.server: [POST-7] <XForwardedForRequest at 0x7f477124dca0 method='POST' uri='/_matrix/client/r0/join/!PZwRnxCHGkegUXtiUP%3Alossy.network?access_token=<redacted>' clientproto='HTTP/1.0' site='8008'> SynapseError: 404 - Profile was not found
May 27 02:37:13 matrix synapse[3908]: synapse.access.http.8008: [POST-7] 127.0.0.1 - 8008 - {@appservice-irc:hackint.org} Processed request: 0.008sec/-0.000sec (0.003sec, 0.001sec) (0.001sec/0.003sec/2) 57B 404 "POST /_matrix/client/r0/join/!PZwRnxCHGkegUXtiUP%3Alossy.network?access_token=<redacted> HTTP/1.0" "-" [0 dbevts]
May 27 02:37:13 matrix matrix-appservice-irc[3817]: 2021-05-27 02:37:13 ERROR:IrcBridge [-] POST https://matrix.hackint.org/_matrix/client/r0/join/!PZwRnxCHGkegUXtiUP%3Alossy.network (AS) HTTP 404 Error: "{\"errcode\":\"M_NOT_FOUND\",\"error\":\"Profile was not found\"}"
May 27 02:37:13 matrix matrix-appservice-irc[3817]: May-27 02:37:13.772 WARN MembershipQueue [3xw9sgrrguu00] Failed to join !PZwRnxCHGkegUXtiUP:lossy.network, delaying for 500ms
May 27 02:37:13 matrix matrix-appservice-irc[3817]: May-27 02:37:13.772 DEBUG MembershipQueue [3xw9sgrrguu00] Failed with: undefined Failed to join room
May 27 02:37:14 matrix matrix-appservice-irc[3817]: May-27 02:37:14.273 DEBUG MembershipQueue [3xw9sgrrguu00] @appservice-irc:hackint.org@!PZwRnxCHGkegUXtiUP:lossy.network -> join (reason: none, kicker: undefined)
May 27 02:37:14 matrix matrix-appservice-irc[3817]: May-27 02:37:14.274 DEBUG Intent Checking if user @appservice-irc:hackint.org is registered
May 27 02:37:14 matrix matrix-appservice-irc[3817]: May-27 02:37:14.274 DEBUG Intent ensureRegistered: Registered, and not encrypted
May 27 02:37:14 matrix matrix-appservice-irc[3817]: 2021-05-27 02:37:14 INFO:IrcBridge [-] POST https://matrix.hackint.org/_matrix/client/r0/join/!PZwRnxCHGkegUXtiUP%3Alossy.network (AS) Body: "{}"
May 27 02:37:14 matrix synapse[3908]: synapse.http.server: [POST-8] <XForwardedForRequest at 0x7f47741f6af0 method='POST' uri='/_matrix/client/r0/join/!PZwRnxCHGkegUXtiUP%3Alossy.network?access_token=<redacted>' clientproto='HTTP/1.0' site='8008'> SynapseError: 404 - Profile was not found
May 27 02:37:14 matrix synapse[3908]: synapse.access.http.8008: [POST-8] 127.0.0.1 - 8008 - {@appservice-irc:hackint.org} Processed request: 0.009sec/-0.000sec (0.002sec, 0.001sec) (0.001sec/0.004sec/2) 57B 404 "POST /_matrix/client/r0/join/!PZwRnxCHGkegUXtiUP%3Alossy.network?access_token=<redacted> HTTP/1.0" "-" [0 dbevts]
May 27 02:37:14 matrix matrix-appservice-irc[3817]: 2021-05-27 02:37:14 ERROR:IrcBridge [-] POST https://matrix.hackint.org/_matrix/client/r0/join/!PZwRnxCHGkegUXtiUP%3Alossy.network (AS) HTTP 404 Error: "{\"errcode\":\"M_NOT_FOUND\",\"error\":\"Profile was not found\"}"
May 27 02:37:14 matrix matrix-appservice-irc[3817]: May-27 02:37:14.294 WARN MembershipQueue [3xw9sgrrguu00] Failed to join !PZwRnxCHGkegUXtiUP:lossy.network, delaying for 500ms
May 27 02:37:14 matrix matrix-appservice-irc[3817]: May-27 02:37:14.294 DEBUG MembershipQueue [3xw9sgrrguu00] Failed with: undefined Failed to join room
May 27 02:37:14 matrix matrix-appservice-irc[3817]: May-27 02:37:14.795 DEBUG MembershipQueue [3xw9sgrrguu00] @appservice-irc:hackint.org@!PZwRnxCHGkegUXtiUP:lossy.network -> join (reason: none, kicker: undefined)
May 27 02:37:14 matrix matrix-appservice-irc[3817]: May-27 02:37:14.796 DEBUG Intent Checking if user @appservice-irc:hackint.org is registered
May 27 02:37:14 matrix matrix-appservice-irc[3817]: May-27 02:37:14.796 DEBUG Intent ensureRegistered: Registered, and not encrypted
May 27 02:37:14 matrix matrix-appservice-irc[3817]: 2021-05-27 02:37:14 INFO:IrcBridge [-] POST https://matrix.hackint.org/_matrix/client/r0/join/!PZwRnxCHGkegUXtiUP%3Alossy.network (AS) Body: "{}"
May 27 02:37:14 matrix synapse[3908]: synapse.http.server: [POST-9] <XForwardedForRequest at 0x7f47742185e0 method='POST' uri='/_matrix/client/r0/join/!PZwRnxCHGkegUXtiUP%3Alossy.network?access_token=<redacted>' clientproto='HTTP/1.0' site='8008'> SynapseError: 404 - Profile was not found
May 27 02:37:14 matrix synapse[3908]: synapse.access.http.8008: [POST-9] 127.0.0.1 - 8008 - {@appservice-irc:hackint.org} Processed request: 0.006sec/-0.000sec (0.003sec, 0.000sec) (0.001sec/0.002sec/2) 57B 404 "POST /_matrix/client/r0/join/!PZwRnxCHGkegUXtiUP%3Alossy.network?access_token=<redacted> HTTP/1.0" "-" [0 dbevts]
May 27 02:37:14 matrix matrix-appservice-irc[3817]: 2021-05-27 02:37:14 ERROR:IrcBridge [-] POST https://matrix.hackint.org/_matrix/client/r0/join/!PZwRnxCHGkegUXtiUP%3Alossy.network (AS) HTTP 404 Error: "{\"errcode\":\"M_NOT_FOUND\",\"error\":\"Profile was not found\"}"
May 27 02:37:14 matrix matrix-appservice-irc[3817]: May-27 02:37:14.819 ERROR MembershipQueue Failed to handle membership change: Error: Failed to join room
May 27 02:37:14 matrix matrix-appservice-irc[3817]:     at Intent._ensureJoined (/nix/store/w35azw6ryb21g8swwxpn57mxndyc7dqn-node_matrix-appservice-irc-0.26.0/lib/node_modules/matrix-appservice-irc/node_modules/matrix-appservice-bridge/lib/components/intent.js:786:60)
May 27 02:37:14 matrix matrix-appservice-irc[3817]:     at processTicksAndRejections (internal/process/task_queues.js:97:5)
May 27 02:37:15 matrix matrix-appservice-irc[3817]: 2021-05-27 02:37:15 INFO:IrcBridge 127.0.0.1 - - [27/May/2021:00:37:15 +0000] "PUT /transactions/220?access_token=<REDACTED> HTTP/1.1" 200 2 "-" "Synapse/1.34.0"
May 27 02:37:15 matrix synapse[3908]: synapse.http.client: [as-sender-df621695152f1092fb1a7309a14676fe86c49a3ebc0cd50ee2b526accf53f09a-1] Received response to PUT http://127.0.0.1:8009/transactions/220?access_token=<redacted>: 200

Joining rooms, querying users on IRC both works. This is our registration.yml

id: foo
hs_token: bar
as_token: baz
url: 'http://127.0.0.1:8009'
sender_localpart: appservice-irc
de.sorunome.msc2409.push_ephemeral: true
protocols:
  - irc
namespaces:
  aliases:
    - exclusive: true
      regex: '#.*:hackint\.org'
  users:
    - exclusive: true
      regex: '@irc_.*:hackint\.org'
rate_limited: false
{
  "database": {
    "connectionString": "nedb://var/lib/matrix-appservice-irc/data",
    "engine": "nedb"
  },
  "homeserver": {
    "domain": "hackint.org",
    "enablePresence": true,
    "url": "https://matrix.hackint.org"
  },
  "ircService": {
    "ircHandler": {
      "leaveConcurrency": 10,
      "mapIrcMentionsToMatrix": "on"
    },
    "logging": {
      "level": "debug",
      "toConsole": true
    },
    "passwordEncryptionKeyPath": "/var/lib/matrix-appservice-irc/passkey.pem",
    "permissions": {
      "@hexa:example.com": "admin"
    },
    "servers": {
      "irc.hackint.org": {
        "allowExpiredCerts": true,
        "botConfig": {
          "enabled": false
        },
        "dynamicChannels": {
          "aliasTemplate": "$CHANNEL",
          "createAlias": true,
          "enabled": true,
          "federate": true,
          "joinRule": "public",
          "published": true
        },
        "excludedUsers": [],
        "icon": "https://hackint.org/images/avatar.png",
        "ircClients": {
          "allowNickChanges": true,
          "concurrentReconnectLimit": 512,
          "idleTimeout": 604800,
          "lineLimit": 5,
          "maxClients": 4096,
          "nickTemplate": "$DISPLAY|m"
        },
        "matrixClients": {
          "displayName": "$NICK",
          "userTemplate": "@irc_$NICK"
        },
        "membershipLists": {
          "enabled": true,
          "global": {
            "ircToMatrix": {
              "incremental": true,
              "initial": true,
              "requireMatrixJoined": true
            },
            "matrixToIrc": {
              "incremental": true,
              "initial": true,
              "requireMatrixJoined": true
            }
          }
        },
        "modePowerMap": {
          "o": 50,
          "v": 1
        },
        "name": "hackint",
        "port": 6697,
        "privateMessages": {
          "enabled": true,
          "federate": true
        },
        "quitDebounce": {
          "enabled": false
        },
        "sasl": false,
        "ssl": true,
        "sslselfsign": false
      }
    }
  }
}

We are running https://github.com/matrix-org/matrix-appservice-irc/commit/02591d4a2fb82457a67fd30e3c763f4c6278a676 and I've cherrypicked both #1337 and #1339.

Our synapse 1.34.0 configuration looks like this:

no_tls: true
server_name: hackint.org
pid_file: /run/matrix-synapse.pid
public_baseurl: 'https://matrix.hackint.org'
listeners:
  - port: 8008
    bind_address: 127.0.0.1
    type: http
    tls: false
    x_forwarded: true
    resources:
      - names:
          - client
          - metrics
        compress: true
      - names:
          - federation
        compress: false
database:
  name: psycopg2
  args:
    database: matrix-synapse
    user: matrix-synapse
event_cache_size: 10K
verbose: 0
log_config: /nix/store/zc10h40shgrr55qhm14jqywrgih3wwda-log_config.yaml
rc_messages_per_second: 0.2
rc_message_burst_count: 10
federation_rc_window_size: 1000
federation_rc_sleep_limit: 10
federation_rc_sleep_delay: 500
federation_rc_reject_limit: 50
federation_rc_concurrent: 3
media_store_path: /var/lib/matrix-synapse/media
uploads_path: /var/lib/matrix-synapse/uploads
max_upload_size: 10M
max_image_pixels: 32M
dynamic_thumbnails: false
url_preview_enabled: false
recaptcha_private_key: ''
recaptcha_public_key: ''
enable_registration_captcha: false
turn_uris: []
turn_shared_secret: ''
enable_registration: false
recaptcha_siteverify_api: 'https://www.google.com/recaptcha/api/siteverify'
turn_user_lifetime: 1h
user_creation_max_duration: 1209600000
bcrypt_rounds: 12
allow_guest_access: false
account_threepid_delegates: null
room_invite_state_types:
  - m.room.join_rules
  - m.room.canonical_alias
  - m.room.avatar
  - m.room.name
macaroon_secret_key: ...
expire_access_token: false
enable_metrics: true
report_stats: false
signing_key_path: /var/lib/matrix-synapse/homeserver.signing.key
key_refresh_interval: 1d
perspectives:
  servers:
    matrix.org:
      verify_keys:
        'ed25519:auto':
          key: Noi6WqcDj0QmPxCNQqgezwTlBKrfqehY1u2FyWP9uYw
redaction_retention_period: 7
app_service_config_files:
  - /var/lib/matrix-appservice-irc/registration.yml
retention:
  enabled: true
  default_policy:
    min_lifetime: 1m
    max_lifetime: 1m
  allowed_lifetime_min: 1m
  allowed_lifetime_max: 1m
  purge_jobs:
    - interval: 5m
mweinelt commented 3 years ago

To clarify: It works if I stop the appservice, remove all mentions of my account from nedb, start the appservice again and have the appservice bot invite me.

It still doesn't work if I invite the appservice to a DM or a room. My account is also the bridge admin.

Half-Shot commented 3 years ago

This is https://github.com/matrix-org/synapse/issues/2807.

Workaround is to curl --data '{"type": "m.login.application_service", "username": "your_sender_localpart"}' 'http://yourhomeserver/_matrix/client/r0/register?access_token=your_as_token' which will give the bot a profile and allow invites to work.

mweinelt commented 3 years ago

That made the errors go away, but the appservice still won't join the rooms it is invited to.

May 27 19:09:10 matrix synapse[5904]: synapse.access.http.8008: [GET-2033] 2001:67c:2ed8::666:1 - 8008 - {lossy.network} Processed request: 0.005sec/-0.000sec (0.003sec, 0.000sec) (0.001sec/0.001sec/1) 32B 200 "GET /_matrix/federation/v1/query/profile?user_id=%40appservice-irc%3Ahackint.org&field=displayname HTTP/1.0" "Synapse/1.34.0" [0 dbevts]
May 27 19:09:10 matrix synapse[5904]: synapse.access.http.8008: [GET-2034] 2001:67c:2ed8::666:1 - 8008 - {lossy.network} Processed request: 0.004sec/-0.000sec (0.003sec, 0.000sec) (0.000sec/0.001sec/1) 19B 200 "GET /_matrix/federation/v1/query/profile?user_id=%40appservice-irc%3Ahackint.org&field=avatar_url HTTP/1.0" "Synapse/1.34.0" [0 dbevts]
May 27 19:09:10 matrix synapse[5904]: synapse.access.http.8008: [GET-2035] 2001:67c:2ed8::666:1 - 8008 - {lossy.network} Processed request: 0.004sec/-0.000sec (0.003sec, 0.000sec) (0.001sec/0.001sec/1) 32B 200 "GET /_matrix/federation/v1/query/profile?user_id=%40appservice-irc%3Ahackint.org&field=displayname HTTP/1.0" "Synapse/1.34.0" [0 dbevts]
May 27 19:09:10 matrix synapse[5904]: synapse.access.http.8008: [GET-2036] 2001:67c:2ed8::666:1 - 8008 - {lossy.network} Processed request: 0.004sec/-0.000sec (0.002sec, 0.000sec) (0.000sec/0.001sec/1) 19B 200 "GET /_matrix/federation/v1/query/profile?user_id=%40appservice-irc%3Ahackint.org&field=avatar_url HTTP/1.0" "Synapse/1.34.0" [0 dbevts]
May 27 19:09:10 matrix synapse[5904]: synapse.crypto.keyring: [PUT-2037] Waiting for existing lookups for ['lossy.network'] to complete [loop 1]
May 27 19:09:10 matrix synapse[5904]: synapse.access.http.8008: [PUT-2037] 2001:67c:2ed8::666:1 - 8008 - {lossy.network} Processed request: 0.055sec/-0.000sec (0.004sec, 0.000sec) (0.001sec/0.001sec/2) 1467B 200 "PUT /_matrix/federation/v2/invite/%21tvjcYPFyuCmfAbBTwW%3Alossy.network/%24-uU0jyeXyRU12zxfFsjPvviTgvLQI9f4FgBxTbbXYQI HTTP/1.0" "Synapse/1.34.0" [0 dbevts]
May 27 19:09:10 matrix matrix-appservice-irc[5943]: 2021-05-27 19:09:10 INFO:IrcBridge 127.0.0.1 - - [27/May/2021:17:09:10 +0000] "PUT /transactions/1602?access_token=<REDACTED> HTTP/1.1" 200 2 "-" "Synapse/1.34.0"
May 27 19:09:10 matrix synapse[5904]: synapse.http.client: [as-sender-df621695152f1092fb1a7309a14676fe86c49a3ebc0cd50ee2b526accf53f09a-1261] Received response to PUT http://127.0.0.1:8009/transactions/1602?access_token=<redacted>: 200
May 27 19:09:10 matrix matrix-appservice-irc[5943]: 2021-05-27 19:09:10 INFO:req [49ui9wk176q00] [[M->I]] onInvite: from=@hexa:lossy.network to=@appservice-irc:hackint.org rm=!tvjcYPFyuCmfAbBTwW:lossy.network id=$-uU0jyeXyRU12zxfFsjPvviTgvLQI9f4FgBxTbbXYQI
May 27 19:09:10 matrix matrix-appservice-irc[5943]: 2021-05-27 19:09:10 INFO:IrcBridge [49ui9wk176q00] [M->I] SUCCESS  (1ms)
Half-Shot commented 3 years ago

I'm not sure why that's happening, but that sounds more like a synapse issue than ours.

chayleaf commented 2 years ago

happened to me as well

edit: ok, i simply didn't set the firewall up properly...

andir commented 2 years ago

Many months later. We (@mweinelt and I) picked this topic back up. We reset everything and started from scratch (empty synapse, empty appservice irc, ...). On first startup, everything seemingly works except for the Admin room with the appservice.

We are getting invites but are unable to accept the invites. I managed to start a new DM with the appservice after creating the profile (as posted above). New users are still unable to accept an invite from the appservice into the admin room.

After explicitly allowing anyone (in particular matrix.org) to fetch our HS's public key via federation we were able to accept the invites. It is a bit confusing to see that a closed-network of servers doesn't work without federating with matrix.org.

mckaygerhard commented 1 year ago

hi today it seem that prevously bridged rooms have similar problem, i guess, in matrix network:

after solvin the problem of not appears the bridge, i try to rejoin my ones.. checking that irc channels does not show the responses.. but at the side of matrix noted that "there are already bridged channel at irc".. intersting..

i just removed the bridge and try to remade, got this error:

Could not request link. Error IRC_DOUBLE_BRIDGE: Room failed validation. You may be attempting to "double bridge" this room. Error: Error: M_FORBIDDEN: Appservice not in room

becouse appservice it not in the room and must be invited and cannot get invites in matrix public networks