I have a setup with a hue bridge, 3 hue lights (colour + temperature capable) and 2 am

Spurious "manual change",about stefanwichmann/kelvin

Comments (48)

probus commented on June 26, 2024 1

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.

from kelvin.

LiSongMWO commented on June 26, 2024 1

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.

from kelvin.

stefanwichmann commented on June 26, 2024 1

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!

from kelvin.

LiSongMWO commented on June 26, 2024 1

I've updated I'll let it run for some weeks and get back to you.

from kelvin.

probus commented on June 26, 2024 1

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.

from kelvin.

LiSongMWO commented on June 26, 2024 1

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.

from kelvin.

LiSongMWO commented on June 26, 2024 1

I just updated to 1.3.1.

The CPU usage of Kelvin on my RPi Zero is now down to ~1% from the previous 6% (originally 20% before the previous patch). This alone is a nice improvement. My "gut feeling" in #45 that 20% was way too high was right :D. Thanks for the hard work here!

I can also confirm that Kelvin is now only creating one socket connection to the bridge so the patch seems to be WAI on that front.

I will let it run for a few weeks again and report back.

from kelvin.

stefanwichmann commented on June 26, 2024

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...

from kelvin.

LiSongMWO commented on June 26, 2024

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.

from kelvin.

stefanwichmann commented on June 26, 2024

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 5ce86f3#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.

from kelvin.

LiSongMWO commented on June 26, 2024

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:

kelvin/huelight.go

Line 199 in e7c23ff

 if light.TargetColorTemperature != -1 && !equalsInt(light.TargetColorTemperature, light.CurrentColorTemperature, 2) { 

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.

from kelvin.

LiSongMWO commented on June 26, 2024

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.

kelvin/huelight.go

Line 177 in e7c23ff

time.Sleep(lightTransitionIntervalInSeconds + 1*time.Second)

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?

from kelvin.

LiSongMWO commented on June 26, 2024

If it is of any help, I'm fairly certain that my bulbs are 4th gen bulbs (white bottom).

from kelvin.

smockle commented on June 26, 2024

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.

kelvin/huelight.go

Line 177 in e7c23ff

time.Sleep(lightTransitionIntervalInSeconds + 1*time.Second)

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…

from kelvin.

probus commented on June 26, 2024

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?

from kelvin.

LiSongMWO commented on June 26, 2024

Also I should have better mean/stdev/min/max values for the delay if my theory holds.

from kelvin.

stefanwichmann commented on June 26, 2024

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.

from kelvin.

LiSongMWO commented on June 26, 2024

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.

from kelvin.

LiSongMWO commented on June 26, 2024

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.

from kelvin.

LiSongMWO commented on June 26, 2024

It seems that this had not occurred for me on the last weeks which agrees with my experiment not showing anything interesting

from kelvin.

probus commented on June 26, 2024

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.

from kelvin.

stefanwichmann commented on June 26, 2024

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! 👍

from kelvin.

LiSongMWO commented on June 26, 2024

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.

from kelvin.

probus commented on June 26, 2024

@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?

from kelvin.

clemenules commented on June 26, 2024

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?

from kelvin.

LiSongMWO commented on June 26, 2024

@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 🙄

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.

from kelvin.

probus commented on June 26, 2024

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.

from kelvin.

LiSongMWO commented on June 26, 2024

@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 ¯_(ツ)_/¯

from kelvin.

stefanwichmann commented on June 26, 2024

Kelvin 1.2.0 is out and should greatly improve the reliability after switching to a single thread architecture. Give it a spin...

from kelvin.

stefanwichmann commented on June 26, 2024

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...

from kelvin.

stefanwichmann commented on June 26, 2024

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.

from kelvin.

probus commented on June 26, 2024

I updated to the new patch a couple of days ago and I haven't observed any change. A few bulbs still desync in every transition.

from kelvin.

stefanwichmann commented on June 26, 2024

@probus Could you paste a debug log extract of the bulbs that still desync? I added a lot of additional information to the log. Maybe that helps to track down the issue! Thanks!

from kelvin.

LiSongMWO commented on June 26, 2024

I have still seen some occasional "manual change", here is an excerpt from the logs:

$ journalctl -fu kelvin -n 10000 | grep -B4 -i manual
----- snipp -----
--
Apr 29 20:59:35 raspberrypi kelvin[31231]: time="2019/29/04 20:59:35" level=info msg="💡 Light Hue ambiance lamp 2 - Light is no longer reachable. Clearing state..."
Apr 29 20:59:52 raspberrypi kelvin[31231]: time="2019/29/04 20:59:52" level=info msg="💡 Light Hue color lamp 1 - Updated light state to 3940K at 66% brightness"
Apr 29 20:59:52 raspberrypi kelvin[31231]: time="2019/29/04 20:59:52" level=info msg="💡 Light Hue color lamp 2 - Updated light state to 3940K at 66% brightness"
Apr 29 20:59:53 raspberrypi kelvin[31231]: time="2019/29/04 20:59:53" level=info msg="💡 Light Hue ambiance lamp 1 - Updated light state to 3940K at 66% brightness"
Apr 29 21:00:03 raspberrypi kelvin[31231]: time="2019/29/04 21:00:03" level=info msg="💡 Light Hue color lamp 1 - Light state has been changed manually. Disabling Kelvin..."
--
Apr 29 22:48:48 raspberrypi kelvin[31231]: time="2019/29/04 22:48:48" level=info msg="💡 Light Hue ambiance lamp 2 - Light is no longer reachable. Clearing state..."
Apr 29 22:54:05 raspberrypi kelvin[31231]: time="2019/29/04 22:54:05" level=info msg="Looking for updates..."
Apr 29 23:56:02 raspberrypi kelvin[31231]: time="2019/29/04 23:56:02" level=info msg="💡 Light Hue ambiance lamp 2 - Light just appeared."
Apr 29 23:56:02 raspberrypi kelvin[31231]: time="2019/29/04 23:56:02" level=info msg="💡 Light Hue ambiance lamp 2 - Initializing state to 2000K at 40% brightness."
Apr 29 23:56:25 raspberrypi kelvin[31231]: time="2019/29/04 23:56:25" level=info msg="💡 Light Hue ambiance lamp 2 - Light state has been changed manually. Disabling Kelvin..."
Apr 29 23:56:38 raspberrypi kelvin[31231]: time="2019/29/04 23:56:38" level=info msg="💡 Light Hue color lamp 1 - Light is no longer reachable. Clearing state..."
Apr 29 23:56:50 raspberrypi kelvin[31231]: time="2019/29/04 23:56:50" level=info msg="💡 Light Hue color lamp 1 - Light just appeared."
Apr 29 23:56:50 raspberrypi kelvin[31231]: time="2019/29/04 23:56:50" level=info msg="💡 Light Hue color lamp 1 - Initializing state to 2000K at 40% brightness."
Apr 29 23:57:35 raspberrypi kelvin[31231]: time="2019/29/04 23:57:35" level=info msg="💡 Light Hue ambiance lamp 2 - Light is no longer reachable. Clearing state..."
Apr 29 23:57:50 raspberrypi kelvin[31231]: time="2019/29/04 23:57:50" level=info msg="💡 Light Hue color lamp 1 - Light state has been changed manually. Disabling Kelvin..."
Apr 29 23:57:50 raspberrypi kelvin[31231]: time="2019/29/04 23:57:50" level=info msg="💡 Light Hue color lamp 2 - Light state has been changed manually. Disabling Kelvin..."
--
Apr 30 08:01:50 raspberrypi kelvin[31231]: time="2019/30/04 08:01:50" level=info msg="💡 Light Hue ambiance lamp 2 - Initializing state to 6500K at 100% brightness."
Apr 30 08:10:44 raspberrypi kelvin[31231]: time="2019/30/04 08:10:44" level=info msg="💡 Light Hue ambiance lamp 2 - Light is no longer reachable. Clearing state..."
Apr 30 08:32:21 raspberrypi kelvin[31231]: time="2019/30/04 08:32:21" level=info msg="💡 Light Hue ambiance lamp 2 - Light just appeared."
Apr 30 08:32:21 raspberrypi kelvin[31231]: time="2019/30/04 08:32:21" level=info msg="💡 Light Hue ambiance lamp 2 - Initializing state to 6500K at 100% brightness."
Apr 30 08:32:49 raspberrypi kelvin[31231]: time="2019/30/04 08:32:49" level=info msg="💡 Light Hue ambiance lamp 2 - Light state has been changed manually. Disabling Kelvin..."
--
Apr 30 20:41:53 raspberrypi kelvin[31231]: time="2019/30/04 20:41:53" level=info msg="💡 Light Hue color lamp 3 - Updated light state to 4544K at 74% brightness"
Apr 30 20:41:53 raspberrypi kelvin[31231]: time="2019/30/04 20:41:53" level=info msg="💡 Light Hue ambiance lamp 1 - Updated light state to 4544K at 74% brightness"
Apr 30 20:42:05 raspberrypi kelvin[31231]: time="2019/30/04 20:42:05" level=info msg="💡 Light Hue color lamp 1 - Light just appeared."
Apr 30 20:42:05 raspberrypi kelvin[31231]: time="2019/30/04 20:42:05" level=info msg="💡 Light Hue color lamp 1 - Initializing state to 4544K at 74% brightness."
Apr 30 20:42:10 raspberrypi kelvin[31231]: time="2019/30/04 20:42:10" level=info msg="💡 Light Hue color lamp 1 - Light state has been changed manually. Disabling Kelvin..."
--
May 01 00:00:00 raspberrypi kelvin[31231]: time="2019/01/05 00:00:00" level=info msg="💡 Light Hue ambiance lamp 2 - Activating schedule for May 1 2019 (Sunrise: 06:39, Sunset: 19:43)"
May 01 00:00:00 raspberrypi kelvin[31231]: time="2019/01/05 00:00:00" level=info msg="💡 Light Hue ambiance lamp 2 - Activating interval 00:00 - 04:00"
May 01 00:02:17 raspberrypi kelvin[31231]: time="2019/01/05 00:02:17" level=info msg="💡 Light Hue ambiance lamp 2 - Light just appeared."
May 01 00:02:17 raspberrypi kelvin[31231]: time="2019/01/05 00:02:17" level=info msg="💡 Light Hue ambiance lamp 2 - Initializing state to 2000K at 40% brightness."
May 01 00:02:33 raspberrypi kelvin[31231]: time="2019/01/05 00:02:33" level=info msg="💡 Light Hue ambiance lamp 2 - Light state has been changed manually. Disabling Kelvin..."

Based on the above it looks like now the desyncs happen mostly ~10-30s after the light has been turned off/on using the power switch. Could it be that the regular schedule and the handling for new lights appearing are having some kind of unexpected interaction?

from kelvin.

LiSongMWO commented on June 26, 2024

What I'm observing seems like a glitch when turning on a light, it takes around 10-30s for the light to be set to the expected CT/Brightness. With a matching "manual" change in the logs...

from kelvin.

stefanwichmann commented on June 26, 2024

Hi Emily,

I can definitely confirm that there are still some glitches. Here is an extract from my logs showing a similar behavior:

time="2019/21/04 22:13:16" level=debug msg="💡 Light Spot 1 - Light state has been changed manually after 13.81173107s (TargetColorTemperature: 454, CurrentColorTemperature: 366, TargetColor: [0.506 0.415], CurrentColor: [], TargetBrightness: 203, CurrentBrightness: 254)" 
time="2019/21/04 22:13:59" level=debug msg="💡 Light Spot 2 - Light state has been changed manually after 56.133041185s (TargetColorTemperature: 454, CurrentColorTemperature: 366, TargetColor: [0.506 0.415], CurrentColor: [], TargetBrightness: 203, CurrentBrightness: 254)" 
time="2019/21/04 22:16:42" level=debug msg="💡 Light Spot 2 - Light state has been changed manually after 8.114111817s (TargetColorTemperature: 454, CurrentColorTemperature: 454, TargetColor: [0.506 0.415], CurrentColor: [], TargetBrightness: 203, CurrentBrightness: 254)" 
time="2019/22/04 08:46:37" level=debug msg="💡 Light Spot 3 - Light state has been changed manually after 57.456601502s (TargetColorTemperature: 363, CurrentColorTemperature: 366, TargetColor: [0.456 0.41], CurrentColor: [], TargetBrightness: 254, CurrentBrightness: 254)" 
time="2019/22/04 14:13:08" level=debug msg="💡 Light Spot 2 - Light state has been changed manually after 5.356158858s (TargetColorTemperature: 363, CurrentColorTemperature: 366, TargetColor: [0.456 0.41], CurrentColor: [], TargetBrightness: 254, CurrentBrightness: 254)" 
time="2019/22/04 14:13:15" level=debug msg="💡 Light Spot 1 - Light state has been changed manually after 12.589524922s (TargetColorTemperature: 363, CurrentColorTemperature: 366, TargetColor: [0.456 0.41], CurrentColor: [], TargetBrightness: 254, CurrentBrightness: 254)" 
time="2019/22/04 21:06:10" level=debug msg="💡 Light Spot 1 - Light state has been changed manually after 1m2.189894954s (TargetColorTemperature: 445, CurrentColorTemperature: 445, TargetColor: [0.501 0.415], CurrentColor: [], TargetBrightness: 203, CurrentBrightness: 254)" 
time="2019/23/04 06:20:59" level=debug msg="💡 Light Spot 2 - Light state has been changed manually after 16.314423504s (TargetColorTemperature: 377, CurrentColorTemperature: 366, TargetColor: [0.464 0.411], CurrentColor: [], TargetBrightness: 233, CurrentBrightness: 254)" 
time="2019/23/04 06:35:26" level=debug msg="💡 Light Spot 3 - Light state has been changed manually after 8.089303193s (TargetColorTemperature: 370, CurrentColorTemperature: 366, TargetColor: [0.46 0.411], CurrentColor: [], TargetBrightness: 243, CurrentBrightness: 254)" 
time="2019/23/04 06:35:31" level=debug msg="💡 Light Spot 1 - Light state has been changed manually after 12.888875458s (TargetColorTemperature: 370, CurrentColorTemperature: 370, TargetColor: [0.46 0.411], CurrentColor: [], TargetBrightness: 243, CurrentBrightness: 254)" 
time="2019/23/04 06:36:04" level=debug msg="💡 Light Spot 2 - Light state has been changed manually after 44.716808734s (TargetColorTemperature: 370, CurrentColorTemperature: 370, TargetColor: [0.46 0.411], CurrentColor: [], TargetBrightness: 243, CurrentBrightness: 254)" 
time="2019/23/04 22:05:32" level=debug msg="💡 Light Spot 3 - Light state has been changed manually after 6.656725019s (TargetColorTemperature: 454, CurrentColorTemperature: 454, TargetColor: [0.506 0.415], CurrentColor: [], TargetBrightness: 203, CurrentBrightness: 254)" 
time="2019/24/04 06:29:32" level=debug msg="💡 Light Spot 2 - Light state has been changed manually after 11.716167301s (TargetColorTemperature: 372, CurrentColorTemperature: 372, TargetColor: [0.461 0.411], CurrentColor: [], TargetBrightness: 241, CurrentBrightness: 254)" 
time="2019/24/04 20:26:06" level=debug msg="💡 Light Spot 1 - Light state has been changed manually after 10.265045898s (TargetColorTemperature: 438, CurrentColorTemperature: 438, TargetColor: [0.498 0.415], CurrentColor: [], TargetBrightness: 203, CurrentBrightness: 254)" 
time="2019/24/04 21:20:07" level=debug msg="💡 Light Spot 3 - Light state has been changed manually after 54m11.565146247s (TargetColorTemperature: 447, CurrentColorTemperature: 366, TargetColor: [0.502 0.415], CurrentColor: [], TargetBrightness: 203, CurrentBrightness: 254)" 
time="2019/24/04 21:20:11" level=debug msg="💡 Light Spot 2 - Light state has been changed manually after 54m15.070677212s (TargetColorTemperature: 447, CurrentColorTemperature: 366, TargetColor: [0.502 0.415], CurrentColor: [], TargetBrightness: 203, CurrentBrightness: 254)" 
time="2019/24/04 23:57:09" level=debug msg="💡 Light Spot 1 - Light state has been changed manually after 5.153729623s (TargetColorTemperature: 454, CurrentColorTemperature: 366, TargetColor: [0.506 0.415], CurrentColor: [], TargetBrightness: 203, CurrentBrightness: 254)" 
time="2019/25/04 20:31:44" level=debug msg="💡 Light Spot 2 - Light state has been changed manually after 17.02771548s (TargetColorTemperature: 439, CurrentColorTemperature: 366, TargetColor: [0.498 0.415], CurrentColor: [], TargetBrightness: 203, CurrentBrightness: 254)" 
time="2019/25/04 22:14:46" level=debug msg="💡 Light Spot 2 - Light state has been changed manually after 17.992899749s (TargetColorTemperature: 454, CurrentColorTemperature: 366, TargetColor: [0.506 0.415], CurrentColor: [], TargetBrightness: 203, CurrentBrightness: 254)" 
time="2019/25/04 22:18:09" level=debug msg="💡 Light Spot 1 - Light state has been changed manually after 6.385271062s (TargetColorTemperature: 454, CurrentColorTemperature: 454, TargetColor: [0.506 0.415], CurrentColor: [], TargetBrightness: 203, CurrentBrightness: 254)" 
time="2019/25/04 22:18:14" level=debug msg="💡 Light Spot 3 - Light state has been changed manually after 11.52858925s (TargetColorTemperature: 454, CurrentColorTemperature: 454, TargetColor: [0.506 0.415], CurrentColor: [], TargetBrightness: 203, CurrentBrightness: 254)" 
time="2019/25/04 22:42:17" level=debug msg="💡 Light Spot 3 - Light state has been changed manually after 9.563467727s (TargetColorTemperature: 454, CurrentColorTemperature: 454, TargetColor: [0.506 0.415], CurrentColor: [], TargetBrightness: 203, CurrentBrightness: 254)" 
time="2019/25/04 22:42:24" level=debug msg="💡 Light Spot 2 - Light state has been changed manually after 16.792516848s (TargetColorTemperature: 454, CurrentColorTemperature: 454, TargetColor: [0.506 0.415], CurrentColor: [], TargetBrightness: 203, CurrentBrightness: 254)" 
time="2019/26/04 00:39:16" level=debug msg="💡 Light Spot 2 - Light state has been changed manually after 9.130242372s (TargetColorTemperature: 454, CurrentColorTemperature: 366, TargetColor: [0.506 0.415], CurrentColor: [], TargetBrightness: 152, CurrentBrightness: 254)" 
time="2019/26/04 19:27:49" level=debug msg="💡 Light Spot 2 - Light state has been changed manually after 2m44.675316524s (TargetColorTemperature: 363, CurrentColorTemperature: 366, TargetColor: [0.456 0.41], CurrentColor: [], TargetBrightness: 254, CurrentBrightness: 254)" 
time="2019/26/04 19:27:50" level=debug msg="💡 Light Spot 3 - Light state has been changed manually after 2m46.129406584s (TargetColorTemperature: 363, CurrentColorTemperature: 366, TargetColor: [0.456 0.41], CurrentColor: [], TargetBrightness: 254, CurrentBrightness: 254)" 
time="2019/26/04 19:27:51" level=debug msg="💡 Light Spot 1 - Light state has been changed manually after 2m46.933831279s (TargetColorTemperature: 363, CurrentColorTemperature: 366, TargetColor: [0.456 0.41], CurrentColor: [], TargetBrightness: 254, CurrentBrightness: 254)" 
time="2019/26/04 19:42:51" level=debug msg="💡 Light Spot 1 - Light state has been changed manually after 7.693142938s (TargetColorTemperature: 363, CurrentColorTemperature: 366, TargetColor: [0.456 0.41], CurrentColor: [], TargetBrightness: 254, CurrentBrightness: 254)" 
time="2019/26/04 20:45:33" level=debug msg="💡 Light Spot 3 - Light state has been changed manually after 8.19283643s (TargetColorTemperature: 441, CurrentColorTemperature: 366, TargetColor: [0.499 0.415], CurrentColor: [], TargetBrightness: 203, CurrentBrightness: 254)" 
time="2019/26/04 21:11:04" level=debug msg="💡 Light Spot 1 - Light state has been changed manually after 18.946841676s (TargetColorTemperature: 446, CurrentColorTemperature: 446, TargetColor: [0.501 0.415], CurrentColor: [], TargetBrightness: 203, CurrentBrightness: 254)" 
time="2019/26/04 22:44:19" level=debug msg="💡 Light Spot 2 - Light state has been changed manually after 14.214329952s (TargetColorTemperature: 454, CurrentColorTemperature: 454, TargetColor: [0.506 0.415], CurrentColor: [], TargetBrightness: 203, CurrentBrightness: 254)" 
time="2019/26/04 23:00:36" level=debug msg="💡 Light Spot 2 - Light state has been changed manually after 10.285076859s (TargetColorTemperature: 454, CurrentColorTemperature: 366, TargetColor: [0.506 0.415], CurrentColor: [], TargetBrightness: 203, CurrentBrightness: 254)" 
time="2019/26/04 23:01:23" level=debug msg="💡 Light Spot 3 - Light state has been changed manually after 57.273284231s (TargetColorTemperature: 454, CurrentColorTemperature: 366, TargetColor: [0.506 0.415], CurrentColor: [], TargetBrightness: 203, CurrentBrightness: 254)" 
time="2019/26/04 23:17:01" level=debug msg="💡 Light Spot 2 - Light state has been changed manually after 55.017827875s (TargetColorTemperature: 454, CurrentColorTemperature: 366, TargetColor: [0.506 0.415], CurrentColor: [], TargetBrightness: 203, CurrentBrightness: 254)" 
time="2019/27/04 00:37:23" level=debug msg="💡 Light Spot 1 - Light state has been changed manually after 19.238170385s (TargetColorTemperature: 454, CurrentColorTemperature: 454, TargetColor: [0.506 0.415], CurrentColor: [], TargetBrightness: 152, CurrentBrightness: 254)" 
time="2019/27/04 17:57:01" level=debug msg="💡 Light Spot 3 - Light state has been changed manually after 20m58.827936833s (TargetColorTemperature: 363, CurrentColorTemperature: 366, TargetColor: [0.456 0.41], CurrentColor: [], TargetBrightness: 254, CurrentBrightness: 254)" 
time="2019/27/04 17:57:58" level=debug msg="💡 Light Spot 1 - Light state has been changed manually after 21m55.238719609s (TargetColorTemperature: 363, CurrentColorTemperature: 366, TargetColor: [0.456 0.41], CurrentColor: [], TargetBrightness: 254, CurrentBrightness: 254)" 
time="2019/28/04 00:26:32" level=debug msg="💡 Light Spot 2 - Light state has been changed manually after 19.599250648s (TargetColorTemperature: 454, CurrentColorTemperature: 366, TargetColor: [0.506 0.415], CurrentColor: [], TargetBrightness: 152, CurrentBrightness: 254)" 
time="2019/28/04 00:57:35" level=debug msg="💡 Light Spot 1 - Light state has been changed manually after 7.932614004s (TargetColorTemperature: 454, CurrentColorTemperature: 454, TargetColor: [0.506 0.415], CurrentColor: [], TargetBrightness: 152, CurrentBrightness: 254)" 
time="2019/28/04 09:55:10" level=debug msg="💡 Light Spot 2 - Light state has been changed manually after 7.841916884s (TargetColorTemperature: 363, CurrentColorTemperature: 366, TargetColor: [0.456 0.41], CurrentColor: [], TargetBrightness: 254, CurrentBrightness: 254)" 
time="2019/28/04 15:00:11" level=debug msg="💡 Light Spot 1 - Light state has been changed manually after 12.445146966s (TargetColorTemperature: 363, CurrentColorTemperature: 366, TargetColor: [0.456 0.41], CurrentColor: [], TargetBrightness: 254, CurrentBrightness: 254)" 
time="2019/28/04 19:18:52" level=debug msg="💡 Light Spot 1 - Light state has been changed manually after 15.47186933s (TargetColorTemperature: 363, CurrentColorTemperature: 366, TargetColor: [0.456 0.41], CurrentColor: [], TargetBrightness: 254, CurrentBrightness: 254)" 
time="2019/28/04 20:27:31" level=debug msg="💡 Light Spot 2 - Light state has been changed manually after 10.338373734s (TargetColorTemperature: 438, CurrentColorTemperature: 366, TargetColor: [0.498 0.415], CurrentColor: [], TargetBrightness: 203, CurrentBrightness: 254)" 
time="2019/29/04 20:51:47" level=debug msg="💡 Light Spot 3 - Light state has been changed manually after 8.167866226s (TargetColorTemperature: 442, CurrentColorTemperature: 366, TargetColor: [0.5 0.415], CurrentColor: [], TargetBrightness: 203, CurrentBrightness: 254)" 
time="2019/29/04 21:39:17" level=debug msg="💡 Light Spot 1 - Light state has been changed manually after 9.071057407s (TargetColorTemperature: 450, CurrentColorTemperature: 366, TargetColor: [0.504 0.415], CurrentColor: [], TargetBrightness: 203, CurrentBrightness: 254)" 
time="2019/29/04 22:25:36" level=debug msg="💡 Light Spot 1 - Light state has been changed manually after 10.186913157s (TargetColorTemperature: 454, CurrentColorTemperature: 366, TargetColor: [0.506 0.415], CurrentColor: [], TargetBrightness: 203, CurrentBrightness: 254)" 
time="2019/29/04 22:25:44" level=debug msg="💡 Light Spot 3 - Light state has been changed manually after 17.813082533s (TargetColorTemperature: 454, CurrentColorTemperature: 366, TargetColor: [0.506 0.415], CurrentColor: [], TargetBrightness: 203, CurrentBrightness: 254)" 
time="2019/30/04 06:54:17" level=debug msg="💡 Light Spot 1 - Light state has been changed manually after 7.61542092s (TargetColorTemperature: 363, CurrentColorTemperature: 366, TargetColor: [0.456 0.41], CurrentColor: [], TargetBrightness: 254, CurrentBrightness: 254)" 
time="2019/30/04 06:54:25" level=debug msg="💡 Light Spot 3 - Light state has been changed manually after 16.669984928s (TargetColorTemperature: 363, CurrentColorTemperature: 366, TargetColor: [0.456 0.41], CurrentColor: [], TargetBrightness: 254, CurrentBrightness: 254)" 
time="2019/30/04 21:40:21" level=debug msg="💡 Light Spot 1 - Light state has been changed manually after 30m9.35678327s (TargetColorTemperature: 448, CurrentColorTemperature: 366, TargetColor: [0.502 0.415], CurrentColor: [], TargetBrightness: 203, CurrentBrightness: 254)" 
time="2019/30/04 22:25:56" level=debug msg="💡 Light Spot 2 - Light state has been changed manually after 7.986196298s (TargetColorTemperature: 454, CurrentColorTemperature: 454, TargetColor: [0.506 0.415], CurrentColor: [], TargetBrightness: 203, CurrentBrightness: 254)" 
time="2019/30/04 22:26:02" level=debug msg="💡 Light Spot 1 - Light state has been changed manually after 13.889017698s (TargetColorTemperature: 454, CurrentColorTemperature: 454, TargetColor: [0.506 0.415], CurrentColor: [], TargetBrightness: 203, CurrentBrightness: 254)" 
time="2019/30/04 23:38:16" level=debug msg="💡 Light Spot 2 - Light state has been changed manually after 11.413009707s (TargetColorTemperature: 454, CurrentColorTemperature: 366, TargetColor: [0.506 0.415], CurrentColor: [], TargetBrightness: 203, CurrentBrightness: 254)" 
time="2019/01/05 09:58:12" level=debug msg="💡 Light Spot 1 - Light state has been changed manually after 45.898101786s (TargetColorTemperature: 363, CurrentColorTemperature: 366, TargetColor: [0.456 0.41], CurrentColor: [], TargetBrightness: 254, CurrentBrightness: 254)" 
time="2019/01/05 10:04:34" level=debug msg="💡 Light Spot 2 - Light state has been changed manually after 7m7.469332961s (TargetColorTemperature: 363, CurrentColorTemperature: 366, TargetColor: [0.456 0.41], CurrentColor: [], TargetBrightness: 254, CurrentBrightness: 254)" 
time="2019/01/05 10:04:35" level=debug msg="💡 Light Spot 3 - Light state has been changed manually after 7m8.902879601s (TargetColorTemperature: 363, CurrentColorTemperature: 366, TargetColor: [0.456 0.41], CurrentColor: [], TargetBrightness: 254, CurrentBrightness: 254)" 
time="2019/01/05 20:08:39" level=debug msg="💡 Light Spot 2 - Light state has been changed manually after 6.458534175s (TargetColorTemperature: 436, CurrentColorTemperature: 436, TargetColor: [0.496 0.415], CurrentColor: [], TargetBrightness: 203, CurrentBrightness: 254)" 
time="2019/02/05 07:56:35" level=debug msg="💡 Light Spot 2 - Light state has been changed manually after 9.307366462s (TargetColorTemperature: 363, CurrentColorTemperature: 366, TargetColor: [0.456 0.41], CurrentColor: [], TargetBrightness: 254, CurrentBrightness: 254)" 
time="2019/02/05 08:36:02" level=debug msg="💡 Light Spot 1 - Light state has been changed manually after 15.284605247s (TargetColorTemperature: 363, CurrentColorTemperature: 366, TargetColor: [0.456 0.41], CurrentColor: [], TargetBrightness: 254, CurrentBrightness: 254)" 
time="2019/02/05 08:36:32" level=debug msg="💡 Light Spot 3 - Light state has been changed manually after 46.326079663s (TargetColorTemperature: 363, CurrentColorTemperature: 366, TargetColor: [0.456 0.41], CurrentColor: [], TargetBrightness: 254, CurrentBrightness: 254)" 
time="2019/02/05 08:36:34" level=debug msg="💡 Light Spot 2 - Light state has been changed manually after 45.885093477s (TargetColorTemperature: 363, CurrentColorTemperature: 366, TargetColor: [0.456 0.41], CurrentColor: [], TargetBrightness: 254, CurrentBrightness: 254)"

This log spans multiple days and there are some interesting things in there:

The timestamps don't seem to follow a pattern. The glitches occur at daytime, at nighttime and during transition phases...
The glitches can occur after 5 seconds or 54 minutes (even observed one over an hour after power on).
Every time the color deviates the light has the CurrentColorTemperature 366.
Every time the brightness deviates the light has the CurrentBrightness 254.
The glitch seems to happen more ofter on "Hue Ambient" lights the "Hue Color" lights.

Especially the magic values 366 and 254 look really suspicious but I can't make any sense of them yet.

Could you please also post a debug log with the specific color and brightness values in there? Do you also observe these specific values?

from kelvin.

LiSongMWO commented on June 26, 2024

I enabled debug logging. I will get back to you when I have some data.

W.r.t. "magic numbers" you mentioned. Could there be a precision problem in some calculation that is visible with just these numbers?

from kelvin.

LiSongMWO commented on June 26, 2024

I had one event last night, here are the logs. for the time from where the light was written to where the manual change was detected. Not all of my lights were enabled at the time.

It's only one sample point but it's also showing current colour temperature value of 366. But the brightness is also deviating.

I think the "adjusting light temperature to light capability" means that the requested value from the schedule was out of range for the light? But why is it that line printed so often? Shouldn't that happen once when writing the value?

$ journalctl -fu kelvin -n 7000 | cut -b 43- | grep -B40 -i manual
time="2019/03/05 22:49:39" level=debug msg="💡 Light Hue ambiance lamp 2 - Adjusted color temperature to light capability of 2200K"
time="2019/03/05 22:49:39" level=debug msg="💡 HueLight Hue ambiance lamp 2 - Setting light state to 2200K and 40% brightness (TargetColorTemperature: 454, CurrentColorTemperature: 454, TargetColor: [0.506 0.415], CurrentColor: [], TargetBrightness: 101, CurrentBrightness: 101, TransitionTime: 4)"
time="2019/03/05 22:49:39" level=debug msg="💡 HueLight Hue ambiance lamp 2 - Light was successfully updated (TargetColorTemperature: 454, CurrentColorTemperature: 454, TargetColor: [0.506 0.415], CurrentColor: [], TargetBrightness: 101, CurrentBrightness: 101, TransitionTime: 4)"
time="2019/03/05 22:49:39" level=debug msg="💡 Light Hue ambiance lamp 2 - Light was initialized to 2000K at 40% brightness"
time="2019/03/05 22:49:39" level=debug msg="🤖 Light Hue ambiance lamp 2 - Updated light state. Awaiting transition..."
time="2019/03/05 22:49:41" level=debug msg="💡 Light Hue ambiance lamp 1 - Adjusted color temperature to light capability of 2200K"
time="2019/03/05 22:49:41" level=debug msg="💡 Light Hue ambiance lamp 2 - Light in initialization for 1.473941906s (TargetColorTemperature: 454, CurrentColorTemperature: 454, TargetColor: [0.506 0.415], CurrentColor: [], TargetBrightness: 101, CurrentBrightness: 101)"
time="2019/03/05 22:49:42" level=debug msg="💡 Light Hue ambiance lamp 1 - Adjusted color temperature to light capability of 2200K"
time="2019/03/05 22:49:42" level=debug msg="💡 Light Hue ambiance lamp 2 - Light in initialization for 2.716547554s (TargetColorTemperature: 454, CurrentColorTemperature: 454, TargetColor: [0.506 0.415], CurrentColor: [], TargetBrightness: 101, CurrentBrightness: 101)"
time="2019/03/05 22:49:43" level=debug msg="💡 Light Hue ambiance lamp 1 - Adjusted color temperature to light capability of 2200K"
time="2019/03/05 22:49:43" level=debug msg="💡 Light Hue ambiance lamp 2 - Light in initialization for 3.954466237s (TargetColorTemperature: 454, CurrentColorTemperature: 454, TargetColor: [0.506 0.415], CurrentColor: [], TargetBrightness: 101, CurrentBrightness: 101)"
time="2019/03/05 22:49:43" level=debug msg="💡 Light Hue ambiance lamp 2 - Ending initialization phase after 3.960027195s"
time="2019/03/05 22:49:45" level=debug msg="💡 Light Hue ambiance lamp 1 - Adjusted color temperature to light capability of 2200K"
time="2019/03/05 22:49:45" level=debug msg="💡 Light Hue ambiance lamp 2 - Adjusted color temperature to light capability of 2200K"
time="2019/03/05 22:49:46" level=debug msg="💡 Light Hue ambiance lamp 1 - Adjusted color temperature to light capability of 2200K"
time="2019/03/05 22:49:46" level=debug msg="💡 Light Hue ambiance lamp 2 - Adjusted color temperature to light capability of 2200K"
time="2019/03/05 22:49:47" level=debug msg="💡 Light Hue ambiance lamp 1 - Adjusted color temperature to light capability of 2200K"
time="2019/03/05 22:49:47" level=debug msg="💡 Light Hue ambiance lamp 2 - Adjusted color temperature to light capability of 2200K"
time="2019/03/05 22:49:48" level=debug msg="💡 Light Hue ambiance lamp 1 - Adjusted color temperature to light capability of 2200K"
time="2019/03/05 22:49:48" level=debug msg="💡 Light Hue ambiance lamp 2 - Adjusted color temperature to light capability of 2200K"
time="2019/03/05 22:49:50" level=debug msg="💡 Light Hue ambiance lamp 1 - Adjusted color temperature to light capability of 2200K"
time="2019/03/05 22:49:50" level=debug msg="💡 Light Hue ambiance lamp 2 - Adjusted color temperature to light capability of 2200K"
time="2019/03/05 22:49:51" level=debug msg="💡 Light Hue ambiance lamp 1 - Adjusted color temperature to light capability of 2200K"
time="2019/03/05 22:49:51" level=debug msg="💡 Light Hue ambiance lamp 2 - Adjusted color temperature to light capability of 2200K"
time="2019/03/05 22:49:52" level=debug msg="💡 Light Hue ambiance lamp 1 - Adjusted color temperature to light capability of 2200K"
time="2019/03/05 22:49:52" level=debug msg="💡 Light Hue ambiance lamp 2 - Adjusted color temperature to light capability of 2200K"
time="2019/03/05 22:49:53" level=debug msg="💡 Light Hue ambiance lamp 1 - Adjusted color temperature to light capability of 2200K"
time="2019/03/05 22:49:53" level=debug msg="💡 Light Hue ambiance lamp 2 - Adjusted color temperature to light capability of 2200K"
time="2019/03/05 22:49:55" level=debug msg="💡 Light Hue ambiance lamp 1 - Adjusted color temperature to light capability of 2200K"
time="2019/03/05 22:49:55" level=debug msg="💡 Light Hue ambiance lamp 2 - Adjusted color temperature to light capability of 2200K"
time="2019/03/05 22:49:56" level=debug msg="💡 Light Hue ambiance lamp 1 - Adjusted color temperature to light capability of 2200K"
time="2019/03/05 22:49:56" level=debug msg="💡 Light Hue ambiance lamp 2 - Adjusted color temperature to light capability of 2200K"
time="2019/03/05 22:49:57" level=debug msg="💡 Light Hue ambiance lamp 1 - Adjusted color temperature to light capability of 2200K"
time="2019/03/05 22:49:57" level=debug msg="💡 Light Hue ambiance lamp 2 - Adjusted color temperature to light capability of 2200K"
time="2019/03/05 22:49:58" level=debug msg="💡 Light Hue ambiance lamp 1 - Adjusted color temperature to light capability of 2200K"
time="2019/03/05 22:49:58" level=debug msg="💡 Light Hue ambiance lamp 2 - Adjusted color temperature to light capability of 2200K"
time="2019/03/05 22:50:00" level=debug msg="💡 Light Hue ambiance lamp 1 - Adjusted color temperature to light capability of 2200K"
time="2019/03/05 22:50:00" level=debug msg="💡 Light Hue ambiance lamp 2 - Adjusted color temperature to light capability of 2200K"
time="2019/03/05 22:50:01" level=debug msg="💡 Light Hue ambiance lamp 1 - Adjusted color temperature to light capability of 2200K"
time="2019/03/05 22:50:01" level=debug msg="💡 HueLight Hue ambiance lamp 2 - Color temperature has changed! CurrentColorTemperature: 366, TargetColorTemperatur: 454 (2200K)"
time="2019/03/05 22:50:01" level=debug msg="💡 Light Hue ambiance lamp 2 - Light state has been changed manually after 21.327572487s (TargetColorTemperature: 454, CurrentColorTemperature: 366, TargetColor: [0.506 0.415], CurrentColor: [], TargetBrightness: 101, CurrentBrightness: 254)"

from kelvin.

stefanwichmann commented on June 26, 2024

Interesting that in this case both attributes (color temperature and brightness) have the magic value of 366/254...

This should not be a calculation error as these are the real values written to and read from the Hue API. And the difference (454 vs. 366 and 101 vs. 254 in your case) is really big...

For some time I suspected another app or routine but could not find anything... and the occurrence seems random.

Regarding the adjustment to the light capabilities: Yes, this could be refactored to only happen once... that would require some deeper changes though. Didn't want to introduce more changes here just yet.

from kelvin.

LiSongMWO commented on June 26, 2024

There are multiple occurrences of both attributes differing in your log above as well.

I too, don't think another app is involved, as my experiment from some time ago didn't show anything interfering. And nothing else has access to the hue hub at my place, that I know of.

Does the "Adjusted ...." thing communicate with the hub? I'm wondering if that puts more load on the hub overloading it causing the writes to not take? I think we found the limits in #51 (comment).

I'm considering logging all the network packets to/from the hue-hub/RPi... but I'm not sure what I would gain from that and what tools to use to analyse this data as I expect it to be kinda big like finding a needle in a haystack... do you have any thoughts?

from kelvin.

probus commented on June 26, 2024

Sorry for taking a while to reply. Here are a couple of logs from this morning from Kelvin running in debug mode. The bulbs are all white ambience e27 and running identical schedules in the same light fixtures (i.e. three bulbs in one, two bulbs in the other).

https://www.dropbox.com/sh/4z7seog6n5uz2ti/AACC8EbwswODGO097ES46r22a?dl=0

edit. I added two more from today

from kelvin.

LiSongMWO commented on June 26, 2024

Sorry for the delay, I have bzipped the logs from the past few days with debug output enabled (apparently journald wouldn't keep more in memory on my raspberry pi). https://drive.google.com/open?id=1H7ga2R3YGhwP5-LjFT3OF8dY3cHppmu6

The juicy bits:

time="2019/01/06 23:38:40" level=debug msg="💡 Light Hue ambiance lamp 2 - Light state has been changed manually after 18.768246605s (TargetColorTemperature: 454, CurrentColorTemperature: 366, TargetColor: [0.506 0.415], CurrentColor: [], TargetBrightness: 101, CurrentBrightness: 254)"
time="2019/02/06 13:44:55" level=debug msg="💡 Light Hue ambiance lamp 2 - Light state has been changed manually after 7m39.957491607s (TargetColorTemperature: 153, CurrentColorTemperature: 366, TargetColor: [0.313 0.329], CurrentColor: [], TargetBrightness: 254, CurrentBrightness: 254)"
time="2019/03/06 22:20:38" level=debug msg="💡 Light Hue color lamp 1 - Light state has been changed manually after 1h9m6.411216963s (TargetColorTemperature: 500, CurrentColorTemperature: 366, TargetColor: [0.527 0.413], CurrentColor: [0.457 0.41], TargetBrightness: 101, CurrentBrightness: 254)"
time="2019/05/06 18:12:16" level=debug msg="💡 Light Hue ambiance lamp 1 - Light state has been changed manually after 22.372820451s (TargetColorTemperature: 153, CurrentColorTemperature: 366, TargetColor: [0.313 0.329], CurrentColor: [], TargetBrightness: 254, CurrentBrightness: 254)"
time="2019/06/06 21:45:35" level=debug msg="💡 Light Hue color lamp 1 - Light state has been changed manually after 1h35m41.18073888s (TargetColorTemperature: 375, CurrentColorTemperature: 375, TargetColor: [0.463 0.411], CurrentColor: [0.462 0.411], TargetBrightness: 124, CurrentBrightness: 127)"
time="2019/06/06 23:12:33" level=debug msg="💡 Light Hue ambiance lamp 2 - Light state has been changed manually after 19m14.435530872s (TargetColorTemperature: 454, CurrentColorTemperature: 366, TargetColor: [0.506 0.415], CurrentColor: [], TargetBrightness: 101, CurrentBrightness: 254)"
time="2019/07/06 20:32:35" level=debug msg="💡 Light Hue ambiance lamp 1 - Light state has been changed manually after 2h40m1.506628225s (TargetColorTemperature: 166, CurrentColorTemperature: 163, TargetColor: [0.321 0.337], CurrentColor: [], TargetBrightness: 238, CurrentBrightness: 243)"
time="2019/07/06 20:32:44" level=debug msg="💡 Light Hue color lamp 1 - Light state has been changed manually after 10m34.478877324s (TargetColorTemperature: 166, CurrentColorTemperature: 166, TargetColor: [0.321 0.337], CurrentColor: [0.321 0.337], TargetBrightness: 238, CurrentBrightness: 241)"
time="2019/07/06 21:35:40" level=debug msg="💡 Light Hue color lamp 2 - Light state has been changed manually after 3h17m5.692046901s (TargetColorTemperature: 320, CurrentColorTemperature: 319, TargetColor: [0.428 0.401], CurrentColor: [0.428 0.401], TargetBrightness: 139, CurrentBrightness: 142)"
time="2019/07/06 21:57:36" level=debug msg="💡 Light Hue color lamp 1 - Light state has been changed manually after 2m42.831665833s (TargetColorTemperature: 473, CurrentColorTemperature: 473, TargetColor: [0.515 0.415], CurrentColor: [0.514 0.415], TargetBrightness: 106, CurrentBrightness: 109)"
time="2019/07/06 22:00:37" level=debug msg="💡 Light Hue color lamp 1 - Light state has been changed manually after 27.006946926s (TargetColorTemperature: 500, CurrentColorTemperature: 500, TargetColor: [0.527 0.413], CurrentColor: [0.527 0.413], TargetBrightness: 101, CurrentBrightness: 104)"
time="2019/07/06 22:52:17" level=debug msg="💡 Light Hue color lamp 3 - Light state has been changed manually after 7.909301161s (TargetColorTemperature: 500, CurrentColorTemperature: 366, TargetColor: [0.527 0.413], CurrentColor: [0.457 0.41], TargetBrightness: 101, CurrentBrightness: 254)"
time="2019/08/06 07:03:11" level=debug msg="💡 Light Hue ambiance lamp 1 - Light state has been changed manually after 8.925272254s (TargetColorTemperature: 153, CurrentColorTemperature: 366, TargetColor: [0.313 0.329], CurrentColor: [], TargetBrightness: 254, CurrentBrightness: 254)"
time="2019/08/06 07:03:18" level=debug msg="💡 Light Hue color lamp 1 - Light state has been changed manually after 15.834503453s (TargetColorTemperature: 153, CurrentColorTemperature: 153, TargetColor: [0.313 0.329], CurrentColor: [0.312 0.328], TargetBrightness: 254, CurrentBrightness: 101)"
time="2019/08/06 09:38:47" level=debug msg="💡 Light Hue ambiance lamp 2 - Light state has been changed manually after 13.807704879s (TargetColorTemperature: 153, CurrentColorTemperature: 366, TargetColor: [0.313 0.329], CurrentColor: [], TargetBrightness: 254, CurrentBrightness: 254)"
time="2019/08/06 10:33:41" level=debug msg="💡 Light Hue ambiance lamp 2 - Light state has been changed manually after 19.992508687s (TargetColorTemperature: 153, CurrentColorTemperature: 366, TargetColor: [0.313 0.329], CurrentColor: [], TargetBrightness: 254, CurrentBrightness: 254)"

During this time I have made no manual scene changes. I have used the hue remote to turn on/off lights and also the light switches (which cut power) I have also used my Google Home assistant to turn on or off lights but not for brightness, scene or colour. Interestingly once it detected a manual change after 3h17m...

Observation: The hue bridge has a default colour/value transition for lights that come back on after power was cut. Could there be a race condition with this transition and kelvin's scene detection?

I don't use scenes, can we have a workaround to disable scene detection all together and just have kelvin write the light values blindly? This would solve the problem for me at least.

from kelvin.

stefanwichmann commented on June 26, 2024

Hi Emily,
thanks again for your investigation and the provided log output! This really helps in trying to identify the root cause for the observed problems.

To your questions:

When a light gets powered on after power was cut, it will be initialized to its startup color with the default transition time (400ms). Usually after this it will become available to the bridge because the zigbee communication takes some time to stabilize. Once the bridge becomes aware of the light it will be exposed to Kelvin via the bridge API. So in general there should be no race condition with lights coming up after a power cut. In fact all the lights in my house a controlled by conventional light switches so power is cut every time I turn them off. But, just to be sure, Kelvin has an "initialization phase" for all appearing lights (currently 3 seconds, see light.go).

Regarding scenes there might indeed be some problems hidden in Kelvin. For the scene detection Kelvin has to use multiple requests which are currently issued in a rapid rate. This might lead to an overload in the bridge. Over the last few days I investigated this and implemented a rate limiting feature in the hue library. In combination with some mutexes it should ensure that Kelvin will not be able to issue requests faster than every 100ms... I'm testing this feature now, but can still see manual light changes after very different durations like you reported them...

I'll keep searching...

(Side note: I would like to keep the scene feature automatic, but of cause it should not cause any errors in the communication)

from kelvin.

LiSongMWO commented on June 26, 2024

NPYW.

I will setup TCP logging to log all the TCP data to see what can be learned from what actually goes over the wire,

from kelvin.

LiSongMWO commented on June 26, 2024

The fact that kelvin is using HTTPS makes it harder to capture a network dump. Could you add a flag to force kelvin to use HTTP instead of HTTPS please?

from kelvin.

stefanwichmann commented on June 26, 2024

A new flag to disable HTTPS is now in master. I also committed my rate limiting patch...

I'll test it for a few days and push a new release.

from kelvin.

stefanwichmann commented on June 26, 2024

@EmilyBjoerk I just release Kelvin 1.3.2. If you start the application with the flag "-disableHTTPS" you will now be able to debug the plain TCP traffic.

from kelvin.

LiSongMWO commented on June 26, 2024

Sorry for the delay, life's been busy and a few desynced lights didn't make it to my priority list...

However, today when I was fidgeting around with the Hue App on my Android phone after a light had desynced, I noticed something odd: The lights that were still in sync were in RGB Colour mode, while the light that had desynced was in Colour Temperature mode. All three lights that were active at the time were RGB lights, and all my CT lights were off.

I have not adjusted the light colours or intensity manually for months so this is not my doing. It could be related to the soft-on feature of the lights but it might also be related to how Kelvin writes the colour, I think it puts both the XY colour tuplet and the CT value in the POST request.

Note: I have a setup with mixed RGB and CT lights.

from kelvin.

Spurious "manual change" about kelvin HOT 48 OPEN

Comments (48)

Related Issues (20)

Recommend Projects

React

Vue.js

Typescript

TensorFlow

Django

Laravel

D3

Recommend Topics

javascript

web

server

Machine learning

Visualization

Game

Recommend Org

Facebook

Microsoft

Google

Alibaba

D3

Tencent