Connection through SOCKS5 proxy is dropped every 10 seconds

dkarelov commented 4 years ago

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/master.zip and triggered the bug in the latest version.

Code that causes the issue.

bot = TelegramClient('bot', api_id, api_hash, proxy=(
    socks.SOCKS5, ...))

@bot.on(events.NewMessage) 
async def handler(event):
    print('handler fired')

bot.start(bot_token=bot_token)
bot.run_until_disconnected()

Connection drops and re-establishes every 10 seconds

2019-11-04 13:04:30 INFO     Connection to 149.154.167.51:443/TcpFull complete!
2019-11-04 13:04:30 DEBUG    Waiting for messages to send...
2019-11-04 13:04:30 DEBUG    Assigned msg_id = 6755390295336284180 to MsgsAck (7f7864f29e80)
2019-11-04 13:04:30 DEBUG    Encrypting 1 message(s) in 36 bytes for sending
2019-11-04 13:04:30 DEBUG    Encrypted messages put in a queue to be sent
2019-11-04 13:04:30 DEBUG    Waiting for messages to send...
2019-11-04 13:04:30 DEBUG    Receiving items from the network...
2019-11-04 13:04:30 DEBUG    Handling new session created
2019-11-04 13:04:30 DEBUG    Receiving items from the network...
2019-11-04 13:04:41 INFO     The server closed the connection
2019-11-04 13:04:41 INFO     Connection closed while receiving data
2019-11-04 13:04:41 DEBUG    Closing current connection...
2019-11-04 13:04:41 INFO     Connecting to 149.154.167.51:443/TcpFull...
2019-11-04 13:04:41 DEBUG    Connection attempt 1...
2019-11-04 13:04:41 DEBUG    Connection success!
2019-11-04 13:04:41 DEBUG    Starting send loop
2019-11-04 13:04:41 DEBUG    Starting receive loop
2019-11-04 13:04:41 INFO     Connection to 149.154.167.51:443/TcpFull complete!
2019-11-04 13:04:41 DEBUG    Waiting for messages to send...
2019-11-04 13:04:41 DEBUG    Assigned msg_id = 6755390343440586492 to MsgsAck (7f7864f29fd0)
2019-11-04 13:04:41 DEBUG    Encrypting 1 message(s) in 36 bytes for sending
2019-11-04 13:04:41 DEBUG    Encrypted messages put in a queue to be sent
2019-11-04 13:04:41 DEBUG    Waiting for messages to send...
2019-11-04 13:04:41 DEBUG    Receiving items from the network...
2019-11-04 13:04:41 DEBUG    Handling new session created
2019-11-04 13:04:41 DEBUG    Receiving items from the network...
2019-11-04 13:04:52 INFO     The server closed the connection
2019-11-04 13:04:52 INFO     Connection closed while receiving data
2019-11-04 13:04:52 DEBUG    Closing current connection...
2019-11-04 13:04:52 INFO     Connecting to 149.154.167.51:443/TcpFull...
2019-11-04 13:04:52 DEBUG    Connection attempt 1...
2019-11-04 13:04:53 DEBUG    Connection success!
2019-11-04 13:04:53 DEBUG    Starting send loop
2019-11-04 13:04:53 DEBUG    Starting receive loop
2019-11-04 13:04:53 INFO     Connection to 149.154.167.51:443/TcpFull complete!

Note that this is based in Russia, so might be related with government blocking attempts of Telegram. Any potential workarounds? I'm already connected through SOCKS5 proxy and other telegram frameworks don't cause this type of issues.

Lonami commented 4 years ago

Are you sure the proxy is SOCKS5 and not HTTP-only?

dkarelov commented 4 years ago

Yes, it's NordVPN proxy and anything with 1080 port is SOCKS5: https://nordvpn.com/tutorials/socks5/deluge/

Also if it was a proxy issue, it will likely won't be able to establish the connection. In my case the connection is established, and the bot actually manages to send messages to chats.

BUT, it cannot receive any messages. So handlers never get executed.

And just to make sure this is not a proxy issue - I have another bot using different framework (in golang) that works without any issues with this proxy.

I also tried HTTP proxy option (with a right port obviously) like that:

connection=connection.ConnectionHttp, proxy=(socks.HTTP, ...

But it doesn't work:

2019-11-04 17:58:42 INFO     Connecting to 149.154.167.51:443/Http...
2019-11-04 17:58:42 DEBUG    Connection attempt 1...
2019-11-04 17:58:42 WARNING  Attempt 1 at connecting failed: OSError: [Errno 0] Error

And maybe a related question - howcome official telegram client connects without any proxies in Russia? They have some obfuscation methods embedded, or a different set of server IP addresses that are updated constantly?

dkarelov commented 4 years ago

Can I maybe try v2 branch? Is it working? Will it break much besides the change from pysocks to python-proxy?

Lonami commented 4 years ago

You can try it, but it's pretty stale otherwise (ironically).

dkarelov commented 4 years ago

Tried v2 - same problem:

2019-11-05 01:44:38 DEBUG    Receiving items from the network...
2019-11-05 01:44:49 INFO     Connection closed while receiving data
2019-11-05 01:44:49 DEBUG    Closing current connection...
2019-11-05 01:44:49 INFO     Connecting to 149.154.167.51:443/Asyncio...
2019-11-05 01:44:49 DEBUG    Connection attempt 1...
2019-11-05 01:44:49 DEBUG    Connection success!
2019-11-05 01:44:49 DEBUG    Starting send loop
2019-11-05 01:44:49 DEBUG    Starting receive loop
2019-11-05 01:44:49 INFO     Connection to 149.154.167.51:443/Asyncio complete!
2019-11-05 01:44:49 DEBUG    Waiting for messages to send...
2019-11-05 01:44:49 DEBUG    Assigned msg_id = 6755586228000371488 to MsgsAck (1fcb7f46f98)
2019-11-05 01:44:49 DEBUG    Encrypting 1 message(s) in 36 bytes for sending
2019-11-05 01:44:49 DEBUG    Encrypted messages put in a queue to be sent
2019-11-05 01:44:49 DEBUG    Waiting for messages to send...
2019-11-05 01:44:49 DEBUG    Receiving items from the network...
2019-11-05 01:44:49 DEBUG    Handling new session created
2019-11-05 01:44:49 DEBUG    Receiving items from the network...
2019-11-05 01:45:00 INFO     Connection closed while receiving data
2019-11-05 01:45:00 DEBUG    Closing current connection...
2019-11-05 01:45:00 INFO     Connecting to 149.154.167.51:443/Asyncio...
2019-11-05 01:45:00 DEBUG    Connection attempt 1...
2019-11-05 01:45:01 DEBUG    Connection success!
2019-11-05 01:45:01 DEBUG    Starting send loop
2019-11-05 01:45:01 DEBUG    Starting receive loop
2019-11-05 01:45:01 INFO     Connection to 149.154.167.51:443/Asyncio complete!
2019-11-05 01:45:01 DEBUG    Waiting for messages to send...
2019-11-05 01:45:01 DEBUG    Assigned msg_id = 6755586276882562696 to MsgsAck (1fcb7f7a518)
2019-11-05 01:45:01 DEBUG    Encrypting 1 message(s) in 36 bytes for sending
2019-11-05 01:45:01 DEBUG    Encrypted messages put in a queue to be sent
2019-11-05 01:45:01 DEBUG    Waiting for messages to send...
2019-11-05 01:45:01 DEBUG    Receiving items from the network...
2019-11-05 01:45:01 DEBUG    Handling new session created
2019-11-05 01:45:01 DEBUG    Receiving items from the network...
2019-11-05 01:45:03 DEBUG    Assigned msg_id = 6755586288672377888 to Ping (1fcb7f46a58)
2019-11-05 01:45:03 DEBUG    Encrypting 1 message(s) in 28 bytes for sending
2019-11-05 01:45:03 DEBUG    Encrypted messages put in a queue to be sent
2019-11-05 01:45:03 DEBUG    Waiting for messages to send...
2019-11-05 01:45:03 DEBUG    Assigned msg_id = 6755586288700301472 to MsgsAck (1fcb7f7a7f0)
2019-11-05 01:45:03 DEBUG    Encrypting 1 message(s) in 36 bytes for sending
2019-11-05 01:45:03 DEBUG    Encrypted messages put in a queue to be sent
2019-11-05 01:45:03 DEBUG    Waiting for messages to send...
2019-11-05 01:45:03 DEBUG    Handling pong for message 6755586288672377888
2019-11-05 01:45:03 DEBUG    Receiving items from the network...

vegeta1k95 commented 4 years ago

Experiencing the same problem also:

[DEBUG/2020-08-25 23:33:01,377] telethon.network.mtprotosender: Connection success!
[DEBUG/2020-08-25 23:33:01,377] telethon.network.mtprotosender: Starting send loop
[DEBUG/2020-08-25 23:33:01,377] telethon.network.mtprotosender: Starting receive loop
[ INFO/2020-08-25 23:33:01,377] telethon.network.mtprotosender: Connection to 149.154.167.51:443/TcpFull complete!
[DEBUG/2020-08-25 23:33:01,850] telethon.network.mtprotosender: Waiting for messages to send...
[DEBUG/2020-08-25 23:33:01,850] telethon.extensions.messagepacker: Assigned msg_id = 6865037852011098884 to InvokeWithLayerRequest (2b590e2a5f8)
[DEBUG/2020-08-25 23:33:01,850] telethon.network.mtprotosender: Encrypting 1 message(s) in 92 bytes for sending
[DEBUG/2020-08-25 23:33:01,851] telethon.network.mtprotosender: Encrypted messages put in a queue to be sent
[DEBUG/2020-08-25 23:33:01,851] telethon.network.mtprotosender: Waiting for messages to send...
[DEBUG/2020-08-25 23:33:01,851] telethon.network.mtprotosender: Receiving items from the network...
[ INFO/2020-08-25 23:33:01,851] telethon.network.connection.connection: The server closed the connection
[ INFO/2020-08-25 23:33:01,851] telethon.network.mtprotosender: Connection closed while receiving data
[DEBUG/2020-08-25 23:33:01,852] telethon.network.mtprotosender: Closing current connection...
[ INFO/2020-08-25 23:33:01,852] telethon.network.mtprotosender: Connecting to 149.154.167.51:443/TcpFull...
[DEBUG/2020-08-25 23:33:01,852] telethon.network.mtprotosender: Connection attempt 1...
[DEBUG/2020-08-25 23:33:02,875] telethon.network.mtprotosender: Connection success!
[DEBUG/2020-08-25 23:33:02,875] telethon.network.mtprotosender: Starting send loop
[DEBUG/2020-08-25 23:33:02,875] telethon.network.mtprotosender: Starting receive loop
[ INFO/2020-08-25 23:33:02,875] telethon.network.mtprotosender: Connection to 149.154.167.51:443/TcpFull complete!
[DEBUG/2020-08-25 23:33:02,876] telethon.network.mtprotosender: Waiting for messages to send...
[DEBUG/2020-08-25 23:33:02,876] telethon.extensions.messagepacker: Assigned msg_id = 6865037856410259868 to InvokeWithLayerRequest (2b590e2a5f8)
[DEBUG/2020-08-25 23:33:02,876] telethon.network.mtprotosender: Encrypting 1 message(s) in 92 bytes for sending
[DEBUG/2020-08-25 23:33:02,877] telethon.network.mtprotosender: Encrypted messages put in a queue to be sent
[DEBUG/2020-08-25 23:33:02,877] telethon.network.mtprotosender: Waiting for messages to send...
[DEBUG/2020-08-25 23:33:02,877] telethon.network.mtprotosender: Receiving items from the network...
[DEBUG/2020-08-25 23:33:02,877] telethon.extensions.messagepacker: Assigned msg_id = 6865037856416274692 to GetUsersRequest (2b590e2a3c8)
[DEBUG/2020-08-25 23:33:02,877] telethon.network.mtprotosender: Encrypting 1 message(s) in 32 bytes for sending
[DEBUG/2020-08-25 23:33:02,878] telethon.network.mtprotosender: Encrypted messages put in a queue to be sent
[DEBUG/2020-08-25 23:33:02,878] telethon.network.mtprotosender: Waiting for messages to send...
[ INFO/2020-08-25 23:33:03,119] telethon.network.connection.connection: The server closed the connection
[ INFO/2020-08-25 23:33:03,119] telethon.network.mtprotosender: Connection closed while receiving data
[DEBUG/2020-08-25 23:33:03,119] telethon.network.mtprotosender: Closing current connection...
[ INFO/2020-08-25 23:33:03,119] telethon.network.mtprotosender: Connecting to 149.154.167.51:443/TcpFull...
[DEBUG/2020-08-25 23:33:03,119] telethon.network.mtprotosender: Connection attempt 1...
[DEBUG/2020-08-25 23:33:04,209] telethon.network.mtprotosender: Connection success!
[DEBUG/2020-08-25 23:33:04,209] telethon.network.mtprotosender: Starting send loop
[DEBUG/2020-08-25 23:33:04,209] telethon.network.mtprotosender: Starting receive loop
[ INFO/2020-08-25 23:33:04,209] telethon.network.mtprotosender: Connection to 149.154.167.51:443/TcpFull complete!
[ INFO/2020-08-25 23:33:04,209] telethon.network.connection.connection: The server closed the connection
[DEBUG/2020-08-25 23:33:04,209] telethon.network.mtprotosender: Waiting for messages to send...
[DEBUG/2020-08-25 23:33:04,210] telethon.extensions.messagepacker: Assigned msg_id = 6865037862335272700 to InvokeWithLayerRequest (2b590e2a5f8)
[DEBUG/2020-08-25 23:33:04,210] telethon.extensions.messagepacker: Assigned msg_id = 6865037862335272704 to GetUsersRequest (2b590e2a3c8)
[DEBUG/2020-08-25 23:33:04,210] telethon.network.mtprotosender: Encrypting 2 message(s) in 148 bytes for sending
[ INFO/2020-08-25 23:33:04,211] telethon.network.mtprotosender: Connection closed while sending data
[DEBUG/2020-08-25 23:33:04,211] telethon.network.mtprotosender: Closing current connection...
[ INFO/2020-08-25 23:33:04,211] telethon.network.mtprotosender: Connecting to 149.154.167.51:443/TcpFull...
[DEBUG/2020-08-25 23:33:04,212] telethon.network.mtprotosender: Connection attempt 1...
[DEBUG/2020-08-25 23:33:05,196] telethon.network.mtprotosender: Connection success!
[DEBUG/2020-08-25 23:33:05,196] telethon.network.mtprotosender: Starting send loop
[DEBUG/2020-08-25 23:33:05,196] telethon.network.mtprotosender: Starting receive loop
...

Lonami commented 3 years ago

I'm cleaning up proxy-related issues, so closing in favour of the new issue.

LonamiWebs / Telethon

Connection through SOCKS5 proxy is dropped every 10 seconds #1323