RuntimeError: Called reset_deadline on an entry for which we do not have state

[shuternay]

Checklist

• [x] The error is in the library's code, and not in my own.
• [x] I have searched for this issue before posting it and there isn't a duplicate.
• [x] I ran pip install -U https://github.com/LonamiWebs/Telethon/archive/v1.24.zip and triggered the bug in the latest commit of v1.24.

Code that causes the issue

I'm running this code for a bot which is a member of a channel.

#!/usr/bin/env python3
from telethon import TelegramClient

import logging
logging.basicConfig(format='[%(levelname) 5s/%(asctime)s] %(name)s: %(message)s', level=logging.INFO)

session = "test"
api_id = ...
api_hash = ...
token = ...


# to make it reproduce faster, but the problem occurs without it as well
from telethon._updates import messagebox
messagebox.NO_UPDATES_TIMEOUT = 60


async def handler(update):
    print(update)

client = TelegramClient(session, api_id, api_hash, catch_up=True)
client.start(bot_token=token)
client.add_event_handler(handler)
client.run_until_disconnected()

Traceback

[ 20:40:20,764] telethon.network.mtprotosender: Connecting to 149.154.167.51:443/TcpFull...
[ 20:40:20,853] telethon.network.mtprotosender: Connection to 149.154.167.51:443/TcpFull complete!
[ 20:40:21,090] telethon.client.updates: Getting difference for account updates
[ 20:41:20,923] telethon.client.updates: Timeout waiting for updates expired
[ 20:41:20,924] telethon.client.updates: Timeout waiting for updates expired
[ 20:41:20,925] telethon.client.updates: Getting difference for account updates
...
[ 20:41:22,139] telethon.client.updates: Getting difference for channel updates
[ 20:41:22,243] telethon.client.updates: Timeout waiting for updates expired
[ 20:41:22,244] telethon.client.updates: Getting difference for account updates
[ERROR/2022-07-15 20:41:22,348] telethon.client.updates: Fatal error handling updates (this is a bug in Telethon, please report it)
Traceback (most recent call last):
  File "/home/user/miniconda3/envs/py39/lib/python3.9/site-packages/telethon/client/updates.py", line 275, in _update_loop
    updates, users, chats = self._message_box.apply_difference(diff, self._mb_entity_cache)
  File "/home/user/miniconda3/envs/py39/lib/python3.9/site-packages/telethon/_updates/messagebox.py", line 590, in apply_difference
    self.end_get_diff(ENTRY_SECRET)
  File "/home/user/miniconda3/envs/py39/lib/python3.9/site-packages/telethon/_updates/messagebox.py", line 362, in end_get_diff
    self.reset_deadline(entry, next_updates_deadline())
  File "/home/user/miniconda3/envs/py39/lib/python3.9/site-packages/telethon/_updates/messagebox.py", line 277, in reset_deadline
    raise RuntimeError('Called reset_deadline on an entry for which we do not have state')
RuntimeError: Called reset_deadline on an entry for which we do not have state
^C[ 20:42:03,002] telethon.network.mtprotosender: Disconnecting from 149.154.167.51:443/TcpFull...
[ 20:42:03,002] telethon.network.mtprotosender: Disconnection from 149.154.167.51:443/TcpFull complete!
[ 20:42:03,003] telethon.network.mtprotosender: Not disconnecting (already have no connection)

Traceback with debug prints

I've logged requests sent to telegram (telethon.client.users: request ... -> ...response...) and calls to some MessageBox' methods with values of some fields/variables afterwards.

[ 20:40:20,764] telethon.network.mtprotosender: Connecting to 149.154.167.51:443/TcpFull...
[ 20:40:20,853] telethon.network.mtprotosender: Connection to 149.154.167.51:443/TcpFull complete!

[ 20:40:21,090] telethon.client.updates: Getting difference for account updates
[ 20:40:21,187] users: request {'_': 'GetUsersRequest', 'id': [{'_': 'InputUserSelf'}]} -> [{'_': 'User', ... my bot}]
State(pts=783, qts=622502475, date=datetime(2022, 7, 15, 17, 40, 11, tz=utc), seq=101, unread_count=0)
[ 20:40:21,200] users: request {'_': 'GetDifferenceRequest', 'pts': 783, 'date': datetime(2022, 7, 15, 20, 40, 11, tz=utc), 'qts': 622502475, 'pts_total_limit': None} -> {'_': 'DifferenceEmpty', 'date': datetime(2022, 7, 15, 17, 40, 21, tz=utc), 'seq': 101}
[ 20:40:21,200] messagebox: apply_difference({'_': 'DifferenceEmpty', 'date': datetime(2022, 7, 15, 17, 40, 21, tz=utc), 'seq': 101}, <EntityCache object>)
[ 20:40:21,200] messagebox: self.getting_diff_for before: {<class 'ENTRY_ACCOUNT'>}
[ 20:40:21,200] messagebox: self.getting_diff_for after: {<class 'ENTRY_ACCOUNT'>}
[ 20:40:21,200] messagebox: end_get_diff(<class 'ENTRY_ACCOUNT'>)
[ 20:40:21,200] messagebox: self.getting_diff_for: set()
[ 20:40:21,200] messagebox: reset_deadline(<class 'ENTRY_ACCOUNT'>, 183497.98), time from now: 59.99999814899638
[ 20:40:21,201] messagebox: self.next_deadline: <class 'ENTRY_ACCOUNT'>
[ 20:40:21,201] messagebox: self.map: {<class 'ENTRY_ACCOUNT'>: State(pts=783, deadline=183497.65), <class 'ENTRY_SECRET'>: State(pts=622502475, deadline=183497.65), 1234567890: State(pts=6410, deadline=183497.65)}

[ 20:40:21,282] users: request {'_': 'GetStateRequest'} -> {'_': 'State', 'pts': 783, 'qts': 622502475, 'date': datetime(2022, 7, 15, 17, 40, 21, tz=utc), 'seq': 101, 'unread_count': 313}

# init finished, waiting NO_UPDATES_TIMEOUT until the first update

[ 20:41:20,923] telethon.client.updates: Timeout waiting for updates expired

[ 20:41:20,924] telethon.client.updates: Timeout waiting for updates expired

[ 20:41:20,925] telethon.client.updates: Getting difference for account updates
[ 20:41:21,017] users: request {'_': 'GetDifferenceRequest', 'pts': 783, 'date': datetime(2022, 7, 15, 17, 40, 21, tz=utc), 'qts': 622502475, 'pts_total_limit': None} -> {'_': 'DifferenceEmpty', 'date': datetime(2022, 7, 15, 17, 41, 20, tz=utc), 'seq': 101}
[ 20:41:21,018] messagebox: apply_difference({'_': 'DifferenceEmpty', 'date': datetime(2022, 7, 15, 17, 41, 20, tz=utc), 'seq': 101}, <EntityCache object>)
[ 20:41:21,018] messagebox: self.getting_diff_for before: {<class 'ENTRY_SECRET'>, 1234567890, <class 'ENTRY_ACCOUNT'>}
[ 20:41:21,018] messagebox: self.getting_diff_for after: {<class 'ENTRY_SECRET'>, 1234567890, <class 'ENTRY_ACCOUNT'>}
[ 20:41:21,018] messagebox: end_get_diff(<class 'ENTRY_ACCOUNT'>)
[ 20:41:21,018] messagebox: self.getting_diff_for: {<class 'ENTRY_SECRET'>, 1234567890}
[ 20:41:21,018] messagebox: reset_deadline(<class 'ENTRY_ACCOUNT'>, 183557.80), time from now: 59.99999836500501
[ 20:41:21,018] messagebox: self.next_deadline: <class 'ENTRY_ACCOUNT'>
[ 20:41:21,018] messagebox: self.map: {<class 'ENTRY_ACCOUNT'>: State(pts=783, deadline=183497.65), <class 'ENTRY_SECRET'>: State(pts=622502475, deadline=183497.65), 1234567890: State(pts=6410, deadline=183497.65)}
[ 20:41:21,018] messagebox: end_get_diff(<class 'ENTRY_SECRET'>)
[ 20:41:21,018] messagebox: self.getting_diff_for: {1234567890}
[ 20:41:21,018] messagebox: reset_deadline(<class 'ENTRY_SECRET'>, 183557.80), time from now: 59.99999904300785
[ 20:41:21,018] messagebox: self.next_deadline: <class 'ENTRY_ACCOUNT'>
[ 20:41:21,018] messagebox: self.map: {<class 'ENTRY_ACCOUNT'>: State(pts=783, deadline=183497.65), <class 'ENTRY_SECRET'>: State(pts=622502475, deadline=183497.65), 1234567890: State(pts=6410, deadline=183497.65)}

... ~10 empty differences skipped ...

[ 20:41:22,138] messagebox: get_channel_difference()
[ 20:41:22,138] messagebox: self.getting_diff_for: {1234567890}
[ 20:41:22,139] messagebox: entry: 1234567890
[ 20:41:22,139] telethon.client.updates: Getting difference for channel updates
[ 20:41:22,242] users: request {'_': 'GetChannelDifferenceRequest', 'channel': {'_': 'InputChannel', 'channel_id': 1234567890, ...}, 'filter': {...}, 'pts': 6410, 'limit': 100, 'force': False} -> {'_': 'ChannelDifferenceEmpty', 'pts': 6410, 'final': True, 'timeout': 30}
[ 20:41:22,242] messagebox: end_get_diff(1234567890)
[ 20:41:22,242] messagebox: self.getting_diff_for: set()
[ 20:41:22,242] messagebox: reset_deadline(1234567890, 183559.027), time from now: 59.999995702004526
[ 20:41:22,242] messagebox: self.next_deadline: <class 'ENTRY_ACCOUNT'>
[ 20:41:22,243] messagebox: self.map: {<class 'ENTRY_ACCOUNT'>: State(pts=783, deadline=183497.65), <class 'ENTRY_SECRET'>: State(pts=622502475, deadline=183497.65), 1234567890: State(pts=6410, deadline=183497.65)}

[ 20:41:22,243] telethon.client.updates: Timeout waiting for updates expired

# The first nonempty Difference response. For some reason it has qts=0

[ 20:41:22,244] telethon.client.updates: Getting difference for account updates
[ 20:41:22,344] users: request {'_': 'GetDifferenceRequest', 'pts': 783, 'date': datetime(2022, 7, 15, 17, 41, 22, tz=utc), 'qts': 622502475, 'pts_total_limit': None} -> {'_': 'Difference', 'new_messages': [], 'new_encrypted_messages': [], 'other_updates': [], 'chats': [], 'users': [], 'state': {'_': 'State', 'pts': 783, 'qts': 0, 'date': datetime(2022, 7, 15, 17, 41, 22, tz=utc), 'seq': 101, 'unread_count': 313}}
[ 20:41:22,344] messagebox: apply_difference({'_': 'Difference', 'new_messages': [], 'new_encrypted_messages': [], 'other_updates': [], 'chats': [], 'users': [], 'state': {'_': 'State', 'pts': 783, 'qts': 0, 'date': datetime(2022, 7, 15, 17, 41, 22, tz=utc), 'seq': 101, 'unread_count': 313}}, <EntityCache object>)

# here we are inside of apply_difference() and call set_state() which removes ENTRY_SECRET from self.map. self.getting_diff_for doesn't change

[ 20:41:22,345] messagebox: self.getting_diff_for before: {1234567890, <class 'ENTRY_SECRET'>, <class 'ENTRY_ACCOUNT'>}
[ 20:41:22,345] messagebox: set_state(State(pts=783, qts=0, date=datetime(2022, 7, 15, 17, 41, 22, tz=utc), seq=101, unread_count=313))
[ 20:41:22,346] messagebox: self.map before: {<class 'ENTRY_ACCOUNT'>: State(pts=783, deadline=183497.65), <class 'ENTRY_SECRET'>: State(pts=622502475, deadline=183497.65), 1234567890: State(pts=6410, deadline=183497.65)}
[ 20:41:22,346] messagebox: self.map after: {<class 'ENTRY_ACCOUNT'>: State(pts=783, deadline=183559.130), 1234567890: State(pts=6410, deadline=183497.65)}
[ 20:41:22,346] messagebox: self.getting_diff_for (before `if finish`): {1234567890, <class 'ENTRY_SECRET'>, <class 'ENTRY_ACCOUNT'>}

[ 20:41:22,346] messagebox: end_get_diff(<class 'ENTRY_ACCOUNT'>)
[ 20:41:22,346] messagebox: self.getting_diff_for: {1234567890, <class 'ENTRY_SECRET'>}
[ 20:41:22,347] messagebox: reset_deadline(<class 'ENTRY_ACCOUNT'>, 183559.131), time from now: 59.999996147991624
[ 20:41:22,347] messagebox: self.next_deadline: <class 'ENTRY_ACCOUNT'>
[ 20:41:22,347] messagebox: self.map: {<class 'ENTRY_ACCOUNT'>: State(pts=783, deadline=183559.130), 1234567890: State(pts=6410, deadline=183497.65)}

[ 20:41:22,347] messagebox: end_get_diff(<class 'ENTRY_SECRET'>)
[ 20:41:22,347] messagebox: self.getting_diff_for: {1234567890}
[ 20:41:22,347] messagebox: reset_deadline(<class 'ENTRY_SECRET'>, 183559.132), time from now: 59.999996463011485
[ 20:41:22,348] messagebox: self.next_deadline: 1234567890
[ 20:41:22,348] messagebox: self.map: {<class 'ENTRY_ACCOUNT'>: State(pts=783, deadline=183559.130), 1234567890: State(pts=6410, deadline=183497.65)}
[ERROR/2022-07-15 20:41:22,348] telethon.client.updates: Fatal error handling updates (this is a bug in Telethon, please report it)
Traceback (most recent call last):
  File "/home/user/miniconda3/envs/py39/lib/python3.9/site-packages/telethon/client/updates.py", line 275, in _update_loop
    updates, users, chats = self._message_box.apply_difference(diff, self._mb_entity_cache)
  File "/home/user/miniconda3/envs/py39/lib/python3.9/site-packages/telethon/_updates/messagebox.py", line 590, in apply_difference
    self.end_get_diff(ENTRY_SECRET)
  File "/home/user/miniconda3/envs/py39/lib/python3.9/site-packages/telethon/_updates/messagebox.py", line 362, in end_get_diff
    self.reset_deadline(entry, next_updates_deadline())
  File "/home/user/miniconda3/envs/py39/lib/python3.9/site-packages/telethon/_updates/messagebox.py", line 277, in reset_deadline
    raise RuntimeError('Called reset_deadline on an entry for which we do not have state')
RuntimeError: Called reset_deadline on an entry for which we do not have state
^C[ 20:42:03,002] telethon.network.mtprotosender: Disconnecting from 149.154.167.51:443/TcpFull...
[ 20:42:03,002] telethon.network.mtprotosender: Disconnection from 149.154.167.51:443/TcpFull complete!
[ 20:42:03,003] telethon.network.mtprotosender: Not disconnecting (already have no connection)

It seems the following happens: First GetStateRequest call returns non-zero qts, so we have ENTRY_SECRET in MessageBox.map After some time we receive a nonempty response to GetDifferenceRequest, which has qts=0. That moment, telethon first calls set_state, which removes ENTRY_SECRET from MessageBox.map, and then calls self.end_get_diff(ENTRY_SECRET) which expects ENTRY_SECRET to be in MessageBox.map.

I don't quite understand, what qts means for the bots and why it behaves this way, but may be the problem can be fixed by also removing ENTRY_SECRET from MessageBox.getting_diff_for in set_state if qts=0.

Another problem with MessageBox is that at some moment it starts spamming with Getting difference for channel updates / telethon.client.updates: Timeout waiting for updates expired. I guess it happens, because deadline is never updated for the channels in MessageBox.map, but I'm not quite sure.

Finally, it makes sense to re-raise the exception here, because now the bot continues running without processing new updates, so I had to notice the error and restart it by hand each time.