Closed chabanovsky closed 7 years ago
Hm… The only suspicious things is that after the "Pong confirmed a request", things stopped working appearantly. And @strayge is the one who added pings on the updates thread to solve this precise issue (not receiving updates anymore, by sending periodics pings). Could you please print what request the pong did exactly confirm (I have no clue what the pong is supposed to do)?
Hey @Lonami!
Could you please tell me who can I print the request? Is there a debug option or should I use tools like WireShark? If so, what kind of log I should to post?
Could you please tell me who can I print the request?
These are not printed, not even when DEBUG
log level is used, because some are really long, and there exists two versions: repr(tlobject)
, which shows how it's defined on the scheme.tł
file, and str(tlobject)
, which shows the actual values – more useful for debugging, but might not be suitable for posting the logs online.
or should I use tools like WireShark
WireShark would be hard to use with any Telegram API out there, after the logging process, messages are encrypted (though, of course, there may be a way to decrypt them knowing the key), but yet you would see a bunch of raw bytes, not something really useful.
You can add print(tlobject)
yourself wherever you consider it necessary.
I tested with Telethon==0.8, python 3.6, Ubuntu 16.04.2 LTS.
Simple script:
from time import sleep
from telethon import TelegramClient
def update_handler(update_object):
print(update_object)
tg = TelegramClient('sessionid', api_id=****, api_hash='************************************')
tg.connect()
tg.add_update_handler(update_handler)
while True:
sleep(0.1)
It's receiving updates within 14 hours without any issues.
@strayge Could you please test it with 15+ open chats? I mean a user who is logged in in your test app should have 15+ very active chats where the user is a member (in order to receive notifications). In my case after a few hours my app stops receiving updates.
I've added some active chats & channels. Now it doesn't receive any updates right after start. Debug log looks like:
[18:27:42.022/MainThread] INFO: Changing updates thread running status to True
[18:27:42.025/MainThread] DEBUG: send() acquired the lock
[18:27:42.028/MainThread] DEBUG: send() released the lock
[18:27:42.028/MainThread] DEBUG: receive() acquired the lock
[18:27:42.028/MainThread] INFO: Trying to .receive() the request result...
[18:27:42.232/MainThread] DEBUG: Handling RPC result, request is not None
[18:27:42.233/MainThread] DEBUG: Reading request response
[18:27:42.233/MainThread] INFO: Request result received
[18:27:42.233/MainThread] DEBUG: receive() released the lock
[18:27:43.024/UpdatesThread] DEBUG: Updates thread acquired the lock
[18:27:43.024/UpdatesThread] DEBUG: Trying to receive updates from the updates thread
[18:28:43.071/UpdatesThread] DEBUG: Receiving updates timed out
[18:28:43.072/UpdatesThread] DEBUG: Updates thread released the lock
[18:28:43.173/UpdatesThread] DEBUG: Updates thread acquired the lock
[18:28:43.173/UpdatesThread] DEBUG: send() acquired the lock
[18:28:43.175/UpdatesThread] DEBUG: send() released the lock
[18:28:43.175/UpdatesThread] DEBUG: receive() acquired the lock
[18:28:43.175/UpdatesThread] INFO: Trying to .receive() the request result...
[18:28:43.479/UpdatesThread] DEBUG: Handling pong
[18:28:43.479/UpdatesThread] WARNING: Pong confirmed a request
[18:28:43.479/UpdatesThread] INFO: Request result received
[18:28:43.479/UpdatesThread] DEBUG: receive() released the lock
[18:28:43.479/UpdatesThread] DEBUG: Ping sent from the updates thread
[18:28:43.479/UpdatesThread] DEBUG: Trying to receive updates from the updates thread
[18:29:43.490/UpdatesThread] DEBUG: Receiving updates timed out
[18:29:43.491/UpdatesThread] DEBUG: Updates thread released the lock
[18:29:43.591/UpdatesThread] DEBUG: Updates thread acquired the lock
[18:29:43.592/UpdatesThread] DEBUG: send() acquired the lock
[18:29:43.597/UpdatesThread] DEBUG: send() released the lock
[18:29:43.598/UpdatesThread] DEBUG: receive() acquired the lock
[18:29:43.598/UpdatesThread] INFO: Trying to .receive() the request result...
[18:29:43.904/UpdatesThread] DEBUG: Handling pong
[18:29:43.904/UpdatesThread] WARNING: Pong confirmed a request
[18:29:43.905/UpdatesThread] INFO: Request result received
[18:29:43.905/UpdatesThread] DEBUG: receive() released the lock
[18:29:43.905/UpdatesThread] DEBUG: Ping sent from the updates thread
[18:29:43.905/UpdatesThread] DEBUG: Trying to receive updates from the updates thread
Tried to increase timeout in updates_thread_method
up to 15 minutes, but still "Receiving updates timed out".
In TcpClient.read
self.socket.recv(left_count)
raise BlockingIOError
each time when it called from MtProtoSender.updates_thread_method
In
TcpClient.read
self.socket.recv(left_count)
raiseBlockingIOError
each time when it called fromMtProtoSender.updates_thread_method
I wonder if at this point we should totally disconnect from the server and reconnect again. I mean, it's not optimal, but right now I cannot think of any other solution. We already do periodic ping requests and the RLock
seems to be used correctly accross the updates/main thread…
I don't know enough of sockets to improve the TcpClient
class, but there's a lot of room for improvement there. Maybe it just needs some proper way of cancelling the read instead my custom made one. Does anyone know if this is possible?
I wonder if at this point we should totally disconnect from the server and reconnect again.
It happens in first updates_thread_method
fo me now, right after connect. I don't sure that reconnect can fix it.
Full debug log from start provided above. Started at 18:27:42.022, first update receiving at 18:27:43.024, exited by timeout at 18:28:43.071.
I don't know enough of sockets to improve the TcpClient class, but there's a lot of room for improvement there. Maybe it just needs some proper way of cancelling the read instead my custom made one. Does anyone know if this is possible?
Seems like some error in requesting of updates, not in TcpClient
. Server doesn't return any data.
Server doesn't return any data.
But right from the start? It makes a bit more sense after a long while running, but from the start as you showed, it's just strange.
But right from the start? It makes a bit more sense after a long while running, but from the start as you showed, it's just strange.
I've added some active chats & channels. Now it doesn't receive any updates right after start.
If I adding GetStateRequest()
call each 10 secs, update_handler
started works again.
But I don't know how it influence. Maybe some updates skipped with this call.
But I don't know how it influence.
Neither, the PingRequest
should be the one doing that job (i.e., periodic requests so the server knows we're still connected). Maybe the GetStateRequest
is just more "real" than a simple ping? If you do these manually, can you try instead doing a simple Ping
?
After prime time was ended it started works again without any modifications. Now problem appeared again.
Also if client with modifications works, after restart with disabled modifications - it's still works.
With call PingRequest(0)
each 10 secs in loop it doesn't receive updates.
With call GetStateRequest()
each 10 secs in loop it started receive updates.
Thanks for trying to fix this issue yourself @strayge, do you think we should call GetStateRequest
by default 🤔
If we did, it would allow us to access more information than a simple ping, for instance, unread_count
which may even be useful - though, it's also more bytes sent over the network.
Thanks for trying to fix this issue yourself @strayge, do you think we should call GetStateRequest by default 🤔
I don't think so. We still don't understand why this problem appears.
Maybe it can be fixed by decreasing ping timeout.
Maybe we need send different pings with different ping_id (like PingRequest(random.randrange(0, 2**32))
).
Also 10 seconds is very low interval, needs more tests with larger intervals.
And I don't run long tests with GetStateRequest
calls, so maybe issue still appears after some time.
Maybe we need send different pings with different ping_id
It could be a reason, though I believe it's for the client to determine to which Ping
a received Pong
was for.
like
PingRequest(random.randrange(0, 2**32))
.
Better use helpers.generate_random_long()
for this purpose, since that's what's used everywhere else for long numbers.
It could be a reason, though I believe it's for the client to determine to which Ping a received Pong was for.
Yes, I think so, but it can be tested.
As dirty workaround maybe GetStateRequest
can be called only if update_handler
failed by timeout.
As dirty workaround […]
Could try.
Tested within 37 hours. Workaround (GetStateRequest) works. It was called 995 times during test. Script still receiving updates.
Nice to know (and thanks for testing), but I won't consider this as resolved yet. There has to be a cleaner way to fix this.
I'm still having problems receiving updates after a few minutes/hours since launching the script. Code is running version ca80b05694f3e870d5357f7572016a2d7a6934d3
[00:58:19.189/UpdatesThread] DEBUG: Sending GetStateRequest (workaround for issue #50)
[00:58:19.189/UpdatesThread] INFO: Cancelling updates receive from send()...
[00:58:19.190/UpdatesThread] DEBUG: send() acquired the lock
[00:58:19.193/UpdatesThread] DEBUG: send() released the lock
[00:58:19.193/UpdatesThread] DEBUG: receive() acquired the lock
[00:58:19.194/UpdatesThread] INFO: Trying to .receive() the request result...
[00:58:19.300/UpdatesThread] DEBUG: Handling update for object updates_tg#74ae4240
[00:58:19.301/UpdatesThread] INFO: Trying to .receive() the request result...
[00:58:19.304/UpdatesThread] DEBUG: Handling RPC result, request is not None
[00:58:19.304/UpdatesThread] DEBUG: Reading request response
[00:58:19.305/UpdatesThread] INFO: Request result received
[00:58:19.305/UpdatesThread] DEBUG: receive() released the lock
[00:58:19.306/UpdatesThread] DEBUG: Updates thread released the lock
[00:58:19.407/UpdatesThread] DEBUG: Updates thread acquired the lock
[00:58:19.407/UpdatesThread] DEBUG: send() acquired the lock
[00:58:19.410/UpdatesThread] DEBUG: send() released the lock
[00:58:19.410/UpdatesThread] DEBUG: receive() acquired the lock
[00:58:19.411/UpdatesThread] INFO: Trying to .receive() the request result...
[00:58:19.512/UpdatesThread] DEBUG: Handling pong
[00:58:19.513/UpdatesThread] WARNING: Pong confirmed a request
[00:58:19.513/UpdatesThread] INFO: Request result received
[00:58:19.514/UpdatesThread] DEBUG: receive() released the lock
[00:58:19.514/UpdatesThread] DEBUG: Ping sent from the updates thread
[00:58:19.514/UpdatesThread] DEBUG: Trying to receive updates from the updates thread
[00:59:19.578/UpdatesThread] DEBUG: Receiving updates timed out
[00:59:19.579/UpdatesThread] DEBUG: Sending GetStateRequest (workaround for issue #50)
[00:59:19.579/UpdatesThread] INFO: Cancelling updates receive from send()...
[00:59:19.580/UpdatesThread] DEBUG: send() acquired the lock
[00:59:19.582/UpdatesThread] DEBUG: send() released the lock
[00:59:19.589/UpdatesThread] DEBUG: receive() acquired the lock
[00:59:19.590/UpdatesThread] INFO: Trying to .receive() the request result...
[00:59:19.707/UpdatesThread] DEBUG: Handling update for object updates_tg#74ae4240
[00:59:19.708/UpdatesThread] INFO: Cancelling updates receive from send()...
[00:59:19.709/UpdatesThread] DEBUG: send() acquired the lock
[00:59:19.711/UpdatesThread] DEBUG: send() released the lock
[00:59:19.712/UpdatesThread] DEBUG: receive() acquired the lock
[00:59:19.712/UpdatesThread] INFO: Trying to .receive() the request result...
[00:59:19.718/UpdatesThread] DEBUG: Handling container
[00:59:19.719/UpdatesThread] DEBUG: Handling update for object updates_tg#74ae4240
[00:59:19.720/UpdatesThread] DEBUG: Handling update for object updates_tg#74ae4240
[00:59:19.721/UpdatesThread] INFO: Trying to .receive() the request result...
[00:59:19.723/UpdatesThread] DEBUG: Handling RPC result, request is not None
[00:59:19.723/UpdatesThread] DEBUG: Reading request response
[00:59:19.723/UpdatesThread] WARNING: RPC result found for unknown request (maybe from previous connection session)
[00:59:19.724/UpdatesThread] INFO: Trying to .receive() the request result...
[00:59:19.995/UpdatesThread] DEBUG: Handling RPC result, request is not None
[00:59:19.996/UpdatesThread] DEBUG: Reading request response
[00:59:19.996/UpdatesThread] INFO: Request result received
[00:59:19.997/UpdatesThread] DEBUG: receive() released the lock
[00:59:19.997/UpdatesThread] INFO: Cancelling updates receive from send()...
[00:59:19.997/UpdatesThread] DEBUG: send() acquired the lock
[00:59:20.000/UpdatesThread] DEBUG: send() released the lock
[00:59:20.000/UpdatesThread] DEBUG: receive() acquired the lock
[00:59:20.001/UpdatesThread] INFO: Trying to .receive() the request result...
[00:59:20.103/UpdatesThread] DEBUG: Handling RPC result, request is not None
[00:59:20.104/UpdatesThread] DEBUG: Reading request response
[00:59:20.105/UpdatesThread] INFO: Request result received
[00:59:20.105/UpdatesThread] DEBUG: receive() released the lock
[00:59:20.106/UpdatesThread] INFO: Trying to .receive() the request result...
[00:59:25.118/UpdatesThread] WARNING: Timed out inside a timeout, trying to reconnect...
[00:59:25.119/UpdatesThread] INFO: Changing updates thread running status to False
[00:59:25.135/UpdatesThread] INFO: Cancelling updates receive from send()...
[00:59:25.136/UpdatesThread] DEBUG: send() acquired the lock
[00:59:25.138/UpdatesThread] DEBUG: send() released the lock
[00:59:25.139/UpdatesThread] DEBUG: receive() acquired the lock
[00:59:25.139/UpdatesThread] INFO: Trying to .receive() the request result...
[00:59:25.242/UpdatesThread] DEBUG: Handling RPC result, request is not None
[00:59:25.242/UpdatesThread] DEBUG: Reading request response
[00:59:25.243/UpdatesThread] INFO: Request result received
[00:59:25.243/UpdatesThread] DEBUG: receive() released the lock
[00:59:25.243/UpdatesThread] DEBUG: Updates thread released the lock
### NOT UPDATING EVER AGAIN ###
Fix for this issue seems to be kicking in, but ends failing to keep updating again.
I rerun the script with last commit (just in case) 02a847b64a5b37cbbaa05dd2469ee41154326d25
[14:39:48.428/UpdatesThread] INFO: Request result received
[14:39:48.429/UpdatesThread] DEBUG: receive() released the lock
[14:39:48.429/UpdatesThread] INFO: Cancelling updates receive from send()...
[14:39:48.430/UpdatesThread] DEBUG: send() acquired the lock
[14:39:48.432/UpdatesThread] DEBUG: send() released the lock
[14:39:48.433/UpdatesThread] DEBUG: receive() acquired the lock
[14:39:48.433/UpdatesThread] INFO: Trying to .receive() the request result...
[14:39:48.591/UpdatesThread] DEBUG: Handling RPC result, request is not None
[14:39:48.592/UpdatesThread] DEBUG: Reading request response
[14:39:48.592/UpdatesThread] INFO: Request result received
[14:39:48.593/UpdatesThread] DEBUG: receive() released the lock
[14:39:48.593/UpdatesThread] INFO: Cancelling updates receive from send()...
[14:39:48.594/UpdatesThread] DEBUG: send() acquired the lock
[14:39:48.597/UpdatesThread] DEBUG: send() released the lock
[14:39:48.597/UpdatesThread] DEBUG: receive() acquired the lock
[14:39:48.598/UpdatesThread] INFO: Trying to .receive() the request result...
[14:39:48.800/UpdatesThread] DEBUG: Handling RPC result, request is not None
[14:39:48.801/UpdatesThread] DEBUG: Reading request response
[14:39:48.801/UpdatesThread] INFO: Request result received
[14:39:48.802/UpdatesThread] DEBUG: receive() released the lock
[14:39:48.803/UpdatesThread] INFO: Trying to .receive() the request result...
[14:39:53.819/UpdatesThread] WARNING: Timed out inside a timeout, trying to reconnect...
[14:39:53.820/UpdatesThread] INFO: Changing updates thread running status to False
[14:39:53.836/UpdatesThread] INFO: Cancelling updates receive from send()...
[14:39:53.837/UpdatesThread] DEBUG: send() acquired the lock
[14:39:53.840/UpdatesThread] DEBUG: send() released the lock
[14:39:53.840/UpdatesThread] DEBUG: receive() acquired the lock
[14:39:53.841/UpdatesThread] INFO: Trying to .receive() the request result...
[14:39:53.944/UpdatesThread] DEBUG: Handling RPC result, request is not None
[14:39:53.945/UpdatesThread] DEBUG: Reading request response
[14:39:53.946/UpdatesThread] INFO: Request result received
[14:39:53.946/UpdatesThread] DEBUG: receive() released the lock
[14:39:53.947/UpdatesThread] DEBUG: Updates thread released the lock
### NOT UPDATING EVER AGAIN ###
Are you able to invoke normal requests (from the main thread) after the updates thread stopped?
This is the result I got when making also requests from the main thread. I'm not sure if it is the same error
[00:31:52.659/MainThread] DEBUG: Downloading photo
[00:31:52.659/MainThread] DEBUG: send() acquired the lock
[00:31:52.661/MainThread] DEBUG: send() released the lock
[00:31:52.662/MainThread] DEBUG: receive() acquired the lock
[00:31:52.662/MainThread] INFO: Trying to .receive() the request result...
[00:31:52.665/MainThread] DEBUG: Handling update for object updates_tg#74ae4240 updates:Vector<Update> users:Vector<User> chats:Vector<Chat> date:dat
e seq:int = Updates
[00:31:52.667/MainThread] INFO: Trying to .receive() the request result...
[00:31:52.715/MainThread] DEBUG: Handling RPC result, request is not None
[00:31:52.716/MainThread] DEBUG: Reading request response
[00:31:52.721/MainThread] INFO: Trying to .receive() the request result...
[00:31:52.724/MainThread] DEBUG: Handling RPC result, request is not None
[00:31:52.726/MainThread] WARNING: Read RPC error: (RPCError(...), 'The file to be accessed is currently stored in a different data center (#1).')
[00:31:56.972/MainThread] DEBUG: send() acquired the lock
[00:31:56.974/MainThread] DEBUG: send() released the lock
[00:31:56.974/MainThread] DEBUG: receive() acquired the lock
[00:31:56.975/MainThread] INFO: Trying to .receive() the request result...
[00:31:57.176/MainThread] DEBUG: Handling bad server salt
[00:31:57.177/MainThread] DEBUG: send() acquired the lock
[00:31:57.179/MainThread] DEBUG: send() released the lock
[00:31:57.180/MainThread] INFO: Trying to .receive() the request result...
[00:31:57.382/MainThread] DEBUG: Handling update for object new_session_created#9ec20908 first_msg_id:long unique_id:long server_salt:long = NewSessi
on
[00:31:57.383/MainThread] INFO: Trying to .receive() the request result...
[00:31:57.486/MainThread] DEBUG: Handling RPC result, request is not None
[00:31:57.487/MainThread] DEBUG: Reading request response
[00:31:57.487/MainThread] INFO: Request result received
[00:31:57.488/MainThread] DEBUG: receive() released the lock
[00:31:57.488/MainThread] INFO: Changing updates thread running status to True
[00:31:57.489/MainThread] DEBUG: send() acquired the lock
[00:31:57.491/MainThread] DEBUG: send() released the lock
[00:31:57.492/MainThread] DEBUG: receive() acquired the lock
[00:31:57.492/MainThread] INFO: Trying to .receive() the request result...
[00:31:57.796/MainThread] DEBUG: Handling RPC result, request is not None
[00:31:57.799/MainThread] WARNING: Read RPC error: (RPCError(...), 'The key is not registered in the system.')
Traceback (most recent call last):
File "/home/joshua/python/Telethon/telethon/telegram_client.py", line 173, in invoke
self.sender.receive(request, timeout)
File "/home/joshua/python/Telethon/telethon/network/mtproto_sender.py", line 157, in receive
request)
File "/home/joshua/python/Telethon/telethon/network/mtproto_sender.py", line 235, in process_msg
return self.handle_rpc_result(msg_id, sequence, reader, request)
File "/home/joshua/python/Telethon/telethon/network/mtproto_sender.py", line 367, in handle_rpc_result
raise InvalidDCError(error)
telethon.errors.InvalidDCError: (RPCError(...), 'The file to be accessed is currently stored in a different data center (#1).')
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "telegram.py", line 123, in <module>
logger.debug(len(client.get_dialogs()))
File "/home/joshua/python/Telethon/telethon/telegram_client.py", line 305, in get_dialogs
limit=limit))
File "/home/joshua/python/Telethon/telethon/telegram_client.py", line 173, in invoke
self.sender.receive(request, timeout)
File "/home/joshua/python/Telethon/telethon/network/mtproto_sender.py", line 157, in receive
request)
File "/home/joshua/python/Telethon/telethon/network/mtproto_sender.py", line 265, in process_msg
return self.handle_update(msg_id, sequence, reader)
File "/home/joshua/python/Telethon/telethon/network/mtproto_sender.py", line 278, in handle_update
handler(tlobject)
File "telegram.py", line 52, in updatetg_handler
photo = io.BytesIO(download_photo(update.message.media))
File "telegram.py", line 81, in download_photo
GetFileRequest(input_location, offset, part_size))
File "/home/joshua/python/Telethon/telethon/telegram_client.py", line 182, in invoke
return self.invoke(request, timeout=timeout, throw_invalid_dc=True)
File "/home/joshua/python/Telethon/telethon/telegram_client.py", line 173, in invoke
self.sender.receive(request, timeout)
File "/home/joshua/python/Telethon/telethon/network/mtproto_sender.py", line 157, in receive
request)
File "/home/joshua/python/Telethon/telethon/network/mtproto_sender.py", line 235, in process_msg
return self.handle_rpc_result(msg_id, sequence, reader, request)
File "/home/joshua/python/Telethon/telethon/network/mtproto_sender.py", line 370, in handle_rpc_result
raise error
telethon.errors.RPCError: (RPCError(...), 'The key is not registered in the system.')
If you need a longer log, please ask for it and I will send it to you.
InvalidDCError: (RPCError(...), 'The file to be accessed is currently stored in a different data center (#1).')
That's a WIP (see #53).
RPCError: (RPCError(...), 'The key is not registered in the system.')
And that's currently the way it breaks, sorry. What I meant is, after you've been disconnected, making a harmless request (like getting dialogs, or sending a message), to see if the updates thread having stopped also disconnected the client or if it's a different reason.
Are both errors related?
Is there any way to prevent the download of files from other DCs to prevent this error from occuring?
Are both errors related?
"The file to be accessed is currently stored in a different data center" is the cause for "The key is not registered in the system", yes. Again that's being worked on a different branch, but I don't have the time to work on it at the moment.
Is there any way to prevent the download of files from other DCs to prevent this error from occuring?
Not downloading media from people you know who are in a different DC is the only solution at the moment. All help to speed-up the process is welcome.
pip
version) and report feedback. We may have to reopen this, but I hope not.it seems to be rock solid, running since you uploaded the changes without issues.
it seems to be rock solid, running since you uploaded the changes without issues.
I'm so glad to know @chiva, thank you for testing!
My app subscribes for updates using
self.add_update_handler
. It works fine, but after about 5 hours of working it stops receiving updates (according to the web interface there are updates). My log.