I have a Aeotec microswitch G2 acting as a switch to control my garage lights. I’m using the Aeotec Z-satick as the controller.
I’ve noticed that occasionally (but it seems it’s getting more frequent) the status of the switch won’t update in the frontend when the switch is operated by my motion control automation. It only happens on the “turn off” portion. It works fine on the “turn on” part.
To clarify that…
The motion is detected and the light turns on and the frontend switch status gets updated that the switch turned on. After 15 minutes of no motion the automation turns the switch off. The switch actually does turn off but for some reason the status display of the switch indicates that it is still on. If I subsequently click the switch to turn it off manually the display goes from “on” to “off” to “on” then back to “off” in immediate succession.
the logbook shows the timer automation running and then turning off (which then turns off the switch) but the switch status doesn’t show a status change in the logbook.
This has happened twice today. The first time that it should have turned off was at 0946. the second time was at 2152. The home-assistant log doesn’t show the same errors/warnings for both times tho.
These are the home-assistant.log entries for the applicable times:
The first event:
2018-01-03 09:44:38 WARNING (MainThread) [bellows.zigbee.application] Unexpected message send notification
2018-01-03 09:48:55 WARNING (MainThread) [bellows.zigbee.application] Unexpected message send notification
2018-01-03 09:50:39 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal read error on socket transport
Traceback (most recent call last):
File "/usr/local/lib/python3.6/asyncio/selector_events.py", line 724, in _read_ready
data = self._sock.recv(self.max_size)
TimeoutError: [Errno 110] Connection timed out
2018-01-03 09:51:35 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal read error on socket transport
Traceback (most recent call last):
File "/usr/local/lib/python3.6/asyncio/selector_events.py", line 724, in _read_ready
data = self._sock.recv(self.max_size)
TimeoutError: [Errno 110] Connection timed out
2018-01-03 09:51:40 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal read error on socket transport
Traceback (most recent call last):
File "/usr/local/lib/python3.6/asyncio/selector_events.py", line 724, in _read_ready
data = self._sock.recv(self.max_size)
TimeoutError: [Errno 110] Connection timed out
2018-01-03 09:51:40 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal read error on socket transport
Traceback (most recent call last):
File "/usr/local/lib/python3.6/asyncio/selector_events.py", line 724, in _read_ready
data = self._sock.recv(self.max_size)
TimeoutError: [Errno 110] Connection timed out
2018-01-03 09:51:45 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal read error on socket transport
Traceback (most recent call last):
File "/usr/local/lib/python3.6/asyncio/selector_events.py", line 724, in _read_ready
data = self._sock.recv(self.max_size)
TimeoutError: [Errno 110] Connection timed out
2018-01-03 09:54:39 WARNING (MainThread) [bellows.zigbee.application] Unexpected message send notification
2018-01-03 09:58:57 WARNING (MainThread) [bellows.zigbee.application] Unexpected message send notification
then the second event:
2018-01-03 22:20:19 WARNING (MainThread) [bellows.zigbee.application] Unexpected message send notification
2018-01-03 22:20:35 WARNING (MainThread) [bellows.zigbee.application] Unexpected message send notification
2018-01-03 22:22:11 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
2018-01-03 22:24:45 WARNING (Thread-4) [pychromecast.socket_client] Heartbeat timeout, resetting connection
I’m really not even sure if those log errors are related to any zwave functions. Just posting them here for completeness.
And here are the applicable Z Wave log entries:
2018-01-03 09:30:58.757 Info, Node014, Value::Set - COMMAND_CLASS_SWITCH_BINARY - Switch - 0 - 1 - True
2018-01-03 09:30:58.757 Info, Node014, SwitchBinary::Set - Setting node 14 to On
2018-01-03 09:30:58.757 Detail, Node014, Queuing (Send) SwitchBinaryCmd_Set (Node=14): 0x01, 0x0a, 0x00, 0x13, 0x0e, 0x03, 0x25, 0x01, 0xff, 0x25, 0xf0, 0xe5
2018-01-03 09:30:58.758 Detail, Node014, Queuing (Send) SwitchBinaryCmd_Get (Node=14): 0x01, 0x09, 0x00, 0x13, 0x0e, 0x02, 0x25, 0x02, 0x25, 0xf1, 0x1a
2018-01-03 09:30:58.758 Detail,
2018-01-03 09:30:58.758 Info, Node014, Sending (Send) message (Callback ID=0xf0, Expected Reply=0x13) - SwitchBinaryCmd_Set (Node=14): 0x01, 0x0a, 0x00, 0x13, 0x0e, 0x03, 0x25, 0x01, 0xff, 0x25, 0xf0, 0xe5
2018-01-03 09:30:58.767 Detail, Node014, Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-01-03 09:30:58.767 Detail, Node014, ZW_SEND_DATA delivered to Z-Wave stack
2018-01-03 09:30:58.836 Detail, Node014, Received: 0x01, 0x07, 0x00, 0x13, 0xf0, 0x00, 0x00, 0x07, 0x1c
2018-01-03 09:30:58.836 Detail, Node014, ZW_SEND_DATA Request with callback ID 0xf0 received (expected 0xf0)
2018-01-03 09:30:58.836 Info, Node014, Request RTT 78 Average Request RTT 823
2018-01-03 09:30:58.836 Detail, Expected callbackId was received
2018-01-03 09:30:58.836 Detail, Expected reply was received
2018-01-03 09:30:58.836 Detail, Message transaction complete
2018-01-03 09:30:58.836 Detail,
2018-01-03 09:30:58.836 Detail, Node014, Removing current message
2018-01-03 09:30:58.836 Detail,
2018-01-03 09:30:58.836 Info, Node014, Sending (Send) message (Callback ID=0xf1, Expected Reply=0x04) - SwitchBinaryCmd_Get (Node=14): 0x01, 0x09, 0x00, 0x13, 0x0e, 0x02, 0x25, 0x02, 0x25, 0xf1, 0x1a
2018-01-03 09:30:58.845 Detail, Node014, Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-01-03 09:30:58.845 Detail, Node014, ZW_SEND_DATA delivered to Z-Wave stack
2018-01-03 09:30:58.970 Detail, Node014, Received: 0x01, 0x08, 0x00, 0x04, 0x00, 0x0e, 0x02, 0x82, 0x01, 0x7c
2018-01-03 09:30:58.970 Detail,
2018-01-03 09:30:58.970 Info, Node014, Response RTT 133 Average Response RTT 1219
2018-01-03 09:30:58.970 Info, Node014, Received Hail command from node 14
2018-01-03 09:30:58.970 Detail, Node014, Queuing (Send) SwitchBinaryCmd_Get (Node=14): 0x01, 0x09, 0x00, 0x13, 0x0e, 0x02, 0x25, 0x02, 0x25, 0xf2, 0x19
2018-01-03 09:30:59.276 Detail, Node014, Received: 0x01, 0x08, 0x00, 0x04, 0x00, 0x0e, 0x02, 0x25, 0x03, 0xd9
2018-01-03 09:30:59.276 Detail,
2018-01-03 09:30:59.276 Info, Node014, Response RTT 440 Average Response RTT 829
2018-01-03 09:30:59.276 Info, Node014, Received SwitchBinary report from node 14: level=On
2018-01-03 09:30:59.276 Detail, Node014, Refreshed Value: old value=false, new value=true, type=bool
2018-01-03 09:30:59.276 Detail, Node014, Changes to this value are not verified
2018-01-03 09:30:59.276 Detail, Node014, Notification: ValueChanged
2018-01-03 09:30:59.317 Detail, Node014, Received: 0x01, 0x07, 0x00, 0x13, 0xf1, 0x00, 0x00, 0x30, 0x2a
2018-01-03 09:30:59.317 Detail, Node014, ZW_SEND_DATA Request with callback ID 0xf1 received (expected 0xf1)
2018-01-03 09:30:59.317 Info, Node014, Request RTT 481 Average Request RTT 652
2018-01-03 09:30:59.318 Detail, Expected callbackId was received
2018-01-03 09:31:08.836 Error, Node014, ERROR: Dropping command, expected response not received after 1 attempt(s)
2018-01-03 09:31:08.836 Detail, Node014, Removing current message
2018-01-03 09:31:08.836 Detail, Node014, Notification: Notification - TimeOut
2018-01-03 09:31:08.843 Detail,
2018-01-03 09:31:08.844 Info, Node014, Sending (Send) message (Callback ID=0xf2, Expected Reply=0x04) - SwitchBinaryCmd_Get (Node=14): 0x01, 0x09, 0x00, 0x13, 0x0e, 0x02, 0x25, 0x02, 0x25, 0xf2, 0x19
2018-01-03 09:31:08.852 Detail, Node014, Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-01-03 09:31:08.852 Detail, Node014, ZW_SEND_DATA delivered to Z-Wave stack
2018-01-03 09:31:08.921 Detail, Node014, Received: 0x01, 0x07, 0x00, 0x13, 0xf2, 0x00, 0x00, 0x08, 0x11
2018-01-03 09:31:08.921 Detail, Node014, ZW_SEND_DATA Request with callback ID 0xf2 received (expected 0xf2)
2018-01-03 09:31:08.921 Info, Node014, Request RTT 77 Average Request RTT 364
2018-01-03 09:31:08.921 Detail, Expected callbackId was received
2018-01-03 09:31:08.970 Detail, Node014, Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x0e, 0x03, 0x25, 0x03, 0xff, 0x26
2018-01-03 09:31:08.971 Detail,
2018-01-03 09:31:08.971 Info, Node014, Response RTT 126 Average Response RTT 477
2018-01-03 09:31:08.971 Info, Node014, Received SwitchBinary report from node 14: level=On
2018-01-03 09:31:08.971 Detail, Node014, Refreshed Value: old value=true, new value=true, type=bool
2018-01-03 09:31:08.971 Detail, Node014, Changes to this value are not verified
2018-01-03 09:31:08.971 Detail, Node014, Expected reply and command class was received
2018-01-03 09:31:08.971 Detail, Node014, Message transaction complete
2018-01-03 09:31:08.971 Detail,
2018-01-03 09:31:08.971 Detail, Node014, Removing current message
2018-01-03 09:31:08.972 Detail, Node014, Notification: ValueChanged
2018-01-03 09:46:02.391 Info, Node014, Value::Set - COMMAND_CLASS_SWITCH_BINARY - Switch - 0 - 1 - False
2018-01-03 09:46:02.391 Info, Node014, SwitchBinary::Set - Setting node 14 to Off
2018-01-03 09:46:02.391 Detail, Node014, Queuing (Send) SwitchBinaryCmd_Set (Node=14): 0x01, 0x0a, 0x00, 0x13, 0x0e, 0x03, 0x25, 0x01, 0x00, 0x25, 0xf3, 0x19
2018-01-03 09:46:02.391 Detail, Node014, Queuing (Send) SwitchBinaryCmd_Get (Node=14): 0x01, 0x09, 0x00, 0x13, 0x0e, 0x02, 0x25, 0x02, 0x25, 0xf4, 0x1f
2018-01-03 09:46:02.392 Detail,
2018-01-03 09:46:02.392 Info, Node014, Sending (Send) message (Callback ID=0xf3, Expected Reply=0x13) - SwitchBinaryCmd_Set (Node=14): 0x01, 0x0a, 0x00, 0x13, 0x0e, 0x03, 0x25, 0x01, 0x00, 0x25, 0xf3, 0x19
2018-01-03 09:46:02.400 Detail, Node014, Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-01-03 09:46:02.400 Detail, Node014, ZW_SEND_DATA delivered to Z-Wave stack
2018-01-03 09:46:02.470 Detail, Node014, Received: 0x01, 0x07, 0x00, 0x13, 0xf3, 0x00, 0x00, 0x07, 0x1f
2018-01-03 09:46:02.471 Detail, Node014, ZW_SEND_DATA Request with callback ID 0xf3 received (expected 0xf3)
2018-01-03 09:46:02.471 Info, Node014, Request RTT 78 Average Request RTT 221
2018-01-03 09:46:02.471 Detail, Expected callbackId was received
2018-01-03 09:46:02.471 Detail, Expected reply was received
2018-01-03 09:46:02.471 Detail, Message transaction complete
2018-01-03 09:46:02.471 Detail,
2018-01-03 09:46:02.471 Detail, Node014, Removing current message
2018-01-03 09:46:02.471 Detail,
2018-01-03 09:46:02.472 Info, Node014, Sending (Send) message (Callback ID=0xf4, Expected Reply=0x04) - SwitchBinaryCmd_Get (Node=14): 0x01, 0x09, 0x00, 0x13, 0x0e, 0x02, 0x25, 0x02, 0x25, 0xf4, 0x1f
2018-01-03 09:46:02.481 Detail, Node014, Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-01-03 09:46:02.481 Detail, Node014, ZW_SEND_DATA delivered to Z-Wave stack
2018-01-03 09:46:02.757 Detail, Node014, Received: 0x01, 0x07, 0x00, 0x13, 0xf4, 0x00, 0x00, 0x1c, 0x03
2018-01-03 09:46:02.757 Detail, Node014, ZW_SEND_DATA Request with callback ID 0xf4 received (expected 0xf4)
2018-01-03 09:46:02.757 Info, Node014, Request RTT 285 Average Request RTT 253
2018-01-03 09:46:02.757 Detail, Expected callbackId was received
2018-01-03 09:46:12.473 Error, Node014, ERROR: Dropping command, expected response not received after 1 attempt(s)
2018-01-03 09:46:12.473 Detail, Node014, Removing current message
2018-01-03 09:46:12.473 Detail, Node014, Notification: Notification - TimeOut
The second event was similar.
Any ideas on what might be the problem? Failing switch maybe? if so then that would be disheartening since I’ve already had to return one of these due to a complete failure and these aren’t that old.