search

LonamiWebs / Telethon

Pure Python 3 MTProto API Telegram client library, for bots too!
https://docs.telethon.dev
MIT License
9.98k stars 1.4k forks source link

Updates mechanism breaks #313

Closed dimitar-petrov closed 6 years ago

dimitar-petrov commented 7 years ago

Hello,

TelegramClient object was created with update_workers = 4. I am receiving the following exception in couple of minutes:

--- Logging error ---     
Traceback (most recent call last):                   
  File "/home/dpetrov/.pyenv/versions/py3play/lib/python3.6/site-packages/telethon/telegram_bare_client.py", line 795, in _recv_thread_impl
    self._sender.receive(update_state=self.updates)  
  File "/home/dpetrov/.pyenv/versions/py3play/lib/python3.6/site-packages/telethon/network/mtproto_sender.py", line 114, in receive
    self._process_msg(remote_msg_id, remote_seq, reader, update_state)                                    
  File "/home/dpetrov/.pyenv/versions/py3play/lib/python3.6/site-packages/telethon/network/mtproto_sender.py", line 187, in _process_msg
    return self._handle_container(msg_id, sequence, reader, state)                                        
  File "/home/dpetrov/.pyenv/versions/py3play/lib/python3.6/site-packages/telethon/network/mtproto_sender.py", line 264, in _handle_container
    for inner_msg_id, _, inner_len in MessageContainer.iter_read(reader):                                 
  File "/home/dpetrov/.pyenv/versions/py3play/lib/python3.6/site-packages/telethon/tl/message_container.py", line 24, in iter_read
    inner_msg_id = reader.read_long()                
  File "/home/dpetrov/.pyenv/versions/py3play/lib/python3.6/site-packages/telethon/extensions/binary_reader.py", line 42, in read_long
    return int.from_bytes(self.read(8), byteorder='little', signed=signed)                                
  File "/home/dpetrov/.pyenv/versions/py3play/lib/python3.6/site-packages/telethon/extensions/binary_reader.py", line 63, in read
    .format(length, len(result), repr(result), repr(self._last))                                          
BufferError: No more data left to read (need 8, got 0: b''); last read b"'\x00\x00\x00"                   

During handling of the above exception, another exception occurred:                                       

Traceback (most recent call last):                   
  File "/home/dpetrov/.pyenv/versions/3.6.3/lib/python3.6/logging/__init__.py", line 992, in emit         
    msg = self.format(record)                        
  File "/home/dpetrov/.pyenv/versions/3.6.3/lib/python3.6/logging/__init__.py", line 838, in format       
    return fmt.format(record)                        
  File "/home/dpetrov/.pyenv/versions/3.6.3/lib/python3.6/logging/__init__.py", line 575, in format       
    record.message = record.getMessage()             
  File "/home/dpetrov/.pyenv/versions/3.6.3/lib/python3.6/logging/__init__.py", line 338, in getMessage   
    msg = msg % self.args 
TypeError: not all arguments converted during string formatting                                           
Call stack:               
  File "/home/dpetrov/.pyenv/versions/3.6.3/lib/python3.6/threading.py", line 884, in _bootstrap          
    self._bootstrap_inner()                          
  File "/home/dpetrov/.pyenv/versions/3.6.3/lib/python3.6/threading.py", line 916, in _bootstrap_inner    
    self.run()            
  File "/home/dpetrov/.pyenv/versions/3.6.3/lib/python3.6/threading.py", line 864, in run                 
    self._target(*self._args, **self._kwargs)        
  File "/home/dpetrov/.pyenv/versions/py3play/lib/python3.6/site-packages/telethon/telegram_bare_client.py", line 808, in _recv_thread_impl
    error                 
Message: '[ERROR] Unknown error on the read thread, please report'                                        
Arguments: (BufferError('No more data left to read (need 8, got 0: b\'\'); last read b"\'\\x00\\x00\\x00"',),)

/just to clarify I am receiving multiple messages from 100+ channels/

Lonami commented 7 years ago

I doubt this has got anything to do with the updates themselves. But still strange. Can you reproduce this issue consistently?

dimitar-petrov commented 7 years ago

Yes, I am able to reproduce it consistently.

Lonami commented 7 years ago

There probably are some errors while deserializing a packet so we would need to log the payload before reading, what we read, and after reading. The logging calls aren't set for that so you would have to do it yourself or wait for me to add a few calls.

dimitar-petrov commented 7 years ago

Sure, please let me know when you add needed logging and I can provide traces.

Lonami commented 7 years ago

Check out this branch https://github.com/LonamiWebs/Telethon/tree/issue-313 and use it to run the project. Not sure how useful this would be but hopefully I can spot the issue with the data. Note that the data probably contains information about the channels like messages, if you don't want to leak it send me a private message on Telegram (I don't need the information itself, just see where it breaks).

dimitar-petrov commented 7 years ago

Here is an excerpt. Is it possible that some special characters are breaking it?

Reading a container with 2 elements, left data is b"\x01|l\xd99\x95\xdcY\n\x01\x00\x00\x14\x00\x00\x00\xc5sw4\x08Q\xa7\xc29\x95\xdcYKm0\x88\xf5\xdf\xd8\x81\x01\x10m\xd99\x95\xdcY\x0b\x01\x00\x00\xbc\x03\x00\x00@B
\xaet\x15\xc4\xb5\x1c\x01\x00\x00\x00\xd9\x04\xbab\x11\xdc\xdd\x90\x80F\x01\x00\x03\x0c\x00\x002\xe5\xdd\xbd_\xbf\x1cD\x03\x95\xdcYWhttps://itsblockchain.com/2017/10/09/will-bitcoin-ever-legally-accepted-currency
-india/\x00\xd6-\xa3\xbc\xb4\x07_\x1f\x00\x00\x00\x0fN\xeb\t\x95%\xd4\x06Whttps://itsblockchain.com/2017/10/09/will-bitcoin-ever-legally-accepted-currency-india/Nitsblockchain.com/2017/10/09/will-bitcoin-ever-leg
ally-accepted-currency-india\x00\x00\x00\x00\x00\x07article\rItsBlockchain\x00\x00:Will Bitcoin ever be a legally accepted currency in India?\x00\x7fCould Bitcoin could become standard currency in India? I\xe2\x8
0\x99ll take an emphatic stand here though and say that it will never be.)\xdd\x88\x92\x00\x00\x00\x00i\x00:\x1b\xa5\x1ad\x07\xaf\xb7mr\x00\xbf\xa9\xd1\xafC\xdbY\x15\xc4\xb5\x1c\x04\x00\x00\x00\x1b\xb6\xbfw\x01s\
x00\x00v\x90\xd6S\x04\x00\x00\x00\xe1\xd7\xf9\x19\x00\x00\x00\x00\x17\xb0\x01\x00\xdfJ@af%\xb0RZ\x00\x00\x003\x00\x00\x00\x9a\x05\x00\x00\x1b\xb6\xbfw\x01m\x00\x00v\x90\xd6S\x04\x00\x00\x00\xe1\xd7\xf9\x19\x00\x0
0\x00\x00\x18\xb0\x01\x00\x1e\xae\xf1?\x11\x0cYZ@\x01\x00\x00\xb4\x00\x00\x00\xf9P\x00\x00\x1b\xb6\xbfw\x01x\x00\x00v\x90\xd6S\x04\x00\x00\x00\xe1\xd7\xf9\x19\x00\x00\x00\x00\x19\xb0\x01\x00\x00\x8e\xebm0\xc9\xa3
\xca \x03\x00\x00\xc2\x01\x00\x00\xcbQ\x01\x00\x1b\xb6\xbfw\x01y\x00\x00v\x90\xd6S\x04\x00\x00\x00\xe1\xd7\xf9\x19\x00\x00\x00\x00\x1a\xb0\x01\x00pNt89\x97\t\x99\xb6\x03\x00\x00\x16\x02\x00\x00\x00\xeb\x01\x00\x1
5\xc4\xb5\x1c\x01\x00\x00\x008%\xd0n\x00\x00\x00\x00W\x00\x00\x00\x01\x00\x00\x00\x08SuperMan\x00\x00\x00\x07#\x00\x00\x01\x00\x00\x00\x15\xc4\xb5\x1c\x00\x00\x00\x00\x15\xc4\xb5\x1c\x01\x00\x00\x00\x1cK\xb4\x0c`
\x10\x00\x00_\xbf\x1cD\x1c\xf0\x9f\x9a\x80\xf0\x9f\x9a\x80 PUMP NITRO \xf0\x9f\x9a\x80\xf0\x9f\x9a\x80\x00\x00\x00\rSuperManPower\x00\x00j'Sav\x90\xd6S\x05\x00\x00\x00\xf0\x17\xcc2\x00\x00\x00\x00\xf3\xac\x02\x00
:\xdd\x83\xf3<\xc3\\\xd8v\x90\xd6S\x05\x00\x00\x00\xf0\x17\xcc2\x00\x00\x00\x00\xf5\xac\x02\x00\xd8|6\xf96\x98WF\xf3\xde\x97Y\x00\x00\x00\x00\x03\x95\xdcY\x00\x00\x00\x00"                                         
(!) Buffer has left b';\x15\xd8\xdb\xbc\x0c\xd3\xf4'                                                                                                                                                                
(!) Buffer has left b'\xd0\xab\xb1:P\x1aX\x80'                                                                                                                                                                      
Reading a container with 4 elements, left data is b"\x01\x90\xba\x1f\xee\x95\xdcY\x10\x01\x00\x00\x14\x00\x00\x00\xc5sw4@\xab\xfc\x14\xee\x95\xdcY+#\x84\x05\xfe\x12\xdc\x1b\x01\xd8\xba\x1f\xee\x95\xdcY\x11\x01\x0
0\x00\x10\x01\x00\x00@B\xaet\x15\xc4\xb5\x1c\x01\x00\x00\x00\xd9\x04\xbab\x11\xdc\xdd\x90\x00D\x01\x00\x87\x01\x00\x002\xe5\xdd\xbd\x89\xe9CD\xc6\x95\xdcYBGET YOUR BITCOINS READY. SELL ALTCOINS TO INVEST IN TODAY
\xe2\x80\x99S HODL\x00\x01\x00\x00\x00\rGreenSharkBot\x00\x00\xce\x01\x00\x00\x01\x00\x00\x00\x15\xc4\xb5\x1c\x00\x00\x00\x00\x15\xc4\xb5\x1c\x01\x00\x00\x00\x1cK\xb4\x0c`\x10\x00\x00\x89\xe9CD\x0fBITTREX SIGNAL$
\x0eBittrexsignals\x00j'Sav\x90\xd6S\x04\x00\x00\x00\xd7\xdfj0\x00\x00\x00\x00\xff\xb4\x01\x00b\xe4L\xcc\x89\xed\xa4\x00v\x90\xd6S\x04\x00\x00\x00\xd7\xdfj0\x00\x00\x00\x00\x01\xb5\x01\x00\xb8\x1c\x05+\xe4P\xf4KR
~\xa5Y\x00\x00\x00\x00\xc6\x95\xdcY\x00\x00\x00\x00\x01\xdc\xba\x1f\xee\x95\xdcY\x13\x01\x00\x00\xdc\x00\x00\x00@B\xaet\x15\xc4\xb5\x1c\x01\x00\x00\x00\xd9\x04\xbab\x11\xdc\xdd\x90\x00D\x01\x00\x88\x01\x00\x002\x
e5\xdd\xbd\x89\xe9CD\xd4\x95\xdcY\x0c\xe2\x8f\xb0 \xe2\x8f\xb0 \xf0\x9f\x92\xb8\x00\x00\x00\x01\x00\x00\x00\rGreenSharkBot\x00\x00\xcf\x01\x00\x00\x01\x00\x00\x00\x15\xc4\xb5\x1c\x00\x00\x00\x00\x15\xc4\xb5\x1c\x
01\x00\x00\x00\x1cK\xb4\x0c`\x10\x00\x00\x89\xe9CD\x0fBITTREX SIGNALS\x0eBittrexsignals\x00j'Sav\x90\xd6S\x04\x00\x00\x00\xd7\xdfj0\x00\x00\x00\x00\xff\xb4\x01\x00b\xe4L\xcc\x89\xed\xa4\x00v\x90\xd6S\x04\x00\x00\
x00\xd7\xdfj0\x00\x00\x00\x00\x01\xb5\x01\x00\xb8\x1c\x05+\xe4P\xf4KR~\xa5Y\x00\x00\x00\x00\xd4\x95\xdcY\x00\x00\x00\x00\x01D\xbb\x1f\xee\x95\xdcY\x15\x01\x00\x00\x1c\x01\x00\x00@B\xaet\x15\xc4\xb5\x1c\x01\x00\x0
0\x00\xd9\x04\xbab\x11\xdc\xdd\x90\x00D\x00\x00j\x01\x00\x002\xe5\xdd\xbd\xd3\xdb\xa3C\xc6\x95\xdcYBGET YOUR BITCOINS READY. SELL ALTCOINS TO INVEST IN TODAY\xe2\x80\x99S HODL\x00\x01\x00\x00\x00\x16\x02\x00\x00\
x01\x00\x00\x00\x15\xc4\xb5\x1c\x00\x00\x00\x00\x15\xc4\xb5\x1c\x01\x00\x00\x00\x1cK\xb4\x0c`\x10\x00\x00\xd3\xdb\xa3C(MEGA Pumps & Signals - Boost your profit\x00\x00\x00\x0fmegapumpscryptoj'Sav\x90\xd6S\x04\x00
\x00\x00\xed\xee\xf9\x19\x00\x00\x00\x00\xd8\xf2\x00\x00\x80\x00\xe01U\x90\x0f\x1bv\x90\xd6S\x04\x00\x00\x00\xed\xee\xf9\x19\x00\x00\x00\x00\xda\xf2\x00\x00\xd1\xe8\xabk\x8e\xd7\x93\xd4\x81b\xc2Y\x00\x00\x00\x00\
xc6\x95\xdcY\x00\x00\x00\x00"                                                                                                                                                                                       
--- Logging error ---                                                                                                                                                                                               
Traceback (most recent call last):                                                                                                                                                                                  
  File "/home/dpetrov/.pyenv/versions/py3play/lib/python3.6/site-packages/telethon/telegram_bare_client.py", line 795, in _recv_thread_impl                                                                         
    self._sender.receive(update_state=self.updates)                                                                                                                                                                 
  File "/home/dpetrov/.pyenv/versions/py3play/lib/python3.6/site-packages/telethon/network/mtproto_sender.py", line 114, in receive                                                                                 
    self._process_msg(remote_msg_id, remote_seq, reader, update_state)                                                                                                                                              
  File "/home/dpetrov/.pyenv/versions/py3play/lib/python3.6/site-packages/telethon/network/mtproto_sender.py", line 190, in _process_msg                                                                            
    return self._handle_container(msg_id, sequence, reader, state)                                                                                                                                                  
  File "/home/dpetrov/.pyenv/versions/py3play/lib/python3.6/site-packages/telethon/network/mtproto_sender.py", line 267, in _handle_container                                                                       
    for inner_msg_id, _, inner_len in MessageContainer.iter_read(reader):                                                                                                                                           
  File "/home/dpetrov/.pyenv/versions/py3play/lib/python3.6/site-packages/telethon/tl/message_container.py", line 28, in iter_read                                                                                  
  File "/home/dpetrov/.pyenv/versions/py3play/lib/python3.6/site-packages/telethon/extensions/binary_reader.py", line 42, in read_long                                                                              
    return int.from_bytes(self.read(8), byteorder='little', signed=signed)                                                                                                                                          
  File "/home/dpetrov/.pyenv/versions/py3play/lib/python3.6/site-packages/telethon/extensions/binary_reader.py", line 63, in read                                                                                   
    .format(length, len(result), repr(result), repr(self._last))                                                                                                                                                    
BufferError: No more data left to read (need 8, got 0: b''); last read b'\x11\x01\x00\x00'                                                                                                                          

During handling of the above exception, another exception occurred:                 

Traceback (most recent call last):                                                                                                                                                                                  
  File "/home/dpetrov/.pyenv/versions/3.6.3/lib/python3.6/logging/__init__.py", line 992, in emit                                                                                                                   
    msg = self.format(record)                                                                                                                                                                                       
  File "/home/dpetrov/.pyenv/versions/3.6.3/lib/python3.6/logging/__init__.py", line 838, in format                                                                                                                 
    return fmt.format(record)                                                                                                                                                                                       
  File "/home/dpetrov/.pyenv/versions/3.6.3/lib/python3.6/logging/__init__.py", line 575, in format                                                                                                                 
    record.message = record.getMessage()                                                                                                                                                                            
  File "/home/dpetrov/.pyenv/versions/3.6.3/lib/python3.6/logging/__init__.py", line 338, in getMessage                                                                                                             
    msg = msg % self.args
TypeError: not all arguments converted during string formatting
Call stack:
  File "/home/dpetrov/.pyenv/versions/3.6.3/lib/python3.6/threading.py", line 884, in _bootstrap
    self._bootstrap_inner()
  File "/home/dpetrov/.pyenv/versions/3.6.3/lib/python3.6/threading.py", line 916, in _bootstrap_inner
    self.run()
  File "/home/dpetrov/.pyenv/versions/3.6.3/lib/python3.6/threading.py", line 864, in run
    self._target(*self._args, **self._kwargs)
  File "/home/dpetrov/.pyenv/versions/py3play/lib/python3.6/site-packages/telethon/telegram_bare_client.py", line 808, in _recv_thread_impl
    error
Message: '[ERROR] Unknown error on the read thread, please report'
Arguments: (BufferError("No more data left to read (need 8, got 0: b''); last read b'\\x11\\x01\\x00\\x00'",),)
dimitar-petrov commented 7 years ago

Also couple of Unknown messages in the log

2017-10-10,12:39:05.851 DEBUG {mtproto_sender} [_handle_container] Handling container                     
2017-10-10,12:39:05.851 DEBUG {mtproto_sender} [_handle_pong] Handling pong                               
2017-10-10,12:39:05.851 DEBUG {mtproto_sender} [_handle_pong] Pong confirmed a request                    
2017-10-10,12:39:05.851 DEBUG {mtproto_sender} [_process_msg] Unknown message: 0x10b                      
2017-10-10,12:39:05.852 INFO {telethon_signal} [process_update] UpdateDeleteChannelMessages               
2017-10-10,12:40:05.940 DEBUG {mtproto_sender} [_handle_pong] Handling pong                               
2017-10-10,12:40:05.941 DEBUG {mtproto_sender} [_handle_pong] Pong confirmed a request                    
2017-10-10,12:40:05.945 INFO {telethon_signal} [process_update] UpdateEditChannelMessage                  
2017-10-10,12:41:06.041 DEBUG {mtproto_sender} [_handle_pong] Handling pong                               
2017-10-10,12:41:06.041 DEBUG {mtproto_sender} [_handle_pong] Pong confirmed a request                    
2017-10-10,12:42:06.129 DEBUG {mtproto_sender} [_handle_container] Handling container                     
2017-10-10,12:42:06.130 DEBUG {mtproto_sender} [_handle_pong] Handling pong                               
2017-10-10,12:42:06.130 DEBUG {mtproto_sender} [_handle_pong] Pong confirmed a request                    
2017-10-10,12:42:06.130 DEBUG {mtproto_sender} [_process_msg] Unknown message: 0x111
phuonglm commented 7 years ago

I got the same error with Telethon today. My list have about 10 channels 

DEBUG:telethon.update_state:Ignoring "update" of type MsgNewDetailedInfo (15 times)
DEBUG:telethon.network.mtproto_sender:Handling RPC result
DEBUG:telethon.network.mtproto_sender:Reading request response
DEBUG:telethon.network.mtproto_sender:Handling container
DEBUG:telethon.network.mtproto_sender:Handling pong
DEBUG:telethon.network.mtproto_sender:Pong confirmed a request
DEBUG:telethon.network.mtproto_sender:Unknown message: 0x18d
--- Logging error ---
Traceback (most recent call last):
  File "/usr/local/lib/python3.4/dist-packages/telethon/telegram_bare_client.py", line 795, in _recv_thread_impl
    self._sender.receive(update_state=self.updates)
  File "/usr/local/lib/python3.4/dist-packages/telethon/network/mtproto_sender.py", line 114, in receive
    self._process_msg(remote_msg_id, remote_seq, reader, update_state)
  File "/usr/local/lib/python3.4/dist-packages/telethon/network/mtproto_sender.py", line 187, in _process_msg
    return self._handle_container(msg_id, sequence, reader, state)
  File "/usr/local/lib/python3.4/dist-packages/telethon/network/mtproto_sender.py", line 264, in _handle_container
    for inner_msg_id, _, inner_len in MessageContainer.iter_read(reader):
  File "/usr/local/lib/python3.4/dist-packages/telethon/tl/message_container.py", line 24, in iter_read
    inner_msg_id = reader.read_long()
  File "/usr/local/lib/python3.4/dist-packages/telethon/extensions/binary_reader.py", line 42, in read_long
    return int.from_bytes(self.read(8), byteorder='little', signed=signed)
  File "/usr/local/lib/python3.4/dist-packages/telethon/extensions/binary_reader.py", line 63, in read
    .format(length, len(result), repr(result), repr(self._last))
BufferError: No more data left to read (need 8, got 0: b''); last read b'\x8d\x01\x00\x00'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3.4/logging/__init__.py", line 978, in emit
    msg = self.format(record)
  File "/usr/lib/python3.4/logging/__init__.py", line 828, in format
    return fmt.format(record)
  File "/usr/lib/python3.4/logging/__init__.py", line 565, in format
    record.message = record.getMessage()
  File "/usr/lib/python3.4/logging/__init__.py", line 328, in getMessage
    msg = msg % self.args
TypeError: not all arguments converted during string formatting
Call stack:
  File "/usr/lib/python3.4/threading.py", line 888, in _bootstrap
    self._bootstrap_inner()
  File "/usr/lib/python3.4/threading.py", line 920, in _bootstrap_inner
    self.run()
  File "/usr/lib/python3.4/threading.py", line 868, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/local/lib/python3.4/dist-packages/telethon/telegram_bare_client.py", line 808, in _recv_thread_impl
    error
Message: '[ERROR] Unknown error on the read thread, please report'
Arguments: (BufferError("No more data left to read (need 8, got 0: b''); last read b'\\x8d\\x01\\x00\\x00'",),)
dasein108 commented 7 years ago

Same problem. I've over 100 chats and it rises very, very often.

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/logging/__init__.py", line 992, in emit
    msg = self.format(record)
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/logging/__init__.py", line 838, in format
    return fmt.format(record)
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/logging/__init__.py", line 575, in format
    record.message = record.getMessage()
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/logging/__init__.py", line 338, in getMessage
    msg = msg % self.args
TypeError: not all arguments converted during string formatting
Call stack:
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/threading.py", line 884, in _bootstrap
    self._bootstrap_inner()
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/threading.py", line 916, in _bootstrap_inner
    self.run()
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/threading.py", line 864, in run
    self._target(*self._args, **self._kwargs)
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/site-packages/telethon/telegram_bare_client.py", line 808, in _recv_thread_impl
    error
Message: '[ERROR] Unknown error on the read thread, please report'
Arguments: (BufferError("No more data left to read (need 8, got 0: b''); last read b'\\x15\\x05\\x00\\x00'",),)

I'm not familiar with code. But I found the last 'break' in _recv_thread_impl() - stops all updates, but not reset is_connected state. So all hangs incorrectly. Removing of this line prevent breaking infinite updates, and now I may notify it every 5-15 seconds, between correct messages. Maybe there is some decoding problem of some kind of messages?

Lonami commented 7 years ago

Did you have this issue with previous versions? Maybe someone could use git bisect to inspect where this started happening too. After checking the logs I saw that after a lot of pongs there were many "unknown requests", so, now I read everything from the pong https://github.com/LonamiWebs/Telethon/commit/301da16f29462c2bac3581536aa6c416fbea5eb7. But this shouldn't quite affect upcoming messages so I'm still unsure what can be going on.

Lonami commented 7 years ago

@dimitar-petrov I tried the last container with 4 items inside before the crash (from this message) with the following code:

reader = BinaryReader(a)
for _ in range(4):
    inner_msg_id = reader.read_long()
    inner_sequence = reader.read_int()
    inner_length = reader.read_int()
    print(reader.tgread_object())
print(a[reader.tell_position():])

And it works. It prints 4 items and there's no data left in the buffer, so it can be decoded properly. But then we have:

   File "/usr/local/lib/python3.4/dist-packages/telethon/tl/message_container.py", line 24, in iter_read
    inner_msg_id = reader.read_long()

I could just decode the whole thing… I can't see how it fails there!

stops all updates, but not reset is_connected state. So all hangs incorrectly.

Maybe you would like some kind of pull request there to fix it? Since you seem to know how to solve it properly.

Maybe there is some decoding problem of some kind of messages?

Likely.

Maybe commit https://github.com/LonamiWebs/Telethon/commit/f2331107329c9316bfc10b2334d87bd82a8219ae is the one which broke things? I mean it introduced a custom container class, so that may be the issue (commit can be found in this page)

phuonglm commented 7 years ago

since commit https://github.com/LonamiWebs/Telethon/commit/301da16f29462c2bac3581536aa6c416fbea5eb7 everything seem better. However the handler still miss some update. I'm checking again with debug log for more details. Thanks for you help.

Lonami commented 7 years ago

It's very strange that commit fixed anything at all. The data needed for that packet had already been read from the network, so it couldn't be affecting upcoming request. Still something to take into consideration I guess.

Lonami commented 7 years ago

This commit (https://github.com/LonamiWebs/Telethon/commit/88da3bc6bbf356b386d7bae5eb38c80361a74382) likely fixed the issue, please let me know.

Edit: Actually I think I just broke it more. Ugh. I git reset --hard to the previous commit -.-"

phuonglm commented 7 years ago

Seem that error came back again. with newest master branch.

DEBUG:telethon.network.mtproto_sender:Handling container
DEBUG:telethon.update_state:Ignoring "update" of type NewSessionCreated
DEBUG:telethon.network.mtproto_sender:Handling RPC result
DEBUG:telethon.network.mtproto_sender:Lost request will be skipped.
DEBUG:telethon.network.mtproto_sender:[WARN] Unknown message: 0xade, data left in the buffer: b"\xde\n\x00\x00\x00\x00\x00\x00\x13\x8e\xdfY\x91\x05\x00\x00\x03\x00\x00\x00\x01\x9c\xa9~\x13\x8e\xdfY\x07\x00\x00\x00$\x00\x00\x00\x01m\\\xf3\xf0\xf8gQ\x14\x8e\xdfY>*l\xa5\xde\n\x00\x00\x00\x00\x00\x00\x13\x8e\xdfY\x91\x05\x00\x00\x03\x00\x00\x00\x01\x00\xee\xb5\xc7\x8e\xdfY\x19\x00\x00\x00,\x01\x00\x00@B\xaet\x15\xc4\xb5\x1c\x01\x00\x00\x00\xd9\x04\xbab\x11\xdc\xdd\x90\x00D\x00\x00*\x11\x00\x002\xe5\xdd\xbd\xa0jsD\x8e\x8e\xdfYbFREE SIGNAL : \nFLORIN \nBUY PRICE : 0.00001400-1490\nSELL PRICE : 0.00001750-1900-2100-2400\nMID TERM\x00\x01\x00\x00\x00J&\x00\x00\x01\x00\x00\x00\x15\xc4\xb5\x1c\x00\x00\x00\x00\x15\xc4\xb5\x1c\x01\x00\x00\x00\x1cK\xb4\x0c`\x10\x00\x00\xa0jsD\x1dCrypto Trading (Free Signals)\x00\x00\tCryptocap\x00\x00j'Sav\x90\xd6S\x04\x00\x00\x00\x0c\xd8\xf9\x19\x00\x00\x00\x00\x02\x1b\x01\x00\x0e\x02\xdfh?}\xfe\xf0v\x90\xd6S\x04\x00\x00\x00\x0c\xd8\xf9\x19\x00\x00\x00\x00\x04\x1b\x01\x00\x87\xd6\x94\x97\x94\nq\xa1\xdb\x10\x8bY\x00\x00\x00\x00\x8e\x8e\xdfY\x00\x00\x00\x00\x01p\xe1\xad&\x94\xdfYl\x04\x00\x00\x14\x00\x00\x00Y\xb4\xd6b\x15\xc4\xb5\x1c\x01\x00\x00\x00(\xa9K\x7f'\x94\xdfY"
--- Logging error ---
Traceback (most recent call last):
  File "/root/telegram-fowarder/src/src/telethon/telethon/network/mtproto_sender.py", line 282, in _handle_container
    reader.set_position(begin_position + inner_len + 16)
  File "/root/telegram-fowarder/src/src/telethon/telethon/extensions/binary_reader.py", line 159, in set_position
    self.reader.seek(position, os.SEEK_SET)
ValueError: negative seek value -1519637526

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/root/telegram-fowarder/src/src/telethon/telethon/update_state.py", line 117, in _worker_loop
    handler(update)
  File "./app.py", line 65, in update_handler
    all_channels = get_all_entities(client)
  File "./app.py", line 102, in get_all_entities
    limit=chunk_size
  File "/root/telegram-fowarder/src/src/telethon/telethon/telegram_bare_client.py", line 448, in __call__
    result = self._invoke(sender, call_receive, *requests)
  File "/root/telegram-fowarder/src/src/telethon/telethon/telegram_bare_client.py", line 480, in _invoke
    sender.receive(update_state=self.updates)
  File "/root/telegram-fowarder/src/src/telethon/telethon/network/mtproto_sender.py", line 114, in receive
    self._process_msg(remote_msg_id, remote_seq, reader, update_state)
  File "/root/telegram-fowarder/src/src/telethon/telethon/network/mtproto_sender.py", line 187, in _process_msg
    return self._handle_container(msg_id, sequence, reader, state)
  File "/root/telegram-fowarder/src/src/telethon/telethon/network/mtproto_sender.py", line 285, in _handle_container
    reader.set_position(begin_position + inner_len + 16)
  File "/root/telegram-fowarder/src/src/telethon/telethon/extensions/binary_reader.py", line 159, in set_position
    self.reader.seek(position, os.SEEK_SET)
ValueError: negative seek value -1519637526

During handling of the above exception, another exception occurred:
  (repeats 3 times)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  ...
  File "/usr/lib/python3.4/threading.py", line 868, in run
    self._target(*self._args, **self._kwargs)
  File "/root/telegram-fowarder/src/src/telethon/telethon/update_state.py", line 123, in _worker_loop
    '[ERROR] Unhandled exception on worker {}'.format(wid), e
Message: '[ERROR] Unhandled exception on worker 3'
Arguments: (ValueError('negative seek value -1519637526',),)
DEBUG:telethon.network.mtproto_sender:Handling RPC result
DEBUG:telethon.network.mtproto_sender:Lost request will be skipped.
Lonami commented 7 years ago

So the container had a certain payload that failed to decode and then it was left in a bad state, so the sequence even turned negative (probably because the "inner length" was read incorrectly).

Lonami commented 7 years ago

@phuonglm can you test with the issue-313 branch, it would be nice to have the full message rather than just the "broken" part of it. I'm somehow able to see where things can be going wrong but having the full message would be easier.

Edit: I feel like https://github.com/LonamiWebs/Telethon/commit/6242cc81593a08621e78fc537f9555a0af695e9b must have somehow helped, because it probably was seeking wrong after a type not found error. Please test.

Edit 2: Thinking twice, it probably didn't fix it. I don't know where the error can be…

Lonami commented 6 years ago

This was probably #538, sorry it took so long to fix. Please test v0.16.1.x and let me know if it works. If it doesn't I'll reopen again.