Skip to content

heisenbridge is unable to invite its own (puppeted) users to bridged channels

I'm running the heisenbridge app service. When joining an IRC channel, it creates the channel and then joins its puppets to that channel (identified as @irc_networkname_nickname:asf.computer, these are identified by regexes in the app service's "users" namespace). These joins fail, causing the bridging functionality to be quite limited.

Here's the events in one such channel: https://gist.github.com/antifuchs/f1f6965511a884596d9c244ced073739, and here's me logging a join event HTTP request (using this patch):

{
  "timestamp": "2024-10-12T18:09:33.807168Z",
  "level": "TRACE",
  "fields": {
    "message": "debugging this HTTP request",
    "request_uri": "/_matrix/client/v3/join/%21tqUTlf1v2SMoH6ZrC9%3Aasf.computer?user_id=@irc_liberachat_rmmh:asf.computer",
    "request_headers": "{\"host\": \"asf.computer\", \"user-agent\": \"mautrix-python/0.20.6 aiohttp/3.10.3 Python/3.12.3\", \"authorization\": Sensitive, \"content-type\": \"application/json\", \"accept\": \"*/*\", \"accept-encoding\": \"gzip, deflate\", \"content-length\": \"2\", \"x-request-start\": \"t=1728756573805765\", \"fly-client-ip\": \"2605:4c40:222:aaf5:0:e02d:3cbe:1\", \"x-forwarded-for\": \"2605:4c40:222:aaf5:0:e02d:3cbe:1, 2a09:8280:1::44:be5c:0\", \"fly-forwarded-proto\": \"https\", \"x-forwarded-proto\": \"https\", \"fly-forwarded-ssl\": \"on\", \"x-forwarded-ssl\": \"on\", \"fly-forwarded-port\": \"443\", \"x-forwarded-port\": \"443\", \"fly-region\": \"ewr\", \"fly-request-id\": \"01JA0YQSKD0RHVXM4P092XN5PW-ewr\", \"via\": \"1.1 fly.io\"}",
    "request_body": "{}",
    "appservice_info": "Some(RegistrationInfo { registration: Registration { id: \"heisenbridge\", url: Some(\"http://boinkornet-heisenbridge.internal:9898\"), as_token: \"<as_token>\", hs_token: \"<hs_token>\", sender_localpart: \"heisenbridge\", namespaces: Namespaces { users: [Namespace { exclusive: true, regex: \"@irc_.*\" }, Namespace { exclusive: true, regex: \"@heisenbridge:.*\" }], aliases: [], rooms: [] }, rate_limited: Some(false), protocols: None }, users: NamespaceRegex { exclusive: Some(RegexSet([\"@irc_.*\", \"@heisenbridge:.*\"])), non_exclusive: None }, aliases: NamespaceRegex { exclusive: None, non_exclusive: None }, rooms: NamespaceRegex { exclusive: None, non_exclusive: None } })",
    "sender_user": "Some(\"@irc_liberachat_rmmh:asf.computer\")"
  },
  "target": "grapevine::api::ruma_wrapper::axum",
  "span": {
    "name": "incoming_request_debug"
  },
  "spans": [
    {
      "endpoint": "/_matrix/client/v3/join/:room_id_or_alias",
      "method": "POST",
      "otel.name": "POST /_matrix/client/v3/join/:room_id_or_alias",
      "name": "http_request"
    },
    {
      "name": "ar_from_request"
    },
    {
      "name": "incoming_request_debug"
    }
  ]
}

The homeserver logs the following errors at "info" log level:

{
  "timestamp": "2024-10-12T21:14:47.823295Z",
  "level": "INFO",
  "fields": {
    "message": "We can join locally"
  },
  "target": "grapevine::api::client_server::membership",
  "span": {
    "room_id": "\"!ugyqNbeJigrZm4sx3p:asf.computer\"",
    "sender_user": "Some(\"@irc_liberachat_h2t:asf.computer\")",
    "servers": "[\"asf.computer\"]",
    "name": "join_room_by_id_helper"
  },
  "spans": [
    {
      "endpoint": "/_matrix/client/v3/join/:room_id_or_alias",
      "method": "POST",
      "otel.name": "POST /_matrix/client/v3/join/:room_id_or_alias",
      "name": "http_request"
    },
    {
      "auth.appservice_id": "Some(\"heisenbridge\")",
      "auth.device": "None",
      "auth.servername": "None",
      "auth.user": "Some(\"@irc_liberachat_h2t:asf.computer\")",
      "name": "run_ruma_handler"
    },
    {
      "room_id": "\"!ugyqNbeJigrZm4sx3p:asf.computer\"",
      "sender_user": "Some(\"@irc_liberachat_h2t:asf.computer\")",
      "servers": "[\"asf.computer\"]",
      "name": "join_room_by_id_helper"
    }
  ]
}
{
  "timestamp": "2024-10-12T21:14:47.823650Z",
  "level": "INFO",
  "fields": {
    "message": "We couldn't do the join locally, maybe federation can help to satisfy the restricted join requirements",
    "error": "M_FORBIDDEN: Event is not authorized.",
    "authorized_user": "None"
  },
  "target": "grapevine::api::client_server::membership",
  "span": {
    "room_id": "\"!ugyqNbeJigrZm4sx3p:asf.computer\"",
    "sender_user": "Some(\"@irc_liberachat_h2t:asf.computer\")",
    "servers": "[\"asf.computer\"]",
    "name": "join_room_by_id_helper"
  },
  "spans": [
    {
      "endpoint": "/_matrix/client/v3/join/:room_id_or_alias",
      "method": "POST",
      "otel.name": "POST /_matrix/client/v3/join/:room_id_or_alias",
      "name": "http_request"
    },
    {
      "auth.appservice_id": "Some(\"heisenbridge\")",
      "auth.device": "None",
      "auth.servername": "None",
      "auth.user": "Some(\"@irc_liberachat_h2t:asf.computer\")",
      "name": "run_ruma_handler"
    },
    {
      "room_id": "\"!ugyqNbeJigrZm4sx3p:asf.computer\"",
      "sender_user": "Some(\"@irc_liberachat_h2t:asf.computer\")",
      "servers": "[\"asf.computer\"]",
      "name": "join_room_by_id_helper"
    }
  ]
}
{
  "timestamp": "2024-10-12T21:14:47.823713Z",
  "level": "WARN",
  "fields": {
    "message": "Responding with an error",
    "status_code": "500 Internal Server Error",
    "error": "No server available to assist in joining."
  },
  "target": "grapevine::utils::error",
  "span": {
    "endpoint": "/_matrix/client/v3/join/:room_id_or_alias",
    "method": "POST",
    "otel.name": "POST /_matrix/client/v3/join/:room_id_or_alias",
    "name": "http_request"
  },
  "spans": [
    {
      "endpoint": "/_matrix/client/v3/join/:room_id_or_alias",
      "method": "POST",
      "otel.name": "POST /_matrix/client/v3/join/:room_id_or_alias",
      "name": "http_request"
    }
  ]
}

Heisenbridge receives that 500 and doesn't like it, of course (this is from a different join attempt, I lost the original logs; they all look the same though):

2024-10-12 17:14:47.596	
mautrix.errors.base.IntentError: Failed to join room !ugyqNbeJigrZm4sx3p:asf.computer as @irc_liberachat_oth:asf.computer
2024-10-12 17:14:47.596	
raise IntentError(f"Failed to join room {room_id} as {self.mxid}") from e
2024-10-12 17:14:47.596	
File "/usr/lib/python3.12/site-packages/mautrix/appservice/api/intent.py", line 671, in ensure_joined
2024-10-12 17:14:47.596	
await self.az.intent.user(user_id).ensure_joined(self.id, ignore_cache=True)
2024-10-12 17:14:47.596	
File "/opt/heisenbridge/heisenbridge/room.py", line 156, in _join
2024-10-12 17:14:47.596	
await self._join(event["user_id"], event["nick"])
2024-10-12 17:14:47.596	
File "/opt/heisenbridge/heisenbridge/room.py", line 171, in _flush_events
2024-10-12 17:14:47.596	
Traceback (most recent call last):
2024-10-12 17:14:47.596	
The above exception was the direct cause of the following exception:
2024-10-12 17:14:47.596	
mautrix.errors.request.MUnknown: No server available to assist in joining.
2024-10-12 17:14:47.596	
raise make_request_error(
2024-10-12 17:14:47.596	
File "/usr/lib/python3.12/site-packages/mautrix/api.py", line 265, in _send
2024-10-12 17:14:47.596	
^^^^^^^^^^^^^^^^^
2024-10-12 17:14:47.596	
resp_data, resp = await self._send(
2024-10-12 17:14:47.596	
File "/usr/lib/python3.12/site-packages/mautrix/api.py", line 425, in request
2024-10-12 17:14:47.596	
^^^^^^^^^^^^^^^^^^^^^^^
2024-10-12 17:14:47.596	
content = await self.api.request(
2024-10-12 17:14:47.596	
File "/usr/lib/python3.12/site-packages/mautrix/client/api/rooms.py", line 335, in join_room
2024-10-12 17:14:47.596	
^^^^^^^^^^^^^^^^^^^^^^^^
2024-10-12 17:14:47.596	
room_id = await super().join_room(
2024-10-12 17:14:47.596	
File "/usr/lib/python3.12/site-packages/mautrix/client/store_updater.py", line 62, in join_room
2024-10-12 17:14:47.596	
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-10-12 17:14:47.596	
return await __method(*args, **kwargs)
2024-10-12 17:14:47.596	
File "/usr/lib/python3.12/site-packages/mautrix/appservice/api/intent.py", line 130, in wrapper
2024-10-12 17:14:47.596	
await self.join_room(room_id, max_retries=0)
2024-10-12 17:14:47.596	
File "/usr/lib/python3.12/site-packages/mautrix/appservice/api/intent.py", line 649, in ensure_joined
2024-10-12 17:14:47.596	
Traceback (most recent call last):
2024-10-12 17:14:47.596	
ERROR:root:Queued event failed
2024-10-12 17:14:47.595	
DEBUG:mau.appservice.api.@irc_liberachat_oth:asf.computer:req #62 (/v3/join/%21ugyqNbeJigrZm4sx3p%3Aasf.computer) completed in 3.5ms with status 500
2024-10-12 17:14:47.591	
DEBUG:mau.appservice.api.@irc_liberachat_oth:asf.computer:req #62: POST https://asf.computer/_matrix/client/v3/join/%21ugyqNbeJigrZm4sx3p%3Aasf.computer?user_id=@irc_liberachat_oth:asf.computer {}
2024-10-12 17:14:47.591	
DEBUG:mau.appservice.api.@irc_liberachat_oth:asf.computer:req #61 (/v3/profile/%40irc_liberachat_oth%3Aasf.computer/displayname) completed in 2.3ms with status 200
2024-10-12 17:14:47.588	
DEBUG:mau.appservice.api.@irc_liberachat_oth:asf.computer:req #61: GET https://asf.computer/_matrix/client/v3/profile/%40irc_liberachat_oth%3Aasf.computer/displayname?user_id=@irc_liberachat_oth:asf.computer None
2024-10-12 17:14:47.588	
DEBUG:mau.appservice.api.@irc_liberachat_oth:asf.computer:req #60 (/v3/register) completed in 2.8ms with status 400
2024-10-12 17:14:47.585	
DEBUG:mau.appservice.api.@irc_liberachat_oth:asf.computer:req #60: POST https://asf.computer/_matrix/client/v3/register?kind=user&user_id=@irc_liberachat_oth:asf.computer {"username": "irc_liberachat_oth", "type": "m.login.application_service", "inhibit_login": true}

So, hm, I'm not sure what's going on exactly, but this seems rooted in a failure to authenticate the Join PDU, or resolving the app service user.

Several other issues around users and appservices were mentioned, so I'll tag them here: #80, #81, #82, #83, #84.