matrix-appservice-irc fails to register virtual users #388

New issue

Open

opened 2023-09-23 17:45:44 +00:00 by pluth · 2 comments

pluth commented

2023-09-23 17:45:44 +00:00

(Migrated from gitlab.com)

matrix-appservice-irc fails to register virtual users

I'm trying out conduit and am trying to setup an IRC bridge with matrix-appservice-irc. I have a working setup with synapse with a similar configuration on a different server

Description

When I create and join a bridged room matrix-irc-service is supposed to create virtual user in Matrix for each IRC user. What I am observing is that this works only some users but not all. So in the end, some users are missing from the room on the Matrix side. I can see messages from users that join.

Here is a (slighty censored) log excerpts from an exchange between me and our IRC bot. I can see the message sent by me in IRC (pluth) just fine. But for the response from Gune it seems to check if the Gune virtual user exists and then fails to create it.

matrix-appservice-irc_1  | 2023-09-23 17:24:42 INFO:req [crpj07v50kg00] [[I->M]] onMessage: IRCSERVER.URL from=pluth (null@IRCSERVER.URL) to=#wa
matrix-appservice-irc_1  | 2023-09-23 17:24:42 DEBUG:req [crpj07v50kg00] [[I->M]] action={"type":"message","text":"!test","ts":0}
matrix-appservice-irc_1  | 2023-09-23 17:24:42 DEBUG:req [crpj07v50kg00] [[I->M]] !YCX46PVZRHN6391EjH:MYCONDUIT.SERVER does not require Matrix users to be joined
matrix-appservice-irc_1  | 2023-09-23 17:24:42 DEBUG:req [crpj07v50kg00] [[I->M]] Relaying in room(s) !YCX46PVZRHN6391EjH:MYCONDUIT.SERVER
matrix-appservice-irc_1  | DEBUG 17:24:42:286 [Intent] Checking if user @IRCSERVER.URL_pluth:MYCONDUIT.SERVER is registered
matrix-appservice-irc_1  | DEBUG 17:24:42:286 [Intent] ensureRegistered: already registered
matrix-appservice-irc_1  | DEBUG 17:24:42:286 [MatrixHttpClient] (REQ-52) PUT http://matrix-conduit:6167/_matrix/client/v3/rooms/!YCX46PVZRHN6391EjH%3AMYCONDUIT.SERVER/send/m.room.message/1695489882286__inc1
matrix-appservice-irc_1  | 2023-09-23 17:24:42 INFO:IrcBridge [crpj07v50kg00] [I->M] SUCCESS  (31ms)
matrix-appservice-irc_1  | 2023-09-23 17:24:42 INFO:IrcBridge 172.19.0.2 - - [23/Sep/2023:17:24:42 +0000] "PUT /_matrix/app/v1/transactions/U6vXdgrmz_m3ttgGcYi583uVJOgiitck0NtxwvTSHVQ?access_token=<REDACTED> HTTP/1.1" 200 2 "-" "-"
matrix-appservice-irc_1  | 2023-09-23 17:24:42 INFO:req [ankncl19kfc00] [[M->I]] onMessage: m.room.message usr=@IRCSERVER.URL_pluth:MYCONDUIT.SERVER rm=!YCX46PVZRHN6391EjH:MYCONDUIT.SERVER id=$5cbS9RtYvKSo_ocm2Yh0TrikdFomzvSWgjqahBazp1o
matrix-appservice-irc_1  | 2023-09-23 17:24:42 DEBUG:req [ankncl19kfc00] [[M->I]] Message body: !test
matrix-appservice-irc_1  | 2023-09-23 17:24:42 DEBUG:req [ankncl19kfc00] [[M->I]] @IRCSERVER.URL_pluth:MYCONDUIT.SERVER is a virtual user (claimed by IRCSERVER.URL)
matrix-appservice-irc_1  | 2023-09-23 17:24:42 INFO:IrcBridge [ankncl19kfc00] [M->I] IGNORE virtual user  (2ms)
matrix-appservice-irc_1  | 2023-09-23 17:24:42 INFO:req [jbjt6lqpvig00] [[I->M]] onMessage: IRCSERVER.URL from=Gune (null@IRCSERVER.URL) to=#wa
matrix-appservice-irc_1  | 2023-09-23 17:24:42 DEBUG:req [jbjt6lqpvig00] [[I->M]] action={"type":"message","text":"WORX","ts":0}
matrix-appservice-irc_1  | 2023-09-23 17:24:42 DEBUG:req [jbjt6lqpvig00] [[I->M]] !YCX46PVZRHN6391EjH:MYCONDUIT.SERVER does not require Matrix users to be joined
matrix-appservice-irc_1  | 2023-09-23 17:24:42 INFO:IrcBridge IRCSERVER.URL_Gune does not exist in the store yet, setting a profile
matrix-appservice-irc_1  | DEBUG 17:24:42:729 [Intent] Checking if user @IRCSERVER.URL_Gune:MYCONDUIT.SERVER is registered
matrix-appservice-irc_1  | DEBUG 17:24:42:729 [MatrixHttpClient] (REQ-53) PUT http://matrix-conduit:6167/_matrix/client/v3/profile/%40IRCSERVER.URL_Gune%3AMYCONDUIT.SERVER/displayname
matrix-appservice-irc_1  | ERROR 17:24:42:732 [MatrixHttpClient] (REQ-53) { errcode: 'M_FORBIDDEN', error: 'M_FORBIDDEN: User does not exist.' }
matrix-appservice-irc_1  | 2023-09-23 17:24:42 INFO:IrcBridge [jbjt6lqpvig00] [I->M] FAILED  (11ms)

Conduit doesn't say anything on WARN at this point. Higher log levels are spammy, maybe there is something to look for with the right filter?

I would also look at the DB (default rocksdb) but I don't know any rockdbs explorers.

## matrix-appservice-irc fails to register virtual users I'm trying out conduit and am trying to setup an IRC bridge with matrix-appservice-irc. I have a working setup with synapse with a similar configuration on a different server ### Description When I create and join a bridged room `matrix-irc-service` is supposed to create virtual user in Matrix for each IRC user. What I am observing is that this works only _some_ users but not all. So in the end, some users are missing from the room on the Matrix side. I can see messages from users that join. Here is a (slighty censored) log excerpts from an exchange between me and our IRC bot. I can see the message sent by me in IRC (pluth) just fine. But for the response from Gune it seems to check if the Gune virtual user exists and then fails to create it. ``` matrix-appservice-irc_1 | 2023-09-23 17:24:42 INFO:req [crpj07v50kg00] [[I->M]] onMessage: IRCSERVER.URL from=pluth (null@IRCSERVER.URL) to=#wa matrix-appservice-irc_1 | 2023-09-23 17:24:42 DEBUG:req [crpj07v50kg00] [[I->M]] action={"type":"message","text":"!test","ts":0} matrix-appservice-irc_1 | 2023-09-23 17:24:42 DEBUG:req [crpj07v50kg00] [[I->M]] !YCX46PVZRHN6391EjH:MYCONDUIT.SERVER does not require Matrix users to be joined matrix-appservice-irc_1 | 2023-09-23 17:24:42 DEBUG:req [crpj07v50kg00] [[I->M]] Relaying in room(s) !YCX46PVZRHN6391EjH:MYCONDUIT.SERVER matrix-appservice-irc_1 | DEBUG 17:24:42:286 [Intent] Checking if user @IRCSERVER.URL_pluth:MYCONDUIT.SERVER is registered matrix-appservice-irc_1 | DEBUG 17:24:42:286 [Intent] ensureRegistered: already registered matrix-appservice-irc_1 | DEBUG 17:24:42:286 [MatrixHttpClient] (REQ-52) PUT http://matrix-conduit:6167/_matrix/client/v3/rooms/!YCX46PVZRHN6391EjH%3AMYCONDUIT.SERVER/send/m.room.message/1695489882286__inc1 matrix-appservice-irc_1 | 2023-09-23 17:24:42 INFO:IrcBridge [crpj07v50kg00] [I->M] SUCCESS (31ms) matrix-appservice-irc_1 | 2023-09-23 17:24:42 INFO:IrcBridge 172.19.0.2 - - [23/Sep/2023:17:24:42 +0000] "PUT /_matrix/app/v1/transactions/U6vXdgrmz_m3ttgGcYi583uVJOgiitck0NtxwvTSHVQ?access_token=<REDACTED> HTTP/1.1" 200 2 "-" "-" matrix-appservice-irc_1 | 2023-09-23 17:24:42 INFO:req [ankncl19kfc00] [[M->I]] onMessage: m.room.message usr=@IRCSERVER.URL_pluth:MYCONDUIT.SERVER rm=!YCX46PVZRHN6391EjH:MYCONDUIT.SERVER id=$5cbS9RtYvKSo_ocm2Yh0TrikdFomzvSWgjqahBazp1o matrix-appservice-irc_1 | 2023-09-23 17:24:42 DEBUG:req [ankncl19kfc00] [[M->I]] Message body: !test matrix-appservice-irc_1 | 2023-09-23 17:24:42 DEBUG:req [ankncl19kfc00] [[M->I]] @IRCSERVER.URL_pluth:MYCONDUIT.SERVER is a virtual user (claimed by IRCSERVER.URL) matrix-appservice-irc_1 | 2023-09-23 17:24:42 INFO:IrcBridge [ankncl19kfc00] [M->I] IGNORE virtual user (2ms) matrix-appservice-irc_1 | 2023-09-23 17:24:42 INFO:req [jbjt6lqpvig00] [[I->M]] onMessage: IRCSERVER.URL from=Gune (null@IRCSERVER.URL) to=#wa matrix-appservice-irc_1 | 2023-09-23 17:24:42 DEBUG:req [jbjt6lqpvig00] [[I->M]] action={"type":"message","text":"WORX","ts":0} matrix-appservice-irc_1 | 2023-09-23 17:24:42 DEBUG:req [jbjt6lqpvig00] [[I->M]] !YCX46PVZRHN6391EjH:MYCONDUIT.SERVER does not require Matrix users to be joined matrix-appservice-irc_1 | 2023-09-23 17:24:42 INFO:IrcBridge IRCSERVER.URL_Gune does not exist in the store yet, setting a profile matrix-appservice-irc_1 | DEBUG 17:24:42:729 [Intent] Checking if user @IRCSERVER.URL_Gune:MYCONDUIT.SERVER is registered matrix-appservice-irc_1 | DEBUG 17:24:42:729 [MatrixHttpClient] (REQ-53) PUT http://matrix-conduit:6167/_matrix/client/v3/profile/%40IRCSERVER.URL_Gune%3AMYCONDUIT.SERVER/displayname matrix-appservice-irc_1 | ERROR 17:24:42:732 [MatrixHttpClient] (REQ-53) { errcode: 'M_FORBIDDEN', error: 'M_FORBIDDEN: User does not exist.' } matrix-appservice-irc_1 | 2023-09-23 17:24:42 INFO:IrcBridge [jbjt6lqpvig00] [I->M] FAILED (11ms) ``` Conduit doesn't say anything on WARN at this point. Higher log levels are spammy, maybe there is something to look for with the right filter? I would also look at the DB (default rocksdb) but I don't know any rockdbs explorers.

pluth commented

2023-09-24 07:58:14 +00:00

(Migrated from gitlab.com)

It appears to be a problem with case sensitivity.

IRC users that don't work like Gune have names starting with capital letters and have capital letters in their virtual matrix accounts e.g. (from the appservice logs)

DEBUG 07:39:33:333 [Intent] Checking if user @irc_Gune:MYCONDUIT.SERVER is registered
DEBUG 07:39:33:334 [MatrixHttpClient] (REQ-39) PUT http://matrix-conduit:6167/_matrix/client/v3/profile/%40irc_Gune%3AMYCONDUIT.SERVER/displayname

But in the userid_displayname table on conduit, the key is @irc_gune:MYCONDUIT.SERVER all lowercase. I changed to sqlite to be able to exploer the DB but it seems to behave the same as rocksdb before.

Looking at the database of my synapse server, the IRC virtual accounts (from the same irc server) have correct capitalisation e.g. Gune's Matrix accounts appears as @irc_Gune:MYSYNAPSE.SERVER in postgres

It appears to be a problem with case sensitivity. IRC users that don't work like Gune have names starting with capital letters and have capital letters in their virtual matrix accounts e.g. (from the appservice logs) ``` DEBUG 07:39:33:333 [Intent] Checking if user @irc_Gune:MYCONDUIT.SERVER is registered DEBUG 07:39:33:334 [MatrixHttpClient] (REQ-39) PUT http://matrix-conduit:6167/_matrix/client/v3/profile/%40irc_Gune%3AMYCONDUIT.SERVER/displayname ``` But in the `userid_displayname` table on conduit, the key is `@irc_gune:MYCONDUIT.SERVER` all lowercase. I changed to sqlite to be able to exploer the DB but it seems to behave the same as rocksdb before. Looking at the database of my synapse server, the IRC virtual accounts (from the same irc server) have correct capitalisation e.g. Gune's Matrix accounts appears as `@irc_Gune:MYSYNAPSE.SERVER` in postgres

pluth commented

2023-09-24 08:51:06 +00:00

(Migrated from gitlab.com)

I guess basically the same problem as

https://gitlab.com/famedly/conduit/-/issues/295

I guess basically the same problem as https://gitlab.com/famedly/conduit/-/issues/295