search

nickoala / telepot

Python framework for Telegram Bot API
MIT License
2.42k stars 474 forks source link

Connection reset by peer #87

Closed feranto63 closed 8 years ago

feranto63 commented 8 years ago

since I upgrade to telepot 8.0 I got this error when calling a normal bot.sendMessage.

This is an extract of the code that caused the error. Just to say that never occurred with telepot 6 or 7. The error occours if only the program is running since some minutes, the error does not occour if the program has been started very recently. Please help me.

` try: n=persona.index(nome) except ValueError: #non ho riconosciuto la persona bot.sendMessage(CHAT_ID, "Padrone verifica se ci sono sconosciuti in casa!") return

    if status == 'IN':
        if persona_at_home[n] == False:
            persona_at_home[n] = True
            messaggio_IN="Benvenuto a casa "+nome+"\nSono le "+ora_minuti
            bot.sendMessage(CHAT_ID, messaggio_IN ,disable_notification=hide_notify)
            f = open(persona[n]+"_at_home","w")  #apre il file dei dati in write mode, se il file non esiste lo crea
            f.write("IN")  #scrive la info di presence sul file
            f.close()  #chiude il file dei dati e lo salva
    elif status == 'OUT':
        if persona_at_home[n]:
            persona_at_home[n] = False
            messaggio_OUT="Arrivederci a presto "+nome+"\nSono le "+ora_minuti
            bot.sendMessage(CHAT_ID, messaggio_OUT ,disable_notification=hide_notify)
            f = open(persona[n]+"_at_home","w")  #apre il file dei dati in write mode, se il file non esiste lo crea
            f.write("OUT")  #scrive la info di presence sul file
            f.close()  #chiude il file dei dati e lo salva

`

Traceback (most recent call last): File "/home/pi/git/thermostat/thermostat/thermogram2.py", line 825, in check_presence_IP() # controlla la presente con ping IP File "/home/pi/git/thermostat/thermostat/thermogram2.py", line 561, in check_presence_IP set_presence(persona[n]+' IN') #richiama la funzione per la gestisce della presence File "/home/pi/git/thermostat/thermostat/thermogram2.py", line 505, in set_presence bot.sendMessage(CHAT_ID, messaggio_IN ,disable_notification=hide_notify) File "/usr/local/lib/python2.7/dist-packages/telepot/init.py", line 176, in sendMessage return self._api_request('sendMessage', _rectify(p)) File "/usr/local/lib/python2.7/dist-packages/telepot/init.py", line 167, in _api_request return api.request((self._token, method, params, files), _kwargs) File "/usr/local/lib/python2.7/dist-packages/telepot/api.py", line 126, in request r = fn(_args, _kwargs) # fn must be thread-safe File "/usr/local/lib/python2.7/dist-packages/urllib3/request.py", line 151, in request_encode_body return self.urlopen(method, url, *_extra_kw) File "/usr/local/lib/python2.7/dist-packages/urllib3/poolmanager.py", line 165, in urlopen response = conn.urlopen(method, u.request_uri, **kw) File "/usr/local/lib/python2.7/dist-packages/urllib3/connectionpool.py", line 623, in urlopen _stacktrace=sys.exc_info()[2]) File "/usr/local/lib/python2.7/dist-packages/urllib3/util/retry.py", line 232, in increment raise six.reraise(type(error), error, _stacktrace) File "/usr/local/lib/python2.7/dist-packages/urllib3/connectionpool.py", line 578, in urlopen chunked=chunked) File "/usr/local/lib/python2.7/dist-packages/urllib3/connectionpool.py", line 385, in _make_request httplib_response = conn.getresponse(buffering=True) File "/usr/lib/python2.7/httplib.py", line 1073, in getresponse response.begin() File "/usr/lib/python2.7/httplib.py", line 415, in begin version, status, reason = self._read_status() File "/usr/lib/python2.7/httplib.py", line 371, in _read_status line = self.fp.readline(_MAXLINE + 1) File "/usr/lib/python2.7/socket.py", line 476, in readline data = self._sock.recv(self._rbufsize) File "/usr/lib/python2.7/ssl.py", line 714, in recv return self.read(buflen) File "/usr/lib/python2.7/ssl.py", line 608, in read v = self._sslobj.read(len or 1024) urllib3.exceptions.ProtocolError: ('Connection aborted.', error(104, 'Connection reset by peer'))

nickoala commented 8 years ago

Broadcast: Anyone else encountering the same problem?

feranto63 commented 8 years ago

It seems I solved the problem managing the exception with

from socket import error as SocketError
import errno

try:
      bot.sendMessage(CHAT_ID, messaggio_IN ,disable_notification=hide_notify)
except SocketError as e:
      if e.errno != errno.ECONNRESET:
            raise # Not error we are looking for
     pass # Handle error here.

you can close the issue

feranto63 commented 8 years ago

not resolved, even with the previous code I still get the connection error. Any suggestion to debug it?

nickoala commented 8 years ago

I have to reproduce this problem in order to fix it. Here is what I will try: Make a simple program that spawns many threads which send messages to me periodically and simultaneously. See if it reproduces the problem you mentioned.

However, my priority right now is to update telepot's documentations. Assuming this problem is not widespread, I will get back to you after docs are done.

feranto63 commented 8 years ago

Just for your comprehension my program is quite simple:

one bot; one handle that manages commands to the bot (this is always working); one repeating routine ('check_presence') that ping four hosts (4 Android smartphones) every minute to check if they are reachable or not and send a message if host status has changed.

When trying to send a changed status message I got the error. This is happening from telepot release 8.0 maybe when you moved from 'request' to 'urllib3'.

I report again the error I got, maybe you can understand what's happening.

  File "/home/pi/git/thermostat/thermostat/thermogram2.py", line 874, in <module>
    check_presence_IP() # controlla la presente con ping IP
  File "/home/pi/git/thermostat/thermostat/thermogram2.py", line 604, in check_presence_IP
    bot.sendMessage(CHAT_ID, messaggio_IN_OUT)
  File "/usr/local/lib/python2.7/dist-packages/telepot/__init__.py", line 235, in sendMessage
    return self._api_request('sendMessage', _rectify(p))
  File "/usr/local/lib/python2.7/dist-packages/telepot/__init__.py", line 224, in _api_request
    return api.request((self._token, method, params, files), **kwargs)
  File "/usr/local/lib/python2.7/dist-packages/telepot/api.py", line 130, in request
    r = fn(*args, **kwargs)  # `fn` must be thread-safe
  File "/usr/local/lib/python2.7/dist-packages/urllib3/request.py", line 151, in request_encode_body
    return self.urlopen(method, url, **extra_kw)
  File "/usr/local/lib/python2.7/dist-packages/urllib3/poolmanager.py", line 165, in urlopen
    response = conn.urlopen(method, u.request_uri, **kw)
  File "/usr/local/lib/python2.7/dist-packages/urllib3/connectionpool.py", line 623, in urlopen
    _stacktrace=sys.exc_info()[2])
  File "/usr/local/lib/python2.7/dist-packages/urllib3/util/retry.py", line 232, in increment
    raise six.reraise(type(error), error, _stacktrace)
  File "/usr/local/lib/python2.7/dist-packages/urllib3/connectionpool.py", line 578, in urlopen
    chunked=chunked)
  File "/usr/local/lib/python2.7/dist-packages/urllib3/connectionpool.py", line 385, in _make_request
    httplib_response = conn.getresponse(buffering=True)
  File "/usr/lib/python2.7/httplib.py", line 1073, in getresponse
    response.begin()
  File "/usr/lib/python2.7/httplib.py", line 415, in begin
    version, status, reason = self._read_status()
  File "/usr/lib/python2.7/httplib.py", line 371, in _read_status
    line = self.fp.readline(_MAXLINE + 1)
  File "/usr/lib/python2.7/socket.py", line 476, in readline
    data = self._sock.recv(self._rbufsize)
  File "/usr/lib/python2.7/ssl.py", line 714, in recv
    return self.read(buflen)
  File "/usr/lib/python2.7/ssl.py", line 608, in read
    v = self._sslobj.read(len or 1024)
urllib3.exceptions.ProtocolError: ('Connection aborted.', error(104, 'Connection reset by peer'))

Could you suggest me what troubleshooting I can do? Thanks for your support

feranto63 commented 8 years ago

this is a simplified version of my code so you can try to test by yourself

#!/usr/bin/python

import sys
owner_found = False

import ConfigParser

settings = ConfigParser.ConfigParser()
settings.read('thermogram2.ini')
persone_della_casa = settings.getint('SectionOne','persone_della_casa')
persona= settings.get('SectionOne','persona').split("\n")
#persona_at_home=settings.getboolean('SectionOne','persona_at_home').split("\n")
persona_at_home=[True, True, True, True, True, True, True, True, True]
imap_host = settings.get('SectionOne','imap_host')
EMAIL_ID=settings.get('SectionOne','EMAIL_ID')
EMAIL_PASSWD=settings.get('SectionOne','EMAIL_PASSWD')
persona_IP=settings.get('SectionOne','persona_IP').split("\n")
persona_BT=settings.get('SectionOne','persona_BT').split("\n")
GATE_PRESENT = settings.getboolean('SectionOne','GATE_PRESENT')
IP_PRESENCE = settings.getboolean('SectionOne','IP_PRESENCE')
BT_PRESENCE = settings.getboolean('SectionOne','BT_PRESENCE')
DHT_PRESENCE = settings.getboolean('SectionOne','DHT_PRESENCE')
DS_PRESENCE = settings.getboolean('SectionOne','DS_PRESENCE')
owner_found= settings.getboolean('SectionOne','owner_found')

if not owner_found:
    sys.exit("owner not found")

import os
import glob
import time

import telepot

def handle(msg):
    global CHAT_ID

    msg_type, chat_type, chat_id = telepot.glance(msg)
    msg_sender = msg['from']['first_name']

    if msg_type != 'text':
        return

    command = msg['text'].strip().lower()

    if command == '/now':
        bot.sendMessage(CHAT_ID, 'ho ricevuto il comando now')
    else:
        bot.sendMessage(CHAT_ID, "Puoi ripetere, Padrone? I miei circuiti sono un po' arrugginiti")

TOKEN = '99999999999'
CHAT_ID = 26228522

def set_presence(n, presence_msg):
    global persona_at_home
    global CHAT_ID

    if len(presence_msg) !=0:
        words = presence_msg.split(' ', 2)
        nome = words[0]
        status = words[1]
        orario = time.localtime(time.time())

        localtime = time.asctime( orario )
        ora_minuti = time.strftime("%H:%M", orario)
        changed = False

        if n == -1:
            try:
                n=persona.index(nome)
            except ValueError: #non ho riconosciuto la persona
                messaggio_IN_OUT = "Padrone verifica se ci sono sconosciuti in casa!"
                changed = True
                bot.sendMessage(CHAT_ID, "Padrone verifica se ci sono sconosciuti in casa!")
                return changed, messaggio_IN_OUT

        if status == 'IN':
            if persona_at_home[n] == False:
                persona_at_home[n] = True
                messaggio_IN_OUT="Benvenuto a casa "+nome+"\nSono le "+ora_minuti
                changed = True
                bot.sendMessage(CHAT_ID, messaggio_IN_OUT )
        elif status == 'OUT':
            if persona_at_home[n]:
                persona_at_home[n] = False
                messaggio_IN_OUT="Arrivederci a presto "+nome+"\nSono le "+ora_minuti
                changed = True
                bot.sendMessage(CHAT_ID, messaggio_IN_OUT)
    return changed, messaggio_IN_OUT

######################## check presence con ping IP su wifi
import subprocess

def check_presence_IP():
    global personaIP, persona_at_home, persone_della_casa
    global CHAT_ID
    for n in range(persone_della_casa):
        result = subprocess.call(['ping','-c','1',persona_IP[n]])
        if (result == 0):
            if not persona_at_home[n]:
                changed, messaggio_IN_OUT= set_presence(n, persona[n]+' IN') 
        else:
            if persona_at_home[n]:
                changed, messaggio_IN_OUT= set_presence(n, persona[n]+' OUT')

####################################################

############ legge da file lo stato delle persone della casa ###############
for n in range(persone_della_casa):
    try:
        f = open(persona[n]+"_at_home","r")  #apre il file dei dati in read mode
        pres=f.read().strip()   #legge la info di presence sul file
        f.close()  #chiude il file dei dati e lo salva
        if pres == "IN":
            persona_at_home[n] = True
        else:
            persona_at_home[n] = False
    except IOError:
        persona_at_home[n] = False  #se il file non e' presente imposto la presence a False

######## inizializza il bot Telegram ###########
bot = telepot.Bot(TOKEN)
bot.message_loop(handle)
logging.info("Listening ...")

main_show_keyboard = {'keyboard': [['/now']]}
bot.sendMessage(CHAT_ID, 'Mi sono appena svegliato, Padrone')

bot.sendMessage(CHAT_ID, 'Come ti posso aiutare?', reply_markup=main_show_keyboard)

while True:
    now = time.time()
    localtime = time.strftime('%Y-%m-%d %H:%M:%S',time.localtime(time.time()))
    if IP_PRESENCE:
        check_presence_IP() # controlla la presente con ping IP
    time.sleep(60)
feranto63 commented 8 years ago

I think I found what is the cause of this problem but I do not know how to solve it. I think it is some sort of timeout or disconnection due to the fact that the bot tries to send a message in the chat after some minutes from last activity and this causes the connection reset from the server. To test this I just added a sendMessage every 60 seconds in the while loop. This is keeping the connection open so when there is a change in the status the sendMessage does not get rejected by server.

So my question is: how can I keep the connection up and avoid reject?

nickoala commented 8 years ago

Thanks for looking into the problem. I have been busy. I will take some time to look at it tomorrow.

k-freeman commented 8 years ago

I think I found what is the cause of this problem but I do not know how to solve it. I think it is some sort of timeout or disconnection due to the fact that the bot tries to send a message in the chat after some minutes from last activity and this causes the connection reset from the server.

I have a public repository called "Abb1t". All commands are working, independent from time except one, which causes the same error (Connection reset by peer)[https://github.com/k-freeman/Abb1t/blob/master/mods/mensa.py#L53]. I could not figure out why this error is occuring, but I am currently observing it. As other commands are even working after 20h of idle time, i dont think that it is a sort of timeout... Here's my traceback:

Traceback (most recent call last):
  File "/home/kevin/git/modular-telegram-bot/mods/mensa.py", line 54, in run
    self.bot.sendMessage(chat_id,reply)#,parse_mode="Markdown")
  File "/usr/local/lib/python3.5/dist-packages/telepot/__init__.py", line 235, in sendMessage
    return self._api_request('sendMessage', _rectify(p))
  File "/usr/local/lib/python3.5/dist-packages/telepot/__init__.py", line 224, in _api_request
    return api.request((self._token, method, params, files), **kwargs)
  File "/usr/local/lib/python3.5/dist-packages/telepot/api.py", line 130, in request
    r = fn(*args, **kwargs)  # `fn` must be thread-safe
  File "/usr/local/lib/python3.5/dist-packages/urllib3/request.py", line 151, in request_encode_body
    return self.urlopen(method, url, **extra_kw)
  File "/usr/local/lib/python3.5/dist-packages/urllib3/poolmanager.py", line 165, in urlopen
    response = conn.urlopen(method, u.request_uri, **kw)
  File "/usr/local/lib/python3.5/dist-packages/urllib3/connectionpool.py", line 623, in urlopen
    _stacktrace=sys.exc_info()[2])
  File "/usr/local/lib/python3.5/dist-packages/urllib3/util/retry.py", line 232, in increment
    raise six.reraise(type(error), error, _stacktrace)
  File "/usr/local/lib/python3.5/dist-packages/urllib3/packages/six.py", line 309, in reraise
    raise value.with_traceback(tb)
  File "/usr/local/lib/python3.5/dist-packages/urllib3/connectionpool.py", line 578, in urlopen
    chunked=chunked)
  File "/usr/local/lib/python3.5/dist-packages/urllib3/connectionpool.py", line 387, in _make_request
    httplib_response = conn.getresponse()
  File "/usr/lib/python3.5/http/client.py", line 1197, in getresponse
    response.begin()
  File "/usr/lib/python3.5/http/client.py", line 297, in begin
    version, status, reason = self._read_status()
  File "/usr/lib/python3.5/http/client.py", line 258, in _read_status
    line = str(self.fp.readline(_MAXLINE + 1), "iso-8859-1")
  File "/usr/lib/python3.5/socket.py", line 575, in readinto
    return self._sock.recv_into(b)
  File "/usr/lib/python3.5/ssl.py", line 925, in recv_into
    return self.read(nbytes, buffer)
  File "/usr/lib/python3.5/ssl.py", line 787, in read
    return self._sslobj.read(len, buffer)
  File "/usr/lib/python3.5/ssl.py", line 571, in read
    v = self._sslobj.read(len, buffer)
urllib3.exceptions.ProtocolError: ('Connection aborted.', ConnectionResetError(104, 'Connection reset by peer'))
nickoala commented 8 years ago

Thanks. I am investigating it, with no more meaningful comments to make at this moment. It is good to know it happens to more than one person.

k-freeman commented 8 years ago

I see that this is supposed to be fixed with 8.2. Did you fix it already or do you still have to investigate it? thx

nickoala commented 8 years ago

Not yet. I did try a simple bot which sends me 5 messages per minute. It stopped for some reason after 2 hours. I did not capture stderr, so didn't really know what was going on. And I did not have time to investigate again. I will try to fix it for 8.2, but no guarantee.

If you really want it to be stable, I suggest you move back to an older version. But this problem will have to be fixed, because I am determined not to go back to requests.

k-freeman commented 8 years ago

Yeah, i moved to 7.1 approx 1hour ago. No errors. It's really coming from that urllib3 stuff, maybe the meta data of the request is buggy (length or something like that)... I'll spend time on debugging that when i have time, if i find the problem, ill create a pull request.

nickoala commented 8 years ago

Thank you very much. I appreciate it.

TheBastelWastl commented 8 years ago

I get the same error using 8.1. But not on all SendMessage-calls in my program. Seems to be depending from the time it does nothing and the content of the message. Serveral SendMessage-calls work without problems even after days.

nickoala commented 8 years ago

Can you elaborate? Which call works ok? What content seems to cause problem? etc.

TheBastelWastl commented 8 years ago

Sorry, I made a mistake. I've now seen that all code that is running fine for hous and days is in the telepot message loop. This is obviously due to the fact that all sendMessages there are a direct response to a incoming message from the server.

I have another loop in the program that reacts on GPIO-pins and sends a message when an I/O-pin gets high. If this loop runs for several hours and then uses the sendMessage the first time, the program stops with "error 104, connection reset by peer".

I think this happens because there was no previous incoming communication from the server. The problem did not occur with telepot 8.1 in Python 2.7, it only happens since I moved my program to Python 3.4. I'm new to Python and telepot, so sometimes I need to look twice... :-) I will try the downgrade to 7.1 and see what happens.

TheBastelWastl commented 8 years ago

Did the downgrade to 7.1 yesterday. 7.1 works without problems with Python 3.4.

amontefusco commented 8 years ago

I have the same error whilst sending a message:

urllib3.exceptions.ProtocolError: ('Connection aborted.', error(104, 'Connection reset by peer'))

My bot is very simple: it is just counter.py but it has a trailing loop that reads a serial interface and (sometimes) reacts to what is read from the serial, caliing the bot.sendMessage(...).

So, I am sending messages from the foreground thread, whilst the main loop is running on the background one.

Python 2.7 , telepot cloned from master branch.

For now I trap the exception and try again after a second.

TheBastelWastl commented 8 years ago

Try the downgrade to telepot 7.1. In my case that helped, program runs perfect for more then 2 weeks now.

Am 28.06.2016 um 22:15 schrieb amontefusco:

I have the same error

urllib3.exceptions.ProtocolError: ('Connection aborted.', error(104, 'Connection reset by peer'))

My bot is very simple: it is just counter.py but it has a trailing loop that reads a serial interface and (sometimes) reacts to what is read from the serial, caliing the bot.sendMessage().

So, I am sending messages from the foreground thread, whilst the main loop is running on the background one.

For now I trap the exception and try again after a second.

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/nickoala/telepot/issues/87#issuecomment-229168924, or mute the thread https://github.com/notifications/unsubscribe/AS6tsz7JDohld-ce9iMFQImxUlZeIaY0ks5qQYDKgaJpZM4IkE_6.

mode2k commented 8 years ago

Logfile with 8.1. 2016-07-01 01:12:15 INFO Thread-6 Starting new HTTPS connection (7): api.telegram.org 2016-07-01 01:12:35 INFO Thread-6 Starting new HTTPS connection (8): api.telegram.org 2016-07-01 01:12:55 INFO Thread-6 Starting new HTTPS connection (9): api.telegram.org 2016-07-01 01:13:15 INFO Thread-6 Starting new HTTPS connection (10): api.telegram.org 2016-07-01 01:13:35 INFO Thread-6 Starting new HTTPS connection (11): api.telegram.org 2016-07-01 01:13:55 INFO Thread-6 Starting new HTTPS connection (12): api.telegram.org 2016-07-01 01:14:16 INFO Thread-6 Starting new HTTPS connection (13): api.telegram.org 2016-07-01 01:14:36 INFO Thread-6 Starting new HTTPS connection (14): api.telegram.org 2016-07-01 01:14:56 INFO Thread-6 Starting new HTTPS connection (15): api.telegram.org 2016-07-01 01:15:16 INFO Thread-6 Starting new HTTPS connection (16): api.telegram.org 2016-07-01 01:15:36 INFO Thread-6 Starting new HTTPS connection (17): api.telegram.org 2016-07-01 01:15:56 INFO Thread-6 Starting new HTTPS connection (18): api.telegram.org 2016-07-01 01:16:16 INFO Thread-6 Starting new HTTPS connection (19): api.telegram.org 2016-07-01 01:16:36 INFO Thread-6 Starting new HTTPS connection (20): api.telegram.org 2016-07-01 01:16:57 INFO Thread-6 Starting new HTTPS connection (21): api.telegram.org 2016-07-01 01:17:17 INFO Thread-6 Starting new HTTPS connection (22): api.telegram.org 2016-07-01 01:17:37 INFO Thread-6 Starting new HTTPS connection (23): api.telegram.org 2016-07-01 01:17:57 INFO Thread-6 Starting new HTTPS connection (24): api.telegram.org 2016-07-01 01:18:17 INFO Thread-6 Starting new HTTPS connection (25): api.telegram.org 2016-07-01 01:18:37 INFO Thread-6 Starting new HTTPS connection (26): api.telegram.org 2016-07-01 01:18:57 INFO Thread-6 Starting new HTTPS connection (27): api.telegram.org 2016-07-01 01:19:17 INFO Thread-6 Starting new HTTPS connection (28): api.telegram.org 2016-07-01 01:19:37 INFO Thread-6 Starting new HTTPS connection (29): api.telegram.org 2016-07-01 01:19:58 INFO Thread-6 Starting new HTTPS connection (30): api.telegram.org 2016-07-01 01:20:18 INFO Thread-6 Starting new HTTPS connection (31): api.telegram.org 2016-07-01 01:20:38 INFO Thread-6 Starting new HTTPS connection (32): api.telegram.org 2016-07-01 01:20:58 INFO Thread-6 Starting new HTTPS connection (33): api.telegram.org 2016-07-01 01:21:18 INFO Thread-6 Starting new HTTPS connection (34): api.telegram.org 2016-07-01 01:21:38 INFO Thread-6 Starting new HTTPS connection (35): api.telegram.org 2016-07-01 01:21:58 INFO Thread-6 Starting new HTTPS connection (36): api.telegram.org 2016-07-01 01:22:18 INFO Thread-6 Starting new HTTPS connection (37): api.telegram.org 2016-07-01 01:22:38 INFO Thread-6 Starting new HTTPS connection (38): api.telegram.org 2016-07-01 01:22:59 INFO Thread-6 Starting new HTTPS connection (39): api.telegram.org 2016-07-01 01:23:19 INFO Thread-6 Starting new HTTPS connection (40): api.telegram.org 2016-07-01 01:23:39 INFO Thread-6 Starting new HTTPS connection (41): api.telegram.org 2016-07-01 01:23:59 INFO Thread-6 Starting new HTTPS connection (42): api.telegram.org 2016-07-01 01:24:19 INFO Thread-6 Starting new HTTPS connection (43): api.telegram.org 2016-07-01 01:24:39 INFO Thread-6 Starting new HTTPS connection (44): api.telegram.org 2016-07-01 01:24:59 INFO Thread-6 Starting new HTTPS connection (45): api.telegram.org 2016-07-01 01:25:19 INFO Thread-6 Starting new HTTPS connection (46): api.telegram.org 2016-07-01 01:25:40 INFO Thread-6 Starting new HTTPS connection (47): api.telegram.org 2016-07-01 01:26:00 INFO Thread-6 Starting new HTTPS connection (48): api.telegram.org 2016-07-01 01:26:20 INFO Thread-6 Starting new HTTPS connection (49): api.telegram.org 2016-07-01 01:26:40 INFO Thread-6 Starting new HTTPS connection (50): api.telegram.org 2016-07-01 01:27:00 INFO Thread-6 Starting new HTTPS connection (51): api.telegram.org 2016-07-01 01:27:20 INFO Thread-6 Starting new HTTPS connection (52): api.telegram.org 2016-07-01 01:27:40 INFO Thread-6 Starting new HTTPS connection (53): api.telegram.org 2016-07-01 01:28:00 INFO Thread-6 Starting new HTTPS connection (54): api.telegram.org 2016-07-01 01:28:20 INFO Thread-6 Starting new HTTPS connection (55): api.telegram.org 2016-07-01 01:28:41 INFO Thread-6 Starting new HTTPS connection (56): api.telegram.org 2016-07-01 01:29:01 INFO Thread-6 Starting new HTTPS connection (57): api.telegram.org 2016-07-01 01:29:21 INFO Thread-6 Starting new HTTPS connection (58): api.telegram.org 2016-07-01 01:29:41 INFO Thread-6 Starting new HTTPS connection (59): api.telegram.org 2016-07-01 01:30:01 INFO Thread-6 Starting new HTTPS connection (60): api.telegram.org 2016-07-01 01:30:21 INFO Thread-6 Starting new HTTPS connection (61): api.telegram.org 2016-07-01 01:30:41 INFO Thread-6 Starting new HTTPS connection (62): api.telegram.org 2016-07-01 01:31:01 INFO Thread-6 Starting new HTTPS connection (63): api.telegram.org 2016-07-01 01:31:22 INFO Thread-6 Starting new HTTPS connection (64): api.telegram.org 2016-07-01 01:31:42 INFO Thread-6 Starting new HTTPS connection (65): api.telegram.org 2016-07-01 01:32:02 INFO Thread-6 Starting new HTTPS connection (66): api.telegram.org 2016-07-01 01:32:22 INFO Thread-6 Starting new HTTPS connection (67): api.telegram.org 2016-07-01 01:32:42 INFO Thread-6 Starting new HTTPS connection (68): api.telegram.org 2016-07-01 01:34:58 INFO Thread-6 Starting new HTTPS connection (69): api.telegram.org 2016-07-01 01:35:23 INFO Thread-6 Starting new HTTPS connection (70): api.telegram.org 2016-07-01 01:35:43 INFO Thread-6 Starting new HTTPS connection (71): api.telegram.org 2016-07-01 01:36:03 INFO Thread-6 Starting new HTTPS connection (72): api.telegram.org 2016-07-01 01:36:23 INFO Thread-6 Starting new HTTPS connection (73): api.telegram.org 2016-07-01 01:36:43 INFO Thread-6 Starting new HTTPS connection (74): api.telegram.org 2016-07-01 02:10:21 INFO Thread-6 Resetting dropped connection: api.telegram.org 2016-07-01 02:43:53 INFO Thread-6 Resetting dropped connection: api.telegram.org 2016-07-01 03:17:26 INFO Thread-6 Resetting dropped connection: api.telegram.org 2016-07-01 03:50:59 INFO Thread-6 Resetting dropped connection: api.telegram.org 2016-07-01 04:24:32 INFO Thread-6 Resetting dropped connection: api.telegram.org 2016-07-01 04:58:04 INFO Thread-6 Resetting dropped connection: api.telegram.org 2016-07-01 05:31:36 INFO Thread-6 Resetting dropped connection: api.telegram.org 2016-07-01 06:05:09 INFO Thread-6 Resetting dropped connection: api.telegram.org 2016-07-01 06:38:42 INFO Thread-6 Resetting dropped connection: api.telegram.org 2016-07-01 07:12:15 INFO Thread-6 Resetting dropped connection: api.telegram.org 2016-07-01 07:45:48 INFO Thread-6 Resetting dropped connection: api.telegram.org 2016-07-01 08:19:21 INFO Thread-6 Resetting dropped connection: api.telegram.org 2016-07-01 08:52:53 INFO Thread-6 Resetting dropped connection: api.telegram.org 2016-07-01 09:26:26 INFO Thread-6 Resetting dropped connection: api.telegram.org 2016-07-01 09:59:59 INFO Thread-6 Resetting dropped connection: api.telegram.org 2016-07-01 10:33:32 INFO Thread-6 Resetting dropped connection: api.telegram.org 2016-07-01 11:07:05 INFO Thread-6 Resetting dropped connection: api.telegram.org Suddenly it stops "starting new https connection (x)". Then it tries "resetting dropped connection".

With 7.1. i have only: 2016-07-01 13:46:22 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 13:46:42 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 13:47:02 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 13:47:23 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 13:47:43 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 13:48:03 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 13:48:23 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 13:48:43 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 13:49:04 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 13:49:24 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 13:49:44 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 13:50:04 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 13:50:24 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 13:50:45 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 13:51:05 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 13:51:25 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 13:51:45 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 13:52:05 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 13:52:26 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 13:52:46 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 13:53:06 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 13:53:26 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 13:53:46 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 13:54:07 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 13:54:27 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 13:54:47 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 13:55:07 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 13:55:27 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 13:55:48 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 13:56:08 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 13:56:28 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 13:56:48 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 13:57:09 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 13:57:29 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 13:57:49 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 13:58:09 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 13:58:29 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 13:58:50 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 13:59:10 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 13:59:30 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 13:59:50 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:00:10 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:00:31 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:00:51 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:01:11 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:01:31 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:01:51 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:02:12 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:02:32 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:02:52 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:03:12 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:03:32 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:03:53 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:04:13 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:04:33 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:04:53 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:05:13 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:05:34 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:05:54 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:06:14 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:06:34 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:06:55 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:07:15 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:07:35 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:07:55 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:08:15 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:08:36 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:08:56 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:09:16 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:09:36 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:09:56 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:10:17 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:10:37 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:10:57 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:11:17 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:11:37 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:11:58 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:12:18 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:12:38 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:12:58 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:13:19 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:13:39 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:13:59 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:14:19 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:14:39 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:15:00 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:15:20 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:15:40 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:16:00 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:16:20 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:16:41 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:17:01 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:17:21 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:17:41 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:18:01 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:18:22 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:18:42 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:19:02 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:19:22 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:19:43 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:20:03 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:20:23 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:20:43 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:21:03 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:21:24 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:21:44 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:22:04 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:22:24 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:22:44 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:23:05 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:23:25 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:23:45 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:24:05 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org 2016-07-01 14:24:25 INFO Thread-6 Starting new HTTPS connection (1): api.telegram.org Note that the Counter (1) is not rising in this test.

nickoala commented 8 years ago

After two days of investigation, here's what I found.

I ran a simple script which sent me a bunch of messages every minute. I tried it on various versions of Python and urllib3.

Python urllib3 Result
2.7 1.9.1 9 hours without error
3.5 1.16 50 minutes until above error occurred
3.5 1.9.1 4 hours without error
3.5 1.9.1 5 hours without error

So, I think it's pretty clear that urllib3 version is causing the problem.

In the current setup.py, I have urllib3>=1.15.1, clearly too high. Do pip install urllib3==1.9.1 to downgrade to the stable version.

1.9.1 just happens to be the version shipped with Raspbian. That's why I am using it. Thanks to Debian for giving us the stable version.

Would anyone please try this fix and report back? I'd like to get some independent verifications. Thanks in advance.

feranto63 commented 8 years ago

I downgraded urllib to 1.9.1 but the error is still there with same behaviour as before. I'm using python 3.

nickoala commented 8 years ago

Not sure whether that's a typo. You downgraded urllib or urllib3?

feranto63 commented 8 years ago

it's a typo, I downgraded urllib3 to 1.9.1.

nickoala commented 8 years ago

Ok. Below is the simple script I have tried. It reproduces the two basic behaviors of your programs:

  1. It accepts a command /roll. Like rolling a dice, it replies back with a random number from 1 to 6.
  2. It sends you a bunch of messages every 60 seconds.

On command line, supply the bot token and your user id (because it needs to know who to send messages to).

$ python script.py <token> <your_user_id>
import sys
import time
import random
import datetime
import telepot

def handle(msg):
    content_type, chat_type, chat_id = telepot.glance(msg)

    if chat_id != USER_ID:
        return

    if content_type != 'text':
        return

    command = msg['text']

    if command == '/roll':
        bot.sendMessage(chat_id, random.randint(1,6))

TOKEN, USER_ID = sys.argv[1], int(sys.argv[2])

bot = telepot.Bot(TOKEN)
bot.message_loop(handle)
print('I am listening ...')

while 1:
    bot.sendMessage(USER_ID, 'Heartbeat')
    bot.sendMessage(USER_ID, 'Heartbeat')
    bot.sendMessage(USER_ID, 'Heartbeat')
    bot.sendMessage(USER_ID, 'Heartbeat')
    bot.sendMessage(USER_ID, 'Heartbeat')
    bot.sendMessage(USER_ID, '---------')
    time.sleep(60)

As I said above, it gives me no error after running for many hours. Can you try it? Thanks.

feranto63 commented 8 years ago

I think 60 seconds is too short, I see the problem after 2 minutes (roughly) of inactivity so please put a larger timeout (3 to 5 minutes). I will try your script this evening and I will return the results.

nickoala commented 8 years ago

Change the delay however you want. Just tell me what you have done, and hopefully I can reproduce the error on urllib3 1.9.1 .........

nickoala commented 8 years ago

@feranto63, just a reminder, when you do pip install urllib3==1.9.1, it may change the version for Python 2.7, depending on your pip. You mentioned using Python 3. Maybe pip3 or pip3.5 is what you need. In any case, check the Python packages directory to make sure.

feranto63 commented 8 years ago

Hi. I made this morning a test with your script with Python 2 and a timeout of 7 minutes (420 seconds) and I got the error. Let me know if you can reproduce it. Thank you for your support, telepot is a great library.

nickoala commented 8 years ago

I tested it the other day on Python 3.5 (because I missed your comment about Python 2) after changing the delay to 420 seconds. I ran it for more than 4 hours without error, then ran it again for 6 more hours without error.

Just to be absolutely certain, I am testing it on Python 2.7 ..... Wait for my updates.

nickoala commented 8 years ago

@feranto63, Python 2.7 using urllib3 1.9.1, running 5.5 hours without errors. Cannot reproduce your situation. How should I go from here?

Given the instability after implementing connection pooling (on both urllib3 and aiohttp) and the sporadic nature of those problems (unable or hard to reproduce), I am inclined to dump connection pooling. I may still keep the logic in telepot.api and telepot.aio.api, but configure it to use an independent session for each call (like the "old days"). I'd rather it be dumb/slow/inefficient than unstable. Anyone interested in connection pooling may configure it to do so, and bear the consequences.

I don't want to be bogged down by these issues, while having other improvements to make.

nickoala commented 8 years ago

@feranto63, now I have a few more suggestions.

  1. Try setting retries for PoolManager. By default, it does not retry. Below, I tell it to retry 3 times. Put this segment at the beginning of your program.

    import telepot.api

telepot.api._pools = {
   'default': urllib3.PoolManager(num_pools=3, maxsize=10, retries=3, timeout=30),
}

  2. Override function _which_pool to force independent connection each time:

    def force_independent_connection(req, **user_kw):
   return None

telepot.api._which_pool = force_independent_connection

  3. Set retries even for independent connections:

    telepot.api._onetime_pool_spec = (urllib3.PoolManager, dict(num_pools=1, maxsize=1, retries=3, timeout=30))

Try them in order, and see which one (or combination of them) can remedy your situation.

feranto63 commented 8 years ago

@nickoala I'm trying your suggestion #1 since 2 hours and it seems to solve the problem with retries = 3. I will test it a couple of days and I will return results.

nickoala commented 8 years ago

@feranto63, how are things?

feranto63 commented 8 years ago

@nickoala everithing is working with retry. So I close the issue. Thank you for your support

nickoala commented 8 years ago

Good. I will change the default retry in next version.

mischsa commented 8 years ago

The first retry solution solves the problem for me too. Thanks a lot.

rainer38 commented 8 years ago

The retry solution also fixed the problem for me. :) But now i have multiple messages in my log file for which i use the "logging" module. Is it possible to disable all these warning messages which fill my log file and maybe only create a message if the retry failed?

Here are a few of them which repeats about every 33-34 Minutes all the day long:

17.08.2016 19:00:03 INFO: Resetting dropped connection: api.telegram.org 17.08.2016 19:00:03 WARNING: Retrying (Retry(total=2, connect=None, read=None, redirect=0)) after connection broken by 'ProtocolError('Connection aborted.', gaierror(-2, 'Name or service not known'))': /botXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX/getUpdates 17.08.2016 19:00:03 INFO: Starting new HTTPS connection (2): api.telegram.org 17.08.2016 19:00:03 WARNING: Retrying (Retry(total=1, connect=None, read=None, redirect=0)) after connection broken by 'ProtocolError('Connection aborted.', gaierror(-2, 'Name or service not known'))': /botXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX/getUpdates 17.08.2016 19:00:03 INFO: Starting new HTTPS connection (3): api.telegram.org 17.08.2016 19:33:36 INFO: Resetting dropped connection: api.telegram.org 17.08.2016 19:33:36 WARNING: Retrying (Retry(total=2, connect=None, read=None, redirect=0)) after connection broken by 'ProtocolError('Connection aborted.', gaierror(-2, 'Name or service not known'))': /botXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX/getUpdates 17.08.2016 19:33:36 INFO: Starting new HTTPS connection (4): api.telegram.org 17.08.2016 19:33:36 WARNING: Retrying (Retry(total=1, connect=None, read=None, redirect=0)) after connection broken by 'ProtocolError('Connection aborted.', gaierror(-2, 'Name or service not known'))': /botXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX/getUpdates 17.08.2016 19:33:36 INFO: Starting new HTTPS connection (5): api.telegram.org 17.08.2016 19:33:36 WARNING: Retrying (Retry(total=0, connect=None, read=None, redirect=0)) after connection broken by 'ProtocolError('Connection aborted.', gaierror(-2, 'Name or service not known'))': /botXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX/getUpdates 17.08.2016 19:33:36 INFO: Starting new HTTPS connection (6): api.telegram.org