shred86
commented
6 years ago I've been running the new event listener on my computer (virtualenv) and there's been a few of these messages but it looks like it's reconnecting:
2018-04-06 08:21:18 DEBUG (SocketIOThread) [abodepy.socketio] Poll()
2018-04-06 08:21:18 WARNING (SocketIOThread) [abodepy.socketio] SocketIO Server Ping Timeout
2018-04-06 08:21:18 DEBUG (SocketIOThread) [lomond] WebSocket closing; data not sent
2018-04-06 08:21:18 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1523031678.205319, level=WARNING, message=SocketIO Server Ping Timeout, exception=, source=/Users/shred/virtualenvs/homeassistant/lib/python3.6/site-packages/abodepy/socketio.py>
2018-04-06 08:21:22 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 4533210472: Connection cancelled by server
2018-04-06 08:21:22 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 4533210472: Closed connection
2018-04-06 08:21:23 DEBUG (SocketIOThread) [abodepy.socketio] Poll()
2018-04-06 08:21:23 WARNING (SocketIOThread) [abodepy.socketio] SocketIO Server Ping Timeout
2018-04-06 08:21:23 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1523031683.218399, level=WARNING, message=SocketIO Server Ping Timeout, exception=, source=/Users/shred/virtualenvs/homeassistant/lib/python3.6/site-packages/abodepy/socketio.py>
2018-04-06 08:21:23 DEBUG (SocketIOThread) [lomond] WebSocket closing; data not sent
2018-04-06 08:21:28 DEBUG (SocketIOThread) [abodepy.socketio] Poll()
2018-04-06 08:21:28 WARNING (SocketIOThread) [abodepy.socketio] SocketIO Server Ping Timeout
2018-04-06 08:21:28 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1523031688.232044, level=WARNING, message=SocketIO Server Ping Timeout, exception=, source=/Users/shred/virtualenvs/homeassistant/lib/python3.6/site-packages/abodepy/socketio.py>
2018-04-06 08:21:28 DEBUG (SocketIOThread) [lomond] WebSocket closing; data not sent
2018-04-06 08:21:31 DEBUG (SocketIOThread) [lomond] recv fail; [Errno 60] Operation timed out
2018-04-06 08:21:31 DEBUG (SocketIOThread) [abodepy.socketio] Disconnected('socket fail; recv fail; [Errno 60] Operation timed out', graceful=False)
2018-04-06 08:21:31 INFO (SocketIOThread) [abodepy.socketio] Websocket Disconnected
2018-04-06 08:21:31 DEBUG (SocketIOThread) [abodepy.socketio] BackOff(delay=5.8)
2018-04-06 08:21:37 DEBUG (SocketIOThread) [abodepy.socketio] Connecting(url='wss://my.goabode.com/socket.io/?EIO=3&transport=websocket')
2018-04-06 08:21:37 DEBUG (SocketIOThread) [abodepy.socketio] Connected(url='wss://my.goabode.com/socket.io/?EIO=3&transport=websocket')
2018-04-06 08:21:37 INFO (SocketIOThread) [abodepy.socketio] Websocket Connected
2018-04-06 08:21:37 INFO (SocketIOThread) [abodepy] Updating all devices...However, at some point I stopped receiving any updates from SocketIO which appears to have been after these error messages:
2018-04-06 08:25:39 DEBUG (SocketIOThread) [abodepy.socketio] Poll()
2018-04-06 08:25:39 DEBUG (SocketIOThread) [lomond] WebSocket closing; data not sent
Exception in thread SocketIOThread:
Traceback (most recent call last):
File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/threading.py", line 916, in _bootstrap_inner
self.run()
File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/threading.py", line 864, in run
self._target(*self._args, **self._kwargs)
File "/Users/shred/virtualenvs/homeassistant/lib/python3.6/site-packages/abodepy/socketio.py", line 173, in _run_socketio_thread
self._on_websocket_poll(event)
File "/Users/shred/virtualenvs/homeassistant/lib/python3.6/site-packages/abodepy/socketio.py", line 222, in _on_websocket_poll
self._websocket.send_text(PACKET_PING)
File "/Users/shred/virtualenvs/homeassistant/lib/python3.6/site-packages/lomond/websocket.py", line 427, in send_text
self.session.send(Opcode.TEXT, text.encode('utf-8'))
File "/Users/shred/virtualenvs/homeassistant/lib/python3.6/site-packages/lomond/session.py", line 157, in send
self.write(frame.to_bytes())
File "/Users/shred/virtualenvs/homeassistant/lib/python3.6/site-packages/lomond/session.py", line 138, in write
raise errors.WebSocketClosing('data not sent')
lomond.errors.WebSocketClosing: data not sent
2018-04-06 08:26:27 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 4575170400: Connection cancelled by server
2018-04-06 08:26:27 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 4575170400: Closed connection
2018-04-06 08:29:50 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
2018-04-06 08:29:50 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1523032190.239691, level=ERROR, message=Timer got out of sync. Resetting, exception=, source=core.py>
2018-04-06 08:29:54 INFO (MainThread) [homeassistant.components.http.view] Serving /api/websocket to 172.16.16.79 (auth: True)
2018-04-06 08:29:54 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 4570154600: Connected 
MisterWil
A big problem with the Event Listener is that the socketio client libraries for Python all basically suck. I did, however, find a Websocket library that doesn't suck... so I've written a very light weight EngineIO/SocketIO client that sits on top of this Websocket library. Below are the notes I've compiled for this EngineIO/SocketIO code:
The SocketIO protocol is in fact two protocols. The "transport" is EngineIO and the messaging protocol is SocketIO.
EngineIO Protocol
<packet type id>[<data>]Ex: 0{"sid":"kOeJt3LgKj2im3UVAFiO","upgrades":[],"pingInterval":25000,"pingTimeout":60000} Ex: 2probe Ex: 3probe Ex: 2 Ex: 3 Ex: 40 Ex: 42["com.goabode.device.update","ZW:00000005"]Packet Types:
0 open Sent from the server when a new transport is opened with JSON-encoded handshake data: sid session ID upgrades possible transport upgrades pingTimeout server configured ping timeout - Time to wait for pong response from server before disconnecting pingInterval server configured ping interval - Time between client sends ping packets
1 close Request to close the polling interface since polling will open and close sockets regularly. Not required for websockets but will still react to just in case.
2 ping Sent by the client to the server. Should be sent every pingInterval.
3 pong Sent by the server to the client to respond to a ping. Should be received within pingTimeout after the last ping.
4 message Messages to or from the server. We only care about recieving data.
5 upgrade Upgrade test from one transport to another. Since we're only using websockets we can ignore this.
6 noop A "no op" packet. Ignored.
Ping Timeouts The client must send a ping packet every pingInteveral. The client will consider the server unresponsive after not recieving a reply from the server for pingTimeout. Since the two values are shared between the server and the client, the server will also be able to detect whether the client becomes unresponsive when it does not receive any data within pingTimeout + pingInterval
SocketIO Protocol The data portion of an EngineIO packet type 4 will utilize the SocketIO protocol. Ex: 40 Ex: 42["com.goabode.device.update","ZW:00000005"] Ex: 42["com.goabode.gateway.timeline",{"mac":"B0:C5:CA:30:0A:C8","id":213014558,"date":"04/03/2018","time":"01:15 PM","event_utc":1522786544,"event_cid":"","event_code":"5125","device_id":"ZW:00000005","device_type_id":"66","device_type":"Dimmer","nest_has_motion":"","nest_has_sound":"","nest_has_person":"","device_name":"Kitchen Lights","file_path":"","deep_link":"","file_name":"","file_size":"","file_count":"","file_is_del":0,"event_type":"On","severity":"8","pos":"l","color":" 000000","is_alarm":"0","icon":"assets/email/lightbulb-on.png","user_id":"","user_name":"","mobile_name":"","parent_tid":"","app_type":"","viewed_by_uid":"","verified_by_tid":"","event_name":"Kitchen Lights On","event_by":""}]
In the above examples the first '4' is the EngineIO message type and everything after it is the SocketIO message type.
The SocketIO message itself if some sort of format like:[data] (ex: 42/chat,[“join”,”{room:1}”])
where optional namespace is "/chat", defaulting to /, and ID is used for the ack. The data portion is essentially a json array where the first index is a string for the event name
and the second index onward can be a string or json object.
We will dumb this down: When we receive an event we will parse out only the [data] portion and parse it as json into a dict, pull out the event_name, and then pass that along with the event data through to an on_event method.
Message Types:
0 connect Confirms SocketIO Message Connection 1 disconnect Transmitted before SocketIO Disconnect? Not sure where this is used but will similarly react. 2 event Event message - What We've Done This For 3 ack Acknowledge an event - Ignored 4 error Error message (for example, authentication failure). 5 binary event Binary data event - Ignored for our purposes currently 6 binary ack Acknowledge a binary event - Ignored
https://github.com/wildfoundry/dataplicity-lomond/ https://www.willmcgugan.com/blog/tech/post/announcing-lomond/ http://lomond.readthedocs.io/en/latest/ https://github.com/socketio/engine.io-protocol https://github.com/socketio/socket.io-protocol