nmlorg / metabot

Modularized, multi-account bot.
https://metabot.readthedocs.io/
5 stars 0 forks source link

Read timeouts can trigger a second daily announcement #82

Closed nmlorg closed 3 months ago

nmlorg commented 4 years ago

This morning, the daily announcement for one group was sent twice:  once without the banner image, a second time with it.

8:00:06  The initial announcement (with the banner image) began delivery. 8:00:19  The initial announcement tripped a 12-second timeout. This timeout was caught by logic looking for errors about the banner caption being too large, and caused the announcement to be re-sent without the banner. 8:00:20  The re-sent, bannerless announcement was delivered (1 second after delivery began). 8:00:37  The initial, bannered announcement was delivered (31 seconds after delivery began).

2019-12-04 08:00:06,212 INFO geoutil.py:45] Fetching 'https://api.weather.gov/gridpoints/.../forecast/hourly'.
2019-12-04 08:00:19,801 ERROR reminders.py:71] Downgrading to plain text:
Traceback (most recent call last):
  File "lib/python3.6/site-packages/urllib3/connectionpool.py", line 421, in _make_request
    six.raise_from(e, None)
  File "<string>", line 3, in raise_from
  File "lib/python3.6/site-packages/urllib3/connectionpool.py", line 416, in _make_request
    httplib_response = conn.getresponse()
  File "/usr/lib/python3.6/http/client.py", line 1346, in getresponse
    response.begin()
  File "/usr/lib/python3.6/http/client.py", line 307, in begin
    version, status, reason = self._read_status()
  File "/usr/lib/python3.6/http/client.py", line 268, in _read_status
    line = str(self.fp.readline(_MAXLINE + 1), "iso-8859-1")
  File "/usr/lib/python3.6/socket.py", line 586, in readinto
    return self._sock.recv_into(b)
  File "/usr/lib/python3.6/ssl.py", line 1012, in recv_into
    return self.read(nbytes, buffer)
  File "/usr/lib/python3.6/ssl.py", line 874, in read
    return self._sslobj.read(len, buffer)
  File "/usr/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 "lib/python3.6/site-packages/requests/adapters.py", line 449, in send
    timeout=timeout
  File "lib/python3.6/site-packages/urllib3/connectionpool.py", line 720, in urlopen
    method, url, error=e, _pool=self, _stacktrace=sys.exc_info()[2]
  File "lib/python3.6/site-packages/urllib3/util/retry.py", line 400, in increment
    raise six.reraise(type(error), error, _stacktrace)
  File "lib/python3.6/site-packages/urllib3/packages/six.py", line 735, in reraise
    raise value
  File "lib/python3.6/site-packages/urllib3/connectionpool.py", line 672, in urlopen
    chunked=chunked,
  File "lib/python3.6/site-packages/urllib3/connectionpool.py", line 423, in _make_request
    self._raise_timeout(err=e, url=url, timeout_value=read_timeout)
  File "lib/python3.6/site-packages/urllib3/connectionpool.py", line 331, in _raise_timeout
    self, url, "Read timed out. (read timeout=%s)" % timeout_value
urllib3.exceptions.ReadTimeoutError: HTTPSConnectionPool(host='api.telegram.org', port=443): Read timed out. (read timeout=12)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "lib/python3.6/site-packages/ntelebot/bot.py", line 55, in __call__
    data = requests.post(self.url, timeout=self.timeout, json=params).json()
  File "lib/python3.6/site-packages/requests/api.py", line 116, in post
    return request('post', url, data=data, json=json, **kwargs)
  File "lib/python3.6/site-packages/requests/api.py", line 60, in request
    return session.request(method=method, url=url, **kwargs)
  File "lib/python3.6/site-packages/requests/sessions.py", line 533, in request
    resp = self.send(prep, **send_kwargs)
  File "lib/python3.6/site-packages/requests/sessions.py", line 646, in send
    r = adapter.send(request, **kwargs)
  File "lib/python3.6/site-packages/requests/adapters.py", line 529, in send
    raise ReadTimeout(e, request=request)
requests.exceptions.ReadTimeout: HTTPSConnectionPool(host='api.telegram.org', port=443): Read timed out. (read timeout=12)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "lib/python3.6/site-packages/metabot/modules/reminders.py", line 69, in _daily_messages
    disable_notification=True)
  File "lib/python3.6/site-packages/ntelebot/bot.py", line 57, in __call__
    raise ntelebot.errors.Timeout(exc)
ntelebot.errors.Timeout: HTTPSConnectionPool(host='api.telegram.org', port=443): Read timed out. (read timeout=12)
2019-12-04 08:00:21,243 INFO geoutil.py:45] Fetching 'https://api.weather.gov/gridpoints/.../forecast/hourly'.

 

It's hard to assert what the best behavior would be; if we had implemented general retry-on-failure logic, the bot could have ended up sending tons (duration of response latency spike / 12 seconds, assuming no backoff) of duplicates, so this was sort of accidentally ideal.