HA stops reporting Wink state changes

w1ll1am23 · February 15, 2017, 9:28pm

You can just log wink I would think.

Dayve67 · February 15, 2017, 9:31pm

Just did a restart and noticed this. Its the IP of my wink hub.
17-02-15 16:22:49 ERROR (Thread-15) [netdisco.ssdp] Error fetching description at https://192.168.1.145:8888

Rob3E3 · February 15, 2017, 10:35pm

It was good while it lasted.

Back to not updating. Can see updates in the Wink app. Can see HA continuing to change Wink items, just not when the actions are dependent on a sensor connected to Wink. And even though HA changes the status in Wink, the change is not reflected in the HA frontend.
Only errors in the log around the time that things stopped reporting:

17-02-15 17:28:56 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal read error on socket transport
Traceback (most recent call last):
  File "/usr/lib/python3.4/asyncio/selector_events.py", line 582, in _read_ready
    data = self._sock.recv(self.max_size)
OSError: [Errno 113] No route to host
17-02-15 18:45:51 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal read error on socket transport
Traceback (most recent call last):
  File "/usr/lib/python3.4/asyncio/selector_events.py", line 582, in _read_ready
    data = self._sock.recv(self.max_size)
OSError: [Errno 113] No route to host

Rob3E3 · February 15, 2017, 10:39pm

I get that error every restart. I didn’t actually realize that it was the Wink hub, but now that you mention it, I think it is. But I’ve always assumed it was an error from the nmap device tracking.

w1ll1am23 · February 15, 2017, 11:25pm

I think it has something to do with discovery. The Wink hub responds to a query made, but the response is invalid. It isn’t an error.

w1ll1am23 · February 15, 2017, 11:28pm

I believe every error we have seen related to this always logs something with “take message” in it. Can you try searching your log for that?

bluenote73 · February 16, 2017, 12:10am

I’m afraid i don’t remember exactly my upgrade history, but if i could find it i might be able to narrow it down. Is there a way to know what versions we’ve run in the past? I know suddenly there’s lot of chatter but for me this was preexisting to .38 in .37 and I’d like to confirm which version i was on previous because that was problem free, that might help point the finger a bit.

turboc · February 16, 2017, 2:16am

The No route to host would seem to indicate some type of network error. For some reason HA can’t find a path to the IP address it’s trying to get to. Can you tell me a little about your network configuration (routers, switches, is everything plugged into the same switch, are your devices static address or dhcp)

Secondly, does the not reporting always happen with the same device type? I’ve noticed that when I try to turn off a dimmer switch that because the switch dims to turn out the light, that I’ll usually end up with HA signifying that the light is on for a while when it’s actually already turned off. It may take up to a minute before HA gets the signal that the light has actually turned off.

Rob3E3 · February 16, 2017, 3:01pm

You mean home-assistant.log? If so, then nothing with the word “message” shows up. I don’t know if that error was Wink-related at all. I grabbed it because the time stamps were closest to when I seemed to stop getting Wink updates, but I actually have that error logged a number of times, even when Wink is reporting just fine, so it is likely something else.

Also, in every other case of HA failing to update Wink data, I eventually would solve it, temporarily, with a restart of HA. This time I decided to wait until I got home to deal with it, and by that time, it had self-corrected. I’ve never seen HA go back to working properly with Wink without my intervention before, so maybe this was a fluke. I will keep an eye on it today and see what happens.

Rob3E3 · February 16, 2017, 3:15pm

turboc:

The No route to host would seem to indicate some type of network error. For some reason HA can’t find a path to the IP address it’s trying to get to. Can you tell me a little about your network configuration (routers, switches, is everything plugged into the same switch, are your devices static address or dhcp)[/quote]

Network is pretty standard. Cable modem to Router. Router connects to everything via wifi except the Pi running HA, which is ethernet. IPs are dynamically assigned except when I needed to reserve a few: Pi, Wifi plug, Google Home, and, I think, Wink are reserved.

[quote=“turboc, post:429, topic:5884, full:true”]Secondly, does the not reporting always happen with the same device type? I’ve noticed that when I try to turn off a dimmer switch that because the switch dims to turn out the light, that I’ll usually end up with HA signifying that the light is on for a while when it’s actually already turned off. It may take up to a minute before HA gets the signal that the light has actually turned off.

Don’t know what, if any, specific device might be triggering the issue. In yesterday’s case, I wasn’t home, but my wife was. I only know generally when the freeze happened. I’m use to a slight delay in the HA front end when I toggle a light or switch via Wink, but this freeze lasted about 4 hours.

turboc · February 16, 2017, 3:23pm

Wow, 4 hours. Definitely not what I was experiencing.

Any other problems getting to the internet or anything during the freeze time?

itswag7 · February 16, 2017, 3:36pm

Here is what I am seeing…

17-02-15 17:01:27 DEBUG (EndpointThread-Heartbeat-0) [pubnub] GET https://ps.pndsn.com/v2/presence/sub-key/...
17-02-15 17:01:27 DEBUG (EndpointThread-Heartbeat-0) [pubnub] GOT {"status": 200, "message": "OK", "service": "Presence"}

Then I flip turn on a switch, the device turns on but HA is not updated.

17-02-15 17:08:31 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=homeassistant, service=turn_on, service_call_id=140348561987848-15, service_data=entity_id=switch.game_room>
17-02-15 17:08:31 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=switch, service=turn_on, service_call_id=140348561987848-16, service_data=entity_id=['switch.game_room']>
17-02-15 17:08:32 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=140348561987848-16>
17-02-15 17:08:32 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=140348561987848-15>

When it is working this is what I am seeing.

17-02-15 10:39:12 INFO (MainThread) [homeassistant.components.http] Serving /api/services/homeassistant/turn_on to 192.168.1.83 (auth: True)
17-02-15 10:39:12 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=homeassistant, service=turn_on, service_call_id=140348561987848-1, service_data=entity_id=switch.game_room>
17-02-15 10:39:12 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=switch, service=turn_on, service_call_id=140348561987848-2, service_data=entity_id=['switch.game_room']>
17-02-15 10:39:12 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=140348561987848-2>
17-02-15 10:39:12 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=140348561987848-1>
17-02-15 10:39:12 DEBUG (EndpointThread-Subscribe-0) [pubnub] GOT {"t":{"t":"14871767527361367","r":1}....
17-02-15 10:39:12 DEBUG (EndpointThread-Subscribe-0) [pubnub] GET https://ps.pndsn.com/v2/subscribe/..
17-02-15 10:39:13 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: old_state=<state switch.game_room=off; friendly_name=Game Room @ 2017-02-15T10:38:46.247730-06:00>, entity_id=switch.game_room, new_state=<state switch.game_room=on; friendly_name=Game Room @ 2017-02-15T10:39:13.650540-06:00>>
17-02-15 10:39:13 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 140347190143072: Sending {'type': 'event', 'event': {'data': {'old_state': <state switch.game_room=off; friendly_name=Game Room @ 2017-02-15T10:38:46.247730-06:00>, 'entity_id': 'switch.game_room', 'new_state': <state switch.game_room=on; friendly_name=Game Room @ 2017-02-15T10:39:13.650540-06:00>}, 'origin': 'LOCAL', 'event_type': 'state_changed', 'time_fired': datetime.datetime(2017, 2, 15, 16, 39, 13, 650558, tzinfo=<UTC>)}, 'id': 2}
17-02-15 10:39:13 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: old_state=<state group.upstairs_lights=off; entity_id=('switch.game_room', 'switch.upstairs_hallway'), order=13, friendly_name=Upstairs Lights @ 2017-02-15T10:38:46.245656-06:00>, entity_id=group.upstairs_lights, new_state=<state group.upstairs_lights=on; entity_id=('switch.game_room', 'switch.upstairs_hallway'), order=13, friendly_name=Upstairs Lights @ 2017-02-15T10:39:13.652938-06:00>>
17-02-15 10:39:13 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 140347190143072: Sending {'type': 'event', 'event': {'data': {'old_state': <state group.upstairs_lights=off; entity_id=('switch.game_room', 'switch.upstairs_hallway'), order=13, friendly_name=Upstairs Lights @ 2017-02-15T10:38:46.245656-06:00>, 'entity_id': 'group.upstairs_lights', 'new_state': <state group.upstairs_lights=on; entity_id=('switch.game_room', 'switch.upstairs_hallway'), order=13, friendly_name=Upstairs Lights @ 2017-02-15T10:39:13.652938-06:00>}, 'origin': 'LOCAL', 'event_type': 'state_changed', 'time_fired': datetime.datetime(2017, 2, 15, 16, 39, 13, 652953, tzinfo=<UTC>)}, 'id': 2}

Rob3E3 · February 16, 2017, 4:27pm

Well, I wasn’t home during that time, but my wife was in and out of the house and is pretty quick to say something if the internet isn’t working. Also I only discovered this situation by SSHing into my Pi, so clearly I wasn’t having a general outage.

w1ll1am23 · February 16, 2017, 5:08pm

If pubnub isn’t responding I would expect to see some sort of “take message” error prior (maybe way prior) to the attempt to turn in the switch. If you aren’t seeing any errors it is going to be very difficult to figure out what is going on, and chances are it isn’t something in HA/python-wink/Punnubsub-handler

rainerilgen · February 16, 2017, 9:57pm

Hi w1ll1am23,

I have a similar or possible same issue Rob3E3 is having.
After HA was restarted Wink lights are reporting the state correctly. After a to me unknown time the state of my Wink lights isn’t reported in HA anymore.

I did some testing.
7 am HA restarted.
9 am HA is switching the lights off via script and HA is showing the correct status.
2 pm I switch on a Wink light via HA and the light comes on, but HA doesn’t show the correct state.

I checked the log file and I’m unable to see any errors.
So I wonder if that might be more an error with the HA front end.

Here are some snippets of the log file:

17-02-16 14:33:53 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 2664599984: Received {‘type’: ‘call_service’, ‘domain’: ‘homeassistant’, ‘service’: ‘turn_on’, ‘id’: 9, ‘service_data’: {‘entity_id’: ‘light.sofa_reading’}}
17-02-16 14:33:53 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=homeassistant, service=turn_on, service_call_id=3053725296-74, service_data=entity_id=light.sofa_reading>
17-02-16 14:33:53 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_on, service_call_id=3053725296-75, service_data=entity_id=[‘light.sofa_reading’]>
17-02-16 14:33:54 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=3053725296-75>
17-02-16 14:33:54 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=3053725296-74>
17-02-16 14:33:54 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 2664599984: Sending {‘type’: ‘result’, ‘success’: True, ‘id’: 9, ‘result’: None}

The light on was triggered and websocker_api is sending a response. The Light came on, but HA is still showing it as off.

17-02-16 13:49:41 DEBUG (EndpointThread-Subscribe-0) [pubnub] GOT {“t”:{“t”:“14872602777691559”,“r”:2},“m”:}
17-02-16 13:49:41 DEBUG (EndpointThread-Subscribe-0) [pubnub] GET https://ps.pndsn.com/v2/subscribe/&tr=2&pnsdk=PubNub-Python%2F4.0.5&tt=14872602777691559

And here is a live sign from pubnub prior to my test. And I see similar log entries after my test.

netstat -anp --tcp | grep ’ 54.’
tcp 0 0 192.168.178.12:38849 54.209.255.70:443 ESTABLISHED 32578/python3
tcp 0 0 192.168.178.12:38850 54.209.255.70:443 ESTABLISHED 32578/python3

And netcat shows that the connection to the pubnub server is live.

So could it be that we are chasing an error in the wrong spot?

Thank you for looking into this with us. I’m more than happy to answer your questions and supply any logs or test results.

w1ll1am23 · February 16, 2017, 10:50pm

Did you edit your log in anyway? The [pubnub] GET response should have a list of all of the subscribed to channels in it.

w1ll1am23 · February 16, 2017, 10:58pm

Can someone who is having this problem start with a fresh restart of HA and go through every Wink device they own (while watching the HA frontend/logs) and trigger a state change?

It is also worth noting that in the event that pubnub gets disconnected it will attempt to reconnect, but will do so exponentially so maybe there is some sort of network issue going on and it corrects itself eventually? Kinda like what @Rob3E3 reported? Just a thought.

rainerilgen · February 16, 2017, 11:26pm

Yes, I removed some data from the GET request.
I restarted HA and switched my 3 Wink lights on and off via HA. Then I switched them on and off via the Wink App.
HA is reporting the state correct.

I noticed that the Websocket API Sending part is different.
I will send you the log file via PM.

w1ll1am23 · February 17, 2017, 1:36pm

It it was something with Websockets I would assume logging into another browser display the correct state. Also any automations based on Wink device states would still fire. Based on some above comments I don’t think that is the case. Could you try setting up some sort of automation based on a light state and see if it fires even if the state isn’t displaying correctly in the frontend?

rainerilgen · February 17, 2017, 1:41pm

Sure. I will setup a test environment with just the Wink lights.
An automation will switch on and off the light every hour based on the current state of the light.
This way I hope to get a log file without unrelated entries.
As soon I have the test done I will send the log file.