Python-socketio: How to reconnect after engineio warning

Created on 8 Feb 2019  Â·  43Comments  Â·  Source: miguelgrinberg/python-socketio

Every so often, I run into a situation where I get this stacktrace when running a client:

WARNING:engineio.client:Read loop: WebSocket connection was closed, aborting
INFO:engineio.client:Waiting for write loop task to end
INFO:engineio.client:Exiting write loop task
INFO:engineio.client:Waiting for ping loop task to end
WARNING:engineio.client:PONG response has not been received, aborting
INFO:engineio.client:Exiting ping task
INFO:engineio.client:Exiting read loop task

However, the client never seems to reconnect. Also, there's no exception for me to latch onto (so that I can reconnect, myself).

How would you recommend handling reconnection in this scenario?

bug
Source
picture bachya

All 43 comments

Are you using the latest version of this package and python-engineio?

I had some bugs on the reconnection logic, but I thought I fixed them already. If you get this problem with the latest releases of these two packages, then maybe if you can share your client code it can help me reproduce.

miguelgrinberg picture miguelgrinberg on 8 Feb 2019

Got it. Let me ensure I’m on the latest and get back to you. Thanks!

bachya picture bachya on 8 Feb 2019

Confirmed I'm using version 3.1.2 of python-socketio and version 3.3.0 of python-engineio.

The client logic is a part of my library, aioambient, and can be found there. Including it here for ease:

"""Define an object to interact with the Websocket API."""
# pylint: disable=redefined-builtin
from typing import Awaitable, Callable, Union

from socketio import AsyncClient
from socketio.exceptions import ConnectionError, SocketIOError

from .errors import WebsocketConnectionError, WebsocketError

WEBSOCKET_API_BASE = 'https://dash2.ambientweather.net'


class Websocket:
    """Define to handler."""

    def __init__(
            self, application_key: str, api_key: str,
            api_version: int) -> None:
        """Initialize."""
        self._api_key = api_key
        self._api_version = api_version
        self._application_key = application_key
        self._sio = AsyncClient()

    def on_connect(self, target: Union[Awaitable, Callable]) -> None:
        """Define a method/coroutine to be called when connecting."""
        self._sio.on('connect', target)

    def on_data(self, target: Union[Awaitable, Callable]) -> None:
        """Define a method/coroutine to be called when data is received."""
        self._sio.on('data', target)

    def on_disconnect(self, target: Union[Awaitable, Callable]) -> None:
        """Define a method/coroutine to be called when disconnecting."""
        self._sio.on('disconnect', target)

    def on_subscribed(self, target: Union[Awaitable, Callable]) -> None:
        """Define a method/coroutine to be called when subscribed."""
        self._sio.on('subscribed', target)

    async def connect(self) -> None:
        """Connect to the socket."""
        try:
            await self._sio.connect(
                '{0}/?api={1}&applicationKey={2}'.format(
                    WEBSOCKET_API_BASE, self._api_version,
                    self._application_key),
                transports=['websocket'])
        except (ConnectionError, SocketIOError) as err:
            raise WebsocketConnectionError(err) from None

        try:
            await self._sio.emit('subscribe', {'apiKeys': [self._api_key]})
        except (ConnectionError, SocketIOError) as err:
            raise WebsocketError(err) from None

    async def disconnect(self) -> None:
        """Disconnect from the socket."""
        await self._sio.disconnect()

An example – also found within the project – would be:

"""Run an example script to quickly test."""
import asyncio
import logging

from aiohttp import ClientSession

from aioambient import Client
from aioambient.errors import WebsocketConnectionError, WebsocketError

_LOGGER = logging.getLogger()

API_KEY = '<YOUR API KEY>'
APP_KEY = '<YOUR APPLICATION KEY>'


def print_data(data):
    """Print data as it is received."""
    _LOGGER.info('Data received: %s', data)


def print_goodbye():
    """Print a simple "goodbye" message."""
    _LOGGER.info('Client has disconnected from the websocket')


def print_hello():
    """Print a simple "hello" message."""
    _LOGGER.info('Client has connected to the websocket')


async def main() -> None:
    """Run the websocket example."""
    logging.basicConfig(level=logging.INFO)

    async with ClientSession() as session:
        client = Client(API_KEY, APP_KEY, session)

        client.websocket.on_connect(print_hello)
        client.websocket.on_data(print_data)
        client.websocket.on_disconnect(print_goodbye)
        client.websocket.on_subscribed(print_data)

        try:
            await client.websocket.connect()
        except WebsocketConnectionError as err:
            _LOGGER.error('There was a websocket connection error: %s', err)
            return
        except WebsocketError as err:
            _LOGGER.error('There was a generic websocket error: %s', err)
            return

        for _ in range(30):
            _LOGGER.info('Simulating some other task occurring...')
            await asyncio.sleep(5)

        await client.websocket.disconnect()


loop = asyncio.get_event_loop()
loop.create_task(main())
loop.run_forever()
bachya picture bachya on 8 Feb 2019

Can you upgrade python-engineio and retry please?

miguelgrinberg picture miguelgrinberg on 9 Feb 2019

I ran 3.3.1 of python-engineio successfully for a while, but eventually, this occurred:

INFO:root:Simulating some other task occurring...
INFO:engineio.client:Sending packet PING data None
INFO:engineio.client:Received packet PONG data None
INFO:root:Simulating some other task occurring...
INFO:root:Simulating some other task occurring...
INFO:root:Simulating some other task occurring...
INFO:root:Simulating some other task occurring...
INFO:root:Simulating some other task occurring...
INFO:engineio.client:Sending packet PING data None
INFO:root:Client has disconnected from the websocket
INFO:engineio.client:Sending packet MESSAGE data 1
INFO:engineio.client:Sending packet CLOSE data None
INFO:socketio.client:Engine.IO connection dropped
INFO:root:Client has disconnected from the websocket
INFO:engineio.client:Received packet PONG data None
INFO:engineio.client:Waiting for write loop task to end
WARNING:engineio.client:Write loop: WebSocket connection was closed, aborting
INFO:engineio.client:Exiting write loop task
INFO:engineio.client:Waiting for ping loop task to end
INFO:engineio.client:Exiting ping task
INFO:engineio.client:Exiting read loop task

(reminder that the Simulating some other task occurring... messages are from my example script)

bachya picture bachya on 10 Feb 2019

Any idea how these interruptions happen?

And also, what does this log line mean?

INFO:root:Client has disconnected from the websocket

To me it looks as if the client is disconnecting intentionally, which obviously is outside of the scope of reconnects.

miguelgrinberg picture miguelgrinberg on 10 Feb 2019

Great point; I mistakenly shut down the socket myself. Let me run a new test.

bachya picture bachya on 10 Feb 2019

Quick update: I let my test run for 12 hours. Everything stayed connecting and working for 4 hours or so, but at some point during the night, the client disconnected (without my explicit calling). Unfortunately, I didn’t save enough tmux buffer to see where or why. 😒

I’ll start a new session today (with an expanded buffer) and try to capture when the disconnect occurs.

bachya picture bachya on 10 Feb 2019

I'm not worried about the disconnect. Disconnects can happen for a lot of reasons, all external to this package. The question is if the client reconnected after the disconnection. If it did, then we're good.

miguelgrinberg picture miguelgrinberg on 10 Feb 2019

It doesn’t appear that it did at the end; for a huge chunk of the last stages of the tmux buffer, all I saw was the Simulating some other task... messages from my script. Could be that the socket server was down for a really long time, of course, but I doubt that.

Current test coming up on 3 hours and, whether disconnects are occurring or not (I can’t explicitly tell), I’m still getting data from the socket, which is good. Will keep you posted.

bachya picture bachya on 10 Feb 2019

Latest test ran fine for 10 hours, then saw this:

2019-02-11 00:46:49,905 - root - INFO - Simulating some other task occurring...
2019-02-11 00:46:53,043 - websockets.protocol - DEBUG - client > Frame(fin=True, opcode=9, data=b'G\xd1_\xfa', rsv1=False, rsv2=False, rsv3=False)
2019-02-11 00:46:53,058 - websockets.protocol - DEBUG - client - event = connection_lost([Errno 104] Connection reset by peer)
2019-02-11 00:46:53,058 - websockets.protocol - DEBUG - client - state = CLOSED
2019-02-11 00:46:53,059 - websockets.protocol - DEBUG - client x code = 1006, reason = [no reason]
2019-02-11 00:46:53,059 - websockets.protocol - DEBUG - client - aborted pending ping: 47d15ffa
2019-02-11 00:46:53,059 - websockets.protocol - DEBUG - client ! failing WebSocket connection in the CLOSED state: 1006 [no reason]
2019-02-11 00:46:53,059 - websockets.protocol - DEBUG - client x closing TCP connection
2019-02-11 00:46:53,060 - engineio.client - WARNING - Read loop: WebSocket connection was closed, aborting
2019-02-11 00:46:53,060 - engineio.client - INFO - Waiting for write loop task to end
2019-02-11 00:46:53,060 - engineio.client - INFO - Exiting write loop task
2019-02-11 00:46:53,060 - engineio.client - INFO - Waiting for ping loop task to end
2019-02-11 00:46:53,061 - engineio.client - INFO - Sending packet PING data None
2019-02-11 00:46:53,061 - engineio.client - WARNING - PONG response has not been received, aborting
2019-02-11 00:46:53,061 - engineio.client - INFO - Exiting ping task
2019-02-11 00:46:53,062 - socketio.client - INFO - Engine.IO connection dropped
2019-02-11 00:46:53,062 - root - INFO - Client has disconnected from the websocket
2019-02-11 00:46:53,062 - engineio.client - INFO - Exiting read loop task
2019-02-11 00:46:53,062 - socketio.client - INFO - Connection failed, new attempt in 1.26 seconds
2019-02-11 00:46:54,329 - engineio.client - INFO - Attempting WebSocket upgrade to wss://dash2.ambientweather.net/socket.io/?api=1&applicationKey=REDACTED&transport=websocket&EIO=3
2019-02-11 00:46:54,370 - websockets.protocol - DEBUG - client - state = CONNECTING
2019-02-11 00:46:54,416 - websockets.protocol - DEBUG - client - event = connection_made(<asyncio.sslproto._SSLProtocolTransport object at 0x7ff555a239e8>)
2019-02-11 00:46:54,517 - websockets.protocol - DEBUG - client ! failing WebSocket connection in the CONNECTING state: 1006 [no reason]
2019-02-11 00:46:54,517 - websockets.protocol - DEBUG - client x closing TCP connection
2019-02-11 00:46:54,532 - websockets.protocol - DEBUG - client - event = eof_received()
2019-02-11 00:46:54,532 - websockets.protocol - DEBUG - client - event = connection_lost(None)
2019-02-11 00:46:54,532 - websockets.protocol - DEBUG - client - state = CLOSED
2019-02-11 00:46:54,533 - websockets.protocol - DEBUG - client x code = 1006, reason = [no reason]
2019-02-11 00:46:54,533 - engineio.client - WARNING - WebSocket upgrade failed: connection error
2019-02-11 00:46:54,533 - socketio.client - INFO - Reconnection successful

However, the reconnection doesn’t seem complete, as I didn’t receive data for the remainder of the test’s runtime (another 9 hours):

2019-02-11 00:46:54,907 - root - INFO - Simulating some other task occurring...
2019-02-11 00:46:59,912 - root - INFO - Simulating some other task occurring...
2019-02-11 00:47:04,918 - root - INFO - Simulating some other task occurring...
2019-02-11 00:47:09,924 - root - INFO - Simulating some other task occurring...
2019-02-11 00:47:14,929 - root - INFO - Simulating some other task occurring...
2019-02-11 00:47:19,935 - root - INFO - Simulating some other task occurring...
2019-02-11 00:47:24,941 - root - INFO - Simulating some other task occurring...
2019-02-11 00:47:29,944 - root - INFO - Simulating some other task occurring...
2019-02-11 00:47:34,947 - root - INFO - Simulating some other task occurring...
2019-02-11 00:47:39,953 - root - INFO - Simulating some other task occurring...
2019-02-11 00:47:44,954 - root - INFO - Simulating some other task occurring...
2019-02-11 00:47:49,956 - root - INFO - Simulating some other task occurring...
2019-02-11 00:47:54,959 - root - INFO - Simulating some other task occurring...
2019-02-11 00:47:59,964 - root - INFO - Simulating some other task occurring...
2019-02-11 00:48:04,966 - root - INFO - Simulating some other task occurring...

Almost looks like the subscribe emit (part of my original code) doesn’t happen again. Is it my responsibility to reinitiate it? If so, how? No exception is thrown for me to latch onto.

bachya picture bachya on 11 Feb 2019

The reconnection starts completely from scratch, none of the attributes of the previous connection are restored. The set up of your connection should be done in the connect handler, so that it is done again when the reconnection is established. In your case, it appears that the connection handler is set directly by the caller of the Websocket class. What you should do is have this class install its own connect handler, which then invokes the caller's handler after configuring the connection appropriately.

miguelgrinberg picture miguelgrinberg on 11 Feb 2019

Got it! Thanks so much for your help; I think this info, in combo with 3.3.1 of python-engineio, should get me where I need to be. I’ll close for now and re-open if the issue persists. Thanks again!

bachya picture bachya on 11 Feb 2019

Unfortunately, my latest test is exhibiting the same behavior, despite changes; hoping you’d be willing to check my logic.

Here’s my new Websocket class:

"""Define an object to interact with the Websocket API."""
# pylint: disable=redefined-builtin
from typing import Awaitable, Callable, Union

from socketio import AsyncClient
from socketio.exceptions import ConnectionError, SocketIOError

from .errors import WebsocketConnectionError, WebsocketError

WEBSOCKET_API_BASE = 'https://dash2.ambientweather.net'


class Websocket:
    """Define to handler."""

    def __init__(
            self, application_key: str, api_key: str,
            api_version: int) -> None:
        """Initialize."""
        self._api_key = api_key
        self._api_version = api_version
        self._application_key = application_key
        self._sio = AsyncClient()
        self._user_connect_handler = None

    async def _init_connection(self) -> None:
        """Perform non-user initialization upon connect."""
        try:
            await self._sio.emit('subscribe', {'apiKeys': [self._api_key]})
        except (ConnectionError, SocketIOError) as err:
            raise WebsocketError(err) from None

        if self._user_connect_handler:
            self._user_connect_handler()

    def on_connect(self, target: Union[Awaitable, Callable]) -> None:
        """Define a method/coroutine to be called when connecting."""
        self._user_connect_handler = target

    def on_data(self, target: Union[Awaitable, Callable]) -> None:
        """Define a method/coroutine to be called when data is received."""
        self._sio.on('data', target)

    def on_disconnect(self, target: Union[Awaitable, Callable]) -> None:
        """Define a method/coroutine to be called when disconnecting."""
        self._sio.on('disconnect', target)

    def on_subscribed(self, target: Union[Awaitable, Callable]) -> None:
        """Define a method/coroutine to be called when subscribed."""
        self._sio.on('subscribed', target)

    async def connect(self) -> None:
        """Connect to the socket."""
        self._sio.on('connect', self._init_connection)

        try:
            await self._sio.connect(
                '{0}/?api={1}&applicationKey={2}'.format(
                    WEBSOCKET_API_BASE, self._api_version,
                    self._application_key),
                transports=['websocket'])
        except (ConnectionError, SocketIOError) as err:
            raise WebsocketConnectionError(err) from None

    async def disconnect(self) -> None:
        """Disconnect from the socket."""
        await self._sio.disconnect()

The socket initially connects just fine, but upon failure and reconnection, I don’t see the _init_connection coroutine being called again:

2019-02-11 18:41:53,495 - socketio.client - INFO - Connection failed, new attempt in 0.56 seconds                                                                               
2019-02-11 18:41:54,059 - engineio.client - INFO - Attempting WebSocket upgrade to wss://dash2.ambientweather.net/socket.io/?api=1&applicationKey=REDACTED&transport=websocket&EIO=3                            
2019-02-11 18:41:54,175 - engineio.client - WARNING - WebSocket upgrade failed: connection error                                                                                
2019-02-11 18:41:54,176 - socketio.client - INFO - Reconnection successful              
2019-02-11 18:41:57,251 - root - INFO - Simulating some other task occurring...         
2019-02-11 18:42:02,256 - root - INFO - Simulating some other task occurring...         
2019-02-11 18:42:07,258 - root - INFO - Simulating some other task occurring...         
2019-02-11 18:42:12,263 - root - INFO - Simulating some other task occurring...         
2019-02-11 18:42:17,266 - root - INFO - Simulating some other task occurring...

Thanks!

bachya picture bachya on 12 Feb 2019

@bachya are these logs the complete log output? What I find odd is that there is nothing regarding the HTTP connection that must be occurring before the WebSocket upgrade is attempted, or the regular PING and PONG packets that are constantly being exchanged between the server and each client. I assume you are choosing which log lines to show me?

Based on the logs that you are showing the HTTP long-polling connection reconnected successfully, but then when the WebSocket upgrade was attempted that didn't work. So your reconnected client appears to be on long-polling instead of WebSocket. I also don't see any mention in the logs regarding the emit() that you make in the connect handler in your last version, which is odd, since your code now appears to be correctly doing what I suggested.

If you are filtering the logs, then it might be useful to see the unfiltered stream, to confirm that the long-polling connection is working and that the emit that you make during connection does happen.

Also, is the server a Python server or Node? Either way it might be a good idea to capture logs from that server and client sides for the same session, maybe that'll help us understand why the WebSocket connection fails while the HTTP connection works.

miguelgrinberg picture miguelgrinberg on 12 Feb 2019

I have, indeed, been giving you only (what I hoped were) relevant snippets. From the latest run (on INFO level), here's the entire log (with the latter message truncated due to sufficient duplication):

2019-02-11 18:23:11,291 - engineio.client - INFO - Attempting WebSocket connection to wss://dash2.ambientweather.net/socket.io/?api=1&applicationKey=REDACTED&transport=websocket&EIO=3
2019-02-11 18:23:11,392 - engineio.client - INFO - WebSocket connection accepted with {'sid': '8VKEcASvWkEvVTGaAACl', 'upgrades': [], 'pingInterval': 25000, 'pingTimeout': 60000}
2019-02-11 18:23:11,392 - socketio.client - INFO - Engine.IO connection established
2019-02-11 18:23:11,393 - root - INFO - Simulating some other task occurring...
2019-02-11 18:23:11,393 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:23:11,414 - engineio.client - INFO - Received packet MESSAGE data 0
2019-02-11 18:23:11,414 - socketio.client - INFO - Namespace / is connected
2019-02-11 18:23:11,415 - socketio.client - INFO - Emitting event "subscribe" [/]
2019-02-11 18:23:11,415 - engineio.client - INFO - Sending packet MESSAGE data 2["subscribe",{"apiKeys":["8f13cf5a02b1449e9dae95ecdb9e468709e33db62ad340f1a1085bc9055e9b35"]}]
2019-02-11 18:23:11,415 - root - INFO - Client has connected to the websocket
2019-02-11 18:23:11,438 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:23:11,474 - engineio.client - INFO - Received packet MESSAGE data 2["subscribed",{"devices":[{"macAddress":"AB:CD:EF:12:34:56","lastData":{"dateutc":1549934460000,"winddir":63,"windspeedmph":0.7,"windgustmph":1.1,"maxdailygust":11.4,"tempf":32.4,"hourlyrainin":0,"eventrainin":0,"dailyrainin":0,"weeklyrainin":0,"monthlyrainin":0.02,"totalrainin":1.08,"baromrelin":30.19,"baromabsin":24.7,"humidity":29,"tempinf":61,"humidityin":23,"uv":0,"solarradiation":0,"feelsLike":32.4,"dewPoint":3.73,"lastRain":"2019-02-09T18:28:00.000Z","deviceId":"5c328e3bc4eac477f09b7dc1","date":"2019-02-12T01:21:00.000Z"},"info":{"name":"Side Yard","location":"Home"},"apiKey":"8f13cf5a02b1449e9dae95ecdb9e468709e33db62ad340f1a1085bc9055e9b35"}],"method":"subscribe"}]
2019-02-11 18:23:11,475 - socketio.client - INFO - Received event "subscribed" [/]
2019-02-11 18:23:11,475 - root - INFO - Data received: {'devices': [{'macAddress': 'AB:CD:EF:12:34:56', 'lastData': {'dateutc': 1549934460000, 'winddir': 63, 'windspeedmph': 0.7, 'windgustmph': 1.1, 'maxdailygust': 11.4, 'tempf': 32.4, 'hourlyrainin': 0, 'eventrainin': 0, 'dailyrainin': 0, 'weeklyrainin': 0, 'monthlyrainin': 0.02, 'totalrainin': 1.08, 'baromrelin': 30.19, 'baromabsin': 24.7, 'humidity': 29, 'tempinf': 61, 'humidityin': 23, 'uv': 0, 'solarradiation': 0, 'feelsLike': 32.4, 'dewPoint': 3.73, 'lastRain': '2019-02-09T18:28:00.000Z', 'deviceId': '5c328e3bc4eac477f09b7dc1', 'date': '2019-02-12T01:21:00.000Z'}, 'info': {'name': 'Side Yard', 'location': 'Home'}, 'apiKey': '8f13cf5a02b1449e9dae95ecdb9e468709e33db62ad340f1a1085bc9055e9b35'}], 'method': 'subscribe'}
2019-02-11 18:23:16,399 - root - INFO - Simulating some other task occurring...
2019-02-11 18:23:21,402 - root - INFO - Simulating some other task occurring...
2019-02-11 18:23:21,547 - engineio.client - INFO - Received packet MESSAGE data 2["data",{"dateutc":1549934580000,"winddir":345,"windspeedmph":1.3,"windgustmph":2.2,"maxdailygust":11.4,"tempf":32.4,"hourlyrainin":0,"eventrainin":0,"dailyrainin":0,"weeklyrainin":0,"monthlyrainin":0.02,"totalrainin":1.08,"baromrelin":30.19,"baromabsin":24.7,"humidity":30,"tempinf":61.2,"humidityin":23,"uv":0,"solarradiation":0,"feelsLike":32.4,"dewPoint":4.47,"lastRain":"2019-02-09T18:28:00.000Z","date":"2019-02-12T01:23:00.000Z","macAddress":"AB:CD:EF:12:34:56"}]
2019-02-11 18:23:21,548 - socketio.client - INFO - Received event "data" [/]
2019-02-11 18:23:21,548 - root - INFO - Data received: {'dateutc': 1549934580000, 'winddir': 345, 'windspeedmph': 1.3, 'windgustmph': 2.2, 'maxdailygust': 11.4, 'tempf': 32.4, 'hourlyrainin': 0, 'eventrainin': 0, 'dailyrainin': 0, 'weeklyrainin': 0, 'monthlyrainin': 0.02, 'totalrainin': 1.08, 'baromrelin': 30.19, 'baromabsin': 24.7, 'humidity': 30, 'tempinf': 61.2, 'humidityin': 23, 'uv': 0, 'solarradiation': 0, 'feelsLike': 32.4, 'dewPoint': 4.47, 'lastRain': '2019-02-09T18:28:00.000Z', 'date': '2019-02-12T01:23:00.000Z', 'macAddress': 'AB:CD:EF:12:34:56'}
2019-02-11 18:23:26,406 - root - INFO - Simulating some other task occurring...
2019-02-11 18:23:31,409 - root - INFO - Simulating some other task occurring...
2019-02-11 18:23:36,396 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:23:36,410 - root - INFO - Simulating some other task occurring...
2019-02-11 18:23:36,430 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:23:41,415 - root - INFO - Simulating some other task occurring...
2019-02-11 18:23:46,421 - root - INFO - Simulating some other task occurring...
2019-02-11 18:23:51,426 - root - INFO - Simulating some other task occurring...
2019-02-11 18:23:56,432 - root - INFO - Simulating some other task occurring...
2019-02-11 18:24:01,403 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:24:01,433 - root - INFO - Simulating some other task occurring...
2019-02-11 18:24:01,436 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:24:06,439 - root - INFO - Simulating some other task occurring...
2019-02-11 18:24:11,444 - root - INFO - Simulating some other task occurring...
2019-02-11 18:24:16,446 - root - INFO - Simulating some other task occurring...
2019-02-11 18:24:21,449 - root - INFO - Simulating some other task occurring...
2019-02-11 18:24:21,894 - engineio.client - INFO - Received packet MESSAGE data 2["data",{"dateutc":1549934640000,"winddir":3,"windspeedmph":0.7,"windgustmph":1.1,"maxdailygust":11.4,"tempf":32.2,"hourlyrainin":0,"eventrainin":0,"dailyrainin":0,"weeklyrainin":0,"monthlyrainin":0.02,"totalrainin":1.08,"baromrelin":30.18,"baromabsin":24.69,"humidity":29,"tempinf":61,"humidityin":23,"uv":0,"solarradiation":0,"feelsLike":32.2,"dewPoint":3.56,"lastRain":"2019-02-09T18:28:00.000Z","date":"2019-02-12T01:24:00.000Z","macAddress":"AB:CD:EF:12:34:56"}]
2019-02-11 18:24:21,895 - socketio.client - INFO - Received event "data" [/]
2019-02-11 18:24:21,895 - root - INFO - Data received: {'dateutc': 1549934640000, 'winddir': 3, 'windspeedmph': 0.7, 'windgustmph': 1.1, 'maxdailygust': 11.4, 'tempf': 32.2, 'hourlyrainin': 0, 'eventrainin': 0, 'dailyrainin': 0, 'weeklyrainin': 0, 'monthlyrainin': 0.02, 'totalrainin': 1.08, 'baromrelin': 30.18, 'baromabsin': 24.69, 'humidity': 29, 'tempinf': 61, 'humidityin': 23, 'uv': 0, 'solarradiation': 0, 'feelsLike': 32.2, 'dewPoint': 3.56, 'lastRain': '2019-02-09T18:28:00.000Z', 'date': '2019-02-12T01:24:00.000Z', 'macAddress': 'AB:CD:EF:12:34:56'}
2019-02-11 18:24:26,408 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:24:26,441 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:24:26,451 - root - INFO - Simulating some other task occurring...
2019-02-11 18:24:31,453 - root - INFO - Simulating some other task occurring...
2019-02-11 18:24:36,455 - root - INFO - Simulating some other task occurring...
2019-02-11 18:24:41,460 - root - INFO - Simulating some other task occurring...
2019-02-11 18:24:46,466 - root - INFO - Simulating some other task occurring...
2019-02-11 18:24:51,414 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:24:51,448 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:24:51,467 - root - INFO - Simulating some other task occurring...
2019-02-11 18:24:56,475 - root - INFO - Simulating some other task occurring...
2019-02-11 18:25:00,538 - engineio.client - INFO - Received packet MESSAGE data 2["confirm created",{"_id":"5c6220579b7c2b36ef25cf9a","email":"[email protected]","password":"$2a$10$776TSIzeeFHtJjB4J6PFceMBQoUdfZA5nMMt5n2wnLEjqOUpmkLNm","confirmKey":false,"updatedAt":"2019-02-12T01:24:39.908Z","createdAt":"2019-02-12T01:24:39.908Z","ifttt":[],"roles":["user"],"__v":0,"isVerified":true}]
2019-02-11 18:25:00,539 - socketio.client - INFO - Received event "confirm created" [/]
2019-02-11 18:25:01,476 - root - INFO - Simulating some other task occurring...
2019-02-11 18:25:06,481 - root - INFO - Simulating some other task occurring...
2019-02-11 18:25:11,485 - root - INFO - Simulating some other task occurring...
2019-02-11 18:25:16,419 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:25:16,451 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:25:16,486 - root - INFO - Simulating some other task occurring...
2019-02-11 18:25:21,491 - root - INFO - Simulating some other task occurring...
2019-02-11 18:25:25,873 - engineio.client - INFO - Received packet MESSAGE data 2["data",{"dateutc":1549934700000,"winddir":6,"windspeedmph":1.6,"windgustmph":2.2,"maxdailygust":11.4,"tempf":32.2,"hourlyrainin":0,"eventrainin":0,"dailyrainin":0,"weeklyrainin":0,"monthlyrainin":0.02,"totalrainin":1.08,"baromrelin":30.19,"baromabsin":24.7,"humidity":29,"tempinf":61.2,"humidityin":23,"uv":0,"solarradiation":0,"feelsLike":32.2,"dewPoint":3.56,"lastRain":"2019-02-09T18:28:00.000Z","date":"2019-02-12T01:25:00.000Z","macAddress":"AB:CD:EF:12:34:56"}]
2019-02-11 18:25:25,874 - socketio.client - INFO - Received event "data" [/]
2019-02-11 18:25:25,874 - root - INFO - Data received: {'dateutc': 1549934700000, 'winddir': 6, 'windspeedmph': 1.6, 'windgustmph': 2.2, 'maxdailygust': 11.4, 'tempf': 32.2, 'hourlyrainin': 0, 'eventrainin': 0, 'dailyrainin': 0, 'weeklyrainin': 0, 'monthlyrainin': 0.02, 'totalrainin': 1.08, 'baromrelin': 30.19, 'baromabsin': 24.7, 'humidity': 29, 'tempinf': 61.2, 'humidityin': 23, 'uv': 0, 'solarradiation': 0, 'feelsLike': 32.2, 'dewPoint': 3.56, 'lastRain': '2019-02-09T18:28:00.000Z', 'date': '2019-02-12T01:25:00.000Z', 'macAddress': 'AB:CD:EF:12:34:56'}
2019-02-11 18:25:26,492 - root - INFO - Simulating some other task occurring...
2019-02-11 18:25:31,498 - root - INFO - Simulating some other task occurring...
2019-02-11 18:25:36,504 - root - INFO - Simulating some other task occurring...
2019-02-11 18:25:41,425 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:25:41,458 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:25:41,505 - root - INFO - Simulating some other task occurring...
2019-02-11 18:25:46,511 - root - INFO - Simulating some other task occurring...
2019-02-11 18:25:51,515 - root - INFO - Simulating some other task occurring...
2019-02-11 18:25:56,516 - root - INFO - Simulating some other task occurring...
2019-02-11 18:26:01,518 - root - INFO - Simulating some other task occurring...
2019-02-11 18:26:06,431 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:26:06,467 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:26:06,520 - root - INFO - Simulating some other task occurring...
2019-02-11 18:26:11,526 - root - INFO - Simulating some other task occurring...
2019-02-11 18:26:16,532 - root - INFO - Simulating some other task occurring...
2019-02-11 18:26:21,508 - engineio.client - INFO - Received packet MESSAGE data 2["data",{"dateutc":1549934760000,"winddir":348,"windspeedmph":0.7,"windgustmph":1.1,"maxdailygust":11.4,"tempf":32.4,"hourlyrainin":0,"eventrainin":0,"dailyrainin":0,"weeklyrainin":0,"monthlyrainin":0.02,"totalrainin":1.08,"baromrelin":30.19,"baromabsin":24.7,"humidity":30,"tempinf":61,"humidityin":23,"uv":0,"solarradiation":0,"feelsLike":32.4,"dewPoint":4.47,"lastRain":"2019-02-09T18:28:00.000Z","date":"2019-02-12T01:26:00.000Z","macAddress":"AB:CD:EF:12:34:56"}]
2019-02-11 18:26:21,509 - socketio.client - INFO - Received event "data" [/]
2019-02-11 18:26:21,509 - root - INFO - Data received: {'dateutc': 1549934760000, 'winddir': 348, 'windspeedmph': 0.7, 'windgustmph': 1.1, 'maxdailygust': 11.4, 'tempf': 32.4, 'hourlyrainin': 0, 'eventrainin': 0, 'dailyrainin': 0, 'weeklyrainin': 0, 'monthlyrainin': 0.02, 'totalrainin': 1.08, 'baromrelin': 30.19, 'baromabsin': 24.7, 'humidity': 30, 'tempinf': 61, 'humidityin': 23, 'uv': 0, 'solarradiation': 0, 'feelsLike': 32.4, 'dewPoint': 4.47, 'lastRain': '2019-02-09T18:28:00.000Z', 'date': '2019-02-12T01:26:00.000Z', 'macAddress': 'AB:CD:EF:12:34:56'}
2019-02-11 18:26:21,533 - root - INFO - Simulating some other task occurring...
2019-02-11 18:26:26,538 - root - INFO - Simulating some other task occurring...
2019-02-11 18:26:31,437 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:26:31,469 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:26:31,539 - root - INFO - Simulating some other task occurring...
2019-02-11 18:26:36,545 - root - INFO - Simulating some other task occurring...
2019-02-11 18:26:41,551 - root - INFO - Simulating some other task occurring...
2019-02-11 18:26:46,556 - root - INFO - Simulating some other task occurring...
2019-02-11 18:26:51,562 - root - INFO - Simulating some other task occurring...
2019-02-11 18:26:56,442 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:26:56,479 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:26:56,563 - root - INFO - Simulating some other task occurring...
2019-02-11 18:27:01,569 - root - INFO - Simulating some other task occurring...
2019-02-11 18:27:06,572 - root - INFO - Simulating some other task occurring...
2019-02-11 18:27:11,574 - root - INFO - Simulating some other task occurring...
2019-02-11 18:27:16,580 - root - INFO - Simulating some other task occurring...
2019-02-11 18:27:21,360 - engineio.client - INFO - Received packet MESSAGE data 2["data",{"dateutc":1549934820000,"winddir":344,"windspeedmph":0,"windgustmph":0,"maxdailygust":11.4,"tempf":32.5,"hourlyrainin":0,"eventrainin":0,"dailyrainin":0,"weeklyrainin":0,"monthlyrainin":0.02,"totalrainin":1.08,"baromrelin":30.19,"baromabsin":24.7,"humidity":30,"tempinf":61,"humidityin":23,"uv":0,"solarradiation":0,"feelsLike":32.5,"dewPoint":4.55,"lastRain":"2019-02-09T18:28:00.000Z","date":"2019-02-12T01:27:00.000Z","macAddress":"AB:CD:EF:12:34:56"}]
2019-02-11 18:27:21,360 - socketio.client - INFO - Received event "data" [/]
2019-02-11 18:27:21,360 - root - INFO - Data received: {'dateutc': 1549934820000, 'winddir': 344, 'windspeedmph': 0, 'windgustmph': 0, 'maxdailygust': 11.4, 'tempf': 32.5, 'hourlyrainin': 0, 'eventrainin': 0, 'dailyrainin': 0, 'weeklyrainin': 0, 'monthlyrainin': 0.02, 'totalrainin': 1.08, 'baromrelin': 30.19, 'baromabsin': 24.7, 'humidity': 30, 'tempinf': 61, 'humidityin': 23, 'uv': 0, 'solarradiation': 0, 'feelsLike': 32.5, 'dewPoint': 4.55, 'lastRain': '2019-02-09T18:28:00.000Z', 'date': '2019-02-12T01:27:00.000Z', 'macAddress': 'AB:CD:EF:12:34:56'}
2019-02-11 18:27:21,443 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:27:21,476 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:27:21,581 - root - INFO - Simulating some other task occurring...
2019-02-11 18:27:26,583 - root - INFO - Simulating some other task occurring...
2019-02-11 18:27:31,586 - root - INFO - Simulating some other task occurring...
2019-02-11 18:27:36,592 - root - INFO - Simulating some other task occurring...
2019-02-11 18:27:41,598 - root - INFO - Simulating some other task occurring...
2019-02-11 18:27:46,449 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:27:46,488 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:27:46,599 - root - INFO - Simulating some other task occurring...
2019-02-11 18:27:51,605 - root - INFO - Simulating some other task occurring...
2019-02-11 18:27:56,607 - root - INFO - Simulating some other task occurring...
2019-02-11 18:28:01,613 - root - INFO - Simulating some other task occurring...
2019-02-11 18:28:06,617 - root - INFO - Simulating some other task occurring...
2019-02-11 18:28:11,455 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:28:11,488 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:28:11,619 - root - INFO - Simulating some other task occurring...
2019-02-11 18:28:16,624 - root - INFO - Simulating some other task occurring...
2019-02-11 18:28:21,630 - root - INFO - Simulating some other task occurring...
2019-02-11 18:28:21,919 - engineio.client - INFO - Received packet MESSAGE data 2["data",{"dateutc":1549934880000,"winddir":14,"windspeedmph":0.7,"windgustmph":2.2,"maxdailygust":11.4,"tempf":32.4,"hourlyrainin":0,"eventrainin":0,"dailyrainin":0,"weeklyrainin":0,"monthlyrainin":0.02,"totalrainin":1.08,"baromrelin":30.19,"baromabsin":24.7,"humidity":30,"tempinf":61,"humidityin":23,"uv":0,"solarradiation":0,"feelsLike":32.4,"dewPoint":4.47,"lastRain":"2019-02-09T18:28:00.000Z","date":"2019-02-12T01:28:00.000Z","macAddress":"AB:CD:EF:12:34:56"}]
2019-02-11 18:28:21,919 - socketio.client - INFO - Received event "data" [/]
2019-02-11 18:28:21,920 - root - INFO - Data received: {'dateutc': 1549934880000, 'winddir': 14, 'windspeedmph': 0.7, 'windgustmph': 2.2, 'maxdailygust': 11.4, 'tempf': 32.4, 'hourlyrainin': 0, 'eventrainin': 0, 'dailyrainin': 0, 'weeklyrainin': 0, 'monthlyrainin': 0.02, 'totalrainin': 1.08, 'baromrelin': 30.19, 'baromabsin': 24.7, 'humidity': 30, 'tempinf': 61, 'humidityin': 23, 'uv': 0, 'solarradiation': 0, 'feelsLike': 32.4, 'dewPoint': 4.47, 'lastRain': '2019-02-09T18:28:00.000Z', 'date': '2019-02-12T01:28:00.000Z', 'macAddress': 'AB:CD:EF:12:34:56'}
2019-02-11 18:28:26,635 - root - INFO - Simulating some other task occurring...
2019-02-11 18:28:31,641 - root - INFO - Simulating some other task occurring...
2019-02-11 18:28:36,459 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:28:36,492 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:28:36,642 - root - INFO - Simulating some other task occurring...
2019-02-11 18:28:41,644 - root - INFO - Simulating some other task occurring...
2019-02-11 18:28:46,650 - root - INFO - Simulating some other task occurring...
2019-02-11 18:28:51,653 - root - INFO - Simulating some other task occurring...
2019-02-11 18:28:56,659 - root - INFO - Simulating some other task occurring...
2019-02-11 18:29:01,465 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:29:01,628 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:29:01,661 - root - INFO - Simulating some other task occurring...
2019-02-11 18:29:06,663 - root - INFO - Simulating some other task occurring...
2019-02-11 18:29:11,669 - root - INFO - Simulating some other task occurring...
2019-02-11 18:29:16,670 - root - INFO - Simulating some other task occurring...
2019-02-11 18:29:21,676 - root - INFO - Simulating some other task occurring...
2019-02-11 18:29:25,888 - engineio.client - INFO - Received packet MESSAGE data 2["data",{"dateutc":1549934940000,"winddir":55,"windspeedmph":1.6,"windgustmph":3.4,"maxdailygust":11.4,"tempf":32.4,"hourlyrainin":0,"eventrainin":0,"dailyrainin":0,"weeklyrainin":0,"monthlyrainin":0.02,"totalrainin":1.08,"baromrelin":30.19,"baromabsin":24.7,"humidity":31,"tempinf":61.2,"humidityin":23,"uv":0,"solarradiation":0,"feelsLike":32.4,"dewPoint":5.18,"lastRain":"2019-02-09T18:28:00.000Z","date":"2019-02-12T01:29:00.000Z","macAddress":"AB:CD:EF:12:34:56"}]
2019-02-11 18:29:25,889 - socketio.client - INFO - Received event "data" [/]
2019-02-11 18:29:25,889 - root - INFO - Data received: {'dateutc': 1549934940000, 'winddir': 55, 'windspeedmph': 1.6, 'windgustmph': 3.4, 'maxdailygust': 11.4, 'tempf': 32.4, 'hourlyrainin': 0, 'eventrainin': 0, 'dailyrainin': 0, 'weeklyrainin': 0, 'monthlyrainin': 0.02, 'totalrainin': 1.08, 'baromrelin': 30.19, 'baromabsin': 24.7, 'humidity': 31, 'tempinf': 61.2, 'humidityin': 23, 'uv': 0, 'solarradiation': 0, 'feelsLike': 32.4, 'dewPoint': 5.18, 'lastRain': '2019-02-09T18:28:00.000Z', 'date': '2019-02-12T01:29:00.000Z', 'macAddress': 'AB:CD:EF:12:34:56'}
2019-02-11 18:29:26,467 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:29:26,530 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:29:26,677 - root - INFO - Simulating some other task occurring...
2019-02-11 18:29:31,682 - root - INFO - Simulating some other task occurring...
2019-02-11 18:29:36,688 - root - INFO - Simulating some other task occurring...
2019-02-11 18:29:41,692 - root - INFO - Simulating some other task occurring...
2019-02-11 18:29:46,698 - root - INFO - Simulating some other task occurring...
2019-02-11 18:29:51,473 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:29:51,515 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:29:51,699 - root - INFO - Simulating some other task occurring...
2019-02-11 18:29:56,705 - root - INFO - Simulating some other task occurring...
2019-02-11 18:30:01,705 - root - INFO - Simulating some other task occurring...
2019-02-11 18:30:06,710 - root - INFO - Simulating some other task occurring...
2019-02-11 18:30:11,716 - root - INFO - Simulating some other task occurring...
2019-02-11 18:30:16,479 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:30:16,530 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:30:16,716 - root - INFO - Simulating some other task occurring...
2019-02-11 18:30:21,389 - engineio.client - INFO - Received packet MESSAGE data 2["data",{"dateutc":1549935000000,"winddir":350,"windspeedmph":1.6,"windgustmph":2.2,"maxdailygust":11.4,"tempf":32.2,"hourlyrainin":0,"eventrainin":0,"dailyrainin":0,"weeklyrainin":0,"monthlyrainin":0.02,"totalrainin":1.08,"baromrelin":30.2,"baromabsin":24.71,"humidity":29,"tempinf":61.2,"humidityin":23,"uv":0,"solarradiation":0,"feelsLike":32.2,"dewPoint":3.56,"lastRain":"2019-02-09T18:28:00.000Z","date":"2019-02-12T01:30:00.000Z","macAddress":"AB:CD:EF:12:34:56"}]
2019-02-11 18:30:21,389 - socketio.client - INFO - Received event "data" [/]
2019-02-11 18:30:21,389 - root - INFO - Data received: {'dateutc': 1549935000000, 'winddir': 350, 'windspeedmph': 1.6, 'windgustmph': 2.2, 'maxdailygust': 11.4, 'tempf': 32.2, 'hourlyrainin': 0, 'eventrainin': 0, 'dailyrainin': 0, 'weeklyrainin': 0, 'monthlyrainin': 0.02, 'totalrainin': 1.08, 'baromrelin': 30.2, 'baromabsin': 24.71, 'humidity': 29, 'tempinf': 61.2, 'humidityin': 23, 'uv': 0, 'solarradiation': 0, 'feelsLike': 32.2, 'dewPoint': 3.56, 'lastRain': '2019-02-09T18:28:00.000Z', 'date': '2019-02-12T01:30:00.000Z', 'macAddress': 'AB:CD:EF:12:34:56'}
2019-02-11 18:30:21,717 - root - INFO - Simulating some other task occurring...
2019-02-11 18:30:26,723 - root - INFO - Simulating some other task occurring...
2019-02-11 18:30:31,727 - root - INFO - Simulating some other task occurring...
2019-02-11 18:30:36,732 - root - INFO - Simulating some other task occurring...
2019-02-11 18:30:41,484 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:30:41,522 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:30:41,733 - root - INFO - Simulating some other task occurring...
2019-02-11 18:30:46,739 - root - INFO - Simulating some other task occurring...
2019-02-11 18:30:51,744 - root - INFO - Simulating some other task occurring...
2019-02-11 18:30:56,750 - root - INFO - Simulating some other task occurring...
2019-02-11 18:31:01,755 - root - INFO - Simulating some other task occurring...
2019-02-11 18:31:06,487 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:31:06,525 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:31:06,756 - root - INFO - Simulating some other task occurring...
2019-02-11 18:31:11,762 - root - INFO - Simulating some other task occurring...
2019-02-11 18:31:16,768 - root - INFO - Simulating some other task occurring...
2019-02-11 18:31:21,373 - engineio.client - INFO - Received packet MESSAGE data 2["data",{"dateutc":1549935060000,"winddir":51,"windspeedmph":2.5,"windgustmph":3.4,"maxdailygust":11.4,"tempf":32.2,"hourlyrainin":0,"eventrainin":0,"dailyrainin":0,"weeklyrainin":0,"monthlyrainin":0.02,"totalrainin":1.08,"baromrelin":30.19,"baromabsin":24.7,"humidity":28,"tempinf":61.2,"humidityin":23,"uv":0,"solarradiation":0,"feelsLike":32.2,"dewPoint":2.8,"lastRain":"2019-02-09T18:28:00.000Z","date":"2019-02-12T01:31:00.000Z","macAddress":"AB:CD:EF:12:34:56"}]
2019-02-11 18:31:21,373 - socketio.client - INFO - Received event "data" [/]
2019-02-11 18:31:21,374 - root - INFO - Data received: {'dateutc': 1549935060000, 'winddir': 51, 'windspeedmph': 2.5, 'windgustmph': 3.4, 'maxdailygust': 11.4, 'tempf': 32.2, 'hourlyrainin': 0, 'eventrainin': 0, 'dailyrainin': 0, 'weeklyrainin': 0, 'monthlyrainin': 0.02, 'totalrainin': 1.08, 'baromrelin': 30.19, 'baromabsin': 24.7, 'humidity': 28, 'tempinf': 61.2, 'humidityin': 23, 'uv': 0, 'solarradiation': 0, 'feelsLike': 32.2, 'dewPoint': 2.8, 'lastRain': '2019-02-09T18:28:00.000Z', 'date': '2019-02-12T01:31:00.000Z', 'macAddress': 'AB:CD:EF:12:34:56'}
2019-02-11 18:31:21,770 - root - INFO - Simulating some other task occurring...
2019-02-11 18:31:26,775 - root - INFO - Simulating some other task occurring...
2019-02-11 18:31:31,491 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:31:31,524 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:31:31,777 - root - INFO - Simulating some other task occurring...
2019-02-11 18:31:36,783 - root - INFO - Simulating some other task occurring...
2019-02-11 18:31:41,784 - root - INFO - Simulating some other task occurring...
2019-02-11 18:31:46,787 - root - INFO - Simulating some other task occurring...
2019-02-11 18:31:51,793 - root - INFO - Simulating some other task occurring...
2019-02-11 18:31:56,497 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:31:56,547 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:31:56,794 - root - INFO - Simulating some other task occurring...
2019-02-11 18:32:01,795 - root - INFO - Simulating some other task occurring...
2019-02-11 18:32:06,801 - root - INFO - Simulating some other task occurring...
2019-02-11 18:32:11,807 - root - INFO - Simulating some other task occurring...
2019-02-11 18:32:16,813 - root - INFO - Simulating some other task occurring...
2019-02-11 18:32:21,499 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:32:21,532 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:32:21,814 - root - INFO - Simulating some other task occurring...
2019-02-11 18:32:26,819 - root - INFO - Simulating some other task occurring...
2019-02-11 18:32:31,821 - root - INFO - Simulating some other task occurring...
2019-02-11 18:32:36,823 - root - INFO - Simulating some other task occurring...
2019-02-11 18:32:41,829 - root - INFO - Simulating some other task occurring...
2019-02-11 18:32:46,505 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:32:46,604 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:32:46,831 - root - INFO - Simulating some other task occurring...
2019-02-11 18:32:51,836 - root - INFO - Simulating some other task occurring...
2019-02-11 18:32:56,841 - root - INFO - Simulating some other task occurring...
2019-02-11 18:33:01,844 - root - INFO - Simulating some other task occurring...
2019-02-11 18:33:06,846 - root - INFO - Simulating some other task occurring...
2019-02-11 18:33:11,507 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:33:11,564 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:33:11,848 - root - INFO - Simulating some other task occurring...
2019-02-11 18:33:16,853 - root - INFO - Simulating some other task occurring...
2019-02-11 18:33:21,859 - root - INFO - Simulating some other task occurring...
2019-02-11 18:33:25,889 - engineio.client - INFO - Received packet MESSAGE data 2["data",{"dateutc":1549935180000,"winddir":287,"windspeedmph":2.2,"windgustmph":3.4,"maxdailygust":11.4,"tempf":32.4,"hourlyrainin":0,"eventrainin":0,"dailyrainin":0,"weeklyrainin":0,"monthlyrainin":0.02,"totalrainin":1.08,"baromrelin":30.19,"baromabsin":24.7,"humidity":29,"tempinf":61.2,"humidityin":23,"uv":0,"solarradiation":0,"feelsLike":32.4,"dewPoint":3.73,"lastRain":"2019-02-09T18:28:00.000Z","date":"2019-02-12T01:33:00.000Z","macAddress":"AB:CD:EF:12:34:56"}]
2019-02-11 18:33:25,889 - socketio.client - INFO - Received event "data" [/]
2019-02-11 18:33:25,890 - root - INFO - Data received: {'dateutc': 1549935180000, 'winddir': 287, 'windspeedmph': 2.2, 'windgustmph': 3.4, 'maxdailygust': 11.4, 'tempf': 32.4, 'hourlyrainin': 0, 'eventrainin': 0, 'dailyrainin': 0, 'weeklyrainin': 0, 'monthlyrainin': 0.02, 'totalrainin': 1.08, 'baromrelin': 30.19, 'baromabsin': 24.7, 'humidity': 29, 'tempinf': 61.2, 'humidityin': 23, 'uv': 0, 'solarradiation': 0, 'feelsLike': 32.4, 'dewPoint': 3.73, 'lastRain': '2019-02-09T18:28:00.000Z', 'date': '2019-02-12T01:33:00.000Z', 'macAddress': 'AB:CD:EF:12:34:56'}
2019-02-11 18:33:26,861 - root - INFO - Simulating some other task occurring...
2019-02-11 18:33:31,862 - root - INFO - Simulating some other task occurring...
2019-02-11 18:33:36,512 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:33:36,558 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:33:36,864 - root - INFO - Simulating some other task occurring...
2019-02-11 18:33:41,869 - root - INFO - Simulating some other task occurring...
2019-02-11 18:33:46,875 - root - INFO - Simulating some other task occurring...
2019-02-11 18:33:51,879 - root - INFO - Simulating some other task occurring...
2019-02-11 18:33:56,884 - root - INFO - Simulating some other task occurring...
2019-02-11 18:34:01,518 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:34:01,551 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:34:01,886 - root - INFO - Simulating some other task occurring...
2019-02-11 18:34:06,889 - root - INFO - Simulating some other task occurring...
2019-02-11 18:34:11,894 - root - INFO - Simulating some other task occurring...
2019-02-11 18:34:16,896 - root - INFO - Simulating some other task occurring...
2019-02-11 18:34:21,901 - root - INFO - Simulating some other task occurring...
2019-02-11 18:34:26,524 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:34:26,611 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:34:26,902 - root - INFO - Simulating some other task occurring...
2019-02-11 18:34:31,908 - root - INFO - Simulating some other task occurring...
2019-02-11 18:34:36,910 - root - INFO - Simulating some other task occurring...
2019-02-11 18:34:41,914 - root - INFO - Simulating some other task occurring...
2019-02-11 18:34:46,920 - root - INFO - Simulating some other task occurring...
2019-02-11 18:34:51,527 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:34:51,590 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:34:51,921 - root - INFO - Simulating some other task occurring...
2019-02-11 18:34:56,925 - root - INFO - Simulating some other task occurring...
2019-02-11 18:35:01,926 - root - INFO - Simulating some other task occurring...
2019-02-11 18:35:06,932 - root - INFO - Simulating some other task occurring...
2019-02-11 18:35:11,937 - root - INFO - Simulating some other task occurring...
2019-02-11 18:35:16,532 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:35:16,566 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:35:16,939 - root - INFO - Simulating some other task occurring...
2019-02-11 18:35:21,463 - engineio.client - INFO - Received packet MESSAGE data 2["data",{"dateutc":1549935300000,"winddir":24,"windspeedmph":1.8,"windgustmph":3.4,"maxdailygust":11.4,"tempf":32.4,"hourlyrainin":0,"eventrainin":0,"dailyrainin":0,"weeklyrainin":0,"monthlyrainin":0.02,"totalrainin":1.08,"baromrelin":30.2,"baromabsin":24.71,"humidity":29,"tempinf":61,"humidityin":23,"uv":0,"solarradiation":0,"feelsLike":32.4,"dewPoint":3.73,"lastRain":"2019-02-09T18:28:00.000Z","date":"2019-02-12T01:35:00.000Z","macAddress":"AB:CD:EF:12:34:56"}]
2019-02-11 18:35:21,464 - socketio.client - INFO - Received event "data" [/]
2019-02-11 18:35:21,464 - root - INFO - Data received: {'dateutc': 1549935300000, 'winddir': 24, 'windspeedmph': 1.8, 'windgustmph': 3.4, 'maxdailygust': 11.4, 'tempf': 32.4, 'hourlyrainin': 0, 'eventrainin': 0, 'dailyrainin': 0, 'weeklyrainin': 0, 'monthlyrainin': 0.02, 'totalrainin': 1.08, 'baromrelin': 30.2, 'baromabsin': 24.71, 'humidity': 29, 'tempinf': 61, 'humidityin': 23, 'uv': 0, 'solarradiation': 0, 'feelsLike': 32.4, 'dewPoint': 3.73, 'lastRain': '2019-02-09T18:28:00.000Z', 'date': '2019-02-12T01:35:00.000Z', 'macAddress': 'AB:CD:EF:12:34:56'}
2019-02-11 18:35:21,941 - root - INFO - Simulating some other task occurring...
2019-02-11 18:35:26,947 - root - INFO - Simulating some other task occurring...
2019-02-11 18:35:31,949 - root - INFO - Simulating some other task occurring...
2019-02-11 18:35:36,955 - root - INFO - Simulating some other task occurring...
2019-02-11 18:35:41,534 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:35:41,566 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:35:41,957 - root - INFO - Simulating some other task occurring...
2019-02-11 18:35:46,963 - root - INFO - Simulating some other task occurring...
2019-02-11 18:35:51,968 - root - INFO - Simulating some other task occurring...
2019-02-11 18:35:56,974 - root - INFO - Simulating some other task occurring...
2019-02-11 18:36:01,979 - root - INFO - Simulating some other task occurring...
2019-02-11 18:36:06,539 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:36:06,571 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:36:06,982 - root - INFO - Simulating some other task occurring...
2019-02-11 18:36:11,987 - root - INFO - Simulating some other task occurring...
2019-02-11 18:36:16,991 - root - INFO - Simulating some other task occurring...
2019-02-11 18:36:21,996 - root - INFO - Simulating some other task occurring...
2019-02-11 18:36:27,002 - root - INFO - Simulating some other task occurring...
2019-02-11 18:36:31,542 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:36:31,575 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:36:32,003 - root - INFO - Simulating some other task occurring...
2019-02-11 18:36:37,006 - root - INFO - Simulating some other task occurring...
2019-02-11 18:36:42,010 - root - INFO - Simulating some other task occurring...
2019-02-11 18:36:47,014 - root - INFO - Simulating some other task occurring...
2019-02-11 18:36:52,020 - root - INFO - Simulating some other task occurring...
2019-02-11 18:36:56,547 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:36:56,580 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:36:57,022 - root - INFO - Simulating some other task occurring...
2019-02-11 18:37:02,027 - root - INFO - Simulating some other task occurring...
2019-02-11 18:37:07,030 - root - INFO - Simulating some other task occurring...
2019-02-11 18:37:12,033 - root - INFO - Simulating some other task occurring...
2019-02-11 18:37:17,038 - root - INFO - Simulating some other task occurring...
2019-02-11 18:37:21,549 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:37:21,582 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:37:22,039 - root - INFO - Simulating some other task occurring...
2019-02-11 18:37:25,882 - engineio.client - INFO - Received packet MESSAGE data 2["data",{"dateutc":1549935420000,"winddir":77,"windspeedmph":0.7,"windgustmph":1.1,"maxdailygust":11.4,"tempf":32.4,"hourlyrainin":0,"eventrainin":0,"dailyrainin":0,"weeklyrainin":0,"monthlyrainin":0.02,"totalrainin":1.08,"baromrelin":30.19,"baromabsin":24.7,"humidity":29,"tempinf":61,"humidityin":23,"uv":0,"solarradiation":0,"feelsLike":32.4,"dewPoint":3.73,"lastRain":"2019-02-09T18:28:00.000Z","date":"2019-02-12T01:37:00.000Z","macAddress":"AB:CD:EF:12:34:56"}]
2019-02-11 18:37:25,883 - socketio.client - INFO - Received event "data" [/]
2019-02-11 18:37:25,883 - root - INFO - Data received: {'dateutc': 1549935420000, 'winddir': 77, 'windspeedmph': 0.7, 'windgustmph': 1.1, 'maxdailygust': 11.4, 'tempf': 32.4, 'hourlyrainin': 0, 'eventrainin': 0, 'dailyrainin': 0, 'weeklyrainin': 0, 'monthlyrainin': 0.02, 'totalrainin': 1.08, 'baromrelin': 30.19, 'baromabsin': 24.7, 'humidity': 29, 'tempinf': 61, 'humidityin': 23, 'uv': 0, 'solarradiation': 0, 'feelsLike': 32.4, 'dewPoint': 3.73, 'lastRain': '2019-02-09T18:28:00.000Z', 'date': '2019-02-12T01:37:00.000Z', 'macAddress': 'AB:CD:EF:12:34:56'}
2019-02-11 18:37:27,042 - root - INFO - Simulating some other task occurring...
2019-02-11 18:37:32,047 - root - INFO - Simulating some other task occurring...
2019-02-11 18:37:37,051 - root - INFO - Simulating some other task occurring...
2019-02-11 18:37:42,053 - root - INFO - Simulating some other task occurring...
2019-02-11 18:37:46,555 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:37:46,603 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:37:47,055 - root - INFO - Simulating some other task occurring...
2019-02-11 18:37:52,061 - root - INFO - Simulating some other task occurring...
2019-02-11 18:37:57,066 - root - INFO - Simulating some other task occurring...
2019-02-11 18:38:02,070 - root - INFO - Simulating some other task occurring...
2019-02-11 18:38:07,074 - root - INFO - Simulating some other task occurring...
2019-02-11 18:38:11,557 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:38:11,591 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:38:12,076 - root - INFO - Simulating some other task occurring...
2019-02-11 18:38:17,081 - root - INFO - Simulating some other task occurring...
2019-02-11 18:38:21,497 - engineio.client - INFO - Received packet MESSAGE data 2["data",{"dateutc":1549935480000,"winddir":83,"windspeedmph":0.2,"windgustmph":1.1,"maxdailygust":11.4,"tempf":32.4,"hourlyrainin":0,"eventrainin":0,"dailyrainin":0,"weeklyrainin":0,"monthlyrainin":0.02,"totalrainin":1.08,"baromrelin":30.2,"baromabsin":24.71,"humidity":29,"tempinf":61,"humidityin":23,"uv":0,"solarradiation":0,"feelsLike":32.4,"dewPoint":3.73,"lastRain":"2019-02-09T18:28:00.000Z","date":"2019-02-12T01:38:00.000Z","macAddress":"AB:CD:EF:12:34:56"}]
2019-02-11 18:38:21,498 - socketio.client - INFO - Received event "data" [/]
2019-02-11 18:38:21,498 - root - INFO - Data received: {'dateutc': 1549935480000, 'winddir': 83, 'windspeedmph': 0.2, 'windgustmph': 1.1, 'maxdailygust': 11.4, 'tempf': 32.4, 'hourlyrainin': 0, 'eventrainin': 0, 'dailyrainin': 0, 'weeklyrainin': 0, 'monthlyrainin': 0.02, 'totalrainin': 1.08, 'baromrelin': 30.2, 'baromabsin': 24.71, 'humidity': 29, 'tempinf': 61, 'humidityin': 23, 'uv': 0, 'solarradiation': 0, 'feelsLike': 32.4, 'dewPoint': 3.73, 'lastRain': '2019-02-09T18:28:00.000Z', 'date': '2019-02-12T01:38:00.000Z', 'macAddress': 'AB:CD:EF:12:34:56'}
2019-02-11 18:38:22,082 - root - INFO - Simulating some other task occurring...
2019-02-11 18:38:27,087 - root - INFO - Simulating some other task occurring...
2019-02-11 18:38:32,089 - root - INFO - Simulating some other task occurring...
2019-02-11 18:38:36,561 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:38:36,595 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:38:37,091 - root - INFO - Simulating some other task occurring...
2019-02-11 18:38:42,095 - root - INFO - Simulating some other task occurring...
2019-02-11 18:38:47,100 - root - INFO - Simulating some other task occurring...
2019-02-11 18:38:52,106 - root - INFO - Simulating some other task occurring...
2019-02-11 18:38:57,110 - root - INFO - Simulating some other task occurring...
2019-02-11 18:39:01,568 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:39:01,606 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:39:02,111 - root - INFO - Simulating some other task occurring...
2019-02-11 18:39:07,116 - root - INFO - Simulating some other task occurring...
2019-02-11 18:39:12,122 - root - INFO - Simulating some other task occurring...
2019-02-11 18:39:17,126 - root - INFO - Simulating some other task occurring...
2019-02-11 18:39:21,519 - engineio.client - INFO - Received packet MESSAGE data 2["data",{"dateutc":1549935540000,"winddir":24,"windspeedmph":0.9,"windgustmph":2.2,"maxdailygust":11.4,"tempf":32.2,"hourlyrainin":0,"eventrainin":0,"dailyrainin":0,"weeklyrainin":0,"monthlyrainin":0.02,"totalrainin":1.08,"baromrelin":30.19,"baromabsin":24.7,"humidity":28,"tempinf":61,"humidityin":23,"uv":0,"solarradiation":0,"feelsLike":32.2,"dewPoint":2.8,"lastRain":"2019-02-09T18:28:00.000Z","date":"2019-02-12T01:39:00.000Z","macAddress":"AB:CD:EF:12:34:56"}]
2019-02-11 18:39:21,520 - socketio.client - INFO - Received event "data" [/]
2019-02-11 18:39:21,520 - root - INFO - Data received: {'dateutc': 1549935540000, 'winddir': 24, 'windspeedmph': 0.9, 'windgustmph': 2.2, 'maxdailygust': 11.4, 'tempf': 32.2, 'hourlyrainin': 0, 'eventrainin': 0, 'dailyrainin': 0, 'weeklyrainin': 0, 'monthlyrainin': 0.02, 'totalrainin': 1.08, 'baromrelin': 30.19, 'baromabsin': 24.7, 'humidity': 28, 'tempinf': 61, 'humidityin': 23, 'uv': 0, 'solarradiation': 0, 'feelsLike': 32.2, 'dewPoint': 2.8, 'lastRain': '2019-02-09T18:28:00.000Z', 'date': '2019-02-12T01:39:00.000Z', 'macAddress': 'AB:CD:EF:12:34:56'}
2019-02-11 18:39:22,128 - root - INFO - Simulating some other task occurring...
2019-02-11 18:39:26,571 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:39:26,607 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:39:27,129 - root - INFO - Simulating some other task occurring...
2019-02-11 18:39:32,135 - root - INFO - Simulating some other task occurring...
2019-02-11 18:39:37,140 - root - INFO - Simulating some other task occurring...
2019-02-11 18:39:42,142 - root - INFO - Simulating some other task occurring...
2019-02-11 18:39:47,148 - root - INFO - Simulating some other task occurring...
2019-02-11 18:39:51,577 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:39:51,610 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:39:52,149 - root - INFO - Simulating some other task occurring...
2019-02-11 18:39:57,154 - root - INFO - Simulating some other task occurring...
2019-02-11 18:40:02,160 - root - INFO - Simulating some other task occurring...
2019-02-11 18:40:07,165 - root - INFO - Simulating some other task occurring...
2019-02-11 18:40:12,170 - root - INFO - Simulating some other task occurring...
2019-02-11 18:40:16,581 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:40:16,621 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:40:17,171 - root - INFO - Simulating some other task occurring...
2019-02-11 18:40:22,027 - engineio.client - INFO - Received packet MESSAGE data 2["data",{"dateutc":1549935600000,"winddir":161,"windspeedmph":1.3,"windgustmph":2.2,"maxdailygust":11.4,"tempf":32.2,"hourlyrainin":0,"eventrainin":0,"dailyrainin":0,"weeklyrainin":0,"monthlyrainin":0.02,"totalrainin":1.08,"baromrelin":30.2,"baromabsin":24.71,"humidity":29,"tempinf":61,"humidityin":23,"uv":0,"solarradiation":0,"feelsLike":32.2,"dewPoint":3.56,"lastRain":"2019-02-09T18:28:00.000Z","date":"2019-02-12T01:40:00.000Z","macAddress":"AB:CD:EF:12:34:56"}]
2019-02-11 18:40:22,028 - socketio.client - INFO - Received event "data" [/]
2019-02-11 18:40:22,028 - root - INFO - Data received: {'dateutc': 1549935600000, 'winddir': 161, 'windspeedmph': 1.3, 'windgustmph': 2.2, 'maxdailygust': 11.4, 'tempf': 32.2, 'hourlyrainin': 0, 'eventrainin': 0, 'dailyrainin': 0, 'weeklyrainin': 0, 'monthlyrainin': 0.02, 'totalrainin': 1.08, 'baromrelin': 30.2, 'baromabsin': 24.71, 'humidity': 29, 'tempinf': 61, 'humidityin': 23, 'uv': 0, 'solarradiation': 0, 'feelsLike': 32.2, 'dewPoint': 3.56, 'lastRain': '2019-02-09T18:28:00.000Z', 'date': '2019-02-12T01:40:00.000Z', 'macAddress': 'AB:CD:EF:12:34:56'}
2019-02-11 18:40:22,174 - root - INFO - Simulating some other task occurring...
2019-02-11 18:40:27,180 - root - INFO - Simulating some other task occurring...
2019-02-11 18:40:32,185 - root - INFO - Simulating some other task occurring...
2019-02-11 18:40:37,190 - root - INFO - Simulating some other task occurring...
2019-02-11 18:40:41,586 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:40:41,630 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:40:42,190 - root - INFO - Simulating some other task occurring...
2019-02-11 18:40:47,195 - root - INFO - Simulating some other task occurring...
2019-02-11 18:40:52,201 - root - INFO - Simulating some other task occurring...
2019-02-11 18:40:57,206 - root - INFO - Simulating some other task occurring...
2019-02-11 18:41:02,209 - root - INFO - Simulating some other task occurring...
2019-02-11 18:41:06,589 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:41:06,757 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:41:07,210 - root - INFO - Simulating some other task occurring...
2019-02-11 18:41:12,215 - root - INFO - Simulating some other task occurring...
2019-02-11 18:41:17,218 - root - INFO - Simulating some other task occurring...
2019-02-11 18:41:22,224 - root - INFO - Simulating some other task occurring...
2019-02-11 18:41:25,889 - engineio.client - INFO - Received packet MESSAGE data 2["data",{"dateutc":1549935660000,"winddir":42,"windspeedmph":1.6,"windgustmph":3.4,"maxdailygust":11.4,"tempf":32.4,"hourlyrainin":0,"eventrainin":0,"dailyrainin":0,"weeklyrainin":0,"monthlyrainin":0.02,"totalrainin":1.08,"baromrelin":30.2,"baromabsin":24.71,"humidity":28,"tempinf":61,"humidityin":23,"uv":0,"solarradiation":0,"feelsLike":32.4,"dewPoint":2.97,"lastRain":"2019-02-09T18:28:00.000Z","date":"2019-02-12T01:41:00.000Z","macAddress":"AB:CD:EF:12:34:56"}]
2019-02-11 18:41:25,889 - socketio.client - INFO - Received event "data" [/]
2019-02-11 18:41:25,889 - root - INFO - Data received: {'dateutc': 1549935660000, 'winddir': 42, 'windspeedmph': 1.6, 'windgustmph': 3.4, 'maxdailygust': 11.4, 'tempf': 32.4, 'hourlyrainin': 0, 'eventrainin': 0, 'dailyrainin': 0, 'weeklyrainin': 0, 'monthlyrainin': 0.02, 'totalrainin': 1.08, 'baromrelin': 30.2, 'baromabsin': 24.71, 'humidity': 28, 'tempinf': 61, 'humidityin': 23, 'uv': 0, 'solarradiation': 0, 'feelsLike': 32.4, 'dewPoint': 2.97, 'lastRain': '2019-02-09T18:28:00.000Z', 'date': '2019-02-12T01:41:00.000Z', 'macAddress': 'AB:CD:EF:12:34:56'}
2019-02-11 18:41:27,226 - root - INFO - Simulating some other task occurring...
2019-02-11 18:41:31,594 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:41:31,629 - engineio.client - INFO - Received packet PONG data None
2019-02-11 18:41:32,227 - root - INFO - Simulating some other task occurring...
2019-02-11 18:41:37,230 - root - INFO - Simulating some other task occurring...
2019-02-11 18:41:42,236 - root - INFO - Simulating some other task occurring...
2019-02-11 18:41:47,242 - root - INFO - Simulating some other task occurring...
2019-02-11 18:41:52,247 - root - INFO - Simulating some other task occurring...
2019-02-11 18:41:53,492 - engineio.client - WARNING - Read loop: WebSocket connection was closed, aborting
2019-02-11 18:41:53,493 - engineio.client - INFO - Waiting for write loop task to end
2019-02-11 18:41:53,493 - engineio.client - INFO - Exiting write loop task
2019-02-11 18:41:53,493 - engineio.client - INFO - Waiting for ping loop task to end
2019-02-11 18:41:53,494 - engineio.client - INFO - Sending packet PING data None
2019-02-11 18:41:53,494 - engineio.client - WARNING - PONG response has not been received, aborting
2019-02-11 18:41:53,494 - engineio.client - INFO - Exiting ping task
2019-02-11 18:41:53,495 - socketio.client - INFO - Engine.IO connection dropped
2019-02-11 18:41:53,495 - root - INFO - Client has disconnected from the websocket
2019-02-11 18:41:53,495 - engineio.client - INFO - Exiting read loop task
2019-02-11 18:41:53,495 - socketio.client - INFO - Connection failed, new attempt in 0.56 seconds
2019-02-11 18:41:54,059 - engineio.client - INFO - Attempting WebSocket upgrade to wss://dash2.ambientweather.net/socket.io/?api=1&applicationKey=REDACTED&transport=websocket&EIO=3
2019-02-11 18:41:54,175 - engineio.client - WARNING - WebSocket upgrade failed: connection error
2019-02-11 18:41:54,176 - socketio.client - INFO - Reconnection successful
2019-02-11 18:41:57,251 - root - INFO - Simulating some other task occurring...
2019-02-11 18:42:02,256 - root - INFO - Simulating some other task occurring...
2019-02-11 18:42:07,258 - root - INFO - Simulating some other task occurring...
2019-02-11 18:42:12,263 - root - INFO - Simulating some other task occurring...
2019-02-11 18:42:17,266 - root - INFO - Simulating some other task occurring...
2019-02-11 18:42:22,269 - root - INFO - Simulating some other task occurring...
...

I do notice something interesting. In my client, I explicity set the websocket transport (since that is what this socket.io server – a NodeJS implementation – requires; for some reason [Ambient has never fully told me], connection upgrading _from_ long-polling is not supported):

try:
    await self._sio.connect(
        '{0}/?api={1}&applicationKey={2}'.format(
            WEBSOCKET_API_BASE, self._api_version,
            self._application_key),
        transports=['websocket'])
except (ConnectionError, SocketIOError) as err:
    raise WebsocketConnectionError(err) from None

I see this reflected at the very beginning of the log:

2019-02-11 18:23:11,291 - engineio.client - INFO - Attempting WebSocket connection to wss://dash2.ambientweather.net/socket.io/?api=1&applicationKey=REDACTED&transport=websocket&EIO=3

However, when the reconnection occurs, it appears that my previous, explicit transport usage isn't honored and long-polling is attempted first (at least, I assume that's the case, given the "WebSocket upgrade" message):

2019-02-11 18:41:54,059 - engineio.client - INFO - Attempting WebSocket upgrade to wss://dash2.ambientweather.net/socket.io/?api=1&applicationKey=REDACTED&transport=websocket&EIO=3
2019-02-11 18:41:54,175 - engineio.client - WARNING - WebSocket upgrade failed: connection error

Is there something I need to explicitly in order to force the reconnection to honor the same transport usage?

bachya picture bachya on 12 Feb 2019

@bachya Okay, now with the additional info I think I've found the reason why the reconnection goes through an upgrade instead of directly through websocket. This bug is also to blame for the reconnection failure. Please upgrade python-engineio to 3.3.2 and retry. 🤞

miguelgrinberg picture miguelgrinberg on 12 Feb 2019

You got it. New test running – will report back as soon as I see a successful reconnect.

bachya picture bachya on 12 Feb 2019

@bachya you can always kill your server and restart it to force the reconnect. That's how I test it here.

miguelgrinberg picture miguelgrinberg on 12 Feb 2019

Unfortunately, this isn't a socket.io server that I control – it's controlled by ambientweather.net.

bachya picture bachya on 12 Feb 2019

Oh, I see. Then you can unplug your Internet for a second or two. Or just wait, if you know that the server will eventually kick you out.

miguelgrinberg picture miguelgrinberg on 12 Feb 2019
👍1

Success! Using 3.3.2 and after a disconnection, my client now gracefully reconnects and resumes.

Thank you for your help!

bachya picture bachya on 12 Feb 2019
🎉1

Hi, how did you solved? With own Websocket class? I have the same problem with 

python-engineio==3.5.1
python-socketio==4.0.1

My client logs:

May 18 02:29:55 raspberrypi python3[522]: Sending polling GET request to http://....:
May 18 02:30:20 raspberrypi python3[522]: Sending packet PING data None
May 18 02:30:20 raspberrypi python3[522]: Connection refused by the server, aborting
May 18 02:30:20 raspberrypi python3[522]: Exiting write loop task
May 18 02:30:45 raspberrypi python3[522]: PONG response has not been received, aborting
May 18 02:30:45 raspberrypi python3[522]: Exiting ping task

My server logs in the same time (with different locale - reason why there is different time)

[2019-05-18 03:29:55,520] {/usr/local/lib/python3.6/site-packages/werkzeug/_internal.py:122} INFO - _log -  172.17.0.1 - - [18/May/2019 03:29:55] "GET /socket.io/?transport=polling&EIO=3&sid=398b2ea0444d4b8c891bc0abc7744750&t=1558142970.5440698 HTTP/1.1" 200 -
[2019-05-18 03:29:55,521] {/usr/local/lib/python3.6/site-packages/werkzeug/_internal.py:122} INFO - _log -  172.17.0.1 - - [18/May/2019 03:29:55] "POST /socket.io/?transport=polling&EIO=3&sid=398b2ea0444d4b8c891bc0abc7744750 HTTP/1.1" 200 -
[2019-05-18 03:30:16,580] {/app/main.py:211} DEBUG - database_check -  03:30
[2019-05-18 03:30:55,562] {/usr/local/lib/python3.6/site-packages/werkzeug/_internal.py:122} INFO - _log -  172.17.0.1 - - [18/May/2019 03:30:55] "GET /socket.io/?transport=polling&EIO=3&sid=398b2ea0444d4b8c891bc0abc7744750&t=1558142995.5451293 HTTP/1.1" 400 -
petrLorenc picture petrLorenc on 20 May 2019

@petrLorenc The server returned an error in this case. Please add logging on the server to see what the error condition was.

miguelgrinberg picture miguelgrinberg on 20 May 2019

What kind of logs do you mean? The logs which I collected on the server are already shown on the previous post I am using build-in tool in SocketIO.

sio = SocketIO(app, engineio_logger=True, async_mode='threading')

petrLorenc picture petrLorenc on 20 May 2019

@miguelgrinberg To add more information - I created service on Raspberry Pi to listen to server

   Active: active (running) since Fri 2019-05-17 14:35:15 BST; 2 days ago
 Main PID: 522 (python3)
   CGroup: /system.slice/xx.service
           └─522 /usr/bin/python3 -u raspberry.py

May 18 02:29:30 raspberrypi python3[522]: Received packet PONG data None
May 18 02:29:30 raspberrypi python3[522]: Sending polling GET request to http:/...:
May 18 02:29:55 raspberrypi python3[522]: Sending packet PING data None
May 18 02:29:55 raspberrypi python3[522]: Received packet PONG data None
May 18 02:29:55 raspberrypi python3[522]: Sending polling GET request to http://...:
May 18 02:30:20 raspberrypi python3[522]: Sending packet PING data None
May 18 02:30:20 raspberrypi python3[522]: Connection refused by the server, aborting
May 18 02:30:20 raspberrypi python3[522]: Exiting write loop task
May 18 02:30:45 raspberrypi python3[522]: PONG response has not been received, aborting
May 18 02:30:45 raspberrypi python3[522]: Exiting ping task

The service is still running but there is no reconnecting

sio = socketio.Client(engineio_logger=logger, logger=logger, reconnection_attempts=0, reconnection_delay=1)
...
 while True:
        try:
            sio.connect(HOST)
            sio.wait()
            logger.info("End of try section")
        except (SystemExit, Exception) as e:
            tb = traceback.format_exc()
            r = requests.post(...)

            import sys
            sys.exit(0)

The service is set to Restart=always so it is the reason for sys.exit(0)

petrLorenc picture petrLorenc on 20 May 2019

@petrLorenc on the client you must have enabled the Socket.IO logs explicitly, right? I need you to do the same thing for the server, you are only showing web server logs, the Socket.IO server logs a lot more information when told to do so.

miguelgrinberg picture miguelgrinberg on 20 May 2019

@miguelgrinberg Currently I am logging the server like this app = create_app() sio = SocketIO(app, engineio_logger=app.logger, logger=app.logger, async_mode='threading'). But the output seem same like the one shown above. The code to start the library looks like this: sio.run(app, host=HOST, port=PORT, debug=False, log_output=True). The reason why I need to turn off the debug is because if not there is an strange behaviour with reloader and timeloop library. But it should not cause any trouble with logging according to documentation (if log_output=True). Is there some way to get even more detailed logs?

petrLorenc picture petrLorenc on 20 May 2019

You are missing all the logs actually, nothing is being logged from this package. Do you have the correct logging level set up on your app.logger object?

miguelgrinberg picture miguelgrinberg on 20 May 2019

I am doing it this way:

def create_app():
    app = Flask(__name__)

    app.config['SECRET_KEY'] = 'xxx'

    # Logging into file
    import logging
    from logging.handlers import RotatingFileHandler
    formatter = logging.Formatter(
        "[%(asctime)s] {%(pathname)s:%(lineno)d} %(levelname)s - %(funcName)s -  %(message)s")
    handler = RotatingFileHandler(LOG_FILENAME, maxBytes=10000000, backupCount=5)
    handler.setFormatter(formatter)

    console_handler = logging.StreamHandler(sys.stdout)
    console_handler.setFormatter(formatter)

    log = logging.getLogger('werkzeug')
    log.setLevel(logging.INFO)

    log.addHandler(handler)
    log.addHandler(console_handler)

    app.logger.setLevel(logging.INFO)
    app.logger.addHandler(handler)
    app.logger.addHandler(console_handler)

    return app
...
app = create_app()
sio = SocketIO(app, engineio_logger=app.logger, logger=app.logger, async_mode='threading')
petrLorenc picture petrLorenc on 20 May 2019

It happens again, at the same time - so I think that focus should be point to server but it is also interesting that after client closed the connection it is not trying to reconnect nor continue with code after sio.wait().

2019-05-21 02:30:47,930] {/home/pi/.local/lib/python3.5/site-packages/engineio/client.py:500} INFO - _ping_loop -  Exiting ping task`

The code is waiting but not trying to reconnect nor continue

sio.connect(HOST)
sio.wait()
logger.info("End of try section")

@miguelgrinberg It is standard behaviour? Or is there a way to reconnect? I was looking into your codes which looks it should do so but it won't happen in this case. I also try this:
if sio.eio.state != 'connected': logger.info("in disconected state") sio.connect(HOST) time.sleep(100)
with no success.

petrLorenc picture petrLorenc on 21 May 2019

I need to see the server logs to answer your questions. There was a 400 error that we need to understand. Reconnections happen on specific situations, until I know exactly what happened I can't tell if this is your problem or a bug.

I don't know if the missing logs are a problem on your side or mine. Did you make any progress getting these logs?

miguelgrinberg picture miguelgrinberg on 21 May 2019

No progress. I am setting all handlers to INFO. No change. But it is hard to find that logs when I don't know what they looks like..

petrLorenc picture petrLorenc on 21 May 2019

They look very much like the logs you get from the client.

miguelgrinberg picture miguelgrinberg on 21 May 2019

I just copied the logging setup you showed above into my example app, and I do get logs. I actually get every line logged twice for some reason. Example:

[2019-05-21 11:20:58,511] INFO in server: Server initialized for eventlet.
[2019-05-21 11:20:58,511] {/Users/miguelgrinberg/Documents/dev/flask/python-engineio/engineio/server.py:139} INFO - __init__ -  Server initialized for eventlet.
[2019-05-21 11:20:58,516] {/Users/miguelgrinberg/Documents/dev/flask/flask-socketio/venv/lib/python3.6/site-packages/werkzeug/_internal.py:88} INFO - _log -   * Restarting with stat
[2019-05-21 11:20:59,055] INFO in server: Server initialized for eventlet.
[2019-05-21 11:20:59,055] {/Users/miguelgrinberg/Documents/dev/flask/python-engineio/engineio/server.py:139} INFO - __init__ -  Server initialized for eventlet.
[2019-05-21 11:20:59,058] {/Users/miguelgrinberg/Documents/dev/flask/flask-socketio/venv/lib/python3.6/site-packages/werkzeug/_internal.py:88} WARNING - _log -   * Debugger is active!
[2019-05-21 11:20:59,074] {/Users/miguelgrinberg/Documents/dev/flask/flask-socketio/venv/lib/python3.6/site-packages/werkzeug/_internal.py:88} INFO - _log -   * Debugger PIN: 162-679-819
(42493) wsgi starting up on http://127.0.0.1:5000
(42493) accepted ('127.0.0.1', 57925)
127.0.0.1 - - [21/May/2019 11:21:09] "GET / HTTP/1.1" 200 6082 0.012929
[2019-05-21 11:21:09,526] INFO in socket: af115078c9784cca80a46b20d77166dd: Sending packet OPEN data {'sid': 'af115078c9784cca80a46b20d77166dd', 'upgrades': ['websocket'], 'pingTimeout': 60000, 'pingInterval': 25000}
[2019-05-21 11:21:09,526] {/Users/miguelgrinberg/Documents/dev/flask/python-engineio/engineio/socket.py:94} INFO - send -  af115078c9784cca80a46b20d77166dd: Sending packet OPEN data {'sid': 'af115078c9784cca80a46b20d77166dd', 'upgrades': ['websocket'], 'pingTimeout': 60000, 'pingInterval': 25000}
[2019-05-21 11:21:09,527] INFO in socket: af115078c9784cca80a46b20d77166dd: Sending packet MESSAGE data 0
[2019-05-21 11:21:09,527] {/Users/miguelgrinberg/Documents/dev/flask/python-engineio/engineio/socket.py:94} INFO - send -  af115078c9784cca80a46b20d77166dd: Sending packet MESSAGE data 0
127.0.0.1 - - [21/May/2019 11:21:09] "GET /socket.io/?EIO=3&transport=polling&t=1558434069523-0 HTTP/1.1" 200 381 0.001564
[2019-05-21 11:21:09,549] INFO in socket: af115078c9784cca80a46b20d77166dd: Received packet MESSAGE data 0/test
[2019-05-21 11:21:09,549] {/Users/miguelgrinberg/Documents/dev/flask/python-engineio/engineio/socket.py:52} INFO - receive -  af115078c9784cca80a46b20d77166dd: Received packet MESSAGE data 0/test
[2019-05-21 11:21:09,550] INFO in server: emitting event "my_response" to af115078c9784cca80a46b20d77166dd [/test]
[2019-05-21 11:21:09,550] {/Users/miguelgrinberg/Documents/dev/flask/python-socketio/socketio/server.py:241} INFO - emit -  emitting event "my_response" to af115078c9784cca80a46b20d77166dd [/test]

The rotating log file has all messages as well, without duplication. The duplicate logs must be because you change the default logging set up somewhere else, I'm guessing. In any case, logging to app.logger appears to work well, so you need to figure out why those logs are getting lost.

miguelgrinberg picture miguelgrinberg on 21 May 2019

Oh, so maybe I have that logs ... is this what you asking for?

[2019-05-21 03:29:56,749] {/usr/local/lib/python3.6/site-packages/werkzeug/_internal.py:122} INFO - _log -  172.17.0.1 - - [21/May/2019 03:29:56] "GET /socket.io/?transport=polling&EIO=3&sid=466e14a094954aebb7fc0995a4cabbc6&t=1558402171.7574456 HTTP/1.1" 200 -
[2019-05-21 03:29:56,749] {/usr/local/lib/python3.6/site-packages/engineio/socket.py:94} INFO - send -  466e14a094954aebb7fc0995a4cabbc6: Sending packet PONG data None
[2019-05-21 03:29:56,750] {/usr/local/lib/python3.6/site-packages/werkzeug/_internal.py:122} INFO - _log -  172.17.0.1 - - [21/May/2019 03:29:56] "POST /socket.io/?transport=polling&EIO=3&sid=466e14a094954aebb7fc0995a4cabbc6 HTTP/1.1" 200 -
[2019-05-21 03:29:57,945] {/usr/local/lib/python3.6/site-packages/engineio/socket.py:52} INFO - receive -  c62e128d4dbd4b429bda3213316cdb0f: Received packet PING data None
[2019-05-21 03:29:57,945] {/usr/local/lib/python3.6/site-packages/engineio/socket.py:94} INFO - send -  c62e128d4dbd4b429bda3213316cdb0f: Sending packet PONG data None
[2019-05-21 03:29:57,945] {/usr/local/lib/python3.6/site-packages/werkzeug/_internal.py:122} INFO - _log -  172.17.0.1 - - [21/May/2019 03:29:57] "POST /socket.io/?transport=polling&EIO=3&sid=c62e128d4dbd4b429bda3213316cdb0f HTTP/1.1" 200 -
[2019-05-21 03:29:57,946] {/usr/local/lib/python3.6/site-packages/werkzeug/_internal.py:122} INFO - _log -  172.17.0.1 - - [21/May/2019 03:29:57] "GET /socket.io/?transport=polling&EIO=3&sid=c62e128d4dbd4b429bda3213316cdb0f&t=1558402172.9831817 HTTP/1.1" 200 -
[2019-05-21 03:30:01,347] {/app/main.py:210} DEBUG - database_check -  03:30
[2019-05-21 03:30:40,615] {/usr/local/lib/python3.6/site-packages/engineio/socket.py:75} INFO - check_ping_timeout -  86a1e89f1fe044e7b860a6a4fa231f4d: Client is gone, closing socket
[2019-05-21 03:30:40,616] {/usr/local/lib/python3.6/site-packages/werkzeug/_internal.py:122} INFO - _log -  172.17.0.1 - - [21/May/2019 03:30:40] "GET /socket.io/?transport=polling&EIO=3&sid=86a1e89f1fe044e7b860a6a4fa231f4d&t=1558402180.6004303 HTTP/1.1" 400 -
[2019-05-21 03:30:42,849] {/usr/local/lib/python3.6/site-packages/engineio/socket.py:75} INFO - check_ping_timeout -  c62e128d4dbd4b429bda3213316cdb0f: Client is gone, closing socket
[2019-05-21 03:30:42,850] {/usr/local/lib/python3.6/site-packages/engineio/socket.py:75} INFO - check_ping_timeout -  c62e128d4dbd4b429bda3213316cdb0f: Client is gone, closing socket
[2019-05-21 03:30:42,850] {/usr/local/lib/python3.6/site-packages/werkzeug/_internal.py:122} INFO - _log -  172.17.0.1 - - [21/May/2019 03:30:42] "GET /socket.io/?transport=polling&EIO=3&sid=c62e128d4dbd4b429bda3213316cdb0f&t=1558402197.9683194 HTTP/1.1" 200 -
[2019-05-21 03:30:56,791] {/usr/local/lib/python3.6/site-packages/engineio/socket.py:75} INFO - check_ping_timeout -  466e14a094954aebb7fc0995a4cabbc6: Client is gone, closing socket
[2019-05-21 03:30:56,792] {/usr/local/lib/python3.6/site-packages/werkzeug/_internal.py:122} INFO - _log -  172.17.0.1 - - [21/May/2019 03:30:56] "GET /socket.io/?transport=polling&EIO=3&sid=466e14a094954aebb7fc0995a4cabbc6&t=1558402196.7734103 HTTP/1.1" 400 -

if I align it with client logs (I know about different time locale)

[2019-05-21 02:29:57,924] {/home/pi/.local/lib/python3.5/site-packages/engineio/client.py:435} INFO - _send_packet -  Sending packet PING data None
[2019-05-21 02:29:57,965] {/home/pi/.local/lib/python3.5/site-packages/engineio/client.py:416} INFO - _receive_packet -  Received packet PONG data None
[2019-05-21 02:29:57,967] {/home/pi/.local/lib/python3.5/site-packages/engineio/client.py:506} INFO - _read_loop_polling -  Sending polling GET request to http://alquist.ciirc.cvut.cz:33000/socket.io/?transport=polling&EIO=3&sid=c62e128d4dbd4b429bda3213316cdb0f
[2019-05-21 02:30:22,926] {/home/pi/.local/lib/python3.5/site-packages/engineio/client.py:435} INFO - _send_packet -  Sending packet PING data None
[2019-05-21 02:30:22,941] {/home/pi/.local/lib/python3.5/site-packages/engineio/client.py:619} WARNING - _write_loop -  Connection refused by the server, aborting
[2019-05-21 02:30:22,942] {/home/pi/.local/lib/python3.5/site-packages/engineio/client.py:636} INFO - _write_loop -  Exiting write loop task
[2019-05-21 02:30:47,928] {/home/pi/.local/lib/python3.5/site-packages/engineio/client.py:492} INFO - _ping_loop -  PONG response has not been received, aborting
[2019-05-21 02:30:47,930] {/home/pi/.local/lib/python3.5/site-packages/engineio/client.py:500} INFO - _ping_loop -  Exiting ping task

I should investigate server, right? It does not look like problem with library, right? Bad that it is not reconnecting ...

petrLorenc picture petrLorenc on 21 May 2019

This is definitely related:

[2019-05-21 03:30:40,615] {/usr/local/lib/python3.6/site-packages/engineio/socket.py:75} INFO - check_ping_timeout -  86a1e89f1fe044e7b860a6a4fa231f4d: Client is gone, closing socket

This message can occur for two reasons. One is that the client stops sending pings. The other is that the server is blocking so much that it cannot process the pings from the client(s) in a timely manner, so it thinks the pings are coming too late.

I think the most likely situation in your case is the latter. Are you doing anything that blocks the server for long periods of time?

miguelgrinberg picture miguelgrinberg on 21 May 2019

Not anything I would know about. Several docker containers are running on that machine (few of them are not mine), so it can be that. It is also the reason why I don't have full control over the behaviour of the server.

Anyway, wouldn't you know about some workaround to reconnecting client after this happens?

petrLorenc picture petrLorenc on 21 May 2019

This isn't a standard disconnection, so the reconnection feature does not apply.

The sequence of events is as follows:

  • Server received a PING from the client at 03:29:57,945, and responded immediately with the PONG packet. So far so good.
  • The client sent the next PING at 02:30:22,926. Assuming the two hosts have exactly one hour difference this is 25 seconds later, which is the correct interval.
  • The server does not show that it has received that PING packet at all, and gave up at 03:30:42,849 declaring the client gone.

The server log shows no activity from Socket.IO between 03:29:57,946 and 03:30:40,615, which really makes no sense since a PING from each client should arrive every 25 seconds. Obviously the moment the server recovers and starts looking at things it decides to cancel clients, because to it it appears as if clients forgot to send their required PINGs.

It's hard for me to guess what's going on there, but really the problem is on this server, which is too busy or somehow prevented from running and responding to clients timely.

As a side note, it looks like you are using the Flask development server for this Socket.IO server. That's a bad idea, I recommend you switch to gunicorn or uWSGI. If you add eventlet you will have access to WebSocket, which has a lighter load than polling and should help if the problem is that your server is doing too much work.

miguelgrinberg picture miguelgrinberg on 21 May 2019

Thank you for your help. I didn't find any reason why the server should be busy ... so at the end I think I will rewrite whole logic to series of HTTP request (each minute or so - to get at least minimum robustness against this type of error)

Anyway, just from the curiosity, would you think that this code can solve that:

 while True:
        try:
            sio.connect(HOST)
            if sio.eio.state != 'connected':
                logger.info("in disconected state")
                sio.disconnect()
                sio.connect(HOST)
            time.sleep(60)
petrLorenc picture petrLorenc on 21 May 2019

So I tested it and code above have run the whole time.

petrLorenc picture petrLorenc on 22 May 2019

So unfortunately, the problem is still there, even with the new code:

    while True:
        try:
            if requests.get(HOST + "/alive/" + USER_ID).text != "OK":
                logger.info("in disconected state or server is not properly connected")
                sio.disconnect()
                time.sleep(2)
                sio.connect(HOST)
            i_am_alive()
            time.sleep(60) # one minute
            logger.info("After alive acknowledgment")
        except (SystemExit, Exception) as e: 
            tb = traceback.format_exc()
            r = requests.post(HOST + "/logs/add/critical", json={"exception": str(tb),
                                                                 DbNamespace.PATIENTS + "_" + DbNamespace.ID: USER_ID,
                                                                 "raspberry_logs": log_capture_string.getvalue()})

            import sys
            sys.exit(0)

it looks like the sio is somehow blocking because my last logs are 

WARNING - _write_loop -  Connection refused by the server, aborting
[2019-05-24 02:30:22,859] {/home/pi/.local/lib/python3.5/site-packages/engineio/client.py:636} INFO - _write_loop -  Exiting write loop task
[2019-05-24 02:30:38,084] {raspberry.py:176} INFO - <module> -  After alive acknowledgment
[2019-05-24 02:30:47,852] {/home/pi/.local/lib/python3.5/site-packages/engineio/client.py:492} INFO - _ping_loop -  PONG response has not been received, aborting
[2019-05-24 02:30:47,854] {/home/pi/.local/lib/python3.5/site-packages/engineio/client.py:500} INFO - _ping_loop -  Exiting ping task

but it shouldn't be blocking if there is no sio.wait(), right @miguelgrinberg ?

petrLorenc picture petrLorenc on 24 May 2019

I don't see how this is related to Socket.IO. You made a request to /alive/<user_id> and because the server is unresponsive it blocked your loop. If the request would have worked your log should have the "in disconnected state..." message.

miguelgrinberg picture miguelgrinberg on 24 May 2019
Was this page helpful?
0 / 5 - 0 ratings

Related issues

sidwarkd picture sidwarkd  Â·  6Comments
sdvcrx picture sdvcrx  Â·  3Comments
sraboncmc picture sraboncmc  Â·  5Comments
sigmavirus24 picture sigmavirus24  Â·  5Comments
WaleedMeselhy picture WaleedMeselhy  Â·  3Comments