Telethon: Using spawn_read_thread=False gives problems in Telethon v0.16

[xates]

I have this piece of code which used to work in Telethon v0.15.5.7. I have updated Telethon to v0.16.1 but it doesn't work anymore. I have only replaced the old authorization procedure with the new client.start().

client = TelegramClient(session_name, api_id, api_hash,
                        update_workers=1, spawn_read_thread=False)
client.start(phone)


def callback(update):
    if isinstance(update, UpdateNewChannelMessage):
        print('Received message:', update.message.message)
        client(ForwardMessagesRequest(
            from_peer=client.get_input_entity(update.message.to_id),
            id=[update.message.id],
            to_peer=InputPeerSelf()
        ))


client.add_update_handler(callback)
client.idle()
client.disconnect()

It seems that the problem is when using ForwardMessagesRequest (maybe also other requests, but I have not tried) in conjunction with spawn_read_thread=False.

This is the output of the program with the error and logging enabled:

INFO:telethon.telegram_bare_client:Connecting to 149.154.167.91:443...
INFO:telethon.telegram_bare_client:Connection success!
DEBUG:telethon.telegram_bare_client:Invoking GetStateRequest
INFO:telethon.telegram_bare_client:Initializing a new connection while invoking
DEBUG:telethon.network.mtproto_sender:Processing BadServerSalt result
DEBUG:telethon.network.mtproto_sender:Processing container result
DEBUG:telethon.network.mtproto_sender:Processing NewSessionCreated result
DEBUG:telethon.network.mtproto_sender:Processing MsgsAck result
DEBUG:telethon.network.mtproto_sender:Processing Remote Procedure Call result
DEBUG:telethon.update_state:Saved new updates state
INFO:telethon.telegram_bare_client:Idling to receive items from the network
DEBUG:telethon.telegram_bare_client:Receiving items from the network...
DEBUG:telethon.network.mtproto_sender:Processing UpdateShort result
DEBUG:telethon.telegram_bare_client:Receiving items from the network...
DEBUG:telethon.network.mtproto_sender:Processing UpdateShort result
DEBUG:telethon.telegram_bare_client:Receiving items from the network...
INFO:telethon.telegram_bare_client:Receiving items from the network timed out
DEBUG:telethon.telegram_bare_client:Receiving items from the network...
DEBUG:telethon.network.mtproto_sender:Processing Updates result
DEBUG:telethon.telegram_bare_client:Receiving items from the network...
Received message: First test message
DEBUG:telethon.telegram_bare_client:Invoking ForwardMessagesRequest
DEBUG:telethon.network.mtproto_sender:Processing Remote Procedure Call result
INFO:telethon.telegram_bare_client:Receiving items from the network timed out
DEBUG:telethon.telegram_bare_client:Receiving items from the network...
DEBUG:telethon.network.mtproto_sender:Processing Updates result
DEBUG:telethon.telegram_bare_client:Receiving items from the network...
Received message: Second test message
DEBUG:telethon.telegram_bare_client:Invoking ForwardMessagesRequest
Traceback (most recent call last):
  File "test_v16.py", line 33, in <module>
    client.idle()
  File "/home/emilio/telethon_v16/lib/python3.5/site-packages/telethon/telegram_bare_client.py", line 849, in idle
    self._sender.receive(update_state=self.updates)
  File "/home/emilio/telethon_v16/lib/python3.5/site-packages/telethon/network/mtproto_sender.py", line 130, in receive
    body = self.connection.recv()
  File "/home/emilio/telethon_v16/lib/python3.5/site-packages/telethon/network/connection.py", line 184, in _recv_tcp_full
    body = self.read(packet_len - 12)
  File "/home/emilio/telethon_v16/lib/python3.5/site-packages/telethon/network/connection.py", line 277, in _read_plain
    return self.conn.read(length)
  File "/home/emilio/telethon_v16/lib/python3.5/site-packages/telethon/extensions/tcp_client.py", line 146, in read
    with BufferedWriter(BytesIO(), buffer_size=size) as buffer:
ValueError: buffer size must be strictly positive

It sometimes crashes at the first, sometimes at the second or at the third message

[andreif]

My code stopped working on master, getting Receiving items from the network timed out.
After checking out 0.15.5 works again. Any idea where to look for debugging it?

[andreif]

I found that it started to spam after c848ae0ace8a6d496fdb52a7f8a0519d0259d839.
@Lonami anything serious or it can be ignored?

[Lonami]

Thanks for the investigation @andreif, that commit may indeed have introduced some subtle bugs as reading items is now done a bit more differently. It would be nice to have dumps of the packets to see where the deserialization fails. Such thing is not logged because it'd probably be a privacy violation, but if you can reproduce consistently and nitpick the faulty packet so I can reproduce the deserialization, it'd be nice).

[Lonami]

The print would be something similar for what I made the issue-313 branch, introduced on this commit https://github.com/LonamiWebs/Telethon/commit/98ab4dcc335e9ea890b41acb8c5b03b35daea971 if you would like to help.

[andreif]

I don't get the same exception as @xates. No exception yet, but it's spamming with the warnings so I guess not everything works as expected. I had a long break and need some time to get through recent changes and the code.

[Lonami]

I'll offer all the help I can in order to solve this issue, if you would like to discuss this on Telegram better just let me know.

[bcairns]

Also seeing this error when trying to use client.download_media().

I added some debug output to connection._recv_tcp_full(), it appears to be decoding packet_len_seq into a massive negative number for packet_len, which then causes the read() to fail:

I received UpdateNewMessage(...)
Media photo received
packet_len_seq: b'\x84[\x00\x00\x06\x00\x00\x00'
packet_len: 23428
seq:  6
packet_len_seq: b'\x06\xb3\x1d\xbdQMg^'
packet_len: -1122127098
seq:  1583828305
I received UpdateReadHistoryInbox(peer=PeerUser(user_id=467283630), max_id=64, pts=123, pts_count=1)
packet_len_seq: b'\x06\xb3\x1d\xbdQMg^'
packet_len: -1122127098
seq:  1583828305
Traceback (most recent call last):
  File "test.py", line 65, in <module>
    client.idle()  # ends with Ctrl+C
  File "/usr/local/lib/python3.6/site-packages/telethon/telegram_bare_client.py", line 849, in idle
    self._sender.receive(update_state=self.updates)
  File "/usr/local/lib/python3.6/site-packages/telethon/network/mtproto_sender.py", line 130, in receive
    body = self.connection.recv()
  File "/usr/local/lib/python3.6/site-packages/telethon/network/connection.py", line 188, in _recv_tcp_full
    body = self.read(packet_len - 12)
  File "/usr/local/lib/python3.6/site-packages/telethon/network/connection.py", line 281, in _read_plain
    return self.conn.read(length)
  File "/usr/local/lib/python3.6/site-packages/telethon/extensions/tcp_client.py", line 146, in read
    with BufferedWriter(BytesIO(), buffer_size=size) as buffer:
ValueError: buffer size must be strictly positive

[bcairns]

After chatting with Lonami about this on Telegram, we believe we've identified the issue (in short, there are multiple threads trying to read at the same time). There is an immediate workaround available, and Lonami should be fixing the root cause bug for the next release.

Workaround:

1) Instead of initializing with update_workers=1, spawn_read_thread=False and using client.idle(),

2) Initialize with update_workers=0, spawn_read_thread=True, and then use client.updates.poll()

In other words, the "Using the main thread instead the ReadThread" example from http://telethon.readthedocs.io/en/latest/extra/basic/working-with-updates.html doesn't currently work with 0.16, and you can use the "Spawning no worker at all" approach in the meantime.

[Lonami]

I have pushed v0.16.1.2 to PyPi to address this issue (with the referenced commit), if someone would like to test, I would appreciate much (edit: actually, I'm uploading, and got "Received "503: Service Unavailable" Package upload appears to have failed. Retry 1 of 5"; edit 2, uploaded, hopefully not corrupted).

[xates]

It works for me, thanks!

[Lonami]

Awesome, thanks for the report/collaboration everyone!