{"action":"created","issue":{"url":"https://api.github.com/repos/MisterWil/abodepy/issues/31","repository_url":"https://api.github.com/repos/MisterWil/abodepy","labels_url":"https://api.github.com/repos/MisterWil/abodepy/issues/31/labels{/name}","comments_url":"https://api.github.com/repos/MisterWil/abodepy/issues/31/comments","events_url":"https://api.github.com/repos/MisterWil/abodepy/issues/31/events","html_url":"https://github.com/MisterWil/abodepy/issues/31","id":311754939,"number":31,"title":"Improve Event Listener","user":{"login":"MisterWil","id":1091741,"avatar_url":"https://avatars2.githubusercontent.com/u/1091741?v=4","gravatar_id":"","url":"https://api.github.com/users/MisterWil","html_url":"https://github.com/MisterWil","followers_url":"https://api.github.com/users/MisterWil/followers","following_url":"https://api.github.com/users/MisterWil/following{/other_user}","gists_url":"https://api.github.com/users/MisterWil/gists{/gist_id}","starred_url":"https://api.github.com/users/MisterWil/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/MisterWil/subscriptions","organizations_url":"https://api.github.com/users/MisterWil/orgs","repos_url":"https://api.github.com/users/MisterWil/repos","events_url":"https://api.github.com/users/MisterWil/events{/privacy}","received_events_url":"https://api.github.com/users/MisterWil/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":0,"created_at":"2018-04-05T20:19:58Z","updated_at":"2018-04-07T16:58:12Z","closed_at":null,"author_association":"OWNER","body":"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:\r\n\r\n_The SocketIO protocol is in fact two protocols. The \"transport\" is EngineIO and the messaging protocol is SocketIO._\r\n\r\n**EngineIO Protocol**\r\n  `<packet type id>[<data>]`\r\n  Ex: 0{\"sid\":\"kOeJt3LgKj2im3UVAFiO\",\"upgrades\":[],\"pingInterval\":25000,\"pingTimeout\":60000}\r\n  Ex: 2probe\r\n  Ex: 3probe\r\n  Ex: 2\r\n  Ex: 3\r\n  Ex: 40\r\n  Ex: 42[\"com.goabode.device.update\",\"ZW:00000005\"]\r\n\r\n**Packet Types:**\r\n\r\n0 open\r\n  Sent from the server when a new transport is opened with JSON-encoded handshake data:\r\n      sid                 session ID\r\n      upgrades            possible transport upgrades\r\n      pingTimeout         server configured ping timeout - Time to wait for pong response from server before disconnecting\r\n      pingInterval        server configured ping interval - Time between client sends ping packets\r\n\r\n1 close\r\n  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.\r\n\r\n2 ping\r\n  Sent by the client to the server. Should be sent every pingInterval.\r\n\r\n3 pong\r\n  Sent by the server to the client to respond to a ping. Should be received within pingTimeout after the last ping.\r\n\r\n4 message\r\n  Messages to or from the server. We only care about recieving data.\r\n\r\n5 upgrade\r\n  Upgrade test from one transport to another. Since we're only using websockets we can ignore this.\r\n\r\n6 noop\r\n  A \"no op\" packet. Ignored.\r\n\r\n**Ping Timeouts**\r\n  The client must send a ping packet every pingInteveral. The client will consider the server unresponsive after not recieving a\r\n  reply from the server for pingTimeout. Since the two values are shared between the server and the client, the server\r\n  will also be able to detect whether the client becomes unresponsive when it does not receive any data within pingTimeout + pingInterval\r\n\r\n**SocketIO Protocol**\r\n  The data portion of an EngineIO packet type 4 will utilize the SocketIO protocol.\r\n  Ex: 40\r\n  Ex: 42[\"com.goabode.device.update\",\"ZW:00000005\"]\r\n  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\":\"\r\n000000\",\"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\":\"\"}]\r\n\r\n  In the above examples the first '4' is the EngineIO message type and everything after it is the SocketIO message type.\r\n\r\n  The SocketIO message itself if some sort of format like: <packet type><message type><optional namespace><optional event ID>[data] (ex: 42/chat,[“join”,”{room:1}”])\r\n  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\r\n  and the second index onward can be a string or json object.\r\n\r\n  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\r\n  the event data through to an on_event method.\r\n\r\n**Message Types:**\r\n\r\n0 connect         Confirms SocketIO Message Connection\r\n1 disconnect      Transmitted before SocketIO Disconnect? Not sure where this is used but will similarly react.\r\n2 event           Event message - What We've Done This For\r\n3 ack             Acknowledge an event - Ignored\r\n4 error           Error message (for example, authentication failure).\r\n5 binary event    Binary data event - Ignored for our purposes currently\r\n6 binary ack      Acknowledge a binary event - Ignored\r\n\r\nhttps://github.com/wildfoundry/dataplicity-lomond/\r\nhttps://www.willmcgugan.com/blog/tech/post/announcing-lomond/\r\nhttp://lomond.readthedocs.io/en/latest/\r\nhttps://github.com/socketio/engine.io-protocol\r\nhttps://github.com/socketio/socket.io-protocol\r\n\r\n"},"comment":{"url":"https://api.github.com/repos/MisterWil/abodepy/issues/comments/379483847","html_url":"https://github.com/MisterWil/abodepy/issues/31#issuecomment-379483847","issue_url":"https://api.github.com/repos/MisterWil/abodepy/issues/31","id":379483847,"user":{"login":"shred86","id":32663154,"avatar_url":"https://avatars0.githubusercontent.com/u/32663154?v=4","gravatar_id":"","url":"https://api.github.com/users/shred86","html_url":"https://github.com/shred86","followers_url":"https://api.github.com/users/shred86/followers","following_url":"https://api.github.com/users/shred86/following{/other_user}","gists_url":"https://api.github.com/users/shred86/gists{/gist_id}","starred_url":"https://api.github.com/users/shred86/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/shred86/subscriptions","organizations_url":"https://api.github.com/users/shred86/orgs","repos_url":"https://api.github.com/users/shred86/repos","events_url":"https://api.github.com/users/shred86/events{/privacy}","received_events_url":"https://api.github.com/users/shred86/received_events","type":"User","site_admin":false},"created_at":"2018-04-07T16:58:12Z","updated_at":"2018-04-07T16:58:12Z","author_association":"CONTRIBUTOR","body":"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:\r\n\r\n````\r\n2018-04-06 08:21:18 DEBUG (SocketIOThread) [abodepy.socketio] Poll()\r\n2018-04-06 08:21:18 WARNING (SocketIOThread) [abodepy.socketio] SocketIO Server Ping Timeout\r\n2018-04-06 08:21:18 DEBUG (SocketIOThread) [lomond] WebSocket closing; data not sent\r\n2018-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>\r\n2018-04-06 08:21:22 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 4533210472: Connection cancelled by server \r\n2018-04-06 08:21:22 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 4533210472: Closed connection \r\n2018-04-06 08:21:23 DEBUG (SocketIOThread) [abodepy.socketio] Poll()\r\n2018-04-06 08:21:23 WARNING (SocketIOThread) [abodepy.socketio] SocketIO Server Ping Timeout\r\n2018-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>\r\n2018-04-06 08:21:23 DEBUG (SocketIOThread) [lomond] WebSocket closing; data not sent\r\n2018-04-06 08:21:28 DEBUG (SocketIOThread) [abodepy.socketio] Poll()\r\n2018-04-06 08:21:28 WARNING (SocketIOThread) [abodepy.socketio] SocketIO Server Ping Timeout\r\n2018-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>\r\n2018-04-06 08:21:28 DEBUG (SocketIOThread) [lomond] WebSocket closing; data not sent\r\n2018-04-06 08:21:31 DEBUG (SocketIOThread) [lomond] recv fail; [Errno 60] Operation timed out\r\n2018-04-06 08:21:31 DEBUG (SocketIOThread) [abodepy.socketio] Disconnected('socket fail; recv fail; [Errno 60] Operation timed out', graceful=False)\r\n2018-04-06 08:21:31 INFO (SocketIOThread) [abodepy.socketio] Websocket Disconnected\r\n2018-04-06 08:21:31 DEBUG (SocketIOThread) [abodepy.socketio] BackOff(delay=5.8)\r\n2018-04-06 08:21:37 DEBUG (SocketIOThread) [abodepy.socketio] Connecting(url='wss://my.goabode.com/socket.io/?EIO=3&transport=websocket')\r\n2018-04-06 08:21:37 DEBUG (SocketIOThread) [abodepy.socketio] Connected(url='wss://my.goabode.com/socket.io/?EIO=3&transport=websocket')\r\n2018-04-06 08:21:37 INFO (SocketIOThread) [abodepy.socketio] Websocket Connected\r\n2018-04-06 08:21:37 INFO (SocketIOThread) [abodepy] Updating all devices...\r\n````\r\n\r\nHowever, at some point I stopped receiving any updates from SocketIO which appears to have been after these error messages:\r\n\r\n````\r\n2018-04-06 08:25:39 DEBUG (SocketIOThread) [abodepy.socketio] Poll()\r\n2018-04-06 08:25:39 DEBUG (SocketIOThread) [lomond] WebSocket closing; data not sent\r\nException in thread SocketIOThread:\r\nTraceback (most recent call last):\r\n  File \"/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/threading.py\", line 916, in _bootstrap_inner\r\n    self.run()\r\n  File \"/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/threading.py\", line 864, in run\r\n    self._target(*self._args, **self._kwargs)\r\n  File \"/Users/jamiemun/virtualenvs/homeassistant/lib/python3.6/site-packages/abodepy/socketio.py\", line 173, in _run_socketio_thread\r\n    self._on_websocket_poll(event)\r\n  File \"/Users/jamiemun/virtualenvs/homeassistant/lib/python3.6/site-packages/abodepy/socketio.py\", line 222, in _on_websocket_poll\r\n    self._websocket.send_text(PACKET_PING)\r\n  File \"/Users/jamiemun/virtualenvs/homeassistant/lib/python3.6/site-packages/lomond/websocket.py\", line 427, in send_text\r\n    self.session.send(Opcode.TEXT, text.encode('utf-8'))\r\n  File \"/Users/jamiemun/virtualenvs/homeassistant/lib/python3.6/site-packages/lomond/session.py\", line 157, in send\r\n    self.write(frame.to_bytes())\r\n  File \"/Users/jamiemun/virtualenvs/homeassistant/lib/python3.6/site-packages/lomond/session.py\", line 138, in write\r\n    raise errors.WebSocketClosing('data not sent')\r\nlomond.errors.WebSocketClosing: data not sent\r\n\r\n2018-04-06 08:26:27 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 4575170400: Connection cancelled by server \r\n2018-04-06 08:26:27 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 4575170400: Closed connection \r\n2018-04-06 08:29:50 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting\r\n2018-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>\r\n2018-04-06 08:29:54 INFO (MainThread) [homeassistant.components.http.view] Serving /api/websocket to 172.16.16.79 (auth: True)\r\n2018-04-06 08:29:54 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 4570154600: Connected \r\n````"}}
{"actor":{"display_login":"shred86"}}