search

mautrix / facebook

A Matrix-Facebook Messenger puppeting bridge
https://matrix.to/#/#facebook:maunium.net
GNU Affero General Public License v3.0
389 stars 64 forks source link

log spammed with AssertionError #274

Closed JuniorJPDJ closed 1 year ago

JuniorJPDJ commented 1 year ago 
matrix-mautrix-facebook-1  | 2022-12-09T17:00:50.238941334Z [2022-12-09 17:00:50,238] [ERROR@mau.user.@X:juniorjpdj.pl] Failed to backfill portal X
matrix-mautrix-facebook-1  | 2022-12-09T17:00:50.238981296Z Traceback (most recent call last):
matrix-mautrix-facebook-1  | 2022-12-09T17:00:50.238987953Z   File "/usr/lib/python3.10/site-packages/mautrix_facebook/user.py", line 562, in _handle_backfill_requests_loop
matrix-mautrix-facebook-1  | 2022-12-09T17:00:50.238992116Z     await portal.backfill(self, req)
matrix-mautrix-facebook-1  | 2022-12-09T17:00:50.238996113Z   File "/usr/lib/python3.10/site-packages/mautrix_facebook/portal.py", line 751, in backfill
matrix-mautrix-facebook-1  | 2022-12-09T17:00:50.238999986Z     last_message_timestamp = await self._backfill(source, backfill_request)
matrix-mautrix-facebook-1  | 2022-12-09T17:00:50.239003818Z   File "/usr/lib/python3.10/site-packages/mautrix_facebook/portal.py", line 807, in _backfill
matrix-mautrix-facebook-1  | 2022-12-09T17:00:50.239007692Z     ) = await self.backfill_message_page(source, messages)
matrix-mautrix-facebook-1  | 2022-12-09T17:00:50.239011838Z   File "/usr/lib/python3.10/site-packages/mautrix_facebook/portal.py", line 891, in backfill_message_page
matrix-mautrix-facebook-1  | 2022-12-09T17:00:50.239015625Z     assert self.first_event_id
matrix-mautrix-facebook-1  | 2022-12-09T17:00:50.239019149Z AssertionError

My log is spammed with messages like this (portal ID changes) and I suspect backfill is not happening in other chats due to that - I tried scheduling backfill on other chat and nothing happened in a few days.

AmineI commented 1 year ago

Same here, on a fresh install w/ double puppets, and even after unbridging, no DMs backfill due to self.first_event_id not being initialized :(

tulir commented 1 year ago

Using MSC2716 backfill is currently not recommended, and it's not going to work on rooms created before the feature was added.

AmineI commented 1 year ago

It seems the log spam should have been caught with your work on commit a23f17f , but it seems it doesn't cover all code paths yet - I was looking into this just now 🙂

Using MSC2716 backfill is currently not recommended, and it's not going to work on rooms created before the feature was added.

Oh so it's an issue with MSC2716 ! Makes sense then, thanks for the heads-up !

EDIT : Adding for posterity that this affects DMs backfill only and not groups

AmineI commented 1 year ago

Have looked it this some more. The issue (might not be the original poster's) is unrelated to MSC2716.

The root cause appears to be a failure to create the first_event_id; it is never set - an exception is returned instead because the bridge bot is not in the room. I'm still familiarizing myself with the code, but it seems that the bot is deliberately not being invited (only the puppets are, unless encryption is enabled as default), and that should have been done by the puppet.

I'll continue to look into this later, and hopefully make a PR if I figure it out. Any pointers regarding the expected design would be appreciated. Otherwise: Enabling encryption by default in the bridge config is a viable workaround - No log spams, backfilling works, etc.

Here's a log when initializing the rooms : 

[...]Failed to create portal[...]
2023-03-18T16:40:28.957153118Z mautrix.errors.request.MForbidden: You are not invited to this room.
2023-03-18T16:40:28.957158118Z 
2023-03-18T16:40:28.957163918Z The above exception was the direct cause of the following exception:
2023-03-18T16:40:28.957158118Z 
2023-03-18T16:40:28.957174818Z Traceback (most recent call last):
2023-03-18T16:40:28.957180418Z   File "/usr/lib/python3.10/site-packages/mautrix_facebook/portal.py", line 589, in create_matrix_room
2023-03-18T16:40:28.957198319Z     return await self._create_matrix_room(source, info)
2023-03-18T16:40:28.957205319Z   File "/usr/lib/python3.10/site-packages/mautrix_facebook/portal.py", line 726, in _create_matrix_room
2023-03-18T16:40:28.957211119Z     self.first_event_id = await self.az.intent.send_message_event(
2023-03-18T16:40:28.957216419Z   File "/usr/lib/python3.10/site-packages/mautrix/appservice/api/intent.py", line 140, in wrapper
2023-03-18T16:40:28.957221819Z     await __self.ensure_joined(room_id)
2023-03-18T16:40:28.957227819Z   File "/usr/lib/python3.10/site-packages/mautrix/appservice/api/intent.py", line 587, in ensure_joined
2023-03-18T16:40:28.957233319Z     raise IntentError(f"Failed to join room {room_id} as {self.mxid}") from e
2023-03-18T16:40:28.957240219Z mautrix.errors.base.IntentError: Failed to join room ![REDACTED] as @facebookbot:[REDACTED]
AmineI commented 1 year ago

Nice catch @tulir . The same issue (and quick fix) can be seen here as well https://github.com/mautrix/facebook/blob/fa7f67db2f442630683bcf44435a93324cc16eea/mautrix_facebook/portal.py#L1039

Likely L1213 too for the read receipts