kelvin
kelvin copied to clipboard
stefanwichmann
Spurious "manual change"
I have a setup with a hue bridge, 3 hue lights (colour + temperature capable) and 2 ambience lights (temperature capable). I've been spuriously getting problems where some lights seemingly randomly "desync" from their expected state. In the logs I find the "changed manually" message which I have not done.
After running with debug enabled I have been able to gather some data:
$ journalctl --no-tail -u kelvin | grep -i changed
Nov 25 14:04:38 raspberrypi kelvin[14308]: time="2018/25/11 14:04:38" level=debug msg="⚙ Configuration hasn't changed. Omitting write."
Nov 25 14:04:41 raspberrypi kelvin[14308]: time="2018/25/11 14:04:41" level=debug msg="⚙ Configuration hasn't changed. Omitting write."
Nov 25 17:22:45 raspberrypi kelvin[14308]: time="2018/25/11 17:22:45" level=debug msg="💡 HueLight Hue color lamp 1 - Brightness has changed! Current light state: &{Name:Hue color lamp 1 HueLight:{Id:1 Name:Hue color lamp 1 Attributes:{State:{Hue:41460 On:true Effect:none Alert:none Bri:241 Sat:77 Ct:153 Xy:[0.3129 0.3289] Reachable:true ColorMode:xy} Type:Extended color light Name:Hue color lamp 1 ModelId:LCT015 UniqueId:00:17:88:01:03:7a:c0:ef-0b ManufacturerName:Philips ProductName:Hue color lamp SoftwareVersion:1.29.0_r21169} bridge:0x7440a8} SetColorTemperature:6500 SetBrightness:94 TargetColorTemperature:153 TargetColor:[0.313 0.329] TargetBrightness:238 CurrentColorTemperature:153 CurrentColor:[0.313 0.329] CurrentBrightness:241 CurrentColorMode:xy SupportsColorTemperature:true SupportsXYColor:true Dimmable:true Reachable:true On:true MinimumColorTemperature:2000}"
Nov 25 17:22:45 raspberrypi kelvin[14308]: time="2018/25/11 17:22:45" level=debug msg="💡 HueLight Hue color lamp 1 - Brightness has changed! Current light state: &{Name:Hue color lamp 1 HueLight:{Id:1 Name:Hue color lamp 1 Attributes:{State:{Hue:41460 On:true Effect:none Alert:none Bri:241 Sat:77 Ct:153 Xy:[0.3129 0.3289] Reachable:true ColorMode:xy} Type:Extended color light Name:Hue color lamp 1 ModelId:LCT015 UniqueId:00:17:88:01:03:7a:c0:ef-0b ManufacturerName:Philips ProductName:Hue color lamp SoftwareVersion:1.29.0_r21169} bridge:0x7440a8} SetColorTemperature:6500 SetBrightness:94 TargetColorTemperature:153 TargetColor:[0.313 0.329] TargetBrightness:238 CurrentColorTemperature:153 CurrentColor:[0.313 0.329] CurrentBrightness:241 CurrentColorMode:xy SupportsColorTemperature:true SupportsXYColor:true Dimmable:true Reachable:true On:true MinimumColorTemperature:2000}"
Nov 25 17:22:45 raspberrypi kelvin[14308]: time="2018/25/11 17:22:45" level=debug msg="💡 Light Hue color lamp 1 - Light state has been changed manually: {Name:Hue color lamp 1 HueLight:{Id:1 Name:Hue color lamp 1 Attributes:{State:{Hue:41460 On:true Effect:none Alert:none Bri:241 Sat:77 Ct:153 Xy:[0.3129 0.3289] Reachable:true ColorMode:xy} Type:Extended color light Name:Hue color lamp 1 ModelId:LCT015 UniqueId:00:17:88:01:03:7a:c0:ef-0b ManufacturerName:Philips ProductName:Hue color lamp SoftwareVersion:1.29.0_r21169} bridge:0x7440a8} SetColorTemperature:6500 SetBrightness:94 TargetColorTemperature:153 TargetColor:[0.313 0.329] TargetBrightness:238 CurrentColorTemperature:153 CurrentColor:[0.313 0.329] CurrentBrightness:241 CurrentColorMode:xy SupportsColorTemperature:true SupportsXYColor:true Dimmable:true Reachable:true On:true MinimumColorTemperature:2000}"
...
Logs for color lamp 1 around and before the time of the first event:
time="2018/25/11 17:03:42" level=debug msg="💡 Light Hue color lamp 1 - Updated target state to {ColorTemperature:6500 Brightness:96}"
time="2018/25/11 17:03:43" level=debug msg="💡 HueLight Hue color lamp 1 - Setting light state to 6500K and 96% brightness."
time="2018/25/11 17:03:45" level=debug msg="💡 HueLight Hue color lamp 1 - Light was successfully updated."
time="2018/25/11 17:03:45" level=info msg="💡 Light Hue color lamp 1 - Updated light state to 6500K at 96% brightness"
time="2018/25/11 17:04:42" level=debug msg="💡 Light Hue color lamp 1 - The calculated lightstate for the interval 16:26 - 18:00 is {ColorTemperature:6500 Brightness:96}"
time="2018/25/11 17:04:42" level=debug msg="💡 Light Hue color lamp 1 - Updated target state to {ColorTemperature:6500 Brightness:96}"
time="2018/25/11 17:05:42" level=debug msg="💡 Light Hue color lamp 1 - The calculated lightstate for the interval 16:26 - 18:00 is {ColorTemperature:6500 Brightness:96}"
time="2018/25/11 17:05:42" level=debug msg="💡 Light Hue color lamp 1 - Updated target state to {ColorTemperature:6500 Brightness:96}"
time="2018/25/11 17:06:42" level=debug msg="💡 Light Hue color lamp 1 - The calculated lightstate for the interval 16:26 - 18:00 is {ColorTemperature:6500 Brightness:96}"
time="2018/25/11 17:06:42" level=debug msg="💡 Light Hue color lamp 1 - Updated target state to {ColorTemperature:6500 Brightness:96}"
time="2018/25/11 17:07:42" level=debug msg="💡 Light Hue color lamp 1 - The calculated lightstate for the interval 16:26 - 18:00 is {ColorTemperature:6500 Brightness:96}"
time="2018/25/11 17:07:42" level=debug msg="💡 Light Hue color lamp 1 - Updated target state to {ColorTemperature:6500 Brightness:96}"
time="2018/25/11 17:08:42" level=debug msg="💡 Light Hue color lamp 1 - The calculated lightstate for the interval 16:26 - 18:00 is {ColorTemperature:6500 Brightness:96}"
time="2018/25/11 17:08:42" level=debug msg="💡 Light Hue color lamp 1 - Updated target state to {ColorTemperature:6500 Brightness:96}"
time="2018/25/11 17:09:43" level=debug msg="💡 Light Hue color lamp 1 - The calculated lightstate for the interval 16:26 - 18:00 is {ColorTemperature:6500 Brightness:96}"
time="2018/25/11 17:09:43" level=debug msg="💡 Light Hue color lamp 1 - Updated target state to {ColorTemperature:6500 Brightness:96}"
time="2018/25/11 17:10:42" level=debug msg="💡 Light Hue color lamp 1 - The calculated lightstate for the interval 16:26 - 18:00 is {ColorTemperature:6500 Brightness:96}"
time="2018/25/11 17:10:42" level=debug msg="💡 Light Hue color lamp 1 - Updated target state to {ColorTemperature:6500 Brightness:96}"
time="2018/25/11 17:11:42" level=debug msg="💡 Light Hue color lamp 1 - The calculated lightstate for the interval 16:26 - 18:00 is {ColorTemperature:6500 Brightness:96}"
time="2018/25/11 17:11:42" level=debug msg="💡 Light Hue color lamp 1 - Updated target state to {ColorTemperature:6500 Brightness:96}"
time="2018/25/11 17:12:43" level=debug msg="💡 Light Hue color lamp 1 - The calculated lightstate for the interval 16:26 - 18:00 is {ColorTemperature:6500 Brightness:96}"
time="2018/25/11 17:12:43" level=debug msg="💡 Light Hue color lamp 1 - Updated target state to {ColorTemperature:6500 Brightness:96}"
time="2018/25/11 17:13:42" level=debug msg="💡 Light Hue color lamp 1 - The calculated lightstate for the interval 16:26 - 18:00 is {ColorTemperature:6500 Brightness:95}"
time="2018/25/11 17:13:42" level=debug msg="💡 Light Hue color lamp 1 - Updated target state to {ColorTemperature:6500 Brightness:95}"
time="2018/25/11 17:14:42" level=debug msg="💡 Light Hue color lamp 1 - The calculated lightstate for the interval 16:26 - 18:00 is {ColorTemperature:6500 Brightness:95}"
time="2018/25/11 17:14:42" level=debug msg="💡 Light Hue color lamp 1 - Updated target state to {ColorTemperature:6500 Brightness:95}"
time="2018/25/11 17:15:42" level=debug msg="💡 Light Hue color lamp 1 - The calculated lightstate for the interval 16:26 - 18:00 is {ColorTemperature:6500 Brightness:95}"
time="2018/25/11 17:15:42" level=debug msg="💡 Light Hue color lamp 1 - Updated target state to {ColorTemperature:6500 Brightness:95}"
time="2018/25/11 17:16:42" level=debug msg="💡 Light Hue color lamp 1 - The calculated lightstate for the interval 16:26 - 18:00 is {ColorTemperature:6500 Brightness:95}"
time="2018/25/11 17:16:42" level=debug msg="💡 Light Hue color lamp 1 - Updated target state to {ColorTemperature:6500 Brightness:95}"
time="2018/25/11 17:17:42" level=debug msg="💡 Light Hue color lamp 1 - The calculated lightstate for the interval 16:26 - 18:00 is {ColorTemperature:6500 Brightness:95}"
time="2018/25/11 17:17:42" level=debug msg="💡 Light Hue color lamp 1 - Updated target state to {ColorTemperature:6500 Brightness:95}"
time="2018/25/11 17:18:42" level=debug msg="💡 Light Hue color lamp 1 - The calculated lightstate for the interval 16:26 - 18:00 is {ColorTemperature:6500 Brightness:95}"
time="2018/25/11 17:18:42" level=debug msg="💡 Light Hue color lamp 1 - Updated target state to {ColorTemperature:6500 Brightness:95}"
time="2018/25/11 17:19:42" level=debug msg="💡 Light Hue color lamp 1 - The calculated lightstate for the interval 16:26 - 18:00 is {ColorTemperature:6500 Brightness:95}"
time="2018/25/11 17:19:42" level=debug msg="💡 Light Hue color lamp 1 - Updated target state to {ColorTemperature:6500 Brightness:95}"
time="2018/25/11 17:20:42" level=debug msg="💡 Light Hue color lamp 1 - The calculated lightstate for the interval 16:26 - 18:00 is {ColorTemperature:6500 Brightness:95}"
time="2018/25/11 17:20:42" level=debug msg="💡 Light Hue color lamp 1 - Updated target state to {ColorTemperature:6500 Brightness:95}"
time="2018/25/11 17:21:42" level=debug msg="💡 Light Hue color lamp 1 - The calculated lightstate for the interval 16:26 - 18:00 is {ColorTemperature:6500 Brightness:95}"
time="2018/25/11 17:21:43" level=debug msg="💡 Light Hue color lamp 1 - Updated target state to {ColorTemperature:6500 Brightness:95}"
time="2018/25/11 17:22:42" level=debug msg="💡 Light Hue color lamp 1 - The calculated lightstate for the interval 16:26 - 18:00 is {ColorTemperature:6500 Brightness:94}"
time="2018/25/11 17:22:42" level=debug msg="💡 Light Hue color lamp 1 - Updated target state to {ColorTemperature:6500 Brightness:94}"
time="2018/25/11 17:22:43" level=debug msg="💡 HueLight Hue color lamp 1 - Setting light state to 6500K and 94% brightness."
time="2018/25/11 17:22:45" level=debug msg="💡 HueLight Hue color lamp 1 - Brightness has changed! Current light state: &{Name:Hue color lamp 1 HueLight:{Id:1 Name:Hue color lamp 1 Attributes:{State:{Hue:41460 On:true Effect:none Alert:none Bri:241 Sat:77 Ct:153 Xy:[0.3129 0.3289] Reachable:true ColorMode:xy} Type:Extended color light Name:Hue color lamp 1 ModelId:LCT015 UniqueId:00:17:88:01:03:7a:c0:ef-0b ManufacturerName:Philips ProductName:Hue color lamp SoftwareVersion:1.29.0_r21169} bridge:0x7440a8} SetColorTemperature:6500 SetBrightness:94 TargetColorTemperature:153 TargetColor:[0.313 0.329] TargetBrightness:238 CurrentColorTemperature:153 CurrentColor:[0.313 0.329] CurrentBrightness:241 CurrentColorMode:xy SupportsColorTemperature:true SupportsXYColor:true Dimmable:true Reachable:true On:true MinimumColorTemperature:2000}"
time="2018/25/11 17:22:45" level=warning msg="💡 HueLight Hue color lamp 1 - Failed to update light state: &{Name:Hue color lamp 1 HueLight:{Id:1 Name:Hue color lamp 1 Attributes:{State:{Hue:41460 On:true Effect:none Alert:none Bri:241 Sat:77 Ct:153 Xy:[0.3129 0.3289] Reachable:true ColorMode:xy} Type:Extended color light Name:Hue color lamp 1 ModelId:LCT015 UniqueId:00:17:88:01:03:7a:c0:ef-0b ManufacturerName:Philips ProductName:Hue color lamp SoftwareVersion:1.29.0_r21169} bridge:0x7440a8} SetColorTemperature:6500 SetBrightness:94 TargetColorTemperature:153 TargetColor:[0.313 0.329] TargetBrightness:238 CurrentColorTemperature:153 CurrentColor:[0.313 0.329] CurrentBrightness:241 CurrentColorMode:xy SupportsColorTemperature:true SupportsXYColor:true Dimmable:true Reachable:true On:true MinimumColorTemperature:2000}"
time="2018/25/11 17:22:45" level=info msg="💡 Light Hue color lamp 1 - Updated light state to 6500K at 94% brightness"
time="2018/25/11 17:22:45" level=debug msg="💡 HueLight Hue color lamp 1 - Brightness has changed! Current light state: &{Name:Hue color lamp 1 HueLight:{Id:1 Name:Hue color lamp 1 Attributes:{State:{Hue:41460 On:true Effect:none Alert:none Bri:241 Sat:77 Ct:153 Xy:[0.3129 0.3289] Reachable:true ColorMode:xy} Type:Extended color light Name:Hue color lamp 1 ModelId:LCT015 UniqueId:00:17:88:01:03:7a:c0:ef-0b ManufacturerName:Philips ProductName:Hue color lamp SoftwareVersion:1.29.0_r21169} bridge:0x7440a8} SetColorTemperature:6500 SetBrightness:94 TargetColorTemperature:153 TargetColor:[0.313 0.329] TargetBrightness:238 CurrentColorTemperature:153 CurrentColor:[0.313 0.329] CurrentBrightness:241 CurrentColorMode:xy SupportsColorTemperature:true SupportsXYColor:true Dimmable:true Reachable:true On:true MinimumColorTemperature:2000}"
time="2018/25/11 17:22:45" level=debug msg="💡 Light Hue color lamp 1 - Light state has been changed manually: {Name:Hue color lamp 1 HueLight:{Id:1 Name:Hue color lamp 1 Attributes:{State:{Hue:41460 On:true Effect:none Alert:none Bri:241 Sat:77 Ct:153 Xy:[0.3129 0.3289] Reachable:true ColorMode:xy} Type:Extended color light Name:Hue color lamp 1 ModelId:LCT015 UniqueId:00:17:88:01:03:7a:c0:ef-0b ManufacturerName:Philips ProductName:Hue color lamp SoftwareVersion:1.29.0_r21169} bridge:0x7440a8} SetColorTemperature:6500 SetBrightness:94 TargetColorTemperature:153 TargetColor:[0.313 0.329] TargetBrightness:238 CurrentColorTemperature:153 CurrentColor:[0.313 0.329] CurrentBrightness:241 CurrentColorMode:xy SupportsColorTemperature:true SupportsXYColor:true Dimmable:true Reachable:true On:true MinimumColorTemperature:2000}"
time="2018/25/11 17:22:53" level=info msg="💡 Light Hue color lamp 1 - Detected matching target state. Activating Kelvin..."
time="2018/25/11 17:22:53" level=debug msg="💡 HueLight Hue color lamp 1 - Setting light state to 6500K and 94% brightness."
time="2018/25/11 17:22:55" level=debug msg="💡 HueLight Hue color lamp 1 - Light was successfully updated."
It looks like the last successful update was:
time="2018/25/11 17:03:43" - Setting light state to 6500K and 96% brightness."
time="2018/25/11 17:03:45" - Light was successfully updated."
The light brightness was then updated to 95 and 94 before the next set was attempted 19 minutes later:
time="2018/25/11 17:22:43" - Setting light state to 6500K and 94% brightness."
Formatting the interesting bits of the changed message for readability:
SetColorTemperature:6500
SetBrightness:94
TargetColorTemperature:153
TargetColor:[0.313 0.329]
TargetBrightness:238 --- (Brightness 94%)
CurrentColorTemperature:153
CurrentColor:[0.313 0.329]
CurrentBrightness:241 --- (Brightness 95%)
CurrentColorMode:xy
The value diff is 3 but the threshold for equality here: https://github.com/stefanwichmann/kelvin/blob/712f49842b809908d16e66369a63aecfb954cb43/huelight.go#L205 is 2. I think a value of 3 would have prevented it in this case but I'm not sure if this is the actual fix or if the problem was the light not being updated for 19 minutes?
Hi Emily,
thanks for the detailed report. What you are seeing is the sad reality when working with the Hue lights API. Individual bulbs behave strange from time to time and have in inaccuracy of 3%...
Could you please make sure that the firmware of all lights and the bridge is up to date? You can check this inside the official hue app.
If this is the case our only possible fix is to increase the accuracy limit as you described from 2 to 3...
I have automatic updates on and I just confirmed everything is up-to-date (android app and API agree):
$ curl -s http://$ip/api/$username/lights/ 2>&1 | json_reformat | grep -A 3 swupdate
"swupdate": {
"state": "noupdates",
"lastinstall": "2018-11-06T00:27:14"
},
--
"swupdate": {
"state": "noupdates",
"lastinstall": "2018-11-06T00:27:09"
},
--
"swupdate": {
"state": "noupdates",
"lastinstall": "2018-11-06T00:27:17"
},
--
"swupdate": {
"state": "noupdates",
"lastinstall": "2018-11-07T22:00:30"
},
--
"swupdate": {
"state": "noupdates",
"lastinstall": "2018-11-10T04:24:44"
},
That sounds a bit odd to me... How do you mean inaccurate? Like it doesn't take a write? Or it forgets a write after some time? Or it just writes the wrong data?
Are we sure 3 will be the right value? Right now I'm basing this of a sample size of one...
I will setup a logging script on my desktop to periodically (0.5s) scrape and record the light state over the bridge API and see if I can get more detailed insight on what transitions the light makes when this occurs.
The closest is: "It forgets the write after some time". But this is really not reliable. Sometimes the values match perfectly, sometimes they deviate after some time, sometimes imitatively...
The magic value "3" has been there from the beginning of Kelvin (see https://github.com/stefanwichmann/kelvin/commit/5ce86f30d2e36cc4d3093cd2b1e84f4a0faf6da0#diff-034d51f7c28f2cfd686dbd3fb8375706R41 from the initial import). After Philips updated the bulb firmware it got much better and I switched to "2"... This worked for a long time... until you reported this error. :-)
I am really hesitating to move back to "3" because it will make the scene detection fuzzy... but this (at least to my knowledge) is the only compromise we could make...
Any ideas are welcome.
Another data point:
Color has changed!
TargetColorTemperature:326
TargetColor:[0.432 0.405]
TargetBrightness:132
CurrentColorTemperature:322
CurrentColor:[0.431 0.405]
CurrentBrightness:133
CurrentColorMode:xy
SupportsColorTemperature:true
SupportsXYColor:true
Dimmable:true
Reachable:true
On:true
MinimumColorTemperature:2000
Suggesting a threshold of 4 for colorTemperature here: https://github.com/stefanwichmann/kelvin/blob/e7c23ff7d07c4e09a5fabcb57162bc8ea9de401a/huelight.go#L199
And a bump of the threshold for XY comparison.
I know the light is in XY mode but the temperature values are written and read too AFAICT.
Massive data dump incoming!
Kelvin logs (edited for clarity) timestamps approx +2 seconds ahead of my logs below:
21:15:07.122394 Setting light state to 2842K and 50% brightness."
21:15:08.975045 Light was successfully updated."
21:15:08.980005 Updated light state to 2842K at 50% brightness"
21:17:07.200366 Setting light state to 2805K and 49% brightness."
21:17:09.026871 Light was successfully updated."
21:17:09.026871 Updated light state to 2805K at 49% brightness"
21:18:07.087774 Setting light state to 2786K and 49% brightness."
21:18:08.601337 Light was successfully updated."
21:18:08.608227 Updated light state to 2786K at 49% brightness"
21:20:07.126406 Setting light state to 2749K and 49% brightness."
21:20:08.717354 Color has changed! Current light state: &{Name:Hue color lamp 2 HueLight:{Id:2 Name:Hue color lamp 2 Attributes:{State:{Hue:8473 On:true Effect:none Alert:none Bri:124 Sat:135 Ct:359 Xy:[0.454 0.4093] Reachable:true ColorMode:xy} Type:Extended color light Name:Hue color lamp 2 ModelId:LCT015 UniqueId:00:17:88:01:03:7b:5d:aa-0b ManufacturerName:Philips ProductName:Hue color lamp SoftwareVersion:1.29.0_r21169} bridge:0x7540f8} SetColorTemperature:2749 SetBrightness:49 TargetColorTemperature:363 TargetColor:[0.456 0.41] TargetBrightness:124 CurrentColorTemperature:359 CurrentColor:[0.454 0.409] CurrentBrightness:124 CurrentColorMode:xy SupportsColorTemperature:true SupportsXYColor:true Dimmable:true Reachable:true On:true MinimumColorTemperature:2000}"
21:20:08.717354 Failed to update light state: &{Name:Hue color lamp 2 HueLight:{Id:2 Name:Hue color lamp 2 Attributes:{State:{Hue:8473 On:true Effect:none Alert:none Bri:124 Sat:135 Ct:359 Xy:[0.454 0.4093] Reachable:true ColorMode:xy} Type:Extended color light Name:Hue color lamp 2 ModelId:LCT015 UniqueId:00:17:88:01:03:7b:5d:aa-0b ManufacturerName:Philips ProductName:Hue color lamp SoftwareVersion:1.29.0_r21169} bridge:0x7540f8} SetColorTemperature:2749 SetBrightness:49 TargetColorTemperature:363 TargetColor:[0.456 0.41] TargetBrightness:124 CurrentColorTemperature:359 CurrentColor:[0.454 0.409] CurrentBrightness:124 CurrentColorMode:xy SupportsColorTemperature:true SupportsXYColor:true Dimmable:true Reachable:true On:true MinimumColorTemperature:2000}"
21:20:08.717354 Updated light state to 2749K at 49% brightness"
21:20:09.087332 Color has changed! Current light state: &{Name:Hue color lamp 2 HueLight:{Id:2 Name:Hue color lamp 2 Attributes:{State:{Hue:8473 On:true Effect:none Alert:none Bri:124 Sat:135 Ct:359 Xy:[0.454 0.4093] Reachable:true ColorMode:xy} Type:Extended color light Name:Hue color lamp 2 ModelId:LCT015 UniqueId:00:17:88:01:03:7b:5d:aa-0b ManufacturerName:Philips ProductName:Hue color lamp SoftwareVersion:1.29.0_r21169} bridge:0x7540f8} SetColorTemperature:2749 SetBrightness:49 TargetColorTemperature:363 TargetColor:[0.456 0.41] TargetBrightness:124 CurrentColorTemperature:359 CurrentColor:[0.454 0.409] CurrentBrightness:124 CurrentColorMode:xy SupportsColorTemperature:true SupportsXYColor:true Dimmable:true Reachable:true On:true MinimumColorTemperature:2000}"
21:20:09.091680 Light state has been changed manually: {Name:Hue color lamp 2 HueLight:{Id:2 Name:Hue color lamp 2 Attributes:{State:{Hue:8473 On:true Effect:none Alert:none Bri:124 Sat:135 Ct:359 Xy:[0.454 0.4093] Reachable:true ColorMode:xy} Type:Extended color light Name:Hue color lamp 2 ModelId:LCT015 UniqueId:00:17:88:01:03:7b:5d:aa-0b ManufacturerName:Philips ProductName:Hue color lamp SoftwareVersion:1.29.0_r21169} bridge:0x7540f8} SetColorTemperature:2749 SetBrightness:49 TargetColorTemperature:363 TargetColor:[0.456 0.41] TargetBrightness:124 CurrentColorTemperature:359 CurrentColor:[0.454 0.409] CurrentBrightness:124 CurrentColorMode:xy SupportsColorTemperature:true SupportsXYColor:true Dimmable:true Reachable:true On:true MinimumColorTemperature:2000}"
21:20:15.124062 Detected matching target state. Activating Kelvin..."
21:20:15.127839 Setting light state to 2749K and 49% brightness."
21:20:16.449304 Light was successfully updated."
21:22:07.202238 Setting light state to 2711K and 48% brightness."
21:22:09.011302 Light was successfully updated."
21:22:09.015609 Updated light state to 2711K at 48% brightness"
21:23:07.128165 Setting light state to 2692K and 48% brightness."
21:23:08.979630 Light was successfully updated."
21:23:08.979630 Updated light state to 2692K at 48% brightness"
21:24:07.102142 Setting light state to 2674K and 48% brightness."
21:24:08.580704 Light was successfully updated."
21:24:08.586940 Updated light state to 2674K at 48% brightness"
Unique state transitions from Hue bridge (21:13:24 start of log, not an actual transition)
"21:13:24,331884740+01:00":{"bri":127,"hue":8662,"sat":124,"xy":[0.4461,0.4081],"ct":347},
"21:15:05,833237382+01:00":{"bri":127,"hue":8662,"sat":124,"xy":[0.4461,0.4081],"ct":347},
"21:15:06,583834737+01:00":{"bri":127,"hue":8662,"sat":124,"xy":[0.449,0.409],"ct":351},
"21:15:11,411455297+01:00":{"bri":127,"hue":8662,"sat":124,"xy":[0.449,0.409],"ct":351},
"21:15:11,930179921+01:00":{"bri":127,"hue":8629,"sat":129,"xy":[0.4491,0.409],"ct":350},
"21:17:05,698362819+01:00":{"bri":127,"hue":8629,"sat":129,"xy":[0.4491,0.409],"ct":350},
"21:17:06,298922512+01:00":{"bri":124,"hue":8629,"sat":129,"xy":[0.451,0.409],"ct":356},
"21:17:08,031122106+01:00":{"bri":124,"hue":8629,"sat":129,"xy":[0.451,0.409],"ct":356},
"21:17:08,550508147+01:00":{"bri":124,"hue":8556,"sat":131,"xy":[0.4509,0.409],"ct":353},
"21:18:05,438338037+01:00":{"bri":124,"hue":8556,"sat":131,"xy":[0.4509,0.409],"ct":353},
"21:18:06,106780348+01:00":{"bri":124,"hue":8556,"sat":131,"xy":[0.453,0.409],"ct":358},
"21:18:08,873234531+01:00":{"bri":124,"hue":8556,"sat":131,"xy":[0.453,0.409],"ct":358},
"21:18:09,391571484+01:00":{"bri":124,"hue":8485,"sat":133,"xy":[0.4528,0.4089],"ct":356},
"21:20:05,428284044+01:00":{"bri":124,"hue":8485,"sat":133,"xy":[0.4528,0.4089],"ct":356},
"21:20:06,103955353+01:00":{"bri":124,"hue":8485,"sat":133,"xy":[0.456,0.41],"ct":363},
"21:20:06,633557702+01:00":{"bri":124,"hue":8485,"sat":133,"xy":[0.456,0.41],"ct":363},
"21:20:07,177219028+01:00":{"bri":124,"hue":8473,"sat":135,"xy":[0.454,0.4093],"ct":359},
"21:20:13,174561548+01:00":{"bri":124,"hue":8473,"sat":135,"xy":[0.454,0.4093],"ct":359},
"21:20:13,696369725+01:00":{"bri":124,"hue":8459,"sat":138,"xy":[0.4558,0.4099],"ct":362},
"21:20:14,223848779+01:00":{"bri":124,"hue":8459,"sat":138,"xy":[0.456,0.41],"ct":363},
"21:20:20,104759143+01:00":{"bri":124,"hue":8459,"sat":138,"xy":[0.456,0.41],"ct":363},
"21:20:20,623429760+01:00":{"bri":124,"hue":8459,"sat":138,"xy":[0.4558,0.4099],"ct":362},
"21:22:05,887230807+01:00":{"bri":124,"hue":8459,"sat":138,"xy":[0.4558,0.4099],"ct":362},
"21:22:06,411876660+01:00":{"bri":121,"hue":8459,"sat":138,"xy":[0.459,0.41],"ct":368},
"21:22:09,254586104+01:00":{"bri":121,"hue":8459,"sat":138,"xy":[0.459,0.41],"ct":368},
"21:22:09,773379461+01:00":{"bri":121,"hue":8362,"sat":142,"xy":[0.4591,0.41],"ct":369},
"21:23:05,920621130+01:00":{"bri":121,"hue":8362,"sat":142,"xy":[0.4591,0.41],"ct":369},
"21:23:06,637622321+01:00":{"bri":121,"hue":8362,"sat":142,"xy":[0.461,0.41],"ct":371},
"21:23:08,368710775+01:00":{"bri":121,"hue":8362,"sat":142,"xy":[0.461,0.41],"ct":371},
"21:23:08,885123905+01:00":{"bri":121,"hue":8300,"sat":144,"xy":[0.4609,0.4099],"ct":369},
"21:24:05,645336192+01:00":{"bri":121,"hue":8300,"sat":144,"xy":[0.4609,0.4099],"ct":369},
Eyeballing the logs I see no spurious changes between writes. But I do see some changes shortly following a write.
These two timestamps are interesting:
21:20:08.717354 Updated light state to 2749K at 49% brightness"
21:20:09.087332 Color has changed!
I will attempt to intersperse my logs with kelvin around this time after adjusting kelvin times -2 s to align the time lines:
21:20:03,848763446+01:00":{"bri":124,"hue":8485,"sat":133,"xy":[0.4528,0.4089],"ct":356},
21:20:05.126406 Setting light state to 2749K and 49% brightness."
21:20:05,428284044+01:00":{"bri":124,"hue":8485,"sat":133,"xy":[0.4528,0.4089],"ct":356},
21:20:06,103955353+01:00":{"bri":124,"hue":8485,"sat":133,"xy":[0.456,0.41],"ct":363}, // 2749K (2754.8)
21:20:06,633557702+01:00":{"bri":124,"hue":8485,"sat":133,"xy":[0.456,0.41],"ct":363},
21:20:06.717354 Color has changed! ...
21:20:06.717354 Failed to update light state: ...
21:20:07.087332 Color has changed! ...
21:20:07.091680 Light state has been changed manually: ...
21:20:07,177219028+01:00":{"bri":124,"hue":8473,"sat":135,"xy":[0.454,0.4093],"ct":359}, // (2785.5)
21:20:13.124062 Detected matching target state. Activating Kelvin..."
21:20:13.127839 Setting light state to 2749K and 49% brightness."
21:20:13,174561548+01:00":{"bri":124,"hue":8473,"sat":135,"xy":[0.454,0.4093],"ct":359},
21:20:13,696369725+01:00":{"bri":124,"hue":8459,"sat":138,"xy":[0.4558,0.4099],"ct":362},
21:20:14,223848779+01:00":{"bri":124,"hue":8459,"sat":138,"xy":[0.456,0.41],"ct":363},
21:20:14.449304 Light was successfully updated."
21:20:20,104759143+01:00":{"bri":124,"hue":8459,"sat":138,"xy":[0.456,0.41],"ct":363},
21:20:20,623429760+01:00":{"bri":124,"hue":8459,"sat":138,"xy":[0.4558,0.4099],"ct":362},
Not sure what to make of that due to the low sampling rate of 0.5s on my logs.
Lets look at three successive successful updates (again adjusting timestamps to align and interspersing):
21:15:04,782555188+01:00":{"bri":127,"hue":8662,"sat":124,"xy":[0.4461,0.4081],"ct":347},
21:15:05.122394 Setting light state to 2842K and 50% brightness."
21:15:05,833237382+01:00":{"bri":127,"hue":8662,"sat":124,"xy":[0.4461,0.4081],"ct":347},
21:15:06,583834737+01:00":{"bri":127,"hue":8662,"sat":124,"xy":[0.449,0.409],"ct":351},
21:15:06.975045 Light was successfully updated."
21:15:11,411455297+01:00":{"bri":127,"hue":8662,"sat":124,"xy":[0.449,0.409],"ct":351},
21:15:11,930179921+01:00":{"bri":127,"hue":8629,"sat":129,"xy":[0.4491,0.409],"ct":350},
21:17:05.200366 Setting light state to 2805K and 49% brightness."
21:17:05,698362819+01:00":{"bri":127,"hue":8629,"sat":129,"xy":[0.4491,0.409],"ct":350},
21:17:06,298922512+01:00":{"bri":124,"hue":8629,"sat":129,"xy":[0.451,0.409],"ct":356},
21:17:07.026871 Light was successfully updated."
21:17:08,031122106+01:00":{"bri":124,"hue":8629,"sat":129,"xy":[0.451,0.409],"ct":356},
21:17:08,550508147+01:00":{"bri":124,"hue":8556,"sat":131,"xy":[0.4509,0.409],"ct":353},
21:18:05.087774 Setting light state to 2786K and 49% brightness."
21:18:05,438338037+01:00":{"bri":124,"hue":8556,"sat":131,"xy":[0.4509,0.409],"ct":353},
21:18:06,106780348+01:00":{"bri":124,"hue":8556,"sat":131,"xy":[0.453,0.409],"ct":358},
21:18:06.601337 Light was successfully updated."
21:18:08,873234531+01:00":{"bri":124,"hue":8556,"sat":131,"xy":[0.453,0.409],"ct":358},
21:18:09,391571484+01:00":{"bri":124,"hue":8485,"sat":133,"xy":[0.4528,0.4089],"ct":356},
Looking at the above it seems as if hue first takes the write into it's own cache and when queried it returns the written value until it communicates it to the bulb and gets it's opinion back of what it has actually stored. The bulb probably doesn't support so many levels of colour/ct as the API can specify so it truncates the value to what is actually on the light. There is probably a non-linearity here because this seems to trigger the manually changed threshold more frequently in the low CTs (seems like every evening). That's is my theory for what is going on.
This procedure seems to take between 1-8 seconds from my limited data set. Based on the variance I don't think this is intentional but probably a function of how many lights there are and how busy the hub is or maybe even just the lights being lazy.
Based on the variance and my observations above I think that the sleep here is probably causing the following check to read 50-50 the cached value or the truncated "true" value. https://github.com/stefanwichmann/kelvin/blob/e7c23ff7d07c4e09a5fabcb57162bc8ea9de401a/huelight.go#L177
How do you feel about after writing a light, wait for say 10-ish seconds and then read back the light state and if the read value is a plausible truncation of the set value, just update the target value for the purpose of detecting a manual change? The manual change detection at that point wouldn't need thresholds as they moved to the "plausible truncation" logic.
I guess one could try all possible CT values with a script and see what they truncate to to determine what is plausible and also confirm this theory.
Sorry if this is a bit rambly, I'm writing as I go.
Side note: Why does kelvin use xy mode when only ct is supported by kelvin?
I have been testing Kelvin for a while and sadly have the same issues. I tried configuring Kelvin to change only the color temperature, but that doesn't help. All the lights still lose sync at some point of the transition, seemingly at random but pretty much guaranteed.
If it is of any help, I'm fairly certain that my bulbs are 4th gen bulbs (white bottom).
Looking at the above it seems as if hue first takes the write into it's own cache and when queried it returns the written value until it communicates it to the bulb and gets it's opinion back of what it has actually stored.…
Based on the variance and my observations above I think that the sleep here is probably causing the following check to read 50-50 the cached value or the truncated "true" value.
https://github.com/stefanwichmann/kelvin/blob/e7c23ff7d07c4e09a5fabcb57162bc8ea9de401a/huelight.go#L177
How do you feel about after writing a light, wait for say 10-ish seconds and then read back the light state and if the read value is a plausible truncation of the set value, just update the target value for the purpose of detecting a manual change?…
I started work inspired by @EmilyBjoerk’s proposal here: https://github.com/smockle/kelvin/commit/e8cacb3b170a0c59ecb68c7b4b42420213da3c18.
When writing a new state, I store an UpdatedAt timestamp. In the looping update function, if fewer than 10 seconds have passed since the UpdatedAt timestamp, I exit early without checking for changes.
If more than 10 seconds have elapsed, the pre-existing hasChanged check is invoked. My hope is that this will delay the check until the real value (vs a cached value) is available.
I haven’t attempted to list or check “plausible truncations” yet. Also, while I did build successfully (with script/dist.sh), ~I haven’t tested this yet~. It is my first-ever Go code, so there are likely issues. 😬
Update 1
I tested my code, and I still see spurious occurrences of 💡 Light <Lamp_Name> - Light state has been changed manually. Disabling Kelvin... when I run sudo journalctl -fu kelvin.
Update 2
I added additional logging to hasColorTemperature and hasChanged and observed a mismatch between light.CurrentColorTemperature (454) and light.TargetColorTemperature (500).
NB: mapColorTemperature(2200) is 454 and mapColorTemperature(2000) is 500.
The light output of Hue White Ambiance Bulbs is 2200K–6500K (see ”Technical Specifications”).
I wonder whether setting a target temperature (2000K) below the stated lower limit (2200K) is what is causing Kelvin to log 💡 Light <Lamp_Name> - Light state has been changed manually. Disabling Kelvin... in my case…
I'm not yet convinced that the culprit is that the bulbs don't support all ct-levels. That would imply that identical bulbs would drop out at the same time, but that's not the case.
I have been playing with the light update interval setting and brightness and color difference threshold values a little during the weekend. It seems no matter what lightUpdateIntervalInSeconds I choose, it takes one cycle for the light to report the correct state. Even 30 seconds isn't enough.
With 15 sec interval:
21:02:56 Updated light state to 2635K at 70% brightness
21:03:10 Color temperature has changed! TargetColorTemperature:379 TargetBrightness:177 CurrentColorTemperature:373 CurrentBrightness:175
21:03:25 Detected matching target state TargetColorTemperature:379 TargetBrightness:177 CurrentColorTemperature:379 CurrentBrightness:177
With 30 sec interval:
21:41:32 Updated light state to 2411K at 27% brightness
21:41:59 Color temperature has changed! TargetColorTemperature:414 TargetBrightness:68 CurrentColorTemperature:408 CurrentBrightness:73
21:42:30 Detected matching target state TargetColorTemperature:414 TargetBrightness:68 CurrentColorTemperature:414 CurrentBrightness:68
Also, scene updates fill the log with "invalid character '<' looking for beginning of value", net/http: request canceled (Client.Timeout exceeded while awaiting headers)" and EOF warnings. I'm not sure if that is expected. Maybe there is some kind of rate limiting going on?
I will be traveling over the holidays but when I come back in January I intend to make a script that run through all CT values writes them to a colour/ambience light respectively and then reads the value back 20 s later. By plotting written to read values I expect this to be able to prove/disprove the truncation hypothesis by the shape of the read curve.
Also I should have better mean/stdev/min/max values for the delay if my theory holds.
Hi Emily,
I am really interested in your results of this. I observed many different behaviours over the years. With the recent firmware version the precision got a little better but is still far from perfect.
I have just started the experiment. Expected runtime 5h ish.
Actual script that I'm running:
#!/usr/bin/env bash
ip="your ip here"
key="your api key here"
api_uri="http://$ip/api/$key"
light_uri=$api_uri/lights/4
#curl -s $light_uri 2>&1 | jq .state.ct
#curl -H "Accept: application/json" -X PUT --data '{"ct":300, "on":true}' $light_uri/state | jq
function read_ct(){
curl -s $light_uri 2>&1 | jq .state.ct
}
function timestamp(){
date -u +%s%N
}
ct_min=153;
ct_max=454;
#ct_max=154; # Uncomment for short test
output_csv=output.csv
echo "unix time ns, written, read"
for expected in $(seq $ct_max -1 $ct_min); do
# Set and print output
curl -s -H "Accept: application/json" -X PUT --data "{\"ct\":$expected}" $light_uri/state 2>&1 > /dev/null
# Assume it took to write immediately and output row
curr_time=$(timestamp)
echo $curr_time, $expected, $expected, 2
# Wait until output changes or we time out (write was correctl stored)
actual=$expected
ticks_passed=0
until [ "$expected" != "$actual" ] || [ $ticks_passed -eq 120 ]; do
actual=$(read_ct)
prev_time=$curr_time
curr_time=$(timestamp)
ticks_passed=$((ticks_passed+1))
sleep 0.5
done
echo $prev_time, $expected, $expected, 0
if [ "$expected" != "$actual" ]; then
echo $curr_time, $expected, $actual, 1
fi
done
Run like so:
sh lighttest.sh | tee >(bzip2 --stdout > lightlog.bz2)
Will output progress to stdout and a bzipped log.
Output for ambience light: https://drive.google.com/open?id=1xawuyfmxlwwUIIlOQyGalM7wK29Ft4de Output for color light: https://drive.google.com/open?id=1A-XO0h4tO4qQ1IQEtLf8TDHkxy-9OBaL
There didn't seem to be much there, the lights seemed to operate as intended with the occasional off-by-one. Kelvin was not running during the experiments. My script waits until they differ once and then moves on which might be a thing so I'm going to just make it measure the full period and not move on when it finds a diff. I will also try different polling rates.
I'll hold of on making plots and further analysis until I have more data.
It seems that this had not occurred for me on the last weeks which agrees with my experiment not showing anything interesting
I've had a few days to play with this again. The first unexpected improvement actually came from moving from an old raspberry to a new 3 b+ and docker. Don't know why but it made things a lot more stable and reduced the errors. Anyway, first I added more logging and extra steps to the light update function. I modified the script so that after every light update it polls the light state again, compares it against the target and tries to update the light state again if there is a difference. After the second update, there is never any difference. Therefore I'm fairly sure the lights are capable of every state. Next, I added some basic rate limiting to light state and scene updates. The modified script updates one scene per second and after that starts updating the light states two lights per second. This improved things dramatically. Suddenly the set light states are a lot more accurate (usually 100%) and I no longer get the "invalid character '<' looking for beginning of value" warnings or other errors. I'm still experimenting with reducing light polling rate (I'm using the hue switches), effect on transition time etc to see if a can get rid of the last inaccuracies. The hue design guidance states "As a general guideline we always recommend to our developers to stay at roughly 10 commands per second to the /lights resource with a 100ms gap between each API call. For /groups commands you should keep to a maximum of 1 per second." I have 20+ hue lights so I guess the script was exceeding the bridge performance limits.
Hi probus, that is a really interesting observation and might be the reason for the observed problems. Currently each light is managed by Kelvin in it's own thread. This encapsulates the functionality beautifully but might lead to many requests to the bridge in a short interval (as the threads don't synchronize anywhere). If you now have a lot of lights this might add to the problem...
I am currently working on a fix that will make Kelvin single threaded and therefore be much more predictable in what requests are made towards the bridge. This should not only help if you have many lights but also reduce the overall requests a lot! I hope to find the needed time for testing over the weekend...
Anyway: Thanks for the detailed analysis and the digging! Very much appreciated! 👍
The behaviour is back for me again.
I'm starting to suspect it might have to do with how long Kelvin had been running? Add that seems to be the one thing connecting the troubles I've had.
@EmilyBjoerk What happens if you restart Kelvin? @stefanwichmann sounds good! Let me know if I can help test things. I haven't been able to get rid of the errors completely, but my system is stable and completely usable now. Pretty much the only new thing I have learned is that long transition times result in errors more often but not larger in value. One idea I had was that we could try to use ct inc and bri inc commands in case there is a difference in performance. To reduce the number of api calls even further maybe Kelvin could calculate the transition until the next timestamp instead of constantly updating the state?
To reduce the number of api calls even further maybe Kelvin could calculate the transition until the next timestamp instead of constantly updating the state?
This would mean lights would not set the right temperature/brightness if powered on mid-transition, no?
@probus I only have anecdotal evidence but it feels like after restarting the lights do not desync for a while.
I think adding rate limiting to the API sounds like a sane solution if too many queries in a short window is indeed the cause. Thought technically any quota management or rate limiting should be applied server side (hue hub) in a sanely designed system :roll_eyes:
I think that Kelvin queries each light individually for it's status right? If that's the case then one could reduce the number of API calls from O(num_lights) to O(1) by querying the /lights endpoint to get data for all lights at once for the purpose detecting light power-on or scene change. And then as @probus said only write the light value when it is expected to change or on power on. This should also make it consume less CPU (less json to parse, less network requests) and allow to increase the poll rate to quicker detect power on events.
Although from what I have seen this runs counter to the current modular, per light design of kelvin.
This would mean lights would not set the right temperature/brightness if powered on mid-transition, no?
You can continue polling the light state, just handle the transitions with one long transition instead of multiple 1 second transitions
I think adding rate limiting to the API sounds like a sane solution if too many queries in a short window is indeed the cause. Thought technically any quota management or rate limiting should be applied server side (hue hub) in a sanely designed system 🙄
According to the api documentation the bridge will first buffer the commands. This increases the latency even up to several seconds. When the buffer is full, the bridge will start dropping commands and returning error 503.
Just to be clear, I don't expect this to make Kelvin 100% accurate. It's only one source of error. But it should be (I'm guessing) fairly easy to reduce the number of api calls and control the rate. When using hue switches (enableWhenLightsAppear=false) even more so since the light state doesn't need to be polled that often.
That said, I don't see a big problem in increasing the tolerance for inaccuracies. The differences are undetectable to my eye.
@probus I think the problem with increasing the tolerance is that it makes detection of manual scene changes more "fuzzy" and tweaking tolerances such as this where it isn't well understood what the tolerance should be is a slippery slope to unending tweaking. But I do agree, it wouldn't be detectable by the eye.
To be fair, I never use manual scene changes and I want a static year around schedule so all I really need is a bash script that curls the api to set the lights once per second from a cron job ¯_(ツ)_/¯
I finally found the time to work on this and just pushed a big bunch of code. From now on Kelvin will only use on thread and query the bridge much less. This should mitigate a lot of the observed problems.
The changes still need some testing and I am running them know at home. Feel free to give them a try and report any problems!
Kelvin 1.2.0 is out and should greatly improve the reliability after switching to a single thread architecture. Give it a spin...
Great job! I've been running the single thread versions since the beginning and especially after the latest changes Kelvin has worked flawlessly. I haven't even increased the tolerances at all.
I have still observed desyncing, although it is much better with the patch.
During regular maintenance of my RPi I decided to check netstat and found something interesting:
$ netstat -p inet
(Not all processes could be identified, non-owned process info
will not be shown, you would have to be root to see it all.)
Active Internet connections (w/o servers)
Proto Recv-Q Send-Q Local Address Foreign Address State PID/Program name
tcp 0 0 raspberrypi.fritz:53824 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53834 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53806 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53802 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53792 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53820 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53810 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53770 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53852 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53788 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53796 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53822 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53816 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53776 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53826 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53848 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53772 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53766 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53814 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53786 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53832 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53830 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53812 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53774 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53842 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53778 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53828 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53850 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53854 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53798 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53818 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53800 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53856 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53790 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53784 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53836 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53840 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53764 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53846 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53768 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53794 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53808 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53838 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53844 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53780 Philips-hue.fritz:https TIME_WAIT -
tcp 0 0 raspberrypi.fritz:53804 Philips-hue.fritz:https TIME_WAIT -
$ man netstat
TIME_WAIT
The socket is waiting after close to handle packets still in the network.
By using:
$ watch -n1 -d netstat -A inet
I could determine that Kelvin still seems to be creating a high number of TCP connections (10-15 per second for 5 lights). And some of these connections seem to not clean up for a long time.
Hey Emily,
thanks for sharing this observation! I allowed my to analyze and discover a bug in the Go library I use in Kelvin (https://github.com/stefanwichmann/go.hue).
This bug seems to have been there from the beginning and nobody noticed until now. It prevented the reuse of HTTP connections, resulting in a new socket for every single request. This is not only inefficient but also puts a heavy load on the bridge (especially when using HTTPS).
I fixed the bug in the underlying library and committed the change. My initial tests confirm that now only a single connection to the bridge is used. Will give it some more testing and then release a fixed version.
I'm really curios if this will improve the reliability...
Just released Kelvin 1.3.1
It contains the mentioned fix in go.hue and should now be able to reuse the existing TCP connection to the bridge instead of establishing a new one for every request.