Xiaomi MI IO Binding - Bad response times for Yeelight Meteorite (ceiling10)

Add-ons Bindings
, ,
1

Hey there,

first of all my setup:
Raspi 3b+ with Openhabian, connected via Ethernet
openhab 2.5.5
Yeelight Meteorite (Ceiling10)
Very strong wifi-signal

My main purpose is to switch power for the Yeelight with a simple On/Off switch.
I have another Yeelight next to it (ceiling11), which is switching instant on press for 90%, other 10% have delay from 5-10s.

Problem with my Meteorite is, there is a huge delay in most cases (10-60s), but sometimes it works as intended.
If I switch it with the remote or the yeelight app it works at once.
I installed yeecli on my raspi for testing and even with executeCommandline + yeecli it works at once.

Thing:

Thing miio:basic:meteorite "Yeelight Meteorite" [host = "x.x.x.x", token = "myToken", deviceId = "myId", 
                                            model ="yeelink.light.ceiling10", timeout = "60000"]

I did not flash the firmware of my Meteorite, because I don’t want to lose the moonlight mode in the app, but I don’t think the firmware is the culprit because yeecli works very fast.

Any ideas are appreciated :slight_smile:

2

The most likely cause of this is having the device defined multiple times.
As the discovery may find the device twice, this error is easily made.

The background of this is that devices tend to expect sequential id’s in the request. As having the device twice in your OH config (or. e.g another homeautomation program on your network) it won’t get the id it in sequence, It will not respond.

If not, maybe good to share a debug log, to see the communication with the device to get further clue’s on what it the issue at hand.

3

Thanks for your reply.
I added both lamps initially via PaperUI to get the tokens. Then I removed them and added both via .things.file.

There is no other HA-Software running besides openhab.

I set the logging to DEBUG here are some outputs:
Working ceiling light power switch off > on:

2020-09-27 14:48:33.886 [ome.event.ItemCommandEvent] - Item 'power_yeelight_wz' received command ON

2020-09-27 14:48:33.931 [nt.ItemStatePredictedEvent] - power_yeelight_wz predicted to become ON

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

2020-09-27 14:48:33.955 [DEBUG] [io.internal.handler.MiIoBasicHandler] - Locating action for channel 'power': 'ON'

2020-09-27 14:48:33.962 [DEBUG] [io.internal.handler.MiIoBasicHandler] - Sending command set_power["on"]

2020-09-27 14:48:33.966 [DEBUG] [nal.transport.MiIoAsyncCommunication] - Command added to Queue {"id":23,"method":"set_power","params":["on"]} -> x.x.x.x (Device: deviceId token: myToken Queue: 1)

2020-09-27 14:48:33.968 [DEBUG] [io.internal.handler.MiIoBasicHandler] - Periodic update for 'miio:basic:wz' (miio:basic)
==> /var/log/openhab2/events.log <==

2020-09-27 14:48:33.969 [vent.ItemStateChangedEvent] - power_yeelight_wz changed from OFF to ON

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

2020-09-27 14:48:33.971 [DEBUG] [nal.transport.MiIoAsyncCommunication] - Command added to Queue {"id":24,"method":"get_prop","params":["power","bright","delayoff","ct","color_mode"]} -> x.x.x.x (Device: deviceId Token: myToken Queue: 2)

2020-09-27 14:48:33.974 [DEBUG] [nal.transport.MiIoAsyncCommunication] - Command added to Queue {"id":25,"method":"get_prop","params":["name","nl_br"]} -> x.x.x.x (Device: deviceId token: myToken Queue: 3)

2020-09-27 14:48:33.977 [DEBUG] [nal.transport.MiIoAsyncCommunication] - Command added to Queue {"id":26,"method":"miIO.info","params":[]} -> x.x.x.x (Device: deviceID token: myToken Queue: 4)

2020-09-27 14:48:34.043 [DEBUG] [internal.handler.MiIoAbstractHandler] - Received response for wz type: SET_POWER, result: ["ok"], fullresponse: {"result":["ok"],"id":23}

2020-09-27 14:48:34.064 [DEBUG] [internal.handler.MiIoAbstractHandler] - Received response for wz type: GET_PROPERTY, result: ["on","1","0","3500","2"], fullresponse: {"result":["on","1","0","3500","2"],"id":24}

2020-09-27 14:48:34.094 [DEBUG] [internal.handler.MiIoAbstractHandler] - Received response for wz type: GET_PROPERTY, result: ["","0"], fullresponse: {"result":["","0"],"id":25}

Here the same for my Meteorite OFF > ON:

2020-09-27 14:56:31.887 [ome.event.ItemCommandEvent] - Item 'power_yeelight_meteorite' received command ON

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

2020-09-27 14:56:31.971 [DEBUG] [io.internal.handler.MiIoBasicHandler] - Locating action for channel 'power': 'ON'

2020-09-27 14:56:31.974 [DEBUG] [io.internal.handler.MiIoBasicHandler] - Sending command set_power["on"]

2020-09-27 14:56:31.979 [DEBUG] [nal.transport.MiIoAsyncCommunication] - Command added to Queue {"id":111,"method":"set_power","params":["on"]} -> x.x.x.x (Device: meteoriteId token: myToken Queue: 10)

2020-09-27 14:56:31.984 [DEBUG] [io.internal.handler.MiIoBasicHandler] - Periodic update for 'miio:basic:meteorite' (miio:basic)

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

2020-09-27 14:56:31.989 [nt.ItemStatePredictedEvent] - power_yeelight_meteorite predicted to become ON

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

2020-09-27 14:56:31.989 [DEBUG] [internal.handler.MiIoAbstractHandler] - Skipping periodic update for 'miio:basic:meteorite'. 10 elements in queue.

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

2020-09-27 14:56:32.030 [vent.ItemStateChangedEvent] - power_yeelight_meteorite changed from OFF to ON

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

2020-09-27 14:56:41.498 [DEBUG] [io.internal.handler.MiIoBasicHandler] - Periodic update for 'miio:basic:meteorite' (miio:basic)

2020-09-27 14:56:41.501 [DEBUG] [internal.handler.MiIoAbstractHandler] - Skipping periodic update for 'miio:basic:meteorite'. 10 elements in queue.

2020-09-27 14:56:43.881 [DEBUG] [nal.transport.MiIoAsyncCommunication] - Communication error for Mi device at 192.168.2.109: Receive timed out

2020-09-27 14:56:43.884 [DEBUG] [nal.transport.MiIoAsyncCommunication] - No response from device meteoriteId at x.x.x.x for command {"id":101,"method":"get_prop","params":["color_mode","name","bg_power","bg_rgb","bg_ct"]}.

2020-09-27 14:56:43.888 [DEBUG] [internal.handler.MiIoAbstractHandler] - Received response for meteorite type: GET_PROPERTY, result: {}, fullresponse: {"error":"No Response"}

2020-09-27 14:56:43.891 [DEBUG] [internal.handler.MiIoAbstractHandler] - Error received: "No Response"

2020-09-27 14:56:43.918 [DEBUG] [internal.handler.MiIoAbstractHandler] - Received response for meteorite type: GET_PROPERTY, result: ["1","0"], fullresponse: {"result":["1","0"],"id":102}

... some times later

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

2020-09-27 14:57:44.107 [DEBUG] [internal.handler.MiIoAbstractHandler] - Received response for meteorite type: GET_PROPERTY, result: ["2","","off","65300","3451"], fullresponse: {"result":["2","","off","65300","3451"],"id":105}

2020-09-27 14:57:44.148 [DEBUG] [internal.handler.MiIoAbstractHandler] - Received response for meteorite type: GET_PROPERTY, result: ["1","0"], fullresponse: {"result":["1","0"],"id":106}

2020-09-27 14:57:44.170 [DEBUG] [internal.handler.MiIoAbstractHandler] - Received response for meteorite type: GET_PROPERTY, result: ["off","5","70","0","3500"], fullresponse: {"result":["off","5","70","0","3500"],"id":107}

2020-09-27 14:57:44.238 [DEBUG] [internal.handler.MiIoAbstractHandler] - Received response for meteorite type: GET_PROPERTY, result: ["2","","off","65300","3451"], fullresponse: {"result":["2","","off","65300","3451"],"id":108}

2020-09-27 14:57:44.258 [DEBUG] [internal.handler.MiIoAbstractHandler] - Received response for meteorite type: GET_PROPERTY, result: ["1","0"], fullresponse: {"result":["1","0"],"id":109}

2020-09-27 14:57:44.325 [DEBUG] [internal.handler.MiIoAbstractHandler] - Received response for meteorite type: MIIO_INFO, result: {"life":2171790,removed sensitive data}

2020-09-27 14:57:44.359 [DEBUG] [internal.handler.MiIoAbstractHandler] - Received response for meteorite type: SET_POWER, result: ["ok"], fullresponse: {"result":["ok"],"id":111}

2020-09-27 14:57:51.539 [DEBUG] [io.internal.handler.MiIoBasicHandler] - Periodic update for 'miio:basic:meteorite' (miio:basic)

Some other DEBUG output regarding my meteorite:

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

2020-09-27 14:53:21.305 [DEBUG] [io.internal.handler.MiIoBasicHandler] - Periodic update for 'miio:basic:meteorite' (miio:basic)

2020-09-27 14:53:21.310 [DEBUG] [internal.handler.MiIoAbstractHandler] - Skipping periodic update for 'miio:basic:meteorite'. 9 elements in queue.

2020-09-27 14:53:31.315 [DEBUG] [io.internal.handler.MiIoBasicHandler] - Periodic update for 'miio:basic:meteorite' (miio:basic)

2020-09-27 14:53:31.317 [DEBUG] [internal.handler.MiIoAbstractHandler] - Skipping periodic update for 'miio:basic:meteorite'. 9 elements in queue.

2020-09-27 14:53:41.320 [DEBUG] [io.internal.handler.MiIoBasicHandler] - Periodic update for 'miio:basic:meteorite' (miio:basic)

2020-09-27 14:53:41.323 [DEBUG] [internal.handler.MiIoAbstractHandler] - Skipping periodic update for 'miio:basic:meteorite'. 9 elements in queue.

2020-09-27 14:53:41.414 [DEBUG] [nal.transport.MiIoAsyncCommunication] - Communication error for Mi device at x.x.x.x: Receive timed out

2020-09-27 14:53:41.417 [DEBUG] [nal.transport.MiIoAsyncCommunication] - No response from device meteoriteId at x.x.x.x for command {"id":90,"method":"get_prop","params":["power","bright","bg_bright","delayoff","ct"]}.

2020-09-27 14:53:41.422 [DEBUG] [internal.handler.MiIoAbstractHandler] - Received response for meteorite type: GET_PROPERTY, result: {}, fullresponse: {"error":"No Response"}

2020-09-27 14:53:41.425 [DEBUG] [internal.handler.MiIoAbstractHandler] - Error received: "No Response"

Looks like there is some kind of communication error:

2020-09-27 15:10:13.254 [DEBUG] [nal.transport.MiIoAsyncCommunication] - Communication error for Mi device at x.x.x.x: Receive timed out

2020-09-27 15:10:13.259 [DEBUG] [nal.transport.MiIoAsyncCommunication] - No response from device deviceId at x.x.x.x for command {"id":11,"method":"set_power","params":["on"]}.

2020-09-27 15:10:13.263 [DEBUG] [internal.handler.MiIoAbstractHandler] - Received response for meteorite type: SET_POWER, result: {}, fullresponse: {"error":"No Response"}

2020-09-27 15:10:13.267 [DEBUG] [internal.handler.MiIoAbstractHandler] - Error received: "No Response"

2020-09-27 15:11:13.318 [DEBUG] [nal.transport.MiIoAsyncCommunication] - Communication error for Mi device at x.x.x.x: Receive timed out

2020-09-27 15:11:13.321 [DEBUG] [nal.transport.MiIoAsyncCommunication] - No response from device deviceId at x.x.x.x for command {"id":12,"method":"get_prop","params":["power","bright","bg_bright","delayoff","ct"]}.

2020-09-27 15:11:13.324 [DEBUG] [internal.handler.MiIoAbstractHandler] - Received response for meteorite type: GET_PROPERTY, result: {}, fullresponse: {"error":"No Response"}

2020-09-27 15:11:13.327 [DEBUG] [internal.handler.MiIoAbstractHandler] - Error received: "No Response"
4

don’t know if it is your heavy editing of the logfile or wrong config, but looks like you have a meteorite and a deviceId conflicting with each other. Your example thing file has again stomething else “myId”

Suggest to first get it properly running with the thing defined via paperUI. (remove the thingfile), see if that solves the issue. Again, making sure you really have defined only 1 thing for each lamp.
You can also set the refresh to a longer refresh, as it is building up commands in the queue (which is why it is taking sometimes long to execute).

If it continues to take long, please try to send a miIO.info[]a few times via the command channel to see if that is causing your lamp to stop responding . (I have seen this behavior in some devices, which can’t handle the info command very well… causing it to sometimes respond, and sometimes reset/disconnect etc) --> setting the refresh to a much longer time avoids triggering this condition

5

Sorry this was my inconsistent editing of the logfile, the IDs are correct and I have only 1 thing for 1 lamp.
Gonna try to remove my .thing-file and go with PaperUI.

I had set the refreshInterval to 300s / 5 Minutes, which unfortunately didn’t solve the problem.

@marcel_verpaalen
I removed my thing-file, added it again via PaperUI as Thing and added a switch-item for the power channel.
Unfortunately it does not seem to help. I tried to raise the timeout and refresh interval on the new thing, but that didn’t help it either.

Here is a DEBUG Log from the new thing:

2020-09-27 18:47:09.921 [ome.event.ItemCommandEvent] - Item 'power_yeelight_meteorite' received command ON

2020-09-27 18:47:09.930 [nt.ItemStatePredictedEvent] - power_yeelight_meteorite predicted to become ON

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

2020-09-27 18:47:09.935 [DEBUG] [io.internal.handler.MiIoBasicHandler] - Locating action for channel 'power': 'ON'

2020-09-27 18:47:09.938 [DEBUG] [io.internal.handler.MiIoBasicHandler] - Sending command set_power["on"]

2020-09-27 18:47:09.940 [DEBUG] [nal.transport.MiIoAsyncCommunication] - Command added to Queue {"id":467,"method":"set_power","params":["on"]} -> 192.168.2.109 (Device: 123D147C token: 9A3EE855XXXXXXXXXXXXXXXX522BED46 Queue: 1)

2020-09-27 18:47:09.943 [DEBUG] [io.internal.handler.MiIoBasicHandler] - Periodic update for 'miio:generic:123D147C' (miio:basic)

2020-09-27 18:47:09.946 [DEBUG] [nal.transport.MiIoAsyncCommunication] - Command added to Queue {"id":468,"method":"get_prop","params":["power","bright","bg_bright","delayoff","ct"]} -> 192.168.2.109 (Device: 123D147C token: 9A3EE855XXXXXXXXXXXXXXXX522BED46 Queue: 2)

2020-09-27 18:47:09.948 [DEBUG] [nal.transport.MiIoAsyncCommunication] - Command added to Queue {"id":469,"method":"get_prop","params":["color_mode","name","bg_power","bg_rgb","bg_ct"]} -> 192.168.2.109 (Device: 123D147C token: 9A3EE855XXXXXXXXXXXXXXXX522BED46 Queue: 3)

2020-09-27 18:47:09.950 [DEBUG] [nal.transport.MiIoAsyncCommunication] - Command added to Queue {"id":470,"method":"get_prop","params":["bg_lmode","nl_br"]} -> 192.168.2.109 (Device: 123D147C token: 9A3EE855XXXXXXXXXXXXXXXX522BED46 Queue: 4)

2020-09-27 18:47:09.953 [DEBUG] [nal.transport.MiIoAsyncCommunication] - Command added to Queue {"id":471,"method":"miIO.info","params":[]} -> 192.168.2.109 (Device: 123D147C token: 9A3EE855XXXXXXXXXXXXXXXX522BED46 Queue: 5)

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

2020-09-27 18:47:09.957 [vent.ItemStateChangedEvent] - power_yeelight_meteorite changed from OFF to ON


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

2020-09-27 18:48:10.060 [DEBUG] [nal.transport.MiIoAsyncCommunication] - Communication error for Mi device at 192.168.2.109: Receive timed out

2020-09-27 18:48:10.070 [DEBUG] [nal.transport.MiIoAsyncCommunication] - No response from device 123D147C at 192.168.2.109 for command {"id":467,"method":"set_power","params":["on"]}.

2020-09-27 18:48:10.075 [DEBUG] [internal.handler.MiIoAbstractHandler] - Received response for 123D147C type: SET_POWER, result: {}, fullresponse: {"error":"No Response"}

2020-09-27 18:48:10.082 [DEBUG] [internal.handler.MiIoAbstractHandler] - Error received: "No Response"

2020-09-27 18:48:10.122 [DEBUG] [internal.handler.MiIoAbstractHandler] - Received response for 123D147C type: GET_PROPERTY, result: ["off","5","70","0","3500"], fullresponse: {"result":["off","5","70","0","3500"],"id":468}

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

2020-09-27 18:48:10.135 [vent.ItemStateChangedEvent] - power_yeelight_meteorite changed from ON to OFF

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

2020-09-27 18:48:10.148 [DEBUG] [internal.handler.MiIoAbstractHandler] - Received response for 123D147C type: GET_PROPERTY, result: ["2","","off","14847","3451"], fullresponse: {"result":["2","","off","14847","3451"],"id":469}

2020-09-27 18:48:10.174 [DEBUG] [internal.handler.MiIoAbstractHandler] - Received response for 123D147C type: GET_PROPERTY, result: ["1","0"], fullresponse: {"result":["1","0"],"id":470}

I set the timeout to 60s, so that is probably why it ocurred after exactly 1 minute.
It looks like only the “set_power” command causes this timeout, because the enqeued get_property (and a miIO.info which I cut out directly after the last log entry) were processed without a problem it seems.

But somehow this is not a general problem with my lamp because yeecli uses lan-control too and works without a problem.

UPDATE:
Looks like these timeouts occur random on all actions:

2020-09-27 23:59:13.332 [DEBUG] [nal.transport.MiIoAsyncCommunication] - Communication error for Mi device at 192.168.2.109: Receive timed out

2020-09-27 23:59:13.334 [DEBUG] [nal.transport.MiIoAsyncCommunication] - No response from device 123D147C at 192.168.2.109 for command {"id":213,"method":"get_prop","params":["bg_lmode","nl_br"]}.

2020-09-27 23:59:13.337 [DEBUG] [internal.handler.MiIoAbstractHandler] - Received response for 123D147C type: GET_PROPERTY, result: {}, fullresponse: {"error":"No Response"}

2020-09-27 23:59:13.340 [DEBUG] [internal.handler.MiIoAbstractHandler] - Error received: "No Response"