Matrix-appservice-irc: M_FORBIDDEN not in room errors when the user should be joining
There's been some cases where IRC users do not appear on Matrix. Logs state:
HTTP 403 Error: {"errcode":"M_FORBIDDEN","error":"User @whatever not in room !zwwefmsiwefwRDjSwe:matrix.org (None)"}
At this point, the bridge should try inviting the user to the room as the AS bot, but this isn't happening for some reason. Cache invalidation?
kegsay
All 8 comments
In PureTryOut's case, this was because the user didn't even attempt to join the room when it got a JOIN - It only joined 1 of the 2 mapped Matrix rooms.
In the OP case, this was because of a nick change not triggering a re-join for some reason.
kegsay
on 16 Jan 2017
This has now started happening to more users. Also the nicks medfly and tsahyt (confirmed showing up fine before) are now hidden from Matrix (in #linuxmasterrace on Snoonet).
PureTryOut
on 17 Jan 2017
I'll look into this today and possibly restart the Snoonet bridge with a fix. As a temp workaround, leaving the channel then rejoining the channel should fix this.
kegsay
on 17 Jan 2017
So I'm somewhat confused how this case can ever happen if things are working as I expect them to. We cache the membership state in Intent objects. This cached state is wrong, so it never tries to join the room.
When we hit /leave, an echo of that request goes to the bridge which then updates the Intent objects with the right membership state:
- https://github.com/matrix-org/matrix-appservice-bridge/blob/master/lib/components/intent.js#L421
- https://github.com/matrix-org/matrix-appservice-bridge/blob/master/lib/bridge.js#L678
- https://github.com/matrix-org/matrix-appservice-bridge/blob/master/lib/bridge.js#L613
If this doesn't happen, then the Intent objects will get out of sync with reality. I am not seeing Synapse echoing back the request (which nop logs) which would explain this.
If we can't trust Synapse to echo back membership changes, then we'll need to modify the Intent class to clear the cached state if we get M_FORBIDDEN then try joining again using the normal logic. This will resolve both causes of this bug:
- OP nick change.
- Forcing a join when message sending fails, so even if it doesn't try to join on a JOIN event, it will lazily do so.
kegsay
on 17 Jan 2017
@PureTryOut : I've got a fix in the works pending review. I plan on restarting Snoonet with this today (latest tomorrow).
kegsay
on 17 Jan 2017
@PureTryOut Snoonet has been restarted with this fix applied. Please let me know if it happens again.
kegsay
on 17 Jan 2017
As reported on #matrix:matrix.org, but for the sake of project history also reporting here: the fix worked great. All users seem to show up again. Thanks for the help!
PureTryOut
on 18 Jan 2017
I've a similar issue running synapse v1.18.0 and current matrix-appservice-irc git master
root@vps733892:~# tail -f -n50 /var/log/syslog | grep ERROR
Aug 3 13:46:53 vps733892 node[18994]: 2020-08-03 13:46:53 ERROR:IrcBridge [-] POST https://matrix.simosnap.com/_matrix/client/r0/register (AS) HTTP 400 Error: "{\"errcode\":\"M_USER_IN_USE\",\"error\":\"User ID already taken.\"}"
Aug 3 13:46:53 vps733892 node[18994]: 2020-08-03 13:46:53 ERROR:IrcBridge [-] POST https://matrix.simosnap.com/_matrix/client/r0/register (AS) HTTP 400 Error: "{\"errcode\":\"M_USER_IN_USE\",\"error\":\"User ID already taken.\"}"
Aug 3 13:46:56 vps733892 node[18994]: 2020-08-03 13:46:56 ERROR:IrcBridge [-] PUT https://matrix.simosnap.com/_matrix/client/r0/rooms/!eaEUdoxhGkZcQRbfdh%3Asimosnap.com/send/m.room.message/m1596455215238.272 (@irc_Smemoranda:simosnap.com) HTTP 403 Error: "{\"errcode\":\"M_FORBIDDEN\",\"error\":\"User @irc_Smemoranda:simosnap.com not in room !eaEUdoxhGkZcQRbfdh:simosnap.com (<FrozenEventV3 event_id='$1qgGDWCyrrknlPCwndz_FvZVWC3aqJGl-INDkus5oEw', type='m.room.member', state_key='@irc_Smemoranda:simosnap.com'>)\"}"
Aug 3 13:47:17 vps733892 node[18994]: 2020-08-03 13:47:17 ERROR:IrcBridge [-] PUT https://matrix.simosnap.com/_matrix/client/r0/rooms/!eaEUdoxhGkZcQRbfdh%3Asimosnap.com/send/m.room.message/m1596455234659.2 (@irc_sharky:simosnap.com) HTTP 403 Error: "{\"errcode\":\"M_FORBIDDEN\",\"error\":\"User @irc_sharky:simosnap.com not in room !eaEUdoxhGkZcQRbfdh:simosnap.com (<FrozenEventV3 event_id='$6kQc3dqwKwtvgaaNHigw04hIDRA4EL4hcYmiiJu9PDU', type='m.room.member', state_key='@irc_sharky:simosnap.com'>)\"}"
Aug 3 13:47:20 vps733892 node[18994]: 2020-08-03 13:47:20 ERROR:IrcBridge [-] POST https://matrix.simosnap.com/_matrix/client/r0/register (AS) HTTP 400 Error: "{\"errcode\":\"M_USER_IN_USE\",\"error\":\"User ID already taken.\"}"
Aug 3 13:47:26 vps733892 node[18994]: 2020-08-03 13:47:26 ERROR:IrcBridge [-] POST https://matrix.simosnap.com/_matrix/client/r0/register (AS) HTTP 400 Error: "{\"errcode\":\"M_USER_IN_USE\",\"error\":\"User ID already taken.\"}"
Aug 3 13:47:32 vps733892 node[18994]: 2020-08-03 13:47:32 ERROR:IrcBridge [-] PUT https://matrix.simosnap.com/_matrix/client/r0/rooms/!MbUEttqEpDiQtWUKCe%3Asimosnap.com/send/m.room.message/m1596455252076.0 (@irc_Nuvolaparma93_:simosnap.com) HTTP 403 Error: "{\"errcode\":\"M_FORBIDDEN\",\"error\":\"User @irc_Nuvolaparma93_:simosnap.com not in room !MbUEttqEpDiQtWUKCe:simosnap.com (None)\"}"
Aug 3 13:47:37 vps733892 node[18994]: 2020-08-03 13:47:37 ERROR:IrcBridge [-] POST https://matrix.simosnap.com/_matrix/client/r0/register (AS) HTTP 400 Error: "{\"errcode\":\"M_USER_IN_USE\",\"error\":\"User ID already taken.\"}"
Aug 3 13:47:39 vps733892 node[18994]: 2020-08-03 13:47:39 ERROR:IrcBridge [-] PUT https://matrix.simosnap.com/_matrix/client/r0/rooms/!eaEUdoxhGkZcQRbfdh%3Asimosnap.com/send/m.room.message/m1596455253037.0 (@irc_FedericoAllenatore:simosnap.com) HTTP 403 Error: "{\"errcode\":\"M_FORBIDDEN\",\"error\":\"User @irc_FedericoAllenatore:simosnap.com not in room !eaEUdoxhGkZcQRbfdh:simosnap.com (<FrozenEventV3 event_id='$vLsS_UR43VnQghUkOUkeu3ZlF-y_DVHXSkSYFhaSfN0', type='m.room.member', state_key='@irc_FedericoAllenatore:simosnap.com'>)\"}"
Aug 3 13:47:49 vps733892 node[18994]: 2020-08-03 13:47:49 ERROR:IrcBridge [-] PUT https://matrix.simosnap.com/_matrix/client/r0/rooms/!MbUEttqEpDiQtWUKCe%3Asimosnap.com/send/m.room.message/m1596455269007.0 (@irc_Bel-maturo-firenze_:simosnap.com) HTTP 403 Error: "{\"errcode\":\"M_FORBIDDEN\",\"error\":\"User @irc_Bel-maturo-firenze_:simosnap.com not in room !MbUEttqEpDiQtWUKCe:simosnap.com (None)\"}"
Aug 3 13:48:02 vps733892 node[18994]: 2020-08-03 13:48:02 ERROR:IrcBridge [-] POST https://matrix.simosnap.com/_matrix/client/r0/register (AS) HTTP 400 Error: "{\"errcode\":\"M_USER_IN_USE\",\"error\":\"User ID already taken.\"}"
Aug 3 13:48:05 vps733892 node[18994]: 2020-08-03 13:48:05 ERROR:IrcBridge [-] POST https://matrix.simosnap.com/_matrix/client/r0/register (AS) HTTP 400 Error: "{\"errcode\":\"M_USER_IN_USE\",\"error\":\"User ID already taken.\"}"
Aug 3 13:48:10 vps733892 node[18994]: 2020-08-03 13:48:10 ERROR:IrcBridge [-] POST https://matrix.simosnap.com/_matrix/client/r0/register (AS) HTTP 400 Error: "{\"errcode\":\"M_USER_IN_USE\",\"error\":\"User ID already taken.\"}"
Aug 3 13:48:14 vps733892 node[18994]: 2020-08-03 13:48:14 ERROR:IrcBridge [-] POST https://matrix.simosnap.com/_matrix/client/r0/rooms/!MbUEttqEpDiQtWUKCe%3Asimosnap.com/leave (@irc_Carlos:simosnap.com) HTTP 403 Error: "{\"errcode\":\"M_FORBIDDEN\",\"error\":\"@irc_Carlos:simosnap.com not in room !MbUEttqEpDiQtWUKCe:simosnap.com.\"}"
Aug 3 13:48:14 vps733892 node[18994]: 2020-08-03 13:48:14 ERROR:MembershipQueue Failed to handle membership: M_FORBIDDEN: @irc_Carlos:simosnap.com not in room !MbUEttqEpDiQtWUKCe:simosnap.com.
Aug 3 13:48:23 vps733892 node[18994]: 2020-08-03 13:48:23 ERROR:IrcBridge [-] POST https://matrix.simosnap.com/_matrix/client/r0/rooms/!jyNNNFWcPszqQuKvPR%3Asimosnap.com/leave (@irc_SIRA-BODYBUILDER_:simosnap.com) HTTP 403 Error: "{\"errcode\":\"M_FORBIDDEN\",\"error\":\"@irc_SIRA-BODYBUILDER_:simosnap.com not in room !jyNNNFWcPszqQuKvPR:simosnap.com.\"}"
Aug 3 13:48:23 vps733892 node[18994]: 2020-08-03 13:48:23 ERROR:MembershipQueue Failed to handle membership: M_FORBIDDEN: @irc_SIRA-BODYBUILDER_:simosnap.com not in room !jyNNNFWcPszqQuKvPR:simosnap.com.
Aug 3 13:48:58 vps733892 node[18994]: 2020-08-03 13:48:58 ERROR:IrcBridge [-] POST https://matrix.simosnap.com/_matrix/client/r0/register (AS) HTTP 400 Error: "{\"errcode\":\"M_USER_IN_USE\",\"error\":\"User ID already taken.\"}"
Aug 3 13:49:00 vps733892 node[18994]: 2020-08-03 13:49:00 ERROR:IrcBridge [-] PUT https://matrix.simosnap.com/_matrix/client/r0/rooms/!eaEUdoxhGkZcQRbfdh%3Asimosnap.com/send/m.room.message/m1596455339731.6 (@irc_Spacciatorediplasmon:simosnap.com) HTTP 403 Error: "{\"errcode\":\"M_FORBIDDEN\",\"error\":\"User @irc_Spacciatorediplasmon:simosnap.com not in room !eaEUdoxhGkZcQRbfdh:simosnap.com (<FrozenEventV3 event_id='$lt0pxXXhokPgMADWu9SXaRxomCsisa-0kIvg0wFkuKs', type='m.room.member', state_key='@irc_Spacciatorediplasmon:simosnap.com'>)\"}"
Aug 3 13:49:02 vps733892 node[18994]: 2020-08-03 13:49:02 ERROR:IrcBridge [-] POST https://matrix.simosnap.com/_matrix/client/r0/rooms/!MbUEttqEpDiQtWUKCe%3Asimosnap.com/leave (@irc_Cerco_schiava_Rm:simosnap.com) HTTP 403 Error: "{\"errcode\":\"M_FORBIDDEN\",\"error\":\"@irc_Cerco_schiava_Rm:simosnap.com not in room !MbUEttqEpDiQtWUKCe:simosnap.com.\"}"
Aug 3 13:49:02 vps733892 node[18994]: 2020-08-03 13:49:02 ERROR:MembershipQueue Failed to handle membership: M_FORBIDDEN: @irc_Cerco_schiava_Rm:simosnap.com not in room !MbUEttqEpDiQtWUKCe:simosnap.com.
Aug 3 13:49:02 vps733892 node[18994]: 2020-08-03 13:49:02 ERROR:IrcBridge [-] POST https://matrix.simosnap.com/_matrix/client/r0/register (AS) HTTP 400 Error: "{\"errcode\":\"M_USER_IN_USE\",\"error\":\"User ID already taken.\"}"
Aug 3 13:49:03 vps733892 node[18994]: 2020-08-03 13:49:03 ERROR:IrcBridge [-] POST https://matrix.simosnap.com/_matrix/client/r0/register (AS) HTTP 400 Error: "{\"errcode\":\"M_USER_IN_USE\",\"error\":\"User ID already taken.\"}"
Aug 3 13:49:11 vps733892 node[18994]: 2020-08-03 13:49:11 ERROR:IrcBridge [-] POST https://matrix.simosnap.com/_matrix/client/r0/rooms/!eaEUdoxhGkZcQRbfdh%3Asimosnap.com/leave (@irc_Fab_78:simosnap.com) HTTP 403 Error: "{\"errcode\":\"M_FORBIDDEN\",\"error\":\"@irc_Fab_78:simosnap.com not in room !eaEUdoxhGkZcQRbfdh:simosnap.com.\"}"
Aug 3 13:49:11 vps733892 node[18994]: 2020-08-03 13:49:11 ERROR:MembershipQueue Failed to handle membership: M_FORBIDDEN: @irc_Fab_78:simosnap.com not in room !eaEUdoxhGkZcQRbfdh:simosnap.com.
Aug 3 13:49:11 vps733892 node[18994]: 2020-08-03 13:49:11 ERROR:MembershipQueue Failed to handle membership: M_FORBIDDEN: @irc_Fab_78:simosnap.com not in room !eaEUdoxhGkZcQRbfdh:simosnap.com.
Aug 3 13:49:11 vps733892 node[18994]: 2020-08-03 13:49:11 ERROR:MembershipQueue Failed to handle membership: M_FORBIDDEN: @irc_Fab_78:simosnap.com not in room !eaEUdoxhGkZcQRbfdh:simosnap.com.
Aug 3 13:49:11 vps733892 node[18994]: 2020-08-03 13:49:11 ERROR:MembershipQueue Failed to handle membership: M_FORBIDDEN: @irc_Fab_78:simosnap.com not in room !eaEUdoxhGkZcQRbfdh:simosnap.com.
Aug 3 13:49:11 vps733892 node[18994]: 2020-08-03 13:49:11 ERROR:MembershipQueue Failed to handle membership: M_FORBIDDEN: @irc_Fab_78:simosnap.com not in room !eaEUdoxhGkZcQRbfdh:simosnap.com.
Aug 3 13:49:16 vps733892 node[18994]: 2020-08-03 13:49:16 ERROR:IrcBridge [-] PUT https://matrix.simosnap.com/_matrix/client/r0/rooms/!eaEUdoxhGkZcQRbfdh%3Asimosnap.com/send/m.room.message/m1596455356129.2 (@irc_Frizzantinadolce25:simosnap.com) HTTP 403 Error: "{\"errcode\":\"M_FORBIDDEN\",\"error\":\"User @irc_Frizzantinadolce25:simosnap.com not in room !eaEUdoxhGkZcQRbfdh:simosnap.com (<FrozenEventV3 event_id='$sczS_7C6tbMWp4M72XPgFI-m1Y0IHR8MnFh9UJrQMeY', type='m.room.member', state_key='@irc_Frizzantinadolce25:simosnap.com'>)\"}"
Aug 3 13:49:20 vps733892 node[18994]: 2020-08-03 13:49:20 ERROR:IrcBridge [-] POST https://matrix.simosnap.com/_matrix/client/r0/register (AS) HTTP 400 Error: "{\"errcode\":\"M_USER_IN_USE\",\"error\":\"User ID already taken.\"}"
Aug 3 13:49:27 vps733892 node[18994]: 2020-08-03 13:49:27 ERROR:IrcBridge [-] PUT https://matrix.simosnap.com/_matrix/client/r0/rooms/!eaEUdoxhGkZcQRbfdh%3Asimosnap.com/send/m.room.message/m1596455367370.0 (@irc_Sara:simosnap.com) HTTP 403 Error: "{\"errcode\":\"M_FORBIDDEN\",\"error\":\"User @irc_Sara:simosnap.com not in room !eaEUdoxhGkZcQRbfdh:simosnap.com (<FrozenEventV3 event_id='$XiHs0vzQOxYi8dCJpAlLuFiAsIAzfGweHqbWPYlOhlA', type='m.room.member', state_key='@irc_Sara:simosnap.com'>)\"}"
Aug 3 13:49:33 vps733892 node[18994]: 2020-08-03 13:49:33 ERROR:IrcBridge [-] POST https://matrix.simosnap.com/_matrix/client/r0/register (AS) HTTP 400 Error: "{\"errcode\":\"M_USER_IN_USE\",\"error\":\"User ID already taken.\"}"
Aug 3 13:49:34 vps733892 node[18994]: 2020-08-03 13:49:34 ERROR:IrcBridge [-] POST https://matrix.simosnap.com/_matrix/client/r0/rooms/!MbUEttqEpDiQtWUKCe%3Asimosnap.com/leave (@irc_Carloss:simosnap.com) HTTP 403 Error: "{\"errcode\":\"M_FORBIDDEN\",\"error\":\"@irc_Carloss:simosnap.com not in room !MbUEttqEpDiQtWUKCe:simosnap.com.\"}"
Aug 3 13:49:34 vps733892 node[18994]: 2020-08-03 13:49:34 ERROR:MembershipQueue Failed to handle membership: M_FORBIDDEN: @irc_Carloss:simosnap.com not in room !MbUEttqEpDiQtWUKCe:simosnap.com.
Aug 3 13:49:34 vps733892 node[18994]: 2020-08-03 13:49:34 ERROR:IrcBridge [-] POST https://matrix.simosnap.com/_matrix/client/r0/register (AS) HTTP 400 Error: "{\"errcode\":\"M_USER_IN_USE\",\"error\":\"User ID already taken.\"}"
Aug 3 13:49:50 vps733892 node[18994]: 2020-08-03 13:49:50 ERROR:IrcBridge [-] POST https://matrix.simosnap.com/_matrix/client/r0/register (AS) HTTP 400 Error: "{\"errcode\":\"M_USER_IN_USE\",\"error\":\"User ID already taken.\"}"
H7-25
on 3 Aug 2020
Related issues
NickHu
路
6Comments
SohumB
路
3Comments
rcurtin
路
5Comments
turt2live
路
5Comments
Nick-Hall
路
3Comments