Openhab-addons: [Milight] Multiple Keep-alive timers after some time

[fab33]

After installing openhab 2.2, milight flood the logs only with V6 bridge (v3 doesn't do that).

15:32:43.991 [INFO ] [smarthome.event.ThingUpdatedEvent    ] - Thing 'milight:bridgeV6:PontMilight2' has been updated.
15:32:44.284 [INFO ] [smarthome.event.ThingUpdatedEvent    ] - Thing 'milight:bridgeV6:PontMilight2' has been updated

and events :

event: message
data: {"topic":"smarthome/things/milight:bridgeV6:PontMilight2/updated","payload":"[{\"label\":\"iBox/iBox2\",\"configuration\":{\"REFRESH_IN_SEC\":5,\"REPEAT\":1,\"WAIT_BETWEEN_COMMANDS\":100,\"ID\":\"0000000012BD\",\"CUSTOM_PORT\":3390,\"PASSWORD_BYTE_1\":0,\"ADDR\":\"192.168.2.15\",\"PASSWORD_BYTE_2\":0},\"properties\":{\"sessionid\":\"00 00\",\"sessionid_last_refresh\":\"1514557579255\"},\"UID\":\"milight:bridgeV6:PontMilight2\",\"thingTypeUID\":\"milight:bridgeV6\",\"channels\":[]},{\"label\":\"iBox/iBox2\",\"configuration\":{\"REFRESH_IN_SEC\":5,\"REPEAT\":1,\"WAIT_BETWEEN_COMMANDS\":100,\"ID\":\"0000000012BD\",\"CUSTOM_PORT\":3390,\"PASSWORD_BYTE_1\":0,\"ADDR\":\"192.168.2.15\",\"PASSWORD_BYTE_2\":0},\"properties\":{\"sessionid\":\"00 00\",\"sessionid_last_refresh\":\"1514557579255\"},\"UID\":\"milight:bridgeV6:PontMilight2\",\"thingTypeUID\":\"milight:bridgeV6\",\"channels\":[]}]","type":"ThingUpdatedEvent"}

the bug is reported on the community forum :
https://community.openhab.org/t/the-new-milight-ibox-and-milight-binding/17621/279

[Tertiush]

@davidgraeff @MikeJMajor
Sorry for linking you both, but do you perhaps know how to solve this issue? Have you experienced it yourself? thanks

[MikeJMajor]

I only have V3 bridges so I haven't seen this issue.
As far as I know this is related to the keep-alive interval which by default is every 10 seconds. Evey time the bridge responds to a keep-alive the binding updates a property value with a timestamp. This results in a log file entry stating the thing has updated and presumably an update to the jsondb thing configuration.

Deleting a couple of lines of code looks like it would resolve the issue, but @davidgraeff needs to comment as to what the purpose of storing the timestamp was.

[davidgraeff]

The timestamp is there to be able to verify the last successful session acknowledge. Openhab can and should be configured to not log state changes or log them to a different file ideally to a ram disk.

[davidgraeff]

The event log looks like a forgotten debug statement

[tuopa]

I would like to test the fix, if available.

[phil2fer]

@davidgraeff

The event log looks like a forgotten debug statement

I dont thing so

could you look my log file

2018-02-06 21:47:09.348 [vent.ItemStateChangedEvent] - CurrentDate changed from 2018-02-06T21:46:09.325+0000 to 2018-02-06T21:47:09.329+0000
 >> 2018-02-06 21:47:51.143 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:F0FE6B16A9CA' has been updated.
2018-02-06 21:47:52.489 [vent.ItemStateChangedEvent] - Moon_Azimuth changed from 70.00 to 70.21
2018-02-06 21:47:52.495 [vent.ItemStateChangedEvent] - Moon_Elevation changed from -29.48 to -29.33
2018-02-06 21:47:53.305 [vent.ItemStateChangedEvent] - Sun_Azimuth changed from 295.67 to 295.92
2018-02-06 21:47:53.311 [vent.ItemStateChangedEvent] - Sun_Elevation changed from -39.93 to -40.08
2018-02-06 21:48:09.363 [vent.ItemStateChangedEvent] - CurrentDate changed from 2018-02-06T21:47:09.329+0000 to 2018-02-06T21:48:09.342+0000
>> 2018-02-06 21:48:51.146 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:F0FE6B16A9CA' has been updated.
2018-02-06 21:48:52.508 [vent.ItemStateChangedEvent] - Moon_Azimuth changed from 70.21 to 70.42
2018-02-06 21:48:52.513 [vent.ItemStateChangedEvent] - Moon_Elevation changed from -29.33 to -29.19
2018-02-06 21:48:53.365 [vent.ItemStateChangedEvent] - Sun_Azimuth changed from 295.92 to 296.17
2018-02-06 21:48:53.380 [vent.ItemStateChangedEvent] - Sun_Elevation changed from -40.08 to -40.22
2018-02-06 21:49:09.365 [vent.ItemStateChangedEvent] - CurrentDate changed from 2018-02-06T21:48:09.342+0000 to 2018-02-06T21:49:09.347+0000
2018-02-06 21:49:52.528 [vent.ItemStateChangedEvent] - Moon_Azimuth changed from 70.42 to 70.64
2018-02-06 21:49:52.531 [vent.ItemStateChangedEvent] - Moon_Elevation changed from -29.19 to -29.04
2018-02-06 21:49:53.504 [vent.ItemStateChangedEvent] - Sun_Azimuth changed from 296.17 to 296.42
2018-02-06 21:49:53.512 [vent.ItemStateChangedEvent] - Sun_Elevation changed from -40.22 to -40.37
2018-02-06 21:50:09.384 [vent.ItemStateChangedEvent] - CurrentDate changed from 2018-02-06T21:49:09.347+0000 to 2018-02-06T21:50:09.361+0000
>> 2018-02-06 21:50:51.149 [hingStatusInfoChangedEvent] - 'milight:bridgeV6:F0FE6B16A9CA' changed from ONLINE to OFFLINE (CONFIGURATION_PENDING): SESSION_WAIT_FOR_BRIDGE
>> 2018-02-06 21:50:51.159 [hingStatusInfoChangedEvent] - 'milight:rgbiboxLed:F0FE6B16A9CA:0' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
>> 2018-02-06 21:50:51.165 [hingStatusInfoChangedEvent] - 'milight:rgbwLed:F0FE6B16A9CA:1' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
>> 2018-02-06 21:50:51.168 [hingStatusInfoChangedEvent] - 'milight:rgbwLed:F0FE6B16A9CA:2' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
>> 2018-02-06 21:50:51.182 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:F0FE6B16A9CA' has been updated.
>> 2018-02-06 21:50:51.308 [hingStatusInfoChangedEvent] - 'milight:bridgeV6:F0FE6B16A9CA' changed from OFFLINE (CONFIGURATION_PENDING): SESSION_WAIT_FOR_BRIDGE to OFFLINE (CONFIGURATION_PENDING): SESSION
_WAIT_FOR_BRIDGE_SID
>> 2018-02-06 21:50:51.353 [hingStatusInfoChangedEvent] - 'milight:bridgeV6:F0FE6B16A9CA' changed from OFFLINE (CONFIGURATION_PENDING): SESSION_WAIT_FOR_BRIDGE_SID to OFFLINE (CONFIGURATION_PENDING): SES
SION_NEED_REGISTER
>> 2018-02-06 21:50:51.603 [hingStatusInfoChangedEvent] - 'milight:bridgeV6:F0FE6B16A9CA' changed from OFFLINE (CONFIGURATION_PENDING): SESSION_NEED_REGISTER to ONLINE
>> 2018-02-06 21:50:51.613 [hingStatusInfoChangedEvent] - 'milight:rgbwLed:F0FE6B16A9CA:1' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
>> 2018-02-06 21:50:51.618 [hingStatusInfoChangedEvent] - 'milight:rgbwLed:F0FE6B16A9CA:2' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
>> 2018-02-06 21:50:51.623 [hingStatusInfoChangedEvent] - 'milight:rgbiboxLed:F0FE6B16A9CA:0' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
>> 2018-02-06 21:50:51.736 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:F0FE6B16A9CA' has been updated.
2018-02-06 21:50:52.545 [vent.ItemStateChangedEvent] - Moon_Azimuth changed from 70.64 to 70.85
2018-02-06 21:50:52.550 [vent.ItemStateChangedEvent] - Moon_Elevation changed from -29.04 to -28.90
2018-02-06 21:50:53.604 [vent.ItemStateChangedEvent] - Sun_Azimuth changed from 296.42 to 296.67
2018-02-06 21:50:53.613 [vent.ItemStateChangedEvent] - Sun_Elevation changed from -40.37 to -40.52
2018-02-06 21:51:09.396 [vent.ItemStateChangedEvent] - CurrentDate changed from 2018-02-06T21:50:09.361+0000 to 2018-02-06T21:51:09.366+0000
>> 2018-02-06 21:51:51.184 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:F0FE6B16A9CA' has been updated.
>> 2018-02-06 21:51:51.605 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:F0FE6B16A9CA' has been updated.
2018-02-06 21:51:52.566 [vent.ItemStateChangedEvent] - Moon_Azimuth changed from 70.85 to 71.06
2018-02-06 21:51:52.570 [vent.ItemStateChangedEvent] - Moon_Elevation changed from -28.90 to -28.75
2018-02-06 21:51:53.695 [vent.ItemStateChangedEvent] - Sun_Azimuth changed from 296.67 to 296.92

At the bigining the keepalive timer rise an event every 60s. After some time the bridge go OFFLINE (I don't know why), and after that there are 2 simultaneous keepalive timer (like 2 session of the bridge)
If i wait few day, i have sometime 4 simultaneous keepalive timer...

[tuopa]

The following exception I get once in a while to "syslog". Not sure if related to this.

Jan 27 18:30:30 openHABianPi karaf[10264]: Exception in thread "SessionThread" java.lang.IllegalArgumentException: Port out of range:-1
Jan 27 18:30:30 openHABianPi karaf[10264]: at java.net.DatagramPacket.setPort(DatagramPacket.java:295)
Jan 27 18:30:30 openHABianPi karaf[10264]: at org.openhab.binding.milight.internal.protocol.MilightV6SessionManager.send_search_for_broadcast(MilightV6SessionManager.java:256)
Jan 27 18:30:30 openHABianPi karaf[10264]: at org.openhab.binding.milight.internal.protocol.MilightV6SessionManager.session_handshake_process(MilightV6SessionManager.java:364)
Jan 27 18:30:30 openHABianPi karaf[10264]: at org.openhab.binding.milight.internal.protocol.MilightV6SessionManager.run(MilightV6SessionManager.java:435)
Jan 27 18:30:30 openHABianPi karaf[10264]: at java.lang.Thread.run(Thread.java:748)

[fab33]

everything like @phil2fer after few days, my logs are plenty of keepalive. With latest snapshot it's the same.

[davidgraeff]

@fab33 Could you please rename the title to something like "[Milight] Multiple Keep-alive timers after some time"? Because this is a serious bug actually, not just a log message problem, if @phil2fer is right.

[Abraxotl]

Confirm!

Same error here, hundreds of these log-entrys:

2018-03-15 00:42:30.870 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:250c498a' has been updated.
2018-03-15 00:42:36.133 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:250c498a' has been updated.
2018-03-15 00:42:40.874 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:250c498a' has been updated.
2018-03-15 00:42:46.136 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:250c498a' has been updated.
2018-03-15 00:42:50.879 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:250c498a' has been updated.
2018-03-15 00:42:56.140 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:250c498a' has been updated.
2018-03-15 00:43:00.882 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:250c498a' has been updated.
2018-03-15 00:43:06.143 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:250c498a' has been updated.
2018-03-15 00:43:10.886 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:250c498a' has been updated.
2018-03-15 00:43:16.146 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:250c498a' has been updated.
2018-03-15 00:43:20.890 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:250c498a' has been updated.
2018-03-15 00:43:26.150 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:250c498a' has been updated.
2018-03-15 00:43:30.893 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:250c498a' has been updated.
2018-03-15 00:43:36.154 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:250c498a' has been updated.
2018-03-15 00:43:40.897 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:250c498a' has been updated.
2018-03-15 00:43:46.157 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:250c498a' has been updated.
2018-03-15 00:43:50.900 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:250c498a' has been updated.
2018-03-15 00:43:56.161 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:250c498a' has been updated.
2018-03-15 00:44:00.904 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:250c498a' has been updated.
2018-03-15 00:44:06.165 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:250c498a' has been updated.
2018-03-15 00:44:10.908 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:250c498a' has been updated.
2018-03-15 00:44:16.168 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:250c498a' has been updated.
2018-03-15 00:44:20.911 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:250c498a' has been updated.
2018-03-15 00:44:26.172 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:250c498a' has been updated.
2018-03-15 00:44:30.915 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:250c498a' has been updated.
2018-03-15 00:44:36.176 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:250c498a' has been updated.
2018-03-15 00:44:40.919 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:250c498a' has been updated.
2018-03-15 00:44:46.180 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:250c498a' has been updated.
2018-03-15 00:44:50.923 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:250c498a' has been updated.

[davidgraeff]

As soon as #3306 is merged, we can tackle the SessionTimer problem.

[valki2]

any updates to this issue?

[davidgraeff]

Nobody is working on it, I'm afraid

[tuopa]

Could anyway the following uncatched exception (from /var/log/syslog) be part of what is causing this? I get the following in /var/log/syslog multiple times:

Aug 13 09:11:42 openHABianPi karaf[871]: Exception in thread "SessionThread" java.lang.IllegalArgumentException: Port out of range:-1 Aug 13 09:11:42 openHABianPi karaf[871]: at java.net.DatagramPacket.setPort(DatagramPacket.java:295) Aug 13 09:11:42 openHABianPi karaf[871]: at org.openhab.binding.milight.internal.protocol.MilightV6SessionManager.sendSearchForBroadcast(MilightV6SessionManager.java:256) Aug 13 09:11:42 openHABianPi karaf[871]: at org.openhab.binding.milight.internal.protocol.MilightV6SessionManager.sessionHandshakeProcess(MilightV6SessionManager.java:364) Aug 13 09:11:42 openHABianPi karaf[871]: at org.openhab.binding.milight.internal.protocol.MilightV6SessionManager.run(MilightV6SessionManager.java:432) Aug 13 09:11:42 openHABianPi karaf[871]: at java.lang.Thread.run(Thread.java:748)

[rbrueckner82]

hey,

same error at with the Version 2.3.0, has anyone solved this problem?

pi@jarvisonpi:~ $ tail -500 /opt/openhab/userdata/logs/events.log | grep -i "'milight:bridgeV6:ba079ec8' changed" 2018-09-25 11:09:25.499 [hingStatusInfoChangedEvent] - 'milight:bridgeV6:ba079ec8' changed from ONLINE to OFFLINE (CONFIGURATION_PENDING): SESSION_WAIT_FOR_BRIDGE 2018-09-25 11:09:25.599 [hingStatusInfoChangedEvent] - 'milight:bridgeV6:ba079ec8' changed from OFFLINE (CONFIGURATION_PENDING): SESSION_WAIT_FOR_BRIDGE to OFFLINE (CONFIGURATION_PENDING): SESSION_WAIT_FOR_BRIDGE_SID 2018-09-25 11:24:49.193 [hingStatusInfoChangedEvent] - 'milight:bridgeV6:ba079ec8' changed from OFFLINE (CONFIGURATION_PENDING): SESSION_WAIT_FOR_BRIDGE_SID to OFFLINE (CONFIGURATION_PENDING): SESSION_NEED_REGISTER 2018-09-25 11:24:49.413 [hingStatusInfoChangedEvent] - 'milight:bridgeV6:ba079ec8' changed from OFFLINE (CONFIGURATION_PENDING): SESSION_NEED_REGISTER to ONLINE pi@jarvisonpi:~ $ tail -f /opt/openhab/userdata/logs/events.log | grep -i "'milight:bridgeV6:ba079ec8' changed" 2018-09-25 11:29:57.707 [hingStatusInfoChangedEvent] - 'milight:bridgeV6:ba079ec8' changed from ONLINE to OFFLINE (CONFIGURATION_PENDING): SESSION_WAIT_FOR_BRIDGE 2018-09-25 11:29:57.764 [hingStatusInfoChangedEvent] - 'milight:bridgeV6:ba079ec8' changed from OFFLINE (CONFIGURATION_PENDING): SESSION_WAIT_FOR_BRIDGE to OFFLINE (CONFIGURATION_PENDING): SESSION_WAIT_FOR_BRIDGE_SID

[Daanozz]

I think this has corrupted my thing file several times.Is there a possibility that someone will look at this bug.
Do not want to buy new bulbs

[davidgraeff]

Hm. I wrote the milight binding, but I do not own the newer bulbs.

If anyone could donate me one of the newer bridges and a colored bulb as well as white bulb I'll look into all the remaining bugs.

Cheers,
David

[Daanozz]

First thanks for all the work. The least I can do is sponsor the new bulbs and controller.

[TomaSpeed]

I have the same issue. (v2.3.0)
I had to add my iBox (not iBox2) manually.
For V3 everything works fine.
As I'm still in the experimental phase, I deleted the V6 bridge and I'll wait for a bug fix.

2018-10-26 08:24:34.125 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:3269a248' has been updated.
2018-10-26 08:24:44.127 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:3269a248' has been updated.
2018-10-26 08:24:49.128 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:3269a248' has been updated.

[davidgraeff]

I will work on this probably this weekend, with a patch included by the 2.4 release

[Daanozz]

I noticed that you had done some update/bug fix. Thanks, can i test it?

[davidgraeff]

I will not compile a jar for it, you would need to do it yourself, or wait another few days for the snapshot.

[Daanozz]

Of course Thanks again

[Abraxotl]

Many Thanks !

[TomaSpeed]

Is the jar file available for testing somewhere?
Or is it possible to test this in an other way?
N.B.: I'm not familiar with java coding, compiling, etc..

[davidgraeff]

org.openhab.binding.milight_2.4.0.201811082139.jar.rename.txt

[Daanozz]

Stupid question. But how do I make a jar of it again. i do not want to ask more than necessary.linux and coding is new for my

[davidgraeff]

I will not support using the provided file. No questions answered. Just this single one: Remove the ".rename.txt" part of the file. github doesn't allow jar files to be uploaded. I thought that this is obvious!

[TomaSpeed]

For me it seem not to work? Or did I something wrong?
Just to let you know about my testing:
I copied the jar file to C:\openHAB2addons\ (+ Remove .rename.txt)
Uninstalled the Milight Binding from PaperUI
V6 bridges have been detected.
Added the Color bulb with cold/warm white (iBox) 1 - 4 Zones manually.
Tested with HABPannel and via PaperUI Rule.
Here what I seen in events.log:
````
2018-11-11 10:30:35.494 [hingStatusInfoChangedEvent] - 'milight:bridgeV6:F0FE6B2DBF16' changed from ONLINE to OFFLINE (CONFIGURATION_PENDING): SESSION_WAIT_FOR_BRIDGE
2018-11-11 10:30:35.495 [hingStatusInfoChangedEvent] - 'milight:rgbwwLed:BurgZinken1' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-11-11 10:30:35.495 [hingStatusInfoChangedEvent] - 'milight:rgbwwLed:BurgZinken2' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-11-11 10:30:35.928 [hingStatusInfoChangedEvent] - 'milight:bridgeV6:F0FE6B2DBF16' changed from OFFLINE (CONFIGURATION_PENDING): SESSION_WAIT_FOR_BRIDGE to OFFLINE (CONFIGURATION_PENDING): SESSION_WAIT_FOR_SESSION_SID
2018-11-11 10:30:35.961 [hingStatusInfoChangedEvent] - 'milight:bridgeV6:F0FE6B2DBF16' changed from OFFLINE (CONFIGURATION_PENDING): SESSION_WAIT_FOR_SESSION_SID to OFFLINE (CONFIGURATION_PENDING): SESSION_NEED_REGISTER
2018-11-11 10:30:36.182 [hingStatusInfoChangedEvent] - 'milight:bridgeV6:F0FE6B2DBF16' changed from OFFLINE (CONFIGURATION_PENDING): SESSION_NEED_REGISTER to ONLINE
2018-11-11 10:30:36.185 [hingStatusInfoChangedEvent] - 'milight:rgbwwLed:BurgZinken1' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2018-11-11 10:30:36.186 [hingStatusInfoChangedEvent] - 'milight:rgbwwLed:BurgZinken2' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2018-11-11 10:30:36.186 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:F0FE6B2DBF16' has been updated.
2018-11-11 10:30:41.213 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:F0FE6B2DBF16' has been updated.
2018-11-11 10:30:56.358 [hingStatusInfoChangedEvent] - 'milight:bridgeV6:F0FE6B2DBF16' changed from ONLINE to OFFLINE (CONFIGURATION_PENDING): SESSION_WAIT_FOR_BRIDGE
2018-11-11 10:30:56.358 [hingStatusInfoChangedEvent] - 'milight:rgbwwLed:BurgZinken1' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-11-11 10:30:56.359 [hingStatusInfoChangedEvent] - 'milight:rgbwwLed:BurgZinken2' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-11-11 10:30:56.777 [hingStatusInfoChangedEvent] - 'milight:bridgeV6:F0FE6B2DBF16' changed from OFFLINE (CONFIGURATION_PENDING): SESSION_WAIT_FOR_BRIDGE to OFFLINE (CONFIGURATION_PENDING): SESSION_WAIT_FOR_SESSION_SID
2018-11-11 10:30:56.808 [hingStatusInfoChangedEvent] - 'milight:bridgeV6:F0FE6B2DBF16' changed from OFFLINE (CONFIGURATION_PENDING): SESSION_WAIT_FOR_SESSION_SID to OFFLINE (CONFIGURATION_PENDING): SESSION_NEED_REGISTER
2018-11-11 10:30:57.015 [hingStatusInfoChangedEvent] - 'milight:bridgeV6:F0FE6B2DBF16' changed from OFFLINE (CONFIGURATION_PENDING): SESSION_NEED_REGISTER to ONLINE
2018-11-11 10:30:57.015 [hingStatusInfoChangedEvent] - 'milight:rgbwwLed:BurgZinken1' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2018-11-11 10:30:57.015 [hingStatusInfoChangedEvent] - 'milight:rgbwwLed:BurgZinken2' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2018-11-11 10:30:57.016 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:F0FE6B2DBF16' has been updated.

[Abraxotl]

Same here,

after updateting from 2.3.0 to
openHAB 2.4.0~20181111101453-1 (Build #1421)
including
org.openhab.binding.milight-2.4.0.M4.jar
org.openhab.binding.milight-2.4.0.M4-p2artifacts.xml
org.openhab.binding.milight-2.4.0.M4-p2metadata.xml

Multiple Log Entries:
2018-11-11 17:11:21.006 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:f2e6d103' has been updated.
2018-11-11 17:11:26.015 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:f2e6d103' has been updated.
2018-11-11 17:11:31.022 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:f2e6d103' has been updated.
2018-11-11 17:11:36.030 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:f2e6d103' has been updated.
2018-11-11 17:11:41.038 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:f2e6d103' has been updated.
2018-11-11 17:11:46.045 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:f2e6d103' has been updated.
2018-11-11 17:11:51.052 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:f2e6d103' has been updated.
2018-11-11 17:11:56.059 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:f2e6d103' has been updated.

[davidgraeff]

The log looks good to me.
If the ibox bridge is online, then the session to the bridge is established successfully. You should see the session id in the Thing properties.

The commands stayed the same from 2.3 to 2.4.

[Daanozz]

it is normal that he updates the Thing almost every second. while spamming the log to?

[davidgraeff]

Yes that's normal. I'm not a fan of the ThingUpdatedEvent events. Those are emitted whenever I update bridge thing properties. You can disable them though. A working system doesn't need them enabled.

[ndom91]

@davidgraeff how do you disable these events? I don't like them filling up my logs either.

[TomaSpeed]

Today i did another test on a fresh setup 2.4.0 build 1422.
And once again: It did not work for me.
All of my V3 bridges were OFFLINE (Except one with same firmware as the others - and this one worked)
My V6 (iBox) did not work. It switched constantly from online to offline and back.
2018-11-12 16:56:41.490 [hingStatusInfoChangedEvent] - 'milight:bridgeV6:F0FE6B2DBF16' changed from ONLINE to OFFLINE (CONFIGURATION_PENDING): SESSION_WAIT_FOR_BRIDGE 2018-11-12 16:56:41.491 [hingStatusInfoChangedEvent] - 'milight:rgbwwLed:MilightBurg2' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE) 2018-11-12 16:56:41.491 [hingStatusInfoChangedEvent] - 'milight:rgbwwLed:MilightBurg1' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE) 2018-11-12 16:56:41.492 [hingStatusInfoChangedEvent] - 'milight:rgbiboxLed:6998502e' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE) 2018-11-12 16:56:41.494 [hingStatusInfoChangedEvent] - 'milight:rgbwwLed:MilightBurg3' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE) 2018-11-12 16:56:41.495 [hingStatusInfoChangedEvent] - 'milight:rgbwwLed:fe374079' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE) 2018-11-12 16:56:41.528 [hingStatusInfoChangedEvent] - 'milight:bridgeV6:F0FE6B2DBF16' changed from OFFLINE (CONFIGURATION_PENDING): SESSION_WAIT_FOR_BRIDGE to OFFLINE (CONFIGURATION_PENDING): SESSION_WAIT_FOR_SESSION_SID 2018-11-12 16:56:41.574 [hingStatusInfoChangedEvent] - 'milight:bridgeV6:F0FE6B2DBF16' changed from OFFLINE (CONFIGURATION_PENDING): SESSION_WAIT_FOR_SESSION_SID to OFFLINE (CONFIGURATION_PENDING): SESSION_NEED_REGISTER 2018-11-12 16:56:41.743 [hingStatusInfoChangedEvent] - 'milight:bridgeV6:F0FE6B2DBF16' changed from OFFLINE (CONFIGURATION_PENDING): SESSION_NEED_REGISTER to ONLINE 2018-11-12 16:56:41.743 [hingStatusInfoChangedEvent] - 'milight:rgbwwLed:MilightBurg1' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE 2018-11-12 16:56:41.745 [hingStatusInfoChangedEvent] - 'milight:rgbwwLed:MilightBurg3' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE 2018-11-12 16:56:41.748 [hingStatusInfoChangedEvent] - 'milight:rgbwwLed:fe374079' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE 2018-11-12 16:56:41.748 [hingStatusInfoChangedEvent] - 'milight:rgbwwLed:MilightBurg2' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE 2018-11-12 16:56:41.748 [hingStatusInfoChangedEvent] - 'milight:rgbiboxLed:6998502e' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE 2018-11-12 16:56:41.748 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:F0FE6B2DBF16' has been updated. 2018-11-12 16:56:46.813 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:F0FE6B2DBF16' has been updated. 2018-11-12 16:56:49.413 [.event.RuleStatusInfoEvent] - f41eb073-2515-462f-85fa-25b633672b10 updated: RUNNING 2018-11-12 16:56:49.413 [ome.event.ItemCommandEvent] - Item 'milight_rgbwwLed_fe374079_ledcolor' received command 240,100,75 2018-11-12 16:56:49.414 [.event.RuleStatusInfoEvent] - f41eb073-2515-462f-85fa-25b633672b10 updated: IDLE 2018-11-12 16:56:49.415 [nt.ItemStatePredictedEvent] - milight_rgbwwLed_fe374079_ledcolor predicted to become 240,100,75 2018-11-12 16:56:49.418 [vent.ItemStateChangedEvent] - milight_rgbwwLed_fe374079_ledcolor changed from 59,71,39 to 240,100,75 2018-11-12 16:56:49.419 [vent.ItemStateChangedEvent] - milight_rgbwwLed_fe374079_ledbrightness changed from 39 to 75 2018-11-12 16:57:01.845 [hingStatusInfoChangedEvent] - 'milight:bridgeV6:F0FE6B2DBF16' changed from ONLINE to OFFLINE (CONFIGURATION_PENDING): SESSION_WAIT_FOR_BRIDGE 2018-11-12 16:57:01.845 [hingStatusInfoChangedEvent] - 'milight:rgbwwLed:MilightBurg1' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE) 2018-11-12 16:57:01.845 [hingStatusInfoChangedEvent] - 'milight:rgbiboxLed:6998502e' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE) 2018-11-12 16:57:01.846 [hingStatusInfoChangedEvent] - 'milight:rgbwwLed:MilightBurg2' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE) 2018-11-12 16:57:01.848 [hingStatusInfoChangedEvent] - 'milight:rgbwwLed:fe374079' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE) 2018-11-12 16:57:01.848 [hingStatusInfoChangedEvent] - 'milight:rgbwwLed:MilightBurg3' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE) 2018-11-12 16:57:01.953 [hingStatusInfoChangedEvent] - 'milight:bridgeV6:F0FE6B2DBF16' changed from OFFLINE (CONFIGURATION_PENDING): SESSION_WAIT_FOR_BRIDGE to OFFLINE (CONFIGURATION_PENDING): SESSION_WAIT_FOR_SESSION_SID 2018-11-12 16:57:01.990 [hingStatusInfoChangedEvent] - 'milight:bridgeV6:F0FE6B2DBF16' changed from OFFLINE (CONFIGURATION_PENDING): SESSION_WAIT_FOR_SESSION_SID to OFFLINE (CONFIGURATION_PENDING): SESSION_NEED_REGISTER 2018-11-12 16:57:02.166 [hingStatusInfoChangedEvent] - 'milight:bridgeV6:F0FE6B2DBF16' changed from OFFLINE (CONFIGURATION_PENDING): SESSION_NEED_REGISTER to ONLINE 2018-11-12 16:57:02.166 [hingStatusInfoChangedEvent] - 'milight:rgbwwLed:MilightBurg1' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE 2018-11-12 16:57:02.167 [hingStatusInfoChangedEvent] - 'milight:rgbwwLed:MilightBurg3' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE 2018-11-12 16:57:02.167 [hingStatusInfoChangedEvent] - 'milight:rgbwwLed:fe374079' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE 2018-11-12 16:57:02.168 [hingStatusInfoChangedEvent] - 'milight:rgbwwLed:MilightBurg2' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE 2018-11-12 16:57:02.168 [hingStatusInfoChangedEvent] - 'milight:rgbiboxLed:6998502e' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE 2018-11-12 16:57:02.168 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:F0FE6B2DBF16' has been updated.
Q: Did It work for you?

[davidgraeff]

Hm, it works perfectly for me with a V3 and V6 bridge. It is essential that you recreate the bridge Things after the version update. Especially the V3 code hasn't changed much.

Wait.. you have multiple V3 bridges? Oh.

The V6 code didn't work for me initially and I changed how the session establishing sequence works. I do not have the "original" milight v6 bridge, mine is from Home-Wize (https://www.amazon.de/Controller-Home-Wize%C2%AE-Technologie-Steuerung-Gl%C3%BChbirnen/dp/B073WZ89DG).

Unfortunately there is no documentation for the V6 API and each implementation does it its own way. My bridge re-negotiates the session about every 5 - 20 mins. If I'm using the app at the same time, the bridge session sometimes not even last for 1 min. It's not stable for sure. I'm thinking of not showing the re-negotiation process to the user and just keep the bridge thing online.

[TomaSpeed]

@davidgraeff

Wait.. you have multiple V3 bridges? Oh.

Yes I have 5 V3 bridges. I did not test them all as only one of them got Online.
I tested V6 with this one: https://www.amazon.com/FUYUTEC-Controller-Wireless-Downight-Compatible/dp/B01M8KR6AD/ref=sr_1_2?ie=UTF8&qid=1542344099&sr=8-2&keywords=milight+ibox
I also have one iBox2 (not connected yet) and ordered 4 more in China (still waiting for them).
I'll test the iBox2 this WE and let you know.
My goal is to replace all V3 with V6 including all the bulbs, ....

How I will proceed for testing:

• Backup of the openHAB2 folder.
• Delete all Mi-Light things & bridges.
• Uninstall the Mi-Light binding.
• Copy the newest Mi-Light binding into the openHAB2addons folder.
• Add the bridges
• Add the things manually (if I remember well)
• Test

I hope this is correct?
Is there a new jar file for testing or should I use the last one?
If there's a new one, how do I find it? Sorry for asking, but I get sometimes a little bit confused with all these updates, ...

[davidgraeff]

Ibox and ibox2 might work a little different. I can't test though, I don't own an ibox1 :/

So many v3 Bridges. The latest pr put all commands in one global send queue with a delay of 100ms. If you issue 5 bulb commands to all the different bridges, the execution is now longer parallel. Just FYI.

The mentioned Pr got merged this week, so the next snapshot should contain the changes. Test it out please and open another GitHub issue for any found problems.