[hue] Wrong additional channel update after sending command (API v2)

[jlaur]

For this thing:

Thing device wiser1 [resourceId="00000000-0000-0000-0000-000000000000"]

and this item:

Dimmer DinnerTableLamps_Brightness { channel="hue:device:home:wiser1:brightness" }

when performing this command:

openhab:send DinnerTableLamps_Brightness 100

the following scenario plays out:

2023-10-05 21:32:40.188 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'DinnerTableLamps_Brightness' received command 100
2023-10-05 21:32:40.194 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'DinnerTableLamps_Brightness' predicted to become 100
2023-10-05 21:32:40.198 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'DinnerTableLamps_Brightness' changed from 0 to 100
2023-10-05 21:32:40.209 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 00000000-0000-0000-0000-000000000000 -> handleCommand() put resource id:00000000-0000-0000-0000-000000000001, type:light
2023-10-05 21:32:40.211 [DEBUG] [.internal.handler.Clip2BridgeHandler] - putResource() id:00000000-0000-0000-0000-000000000001, type:light
2023-10-05 21:32:40.213 [TRACE] [.hue.internal.connection.Clip2Bridge] - PUT https://192.168.0.251/clip/v2/resource/light/00000000-0000-0000-0000-000000000001 HTTP/2 >> {"type":"light","id":"00000000-0000-0000-0000-000000000001","on":{"on":true},"dimming":{"brightness":100.0}}
2023-10-05 21:32:40.292 [TRACE] [.hue.internal.connection.Clip2Bridge] - HTTP/2 200 (Content-Type: application/json) << {"data":[{"rid":"00000000-0000-0000-0000-000000000001","rtype":"light"}],"errors":[]}
2023-10-05 21:32:40.308 [TRACE] [.hue.internal.connection.Clip2Bridge] - onEventData() data:[{"creationtime":"2023-10-05T19:32:40Z","data":[{"id":"00000000-0000-0000-0000-000000000001","id_v1":"/lights/40","on":{"on":true},"owner":{"rid":"00000000-0000-0000-0000-000000000000","rtype":"device"},"type":"light"},{"dimming":{"brightness":100.0},"id":"00000000-0000-0000-0000-000000000001","id_v1":"/lights/40","owner":{"rid":"00000000-0000-0000-0000-000000000000","rtype":"device"},"type":"light"}],"id":"00000000-0000-0000-0000-000000000002","type":"update"}]
2023-10-05 21:32:40.310 [DEBUG] [.internal.handler.Clip2BridgeHandler] - onResourcesEventTask() resource count 2
2023-10-05 21:32:40.312 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 00000000-0000-0000-0000-000000000000 -> updateChannels() from resource id:00000000-0000-0000-0000-000000000001, type:light
2023-10-05 21:32:40.313 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 00000000-0000-0000-0000-000000000000 -> updateState() 'brightness' update with '0' (fullUpdate:false, isDefined:true)
2023-10-05 21:32:40.314 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 00000000-0000-0000-0000-000000000000 -> updateState() 'dimming-only' update with '0' (fullUpdate:false, isDefined:true)
2023-10-05 21:32:40.316 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 00000000-0000-0000-0000-000000000000 -> updateState() 'on-off-only' update with 'ON' (fullUpdate:false, isDefined:true)
2023-10-05 21:32:40.318 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 00000000-0000-0000-0000-000000000000 -> updateState() 'alert' update with 'NO_ACTION' (fullUpdate:false, isDefined:true)
2023-10-05 21:32:40.318 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'DinnerTableLamps_Brightness' changed from 100 to 0
2023-10-05 21:32:40.321 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 00000000-0000-0000-0000-000000000000 -> updateState() 'last-updated' update with '2023-10-05T21:32:40.321365553+0200' (fullUpdate:false, isDefined:true)
2023-10-05 21:32:40.323 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 00000000-0000-0000-0000-000000000000 -> onResource() consumed resource id:00000000-0000-0000-0000-000000000001, type:light
2023-10-05 21:32:40.324 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 00000000-0000-0000-0000-000000000000 -> updateChannels() from resource id:00000000-0000-0000-0000-000000000001, type:light
2023-10-05 21:32:40.325 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 00000000-0000-0000-0000-000000000000 -> updateState() 'brightness' update with '100' (fullUpdate:false, isDefined:true)
2023-10-05 21:32:40.327 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 00000000-0000-0000-0000-000000000000 -> updateState() 'dimming-only' update with '100' (fullUpdate:false, isDefined:true)
2023-10-05 21:32:40.328 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 00000000-0000-0000-0000-000000000000 -> updateState() 'on-off-only' update with 'ON' (fullUpdate:false, isDefined:true)
2023-10-05 21:32:40.331 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 00000000-0000-0000-0000-000000000000 -> updateState() 'alert' update with 'NO_ACTION' (fullUpdate:false, isDefined:true)
2023-10-05 21:32:40.332 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 00000000-0000-0000-0000-000000000000 -> updateState() 'last-updated' update with '2023-10-05T21:32:40.332583885+0200' (fullUpdate:false, isDefined:true)
2023-10-05 21:32:40.334 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 00000000-0000-0000-0000-000000000000 -> onResource() consumed resource id:00000000-0000-0000-0000-000000000001, type:light
2023-10-05 21:32:40.330 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'DinnerTableLamps_Brightness' changed from 0 to 100

Summary to highlight the issue:

• 2023-10-05 21:32:40.198 Item 'DinnerTableLamps_Brightness' changed from 0 to 100
• 2023-10-05 21:32:40.318 Item 'DinnerTableLamps_Brightness' changed from 100 to 0
• 2023-10-05 21:32:40.330 Item 'DinnerTableLamps_Brightness' changed from 0 to 100

Although it ends with the correct state, this additional update is a problem. For example, it will cause unneeded/confusing persisted values. It also causes some strange flickering when using a slider in a sitemap to control the light.

Expected Behavior

I would expect to see only the relevant update setting brightness to 100.

Current Behavior

brightness is updated to 0 after being commanded to 100, then set back to 100.

Possible Solution

I have not looked into the code yet, but might update this issue unless someone will find the issue before me. 😉

Steps to Reproduce

See description.

Context

I have this rule to trick the Wiser dimmer into turning off when the Hue app turns it off without transition time (more details here):

rule "Wiser work-around 1"
when
    Item DinnerTableLamps_Brightness changed to 0
then
    // Work-around for required transition time for LK Wiser
    // relays and dimmers.
    if (Hue_Wiser_WorkAround.state == ON)
    {
        DinnerTableLamps_Brightness.sendCommand("0.0")
    }
end

This will be triggered by the excess update, and as a result, this rule will not work:

rule "Morning wake-up family room"
when
    Time cron "0 30 6 ? * mon,tue,wed,thu,fri"
then
   if (Hue_WakeUp_FamilyRoom.state == ON && Anyone_Home.state == ON && !Ephemeris.isBankHoliday)
   {
       DinnerTableLamps_Brightness.sendCommand(100)
   }
end

Your Environment

• Version used: 4.0

[andrewfg]

@jlaur is this issue just limited to LK Wiser products? (I don't have any such products..)

[jlaur]

is this issue just limited to LK Wiser products? (I don't have any such products..)

Actually that didn't strike my mind. I provided only that example because my "work-around rule" magnifies the problem, so this is how I fully discovered it. Before then I just had this strange impression that something was weirdly flickering when using sitemaps dimmers.

I have now made a first test with another device, a Hue White and color ambiance GU10, EAN 8719514339880. I linked the color channel to a Dimmer item named Sengelampe_Brightness and fired the command openhab:send Sengelampe_Brightness 100:

2023-10-10 21:16:20.952 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'Sengelampe_Brightness' received command 100
2023-10-10 21:16:20.953 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'Sengelampe_Brightness' predicted to become 100
2023-10-10 21:16:20.953 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Sengelampe_Brightness' changed from 0 to 100
2023-10-10 21:16:21.054 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Sengelampe_Brightness' changed from 100 to 0.4000
2023-10-10 21:16:21.055 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Sengelampe_Brightness' changed from 0.4000 to 100

It's slightly different because it changed back to 0.4 rather than 0.0, but otherwise it seems to be the same issue. It's worth noting that there is some randomness involved - it only happened on second attempt. Usually it's quite reproduceable when trying a few times.

[andrewfg]

It sounds that you have a UI page open when you make the change? I have seen previously cases where the SSE event updates the UI page with a rounding error, and the UI page then sends another command to correct the rounding error. So I suggest you try what happens also when no UI page is open, and the command is issued by a rule.

[jlaur]

So I suggest you try what happens also when no UI page is open, and the command is issued by a rule.

I closed my browser to be sure, and repeated the test with the same result.

[jlaur]

@andrewfg - have you tried also? I would be a little surprised if you are not able to reproduce this at all. If you cannot, then that bit of information might also give a clue, i.e. how to isolate it.

[andrewfg]

I will try tomorrow.

[jlaur]

On a closer look, this seems to be related to the handling of this payload:

[
	{
		"creationtime": "2023-10-05T19:32:40Z",
		"data": [
			{
				"id": "00000000-0000-0000-0000-000000000001",
				"id_v1": "/lights/40",
				"on": {
					"on": true
				},
				"owner": {
					"rid": "00000000-0000-0000-0000-000000000000",
					"rtype": "device"
				},
				"type": "light"
			},
			{
				"dimming": {
					"brightness": 100.0
				},
				"id": "00000000-0000-0000-0000-000000000001",
				"id_v1": "/lights/40",
				"owner": {
					"rid": "00000000-0000-0000-0000-000000000000",
					"rtype": "device"
				},
				"type": "light"
			}
		],
		"id": "00000000-0000-0000-0000-000000000002",
		"type": "update"
	}
]

Both resources are of type light, but only the last one contains dimming. Perhaps the first one is incorrectly handled as well with initial values, i.e. brightness considered as 0?

Based on the logs and payload, I think the flow goes like this... the two resources above are received here:

openhab-addons/bundles/org.openhab.binding.hue/src/main/java/org/openhab/binding/hue/internal/handler/Clip2BridgeHandler.java

Lines 530 to 540 in 45760bf

	private void onResourcesEventTask(List<Resource> resources) {
	logger.debug("onResourcesEventTask() resource count {}", resources.size());
	getThing().getThings().forEach(thing -> {
	ThingHandler handler = thing.getHandler();
	if (handler instanceof Clip2ThingHandler) {
	resources.forEach(resource -> {
	((Clip2ThingHandler) handler).onResource(resource);
	});
	}
	});
	}

We end on this line:

openhab-addons/bundles/org.openhab.binding.hue/src/main/java/org/openhab/binding/hue/internal/handler/Clip2ThingHandler.java

Line 661 in 45760bf

resourceConsumed = updateChannels(resource);

Then here:

openhab-addons/bundles/org.openhab.binding.hue/src/main/java/org/openhab/binding/hue/internal/handler/Clip2ThingHandler.java

Lines 861 to 881 in 45760bf

	case LIGHT:
	if (fullUpdate) {
	updateEffectChannel(resource);
	}
	updateState(CHANNEL_2_COLOR_TEMP_PERCENT, resource.getColorTemperaturePercentState(), fullUpdate);
	updateState(CHANNEL_2_COLOR_TEMP_ABSOLUTE, resource.getColorTemperatureAbsoluteState(), fullUpdate);
	updateState(CHANNEL_2_COLOR, resource.getColorState(), fullUpdate);
	updateState(CHANNEL_2_COLOR_XY_ONLY, resource.getColorXyState(), fullUpdate);
	updateState(CHANNEL_2_EFFECT, resource.getEffectState(), fullUpdate);
	// fall through for dimming and on/off related channels
	case GROUPED_LIGHT:
	if (fullUpdate) {
	updateAlertChannel(resource);
	}
	updateState(CHANNEL_2_BRIGHTNESS, resource.getBrightnessState(), fullUpdate);
	updateState(CHANNEL_2_DIMMING_ONLY, resource.getDimmingState(), fullUpdate);
	updateState(CHANNEL_2_SWITCH, resource.getOnOffState(), fullUpdate);
	updateState(CHANNEL_2_ON_OFF_ONLY, resource.getOnOffState(), fullUpdate);
	updateState(CHANNEL_2_ALERT, resource.getAlertState(), fullUpdate);
	break;

Then I'm a bit unsure what is happening, because I would have assumed that dimming is null for the first resource:

openhab-addons/bundles/org.openhab.binding.hue/src/main/java/org/openhab/binding/hue/internal/dto/clip2/Resource.java

Lines 164 to 183 in 45760bf

	/**
	* Get the brightness as a PercentType. If off the brightness is 0, otherwise use dimming value.
	*
	* @return a PercentType with the dimming state, or UNDEF, or NULL
	*/
	public State getBrightnessState() {
	Dimming dimming = this.dimming;
	if (Objects.nonNull(dimming)) {
	try {
	// if off the brightness is 0, otherwise it is dimming value
	OnState on = this.on;
	double brightness = Objects.nonNull(on) && !on.isOn() ? 0f
	: Math.max(0f, Math.min(100f, dimming.getBrightness()));
	return new PercentType(new BigDecimal(brightness, PERCENT_MATH_CONTEXT));
	} catch (DTOPresentButEmptyException e) {
	return UnDefType.UNDEF; // indicates the DTO is present but its inner fields are missing
	}
	}
	return UnDefType.NULL;
	}

[andrewfg]

A couple of general comments..

1. Resources received via SSE will have the hasSparseData flag set which means that the binding shall not expect to receive all fields. i.e. it indicates that the SSE message only contains a 'slice' of data with field(s) which have actually changed state.
2. For this reason, the handler keeps a cache of the last full state of the channel service, and when an SSE message comes in the cache is updated with its prior full data combined with the incoming new 'slice' of data here -- and then the fully updated cached value is used for updating the OH channel states.
3. You are right in that if an SSE event contains two sparse data slices sequentially, it would cause two updates of the channel state.
4. What type of lights do you have? In my own system if a light changes state, the two slices usually come in a single sparse data resource; whereas your log shows the two slices coming sequentially in two sparse resources within the same SSE message. Maybe the behaviour is different for different lights? Or maybe it depends on the bridge firmware?

[jlaur]

@andrewfg - ah, thanks, now I finally get it. I noticed hasSparseData when analyzing the code, but I failed to understand the implications of the merging with the cached Resource here:

openhab-addons/bundles/org.openhab.binding.hue/src/main/java/org/openhab/binding/hue/internal/handler/Clip2ThingHandler.java

Lines 658 to 661 in 59c3135

	Resource cachedService = serviceContributorsCache.get(incomingResourceId);
	if (Objects.nonNull(cachedService)) {
	Setters.setResource(resource, cachedService);
	resourceConsumed = updateChannels(resource);

This obviously triggers the issue I'm seeing when receiving the two mentioned objects. The first one only containing:

				"on": {
					"on": true
				},

will be merged with the current brightness which is still 0 because the next object hasn't been processed yet, and the command is not taken into consideration for this particular logic (it's not included in the cache).

Regarding type of light: LK Wiser Dimmer as well as the Hue bulb mentioned here: #15700 (comment)

However, while it may influence reproduction, the payload posted is delivered by the bridge, so we have to be able to process it correctly no matter the lights or firmware version. And it seems quite doable. The only concern I have is how generic we can fix it. In this specific case, I believe it would almost have worked if we didn't merge anything from the cache before calling updateChannels. This may then have caused the brightness to update to UnDefType.NULL rather than being skipped though.

In general, without considering implementation details yet, in which cases is it important to merge with cached data, and in which cases would it be sufficient to process only received data and update only channels for the provided sparse data? In this case it might even make sense to merge those two Resources and process as only one Resource. That would also fixed the problem. This:

			{
				"id": "00000000-0000-0000-0000-000000000001",
				"id_v1": "/lights/40",
				"on": {
					"on": true
				},
				"owner": {
					"rid": "00000000-0000-0000-0000-000000000000",
					"rtype": "device"
				},
				"type": "light"
			},
			{
				"dimming": {
					"brightness": 100.0
				},
				"id": "00000000-0000-0000-0000-000000000001",
				"id_v1": "/lights/40",
				"owner": {
					"rid": "00000000-0000-0000-0000-000000000000",
					"rtype": "device"
				},
				"type": "light"
			}

merged into:

			{
				"id": "00000000-0000-0000-0000-000000000001",
				"id_v1": "/lights/40",
				"on": {
					"on": true
				},
				"dimming": {
					"brightness": 100.0
				},
				"owner": {
					"rid": "00000000-0000-0000-0000-000000000000",
					"rtype": "device"
				},
				"type": "light"
			}

and then merged with the cache would probably produce the correct result. However, it would be only a partial fix, as it would still not work if we received those two data packets separately with a few milliseconds between them.

[andrewfg]

Yeah. The two event 'slices' could arrive in any of three ways..

1. As two fields within a single DTO in a single SSE event message
2. As individual fields in two DTOs in a single SSE event message
3. As individual fields in two DTOs in two separate SSE event messages

FWIW I have only Philips lamps (of various varieties) and as a general rule case 1. is by far the most common.

[andrewfg]

@jlaur thinking about this further, I am not even sure that I would class this behaviour as a bug. Rather I would class it as a simple fact. As discussed quite frequently and heatedly during the development process, the various state attributes on-off, dimming, color-xy and color-temperature are orthogonal .. that is to say, principally, that each such attribute can change state without influencing the other. (The exception is color-xy and color-temperature where there IS a cross linkage due to color temperatures being a limited arc of values on the color XY gamut). As I stressed before, the real problem is within OH when one tries to map these orthogonal state attributes into a single HSB entity. And as I said before, this is the reason why I fought so strongly to maintain the (orthogonal) "abc-only" channels. Facit: beware of trying to "fix" a problem that is OH self created -- you may end up just making the self created problem worse!

[jlaur]

There is one more issue. If the events are received apart:

[
	{
		"creationtime": "2023-11-30T22:41:08Z",
		"data": [
			{
				"id": "00000000-0000-0000-0000-000000000001",
				"id_v1": "/lights/40",
				"on": {
					"on": true
				},
				"owner": {
					"rid": "00000000-0000-0000-0000-00000000000",
					"rtype": "device"
				},
				"type": "light"
			}
		],
		"id": "00000000-0000-0000-0000-000000000009",
		"type": "update"
	}
]

and:

[
	{
		"creationtime": "2023-11-30T22:41:25Z",
		"data": [
			{
				"dimming": {
					"brightness": 100.0
				},
				"id": "00000000-0000-0000-0000-000000000001",
				"id_v1": "/lights/40",
				"owner": {
					"rid": "00000000-0000-0000-0000-000000000000",
					"rtype": "device"
				},
				"type": "light"
			}
		],
		"id": "00000000-0000-0000-0000-000000000009",
		"type": "update"
	}
]

We will have the same issue when the current dimming is 0. Example:

• Initial: device is off, dimming is 0.
• First event: Device is now on, but still brightness is 0. So actually it's still off (only on-off-only is on).
• Second event then fixes the state.

So what can we do about this? When we receive on=on, we should assume brightness > 0, since otherwise HSB will be off, and we have an inconsistent state (it can't be both on and 0).

[andrewfg]

So what can we do about this? When we receive on=on, we should assume brightness > 0, since otherwise HSB will be off, and we have an inconsistent state (it can't be both on and 0).

By pure physics, a lamp cannot be both on and have brightness = 0. If it has transitioned from off and B=0 to on, (with B not yet defined), then probably B = the minimum dimming level for the particular lamp.

[jlaur]

By pure physics, a lamp cannot be both on and have brightness = 0. If it has transitioned from off and B=0 to on, (with B not yet defined), then probably B = the minimum dimming level for the particular lamp.

If you are fine with fixing this issue, we could include it in #15905 - WDYT?

The only thing is which value to use. Brightness is actually missing - it's undefined, so we don't know the actual value, we only know that it must be > 0.

We could use minimum dimming as you suggest, but we could also use 100%. In real life I have only observed the latter. When I turn on the lamp either from an openHAB command or from a physical button, it turns on with 100% brightness, and the messages received are pasted above. This happens sometimes. Other times, I get both events in the same packet (i.e. fixed by the merge).

I can also turn it on to a specific dimming level. In this case it wouldn't be 100%, but it wouldn't be minimum dimming level either. So it's not possible to correctly predict the brightness, we can only guess.

[andrewfg]

I have no problem if you assume B = 100. The actual B value would come via SSE anyway I suppose.

And yes, let us add this to the PR merge function