Timed out getting updates every time only with PTB 11.1.0 and 11.0.0 (no such issue when using PTB 10.1.0) #1323

wasyawenski · 2019-01-10T09:05:16Z

Original comment:

Hello,
I've seen a similar issue here, but it did not mention that it only occurs with PTB 11.1.0 and 11.0.0.
I have downgraded PTB back to 10.1.0 to test it again and did not have a single problem, which led me to believe that it is not a network issue.

Steps to reproduce

pip install python-telegram-bot -U
or
pip install python-telegram-bot==11.0.0
start a bot with getUpdates method and logging.DEBUG

Expected behaviour

Bot should get updates

Actual behaviour

after entering getUpdates and starting HTTPS connection, telegram.ext.updater reports Timed out getting Updates: Timed out
and it goes again and again in a loop without success

It happens to be the case only with PTB version 11.0.0 and 11.1.0;
with 10.1.0 I am able to get updates without problems

Configuration

Operating System:
Win10 64bit

Version of Python, python-telegram-bot & dependencies:
python-telegram-bot 11.1.0 or python-telegram-bot 11.0.0
certifi 2018.11.29
future 0.17.1
Python 3.6.4 (i've also updated Python to 3.7.2 - issue persists)

Logs

2019-01-10 14:53:23,582 - telegram.bot - DEBUG - Entering: get_updates
2019-01-10 14:53:23,587 - telegram.vendor.ptb_urllib3.urllib3.connectionpool - DEBUG - Starting new HTTPS connection (1): api.telegram.org
2019-01-10 14:53:28,949 - telegram.ext.updater - DEBUG - Timed out getting Updates: Timed out
2019-01-10 14:53:28,956 - telegram.bot - DEBUG - Entering: get_updates
2019-01-10 14:53:28,961 - telegram.vendor.ptb_urllib3.urllib3.connectionpool - DEBUG - Starting new HTTPS connection (2): api.telegram.org
2019-01-10 14:53:34,320 - telegram.ext.updater - DEBUG - Timed out getting Updates: Timed out
2019-01-10 14:53:34,328 - telegram.bot - DEBUG - Entering: get_updates
2019-01-10 14:53:34,333 - telegram.vendor.ptb_urllib3.urllib3.connectionpool - DEBUG - Starting new HTTPS connection (3): api.telegram.org
2019-01-10 14:53:39,700 - telegram.ext.updater - DEBUG - Timed out getting Updates: Timed out

EDIT:

Despite DEBUG constantly showing Timed out, updates strangely enough do work!
I can only wonder why DEBUG shows this
But it does not cause any problems for me so far, so maybe it is a minor bug,
maybe even Windows only

I have an assumption this probably has something to do with .utils.response module

Can someone please confirm they have similar symptoms?

EDIT 2:

It was in fact a 413 (Request Entity Too Large) error returned by Telegram, which had nothing to do with the file size, but rather it so happened, that some of my files did not have Latin only characters in their names, and Telegram didn't like it. Please disregard this:

Uploading several large files in a row (that is, in the range of 10 to 50 mb) prompts two other errors:

json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)
followed by:
TelegramError: Invalid server response

The first upload goes without problems, this happens starting from the second one.
Files less than 10mb seem to be unaffected.

Can somebody please confirm having the same issues as I am?

Here is the log:

2019-01-12 01:36:40,883 - telegram.vendor.ptb_urllib3.urllib3.connectionpool - DEBUG - https://api.telegram.org:443 "POST /bot<TOKEN>/sendVideo HTTP/1.1" 413 0
Exception in thread Thread-1:
Traceback (most recent call last):
  File "C:\Users\username\AppData\Local\Programs\Python\Python37\lib\site-packages\telegram\utils\request.py", line 157, in _parse
    data = json.loads(decoded_s)
  File "C:\Users\username\AppData\Local\Programs\Python\Python37\lib\json\__init__.py", line 348, in loads
    return _default_decoder.decode(s)
  File "C:\Users\username\AppData\Local\Programs\Python\Python37\lib\json\decoder.py", line 337, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "C:\Users\username\AppData\Local\Programs\Python\Python37\lib\json\decoder.py", line 355, in raw_decode
    raise JSONDecodeError("Expecting value", s, err.value) from None
json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "C:\Users\username\AppData\Local\Programs\Python\Python37\lib\threading.py", line 917, in _bootstrap_inner
    self.run()
  File "C:\Users\username\AppData\Local\Programs\Python\Python37\lib\threading.py", line 865, in run
    self._target(*self._args, **self._kwargs)
  File "C:\[DATA]\Bot\mybot.py", line 1385, in task_executor
    Autoposter.poster(thumbname)
  File "C:\[DATA]\Bot\mybot.py", line 1589, in poster
    timeout=5000
  File "C:\Users\username\AppData\Local\Programs\Python\Python37\lib\site-packages\telegram\bot.py", line 65, in decorator
    result = func(self, *args, **kwargs)
  File "C:\Users\username\AppData\Local\Programs\Python\Python37\lib\site-packages\telegram\bot.py", line 90, in decorator
    result = self._request.post(url, data, timeout=kwargs.get('timeout'))
  File "C:\Users\username\AppData\Local\Programs\Python\Python37\lib\site-packages\telegram\utils\request.py", line 331, in post
    result = self._request_wrapper('POST', url, fields=data, **urlopen_kwargs)
  File "C:\Users\username\AppData\Local\Programs\Python\Python37\lib\site-packages\telegram\utils\request.py", line 216, in _request_wrapper
    message = self._parse(resp.data)
  File "C:\Users\username\AppData\Local\Programs\Python\Python37\lib\site-packages\telegram\utils\request.py", line 163, in _parse
    raise TelegramError('Invalid server response')
telegram.error.TelegramError: Invalid server response

The text was updated successfully, but these errors were encountered:

djwessel · 2019-01-21T12:03:35Z

Hey, I can confirm that I am also getting the timed out messages on a raspberry pi running Raspbian.

2019-01-21 12:58:50,354 - telegram.ext.updater - DEBUG - Timed out getting Updates: Timed out
2019-01-21 12:58:50,355 - telegram.bot - DEBUG - Entering: get_updates
2019-01-21 12:58:50,356 - telegram.vendor.ptb_urllib3.urllib3.connectionpool - DEBUG - Starting new HTTPS connection (2): api.telegram.org
2019-01-21 12:58:55,567 - telegram.ext.updater - DEBUG - Timed out getting Updates: Timed out
2019-01-21 12:58:55,569 - telegram.bot - DEBUG - Entering: get_updates
2019-01-21 12:58:55,571 - telegram.vendor.ptb_urllib3.urllib3.connectionpool - DEBUG - Starting new HTTPS connection (3): api.telegram.org
2019-01-21 12:59:00,761 - telegram.ext.updater - DEBUG - Timed out getting Updates: Timed out
2019-01-21 12:59:00,763 - telegram.bot - DEBUG - Entering: get_updates
2019-01-21 12:59:00,765 - telegram.vendor.ptb_urllib3.urllib3.connectionpool - DEBUG - Starting new HTTPS connection (4): api.telegram.org

wasyawenski · 2019-01-22T11:41:29Z

Hey, I can confirm that I am also getting the timed out messages on a raspberry pi running Raspbian.

Does your bot actually get updates?

BTW, I've also tested the bot in Debian, the issue stays the same.
So apparently, it is a library bug starting from v 11.0, which probably was not too obvious due to perhaps nobody using polling method with debug logging level or I dunno

jsmnbom · 2019-01-22T11:57:18Z

I haven't looked too much into this yet, but I think I might know why you're gettng timeouts.
It happens because.. well, the connections timeouts since it uses long-polling (aka hold connection open till there's an update), but only with a 5 sec timeout. So if you receive no updates in 5 sec a timeout is actually to be expected.
The fact that the logs don't actually show any ERROR or even WARNING seem to cooperate this view.

To "fix" either increase your timeout when polling (easy)
(I seem to recall telegram wrote somewhere that 60 sec is recommended)

updater.start_polling(timeout=60)

Or which away from long-polling to webhooks (a bit harder).

wasyawenski · 2019-01-23T08:45:36Z

I haven't looked too much into this yet, but I think I might know why you're gettng timeouts.
It happens because.. well, the connections timeouts since it uses long-polling (aka hold connection open till there's an update), but only with a 5 sec timeout. So if you receive no updates in 5 sec a timeout is actually to be expected.
The fact that the logs don't actually show any ERROR or even WARNING seem to cooperate this view.

To "fix" either increase your timeout when polling (easy)
(I seem to recall telegram wrote somewhere that 60 sec is recommended)
updater.start_polling(timeout=60)
Or which away from long-polling to webhooks (a bit harder).

Hey, thanks for your suggestion, but it does not fix the issue.
I don't really know whether I should say "issue", since my bot actually does get updates, it's just the logging debug level falsely saying it has timeouts.

So I am perfectly fine with all that, I just wanted to point that out as maybe some kind of a minor bug or something along those lines.

My polling timeout setting always used to be 20 sec, which was working perfectly with logging debug under v10.1, but starting from v11.0 it started to "timeout". Change from 20 to 60 seconds did not have any effect.

As for webhooks, I develop the bot locally, so as of now polling is a more convenient option for me.

UPD: the "timeout" message occurs every 5 seconds or so, regardless of which timeout arg value is set

djwessel · 2019-01-25T13:58:23Z

Like @wasyawenski, my bot does still get updates, regardless of these messages. Furthermore, I can confirm that setting the timeout arg on start_polling didn't seem to affect the messages either.

am1ru1 · 2019-01-30T17:16:18Z

Can confirm that the latest version is giving disconnect error:

17:09:25 ERROR    errbot.backends.telegram  Error reading from Telegram updates stream:
Traceback (most recent call last):
  File "/opt/conda/lib/python3.6/site-packages/telegram/vendor/ptb_urllib3/urllib3/connectionpool.py", line 402, in _make_request
    six.raise_from(e, None)
  File "<string>", line 2, in raise_from
  File "/opt/conda/lib/python3.6/site-packages/telegram/vendor/ptb_urllib3/urllib3/connectionpool.py", line 398, in _make_request
    httplib_response = conn.getresponse()
  File "/opt/conda/lib/python3.6/http/client.py", line 1331, in getresponse
    response.begin()
  File "/opt/conda/lib/python3.6/http/client.py", line 297, in begin
    version, status, reason = self._read_status()
  File "/opt/conda/lib/python3.6/http/client.py", line 258, in _read_status
    line = str(self.fp.readline(_MAXLINE + 1), "iso-8859-1")
  File "/opt/conda/lib/python3.6/socket.py", line 586, in readinto
    return self._sock.recv_into(b)
  File "/opt/conda/lib/python3.6/ssl.py", line 1012, in recv_into
    return self.read(nbytes, buffer)
  File "/opt/conda/lib/python3.6/ssl.py", line 874, in read
    return self._sslobj.read(len, buffer)
  File "/opt/conda/lib/python3.6/ssl.py", line 631, in read
    v = self._sslobj.read(len, buffer)
socket.timeout: The read operation timed out

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/conda/lib/python3.6/site-packages/telegram/utils/request.py", line 203, in _request_wrapper
    resp = self._con_pool.request(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/telegram/vendor/ptb_urllib3/urllib3/request.py", line 70, in request
    **urlopen_kw)
  File "/opt/conda/lib/python3.6/site-packages/telegram/vendor/ptb_urllib3/urllib3/request.py", line 148, in request_encode_body
    return self.urlopen(method, url, **extra_kw)
  File "/opt/conda/lib/python3.6/site-packages/telegram/vendor/ptb_urllib3/urllib3/poolmanager.py", line 244, in urlopen
    response = conn.urlopen(method, u.request_uri, **kw)
  File "/opt/conda/lib/python3.6/site-packages/telegram/vendor/ptb_urllib3/urllib3/connectionpool.py", line 666, in urlopen
    _stacktrace=sys.exc_info()[2])
  File "/opt/conda/lib/python3.6/site-packages/telegram/vendor/ptb_urllib3/urllib3/util/retry.py", line 347, in increment
    raise six.reraise(type(error), error, _stacktrace)
  File "/opt/conda/lib/python3.6/site-packages/telegram/vendor/ptb_urllib3/urllib3/packages/six.py", line 686, in reraise
    raise value
  File "/opt/conda/lib/python3.6/site-packages/telegram/vendor/ptb_urllib3/urllib3/connectionpool.py", line 617, in urlopen
    chunked=chunked)
  File "/opt/conda/lib/python3.6/site-packages/telegram/vendor/ptb_urllib3/urllib3/connectionpool.py", line 405, in _make_request
    exc_cls=ReadTimeoutError)
  File "/opt/conda/lib/python3.6/site-packages/telegram/vendor/ptb_urllib3/urllib3/connectionpool.py", line 321, in _raise_timeout
    raise exc_cls(*args)
telegram.vendor.ptb_urllib3.urllib3.exceptions.ReadTimeoutError: HTTPSConnectionPool(host='api.telegram.org', port=443): Read timed out. (read timeout=5.0)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/conda/lib/python3.6/site-packages/errbot/backends/telegram_messenger.py", line 226, in serve_once
    for update in self.telegram.getUpdates(offset=offset, timeout=60):
  File "/opt/conda/lib/python3.6/site-packages/telegram/bot.py", line 65, in decorator
    result = func(self, *args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/telegram/bot.py", line 1975, in get_updates
    result = self._request.post(url, data, timeout=float(read_latency) + float(timeout))
  File "/opt/conda/lib/python3.6/site-packages/telegram/utils/request.py", line 309, in post
    headers={'Content-Type': 'application/json'})
  File "/opt/conda/lib/python3.6/site-packages/telegram/utils/request.py", line 205, in _request_wrapper
    raise TimedOut()
telegram.error.TimedOut: Timed out
```

jsmnbom · 2019-01-30T18:40:41Z

Alright, I just merged #1330 which as far as my testing goes, fixes this issue too.

@vnoxygen @wasyawenski @djwessel are any of you able to confirm this?
(clone master to test)

Once again - mostly everything works okay even without this change - only it was quite noisy in logs and such.

jsmnbom · 2019-02-08T10:03:57Z

Closing due to lack of feedback, assuming #1330 fixed things.

In a desperate attempt to get python-telegram-bot/python-telegram-bot#1330 and fix python-telegram-bot/python-telegram-bot#1323

dmak · 2019-11-15T12:02:50Z

I have the same issue with python_telegram_bot=11.1.0. It floods the log with messages like below:

DEBUG (updater) [telegram.ext.updater] Timed out getting Updates: Timed out     
DEBUG (updater) [telegram.bot] Entering: get_updates                            
DEBUG (updater) [telegram.vendor.ptb_urllib3.urllib3.connectionpool] Starting new HTTPS connection (230): api.telegram.org

They appear every 5 seconds or so. Above all I believe it tries to connect to Telegram server again and again hence loading the network.
Would it be a proper solution to downgrade to v10.1.0?

wasyawenski changed the title ~~Timed out getting updates every time only with PTB 11.0.0 and 11.1.0 (no such issue when using PTB 10.1.0)~~ Timed out getting updates every time only with PTB 11.1.0 and 11.0.0 (no such issue when using PTB 10.1.0) Jan 11, 2019

am1ru1 mentioned this issue Jan 30, 2019

Error reading from Telegram updates stream errbotio/errbot#1271

Closed

5 tasks

jsmnbom mentioned this issue Jan 30, 2019

Fix #1328: custom timeout argument does not work #1330

Merged

jsmnbom closed this as completed Feb 8, 2019

lvps added a commit to WEEE-Open/WEEEtofono that referenced this issue Mar 25, 2019

Updated dependencies with pre-release packages

18e22ed

In a desperate attempt to get python-telegram-bot/python-telegram-bot#1330 and fix python-telegram-bot/python-telegram-bot#1323

github-actions bot locked and limited conversation to collaborators Aug 21, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Timed out getting updates every time only with PTB 11.1.0 and 11.0.0 (no such issue when using PTB 10.1.0) #1323

Timed out getting updates every time only with PTB 11.1.0 and 11.0.0 (no such issue when using PTB 10.1.0) #1323

wasyawenski commented Jan 10, 2019 •

edited

Loading

djwessel commented Jan 21, 2019

wasyawenski commented Jan 22, 2019

jsmnbom commented Jan 22, 2019

wasyawenski commented Jan 23, 2019 •

edited

Loading

djwessel commented Jan 25, 2019

am1ru1 commented Jan 30, 2019 •

edited

Loading

jsmnbom commented Jan 30, 2019

jsmnbom commented Feb 8, 2019

dmak commented Nov 15, 2019

Timed out getting updates every time only with PTB 11.1.0 and 11.0.0 (no such issue when using PTB 10.1.0) #1323

Timed out getting updates every time only with PTB 11.1.0 and 11.0.0 (no such issue when using PTB 10.1.0) #1323

Comments

wasyawenski commented Jan 10, 2019 • edited Loading

Original comment:

Steps to reproduce

Expected behaviour

Actual behaviour

Configuration

Logs

EDIT:

EDIT 2:

djwessel commented Jan 21, 2019

wasyawenski commented Jan 22, 2019

jsmnbom commented Jan 22, 2019

wasyawenski commented Jan 23, 2019 • edited Loading

djwessel commented Jan 25, 2019

am1ru1 commented Jan 30, 2019 • edited Loading

jsmnbom commented Jan 30, 2019

jsmnbom commented Feb 8, 2019

dmak commented Nov 15, 2019

wasyawenski commented Jan 10, 2019 •

edited

Loading

wasyawenski commented Jan 23, 2019 •

edited

Loading

am1ru1 commented Jan 30, 2019 •

edited

Loading