search

mautrix / telegram

A Matrix-Telegram hybrid puppeting/relaybot bridge
https://matrix.to/#/#telegram:maunium.net
GNU Affero General Public License v3.0
1.3k stars 172 forks source link

Double puppeting access token invalidation #439

Open stfnnklv opened 4 years ago

stfnnklv commented 4 years ago

Hello,

With double puppeting enabled, in case the access token becomes invalid, the bridge continues to try to use it, throwing warnings and errors in the log, but neither attempts to login again (if login_shared_secret is enabled) or logout completely. If the bridge process is restarted and login_shared_secret is enabled, the access token is regenerated and double puppeting is working fine again. If you send "ping-matrix" command to the bot, it replies with "Your access token is invalid.". If you "ping-matrix" again, the reply is "You are not logged in with your Matrix account.", although the access_token and custom_mxid remain in the puppet table in the database. So after the process is restarted, they are loaded again. Before that restart, everything behaves as if double puppeting is disabled.

Please find relevant logs:

[2020-03-07 19:23:43,451] [ERROR@mau.user.@snikolov:<redacted>] Failed to handle Telegram update UpdateShortMessage(id=163671, user_id=<redacted>, message='789', pts=270445, pts_count=1, date=datetime.datetime(2020, 3, 7, 17, 23, 43, tzinfo=datetime.timezone.utc), out=True, mentioned=False, media_unread=False, silent=False, fwd_from=None, via_bot_id=None, reply_to_msg_id=None, entities=[])
Traceback (most recent call last):
  File "/opt/mautrix-telegram/lib/python3.7/site-packages/mautrix_telegram/abstract_user.py", line 194, in _update_catch
    await self._update(update)
  File "/opt/mautrix-telegram/lib/python3.7/site-packages/mautrix_telegram/abstract_user.py", line 241, in _update
    await self.update_message(update)
  File "/opt/mautrix-telegram/lib/python3.7/site-packages/mautrix_telegram/abstract_user.py", line 441, in update_message
    return await portal.handle_telegram_message(self, sender, update)
  File "/opt/mautrix-telegram/lib/python3.7/site-packages/mautrix_telegram/portal/telegram.py", line 445, in handle_telegram_message
    event_id = await self.handle_telegram_text(source, intent, is_bot, evt)
  File "/opt/mautrix-telegram/lib/python3.7/site-packages/mautrix_telegram/portal/telegram.py", line 228, in handle_telegram_text
    return await intent.send_message(self.mxid, content, timestamp=evt.date)
  File "/opt/mautrix-telegram/lib/python3.7/site-packages/mautrix/appservice/api/intent.py", line 87, in wrapper
    return await __method(*args, **kwargs)
  File "/opt/mautrix-telegram/lib/python3.7/site-packages/mautrix/appservice/api/intent.py", line 290, in send_message_event
    return await super().send_message_event(room_id, event_type, content, **kwargs)
  File "/opt/mautrix-telegram/lib/python3.7/site-packages/mautrix/client/api/events.py", line 294, in send_message_event
    resp = await self.api.request(Method.PUT, url, content, **kwargs)
  File "/opt/mautrix-telegram/lib/python3.7/site-packages/mautrix/api/http.py", line 205, in request
    return await self._send(method, endpoint, content, query_params, headers or {})
  File "/opt/mautrix-telegram/lib/python3.7/site-packages/mautrix/api/http.py", line 146, in _send
    errcode=errcode, message=message)
mautrix.errors.request.MUnknownToken: Unrecognised access token
[2020-03-07 19:26:32,482] [ERROR@mau.user.bot] Failed to handle Telegram update UpdateNewChannelMessage(message=Message(id=25, to_id=PeerChannel(channel_id=1440481172), date=datetime.datetime(2020, 3, 7, 17, 26, 32, tzinfo=datetime.timezone.utc), message='sdfgh', out=False, mentioned=False, media_unread=False, silent=False, post=False, from_scheduled=False, legacy=False, edit_hide=False, from_id=<redacted>, fwd_from=None, via_bot_id=None, reply_to_msg_id=None, media=None, reply_markup=None, entities=[], views=None, edit_date=None, post_author=None, grouped_id=None, restriction_reason=[]), pts=26, pts_count=1)
Traceback (most recent call last):
  File "/opt/mautrix-telegram/lib/python3.7/site-packages/mautrix_telegram/abstract_user.py", line 194, in _update_catch
    await self._update(update)
  File "/opt/mautrix-telegram/lib/python3.7/site-packages/mautrix_telegram/abstract_user.py", line 241, in _update
    await self.update_message(update)
  File "/opt/mautrix-telegram/lib/python3.7/site-packages/mautrix_telegram/abstract_user.py", line 441, in update_message
    return await portal.handle_telegram_message(self, sender, update)
  File "/opt/mautrix-telegram/lib/python3.7/site-packages/mautrix_telegram/portal/telegram.py", line 445, in handle_telegram_message
    event_id = await self.handle_telegram_text(source, intent, is_bot, evt)
  File "/opt/mautrix-telegram/lib/python3.7/site-packages/mautrix_telegram/portal/telegram.py", line 228, in handle_telegram_text
    return await intent.send_message(self.mxid, content, timestamp=evt.date)
  File "/opt/mautrix-telegram/lib/python3.7/site-packages/mautrix/appservice/api/intent.py", line 87, in wrapper
    return await __method(*args, **kwargs)
  File "/opt/mautrix-telegram/lib/python3.7/site-packages/mautrix/appservice/api/intent.py", line 290, in send_message_event
    return await super().send_message_event(room_id, event_type, content, **kwargs)
  File "/opt/mautrix-telegram/lib/python3.7/site-packages/mautrix/client/api/events.py", line 294, in send_message_event
    resp = await self.api.request(Method.PUT, url, content, **kwargs)
  File "/opt/mautrix-telegram/lib/python3.7/site-packages/mautrix/api/http.py", line 205, in request
    return await self._send(method, endpoint, content, query_params, headers or {})
  File "/opt/mautrix-telegram/lib/python3.7/site-packages/mautrix/api/http.py", line 146, in _send
    errcode=errcode, message=message)
mautrix.errors.request.MUnknownToken: Unrecognised access token
[2020-03-07 19:23:31,206] [WARNING@mau.puppet.<redacted>] Syncer for @snikolov:<redacted> errored: Unrecognised access token. Waiting for 1 seconds...
[2020-03-07 19:23:32,214] [WARNING@mau.puppet.<redacted>] Syncer for @snikolov:<redacted> errored: Unrecognised access token. Waiting for 4 seconds...
[2020-03-07 19:23:36,221] [WARNING@mau.puppet.<redacted>] Syncer for @snikolov:<redacted> errored: Unrecognised access token. Waiting for 9 seconds...
[2020-03-07 19:23:45,235] [WARNING@mau.puppet.<redacted>] Syncer for @snikolov:<redacted> errored: Unrecognised access token. Waiting for 16 seconds...
[2020-03-07 19:24:01,245] [WARNING@mau.puppet.<redacted>] Syncer for @snikolov:<redacted> errored: Unrecognised access token. Waiting for 25 seconds...
[2020-03-07 19:24:26,264] [WARNING@mau.puppet.<redacted>] Syncer for @snikolov:<redacted> errored: Unrecognised access token. Waiting for 36 seconds...
[2020-03-07 19:25:02,279] [WARNING@mau.puppet.<redacted>] Syncer for @snikolov:<redacted> errored: Unrecognised access token. Waiting for 49 seconds...
[2020-03-07 19:25:51,304] [WARNING@mau.puppet.<redacted>] Syncer for @snikolov:<redacted> errored: Unrecognised access token. Waiting for 64 seconds...
[2020-03-07 19:26:55,325] [WARNING@mau.puppet.<redacted>] Syncer for @snikolov:<redacted> errored: Unrecognised access token. Waiting for 81 seconds...

After restart of the process:

[2020-03-07 19:19:27,114] [ERROR@mau.puppet.<redacted>] Failed to initialize custom mxid
Traceback (most recent call last):
  File "/opt/mautrix-telegram/lib/python3.7/site-packages/mautrix/bridge/custom_puppet.py", line 165, in try_start
    await self.start()
  File "/opt/mautrix-telegram/lib/python3.7/site-packages/mautrix/bridge/custom_puppet.py", line 188, in start
    raise InvalidAccessToken()
mautrix.bridge.custom_puppet.InvalidAccessToken: The given access token was invalid.
.........
[2020-03-07 19:19:27,840] [DEBUG@mau.puppet.<redacted>] Logged in for @snikolov:<redacted> using shared secret

If you decide to "ping-matrix" twice:

[2020-03-07 19:03:45,793] [DEBUG@mau.mx] Received event: MessageEvent(type=EventType("m.room.message", EventType.Class.MESSAGE), room_id='!gdlzHglLNRfMhnjzKu:<redacted>', event_id='$rlD_rXS001vfngeuQGqbwC3sxCsVBdvZ8_9V7ZQsekE', sender='@snikolov:<redacted>', timestamp=1583600625715, content=TextMessageEventContent(msgtype=m.text, body='ping-matrix', external_url=None, _relates_to=None, format=None, formatted_body=None), unsigned=MessageUnsigned(age=73, transaction_id=None))
[2020-03-07 19:03:45,794] [DEBUG@mau.mx] Received Matrix event "TextMessageEventContent(msgtype=m.text, body='ping-matrix', external_url=None, _relates_to=None, format=None, formatted_body=None)" from @snikolov:<redacted> in !gdlzHglLNRfMhnjzKu:<redacted>
[2020-03-07 19:03:45,797] [DEBUG@mau.as.api.bot] GET /_matrix/client/r0/rooms/%21gdlzHglLNRfMhnjzKu%3A<redacted>/joined_members {}
[2020-03-07 19:03:45,798] [INFO@aiohttp.access] 127.0.0.1 [07/Mar/2020:17:03:45 +0000] "PUT /transactions/5614?access_token=<redacted> HTTP/1.1" 200 158 "-" "Synapse/1.11.0"
[2020-03-07 19:03:45,803] [DEBUG@mau.as.api.@snikolov:<redacted>] GET /_matrix/client/r0/account/whoami {}
[2020-03-07 19:03:45,816] [DEBUG@mau.as.api.bot] PUT /_matrix/client/r0/rooms/%21gdlzHglLNRfMhnjzKu%3A<redacted>/send/m.room.message/11583600625816 {"msgtype": "m.notice", "body": "Your access token is invalid.", "format": "org.matrix.custom.html", "formatted_body": "<p>Your access token is invalid.</p>\n"}
[2020-03-07 19:03:45,886] [INFO@aiohttp.access] 127.0.0.1 [07/Mar/2020:17:03:45 +0000] "PUT /transactions/5615?access_token=<redacted> HTTP/1.1" 200 158 "-" "Synapse/1.11.0"
[2020-03-07 19:03:49,552] [DEBUG@mau.mx] Received event: MessageEvent(type=EventType("m.room.message", EventType.Class.MESSAGE), room_id='!gdlzHglLNRfMhnjzKu:<redacted>', event_id='$BiCBnyC255ofMCk71wrKEo0S08xInV1_MzdAWzzQNzM', sender='@snikolov:<redacted>', timestamp=1583600629477, content=TextMessageEventContent(msgtype=m.text, body='ping-matrix', external_url=None, _relates_to=None, format=None, formatted_body=None), unsigned=MessageUnsigned(age=72, transaction_id=None))
[2020-03-07 19:03:49,553] [DEBUG@mau.mx] Received Matrix event "TextMessageEventContent(msgtype=m.text, body='ping-matrix', external_url=None, _relates_to=None, format=None, formatted_body=None)" from @snikolov:<redacted> in !gdlzHglLNRfMhnjzKu:<redacted>
[2020-03-07 19:03:49,555] [DEBUG@mau.as.api.bot] GET /_matrix/client/r0/rooms/%21gdlzHglLNRfMhnjzKu%3A<redacted>/joined_members {}
[2020-03-07 19:03:49,557] [INFO@aiohttp.access] 127.0.0.1 [07/Mar/2020:17:03:49 +0000] "PUT /transactions/5616?access_token=<redacted> HTTP/1.1" 200 158 "-" "Synapse/1.11.0"
[2020-03-07 19:03:49,562] [DEBUG@mau.as.api.bot] PUT /_matrix/client/r0/rooms/%21gdlzHglLNRfMhnjzKu%3A<redacted>/send/m.room.message/21583600629562 {"msgtype": "m.notice", "body": "You are not logged in with your Matrix account.", "format": "org.matrix.custom.html", "formatted_body": "<p>You are not logged in with your Matrix account.</p>\n"}
[2020-03-07 19:03:49,636] [INFO@aiohttp.access] 127.0.0.1 [07/Mar/2020:17:03:49 +0000] "PUT /transactions/5617?access_token=<redacted> HTTP/1.1" 200 158 "-" "Synapse/1.11.0"

Kind regards, Stefan Nikolov

bendschs commented 4 years ago

can confirm this, did not "matrix-logout" before logging out of telegram. now after logging in to telegram i am not able to do "matrix-login": access token is not valid. the same access token works for mautrix-whatsapp though.

on startup of the bridge i get:

Apr 01 05:11:52 mautrix-telegram[10186]: [2020-04-01 05:11:52,895] [ERROR@mau.puppet.51752300] Failed to initialize custom mxid
Apr 01 05:11:52 mautrix-telegram[10186]: Traceback (most recent call last):
Apr 01 05:11:52 mautrix-telegram[10186]:   File "/opt/synapse/lib/python3.7/site-packages/mautrix/bridge/custom_puppet.py", line 165, in try_start
Apr 01 05:11:52 mautrix-telegram[10186]:     await self.start()
Apr 01 05:11:52 mautrix-telegram[10186]:   File "/opt/synapse/lib/python3.7/site-packages/mautrix/bridge/custom_puppet.py", line 186, in start
Apr 01 05:11:52 mautrix-telegram[10186]:     raise InvalidAccessToken()
bendschs commented 4 years ago

any news on this?

Valodim commented 4 years ago

I'm also getting stray occurrences of this. In the logs:

[2020-05-05 23:18:30,891] [ERROR@mau.user.@user:stratum0.org] Failed to automatically enable custom puppet
Traceback (most recent call last):
  File "/home/matrix/mautrix-telegram-0.7.1/mautrix_telegram/user.py", line 213, in post_login
    await puppet.switch_mxid(access_token="auto", mxid=self.mxid)
  File "/home/matrix/matrix-appservice-tg/lib/python3.7/site-packages/mautrix/bridge/custom_puppet.py", line 152, in switch_mxid
    await self.start()
  File "/home/matrix/matrix-appservice-tg/lib/python3.7/site-packages/mautrix/bridge/custom_puppet.py", line 186, in start
    raise InvalidAccessToken()

In chats, not only does double puppeting break but telegram messages are reflected back to matrix after they are (correctly) posted to telegram.