[1/2 SOLVED] Xiaomi bindings not behaving as expected (both xiaomi IO and mihome)

Add-ons Bindings
, ,
1

Hi,

I have some problems with Xiaomi devices not behaving as expected.

I have searched a lot on the forum but I can’t find any similar topics, if I missed it I apologize and would be grateful for a link :smile:

The problem:

When I switch something ON, it switches state to ON, then OFF, then ON again in openhab. Switching OFF shows the same behavior. The device itself however will behave as expected.

This applies both to my Zigbee smart socket and air purifier pro (v6), these devices use different bindings.

Looking at the trace it seems to me that the following happens.

  1. Openhab sends a command to the device, the switch item changes state after the command is sent to the device (which is wrong, right?).

  2. The device acknowledges the command and this acknowledgement contains the current unswitched status.

  3. Openhab reads the acknowledgement and updates the status back to the unswitched state.

  4. Once the device has actually switched it sends an update with it’s new state and openhab again updates the state.

Another thing is that the update after switching only contains the new switch state, so other parameters (current consumption, mode, rpm, etc.) are not updated until the next heartbeat (which for the smart socket can be many minutes away).

The questions:
Is this the expected behavior of the bindings?
Have anyone experienced the same behaviours?

INFO level log

2019-01-06 13:23:51.500 [ome.event.ItemCommandEvent] - Item 'Plug_Switch' received command ON

2019-01-06 13:23:51.510 [nt.ItemStatePredictedEvent] - Plug_Switch predicted to become ON

2019-01-06 13:23:51.527 [vent.ItemStateChangedEvent] - Plug_Switch changed from OFF to ON

2019-01-06 13:23:51.535 [vent.ItemStateChangedEvent] - Plug_Switch changed from ON to OFF

2019-01-06 13:23:51.614 [vent.ItemStateChangedEvent] - Plug_Switch changed from OFF to ON

DEBUG level log

2019-01-05 17:45:04.379 [ome.event.ItemCommandEvent] - Item 'Plug_Switch' received command ON

2019-01-05 17:45:04.395 [DEBUG] [rnal.handler.XiaomiDeviceBaseHandler] - Device 158d0002861fb1 on channel mihome:sensor_plug:7c49ebb3ac4c:158d0002861fb1:power received command ON

2019-01-05 17:45:04.398 [nt.ItemStatePredictedEvent] - Plug_Switch predicted to become ON

2019-01-05 17:45:04.423 [vent.ItemStateChangedEvent] - Plug_Switch changed from OFF to ON

2019-01-05 17:45:04.439 [DEBUG] [rnal.handler.XiaomiDeviceBaseHandler] - Item got update: {"cmd":"write_ack","model":"plug","sid":"158d0002861fb1","short_id":28810,"data":"{\"voltage\":3600,\"status\":\"off\",\"inuse\":\"0\",\"power_consumed\":\"1636\",\"load_power\":\"0.00\"}"}

2019-01-05 17:45:04.456 [vent.ItemStateChangedEvent] - Plug_Switch changed from ON to OFF

2019-01-05 17:45:04.515 [DEBUG] [rnal.handler.XiaomiDeviceBaseHandler] - Item got update: {"cmd":"report","model":"plug","sid":"158d0002861fb1","short_id":28810,"data":"{\"status\":\"on\"}"}

2019-01-05 17:45:04.524 [vent.ItemStateChangedEvent] - Plug_Switch changed from OFF to ON

TRACE level log

2019-01-06 12:20:22.167 [nt.ItemStatePredictedEvent] - Plug_Switch predicted to become ON

==> /var/log/openhab2/openhab.log <==

2019-01-06 12:20:22.169 [DEBUG] [internal.handler.XiaomiBridgeHandler] - Send to bridge mihome:bridge:7c49ebb3ac4c: {"cmd": "write", "sid": "158d0002861fb1", "data": "{\"status\": \"on\", \"key\": \"ABB5061B2B3E9FBF7BF284DF73620DB7\"}"}

2019-01-06 12:20:22.173 [TRACE] [.mihome.internal.socket.XiaomiSocket] - Sending message: {"cmd": "write", "sid": "158d0002861fb1", "data": "{\"status\": \"on\", \"key\": \"ABB5061B2B3E9FBF7BF284DF73620DB7\"}"} to /192.168.3.103:9898

==> /var/log/openhab2/events.log <==

2019-01-06 12:20:22.184 [vent.ItemStateChangedEvent] - Plug_Switch changed from OFF to ON

==> /var/log/openhab2/openhab.log <==

2019-01-06 12:20:22.189 [DEBUG] [.mihome.internal.socket.XiaomiSocket] - Received Datagram from 192.168.3.103:9898 on Port 9898

2019-01-06 12:20:22.193 [TRACE] [internal.handler.XiaomiBridgeHandler] - Received message {"cmd":"write_ack","model":"plug","sid":"158d0002861fb1","short_id":28810,"data":"{\"voltage\":3600,\"status\":\"off\",\"inuse\":\"0\",\"power_consumed\":\"1671\",\"load_power\":\"0.00\"}"}

2019-01-06 12:20:22.197 [TRACE] [internal.handler.XiaomiBridgeHandler] - Updated "last time seen" for device 158d0002861fb1

2019-01-06 12:20:22.200 [DEBUG] [internal.handler.XiaomiBridgeHandler] - Cancelled running timer

2019-01-06 12:20:22.205 [DEBUG] [internal.handler.XiaomiBridgeHandler] - Device 158d0002861fb1 honored write request

2019-01-06 12:20:22.208 [DEBUG] [rnal.handler.XiaomiDeviceBaseHandler] - Item got update: {"cmd":"write_ack","model":"plug","sid":"158d0002861fb1","short_id":28810,"data":"{\"voltage\":3600,\"status\":\"off\",\"inuse\":\"0\",\"power_consumed\":\"1671\",\"load_power\":\"0.00\"}"}

==> /var/log/openhab2/events.log <==

2019-01-06 12:20:22.222 [vent.ItemStateChangedEvent] - Plug_Switch changed from ON to OFF

==> /var/log/openhab2/openhab.log <==

2019-01-06 12:20:22.233 [TRACE] [.mihome.internal.socket.XiaomiSocket] - Data received and notified 1 listeners

2019-01-06 12:20:22.236 [TRACE] [.mihome.internal.socket.XiaomiSocket] - Thread Thread[Thread-69,5,main] waiting for data on port 9898

2019-01-06 12:20:22.270 [DEBUG] [.mihome.internal.socket.XiaomiSocket] - Received Datagram from 192.168.3.103:4321 on Port 9898

2019-01-06 12:20:22.272 [TRACE] [internal.handler.XiaomiBridgeHandler] - Received message {"cmd":"report","model":"plug","sid":"158d0002861fb1","short_id":28810,"data":"{\"status\":\"on\"}"}

2019-01-06 12:20:22.274 [TRACE] [internal.handler.XiaomiBridgeHandler] - Updated "last time seen" for device 158d0002861fb1

2019-01-06 12:20:22.277 [DEBUG] [internal.handler.XiaomiBridgeHandler] - Cancelled running timer

2019-01-06 12:20:22.280 [DEBUG] [rnal.handler.XiaomiDeviceBaseHandler] - Item got update: {"cmd":"report","model":"plug","sid":"158d0002861fb1","short_id":28810,"data":"{\"status\":\"on\"}"}

2019-01-06 12:20:22.284 [TRACE] [.mihome.internal.socket.XiaomiSocket] - Data received and notified 1 listeners

2019-01-06 12:20:22.288 [TRACE] [.mihome.internal.socket.XiaomiSocket] - Thread Thread[Thread-69,5,main] waiting for data on port 9898

==> /var/log/openhab2/events.log <==

2019-01-06 12:20:22.289 [vent.ItemStateChangedEvent] - Plug_Switch changed from OFF to ON

EDIT:
This is running on a raspberry pi 3B with openhabian 1.4 and openHAB 2.4.
The gateway/bridge is Xiaomi v3 (not aqara).

2

No that’s correct

You will need to edit the items file to add the following in the binding {}
autoupdate="false"

What is happening is that openHAB automatically changes the state of the item after sending the command and doesn’t wait for the binding to provide an updated state. This is default behaviour and you can change this by turning off the autoupdate

1 Like
3

Thank you! Now it works exactly as I want it to :slight_smile:
I had completely missunderstood the purpose of autoupdate.

4

Xiaomi IO is behaving as expected so the following only applies to mihome.

This is still an issue for me though, the heartbeats are so far apart that I miss events.
If I for example run the kettle on a plug, the active status and consumptions are never updated before the kettle is done and once again is inactive with 0 consumption.

I found sendCommand(Plug_Switch, RefreshType.REFRESH), but it has no effect.

2019-01-07 10:29:20.111 [ome.event.ItemCommandEvent] - Item 'Plug_Switch' received command REFRESH

2019-01-07 10:29:20.117 [DEBUG] [rnal.handler.XiaomiDeviceBaseHandler] - Device 158d0002861fb1 on channel mihome:sensor_plug:7c49ebb3ac4c:158d0002861fb1:power received command REFRESH

Looking at the bindings handler for the plug it seems like there is no support for RefreshType, but should the log not output some kind or error if the command is not supported?

Also I’m thinking maybe there is some more kind of message that the binding is not aware of, or that the gateway does not forward, as the app updates the consumption just seconds after a load is applied/removed but there is no messages about it in the trace log. Does anyone have any sugestions how I would go about to try to find and capture these unknown update messages?

5

You’re not the first one