I
I
Ivan Yakushenko2019-05-09 10:29:25
Python
Ivan Yakushenko, 2019-05-09 10:29:25

Why is the connection to the API being reset?

At startup, two threads are launched:

Thread(target=self.input_event).start()
Thread(target=self.read_input).start()

The first one reads the stream from VK and saves some data for incoming messages:
First thread code
for event in self.long_poll.listen():
                if event.type == VkBotEventType.MESSAGE_NEW:
                    if len(event.object.attachments) > 0:
                        user_id = event.object.from_id
                        for pos in range(len(event.object.attachments[0].get('photo').get('sizes'))):
                            if event.object.attachments[0].get('photo').get('sizes')[pos].get('type', None) == 'w':
                                img_source = event.object.attachments[0].get('photo').get('sizes')[pos].get('url')
                            elif event.object.attachments[0].get('photo').get('sizes')[pos].get('type', None) is 'z':
                                img_source = event.object.attachments[0].get('photo').get('sizes')[pos].get('url')
                        split_url = img_source
                        split_url = split_url.split("/")[-1:][0].split(".")[0]
                        attachments = {'user_id': user_id, 'img_source': img_source, 'split_url': split_url}
                        logging.info(self.send_message(user_id, 'Отлично! Что вы хотите сделать с изображением?'))
                        USER_ATTACHMENTS.append(attachments)
                        logging.info('Received image: ' + str(attachments))
                    else:
                        user_id = event.object.from_id
                        username = self.vk_api.users.get(user_id=user_id)[0]['first_name']
                        text = event.object.text
                        data = {'user_id': user_id, 'username': username, 'text': text}
                        INPUT_EVENTS.append(data)
                        logging.info('Received message: ' + str(data))

The second thread searches this data for keywords and, if found, it creates a new thread for the user with the desired function:
Second thread code
for main_loop in range(len(INPUT_EVENTS)):
                    if COMMANDS.get(INPUT_EVENTS[main_loop].get('text', None).lower(), None) is not None:
                        if COMMANDS.get(INPUT_EVENTS[main_loop].get('text', None).lower(), None) == 1:
                            index_list = main_loop
                            user_id = INPUT_EVENTS[main_loop].get('user_id', None)
                            Thread(target=self.command_start, args=(index_list, user_id)).start()
                            del INPUT_EVENTS[main_loop]

Logging initialized:
logging.basicConfig(filename="log.log",
                    level=logging.DEBUG,
                    format="%(asctime)s:%(levelname)s:%(message)s")

In the logs, in addition to incoming messages and executed commands, something like the following is always displayed:
Log
08:28:53,954:DEBUG:https://lp.vk.com:443 "GET /wh119339221?act=a_check&key=KEY&ts=19492&wait=25 HTTP/1.1" 200 381
08:28:53,956:DEBUG:https://lp.vk.com:443 "GET /wh119339221?act=a_check&key=KEY&ts=19492&wait=25 HTTP/1.1" 200 381
08:29:18,966:DEBUG:https://lp.vk.com:443 "GET /wh119339221?act=a_check&key=KEY&ts=19494&wait=25 HTTP/1.1" 200 29
08:29:18,969:DEBUG:https://lp.vk.com:443 "GET /wh119339221?act=a_check&key=KEY&ts=19494&wait=25 HTTP/1.1" 200 29
08:29:18,972:DEBUG:https://lp.vk.com:443 "GET /wh119339221?act=a_check&key=KEY&ts=19494&wait=25 HTTP/1.1" 200 29
08:29:18,974:DEBUG:https://lp.vk.com:443 "GET /wh119339221?act=a_check&key=KEY&ts=19494&wait=25 HTTP/1.1" 200 29
08:29:38,768:DEBUG:https://lp.vk.com:443 "GET /wh119339221?act=a_check&key=KEY&ts=19494&wait=25 HTTP/1.1" 200 148
08:29:38,769:DEBUG:https://lp.vk.com:443 "GET /wh119339221?act=a_check&key=KEY&ts=19494&wait=25 HTTP/1.1" 200 148

Very often (sometimes once every 15 minutes, and sometimes every few minutes) the following happens:
08:28:49,852:DEBUG:Resetting dropped connection: lp.vk.com

Almost before every user action in the logs:
08:24:27,128:DEBUG:Starting new HTTPS connection (1): pp.userapi.com

Sometimes the bot simply stops receiving any messages from VK, i.e. in the logs there are absolutely the same HTTP requests, but if you write to the bot, then it simply does not accept these messages, i.e. there are no lines like logging.info('Received message: ' + str(data)) at all. In this case, there are no errors at all. Throughout the code, logging.info is stuck, almost all functions are wrapped in a tr-except block, for example, here is the block inside which the first thread works:
try:
            ...
        except requests.exceptions.Timeout as e:
            logging.error(e)
            os.kill(os.getpid(), signal.SIGINT)
        except requests.exceptions.TooManyRedirects as e:
            logging.error(e)
            os.kill(os.getpid(), signal.SIGINT)
        except requests.exceptions.RequestException as e:
            Thread(target=self.read_input).join()
            logging.error(e)
            os.kill(os.getpid(), signal.SIGINT)

But all the same, the bot just "freezes" and does nothing, although there is not a single error in the logs.
Also at night there was an influx of users and something like the following was going on in the logs:
2019-05-09 00:20:38,701:WARNING:Connection pool is full, discarding connection:
lp.vk.com .com

Although it was once and I don’t think that it is connected with the “freezes” of the bot.
The bot itself runs as a service through systemd, and at times of "hanging" systemctl status says that everything is fine with the service.
I've gone through everything I could, maybe someone here has some ideas.
UPD.
In the working state, systemctl status displays 3 processes, but sometimes I noticed that there are 2 of them, apparently just when the input_event stream falls off. There is an idea to make all created threads daemons, except for input_event, then, according to the idea, if this thread falls off, the application should stop its work, and systemd should immediately restart it. After all, I correctly understand the logic that if only daemon threads remain in the program, then it stops its work?

Answer the question

In order to leave comments, you need to log in

1 answer(s)
S
Sergey Tikhonov, 2019-05-09
@kshnkvn

You understand correctly, daemon threads are terminated together with the main thread. The connection is reset because it has not been used for a long time (this is a setting for VK servers)

Didn't find what you were looking for?

Ask your question

Ask a Question

731 491 924 answers to any question