Odd problem with getStateAs

cdstaley · November 15, 2020, 2:35am

Platform information: PC
- Hardware: CPUArchitecture/RAM/storage
- OS: _what OS is used and which version_Win 10
- Java Runtime Environment: which java platform is used and what version
- openHAB version:
Issue of the topic: please be detailed explaining your issue
I’m testing the state of a light to determine if it is on or off and then flip it the opposite. When the rule starts out I get on, on, on all the time. I have a test light that is working perfectly, but the problem light just gets ON, ON, ON etc. The odd part is I can turn the light OFF and then everything works correctly. All I can guess is there is some faulty initial condition that gets set only after one alternate (that’s a leap) command is sent?
Please post configurations (if applicable):
- Items configuration related to the issue
- Sitemap configuration related to the issue
- Rules code related to the issue
- Services configuration related to the issue
If logs where generated please post these here using code fences:

                timer = createTimer(now, [ |
                     
                    Outdoor_Perimeter_Color.sendCommand(if(Outdoor_Perimeter_Color.getStateAs(OnOffType) == ON) OFF else ON)
                                 Test_Color.sendCommand(if(Test_Color.getStateAs(OnOffType) == ON) OFF else ON)
                    if(now.isBefore(timeStarted.plusMinutes(240)))  timer.reschedule(now.plusSeconds(2))         
                    else timer = null
                ] )

The Outdoor_Perimeter_Color doesn’t work, but the Test_Color with the same bulb does work? The later is closer to the transceiver but I thought the state was stored inside openhab, not poled from the HW. Finally, I’m going to just try and initialize it with some value as a work around. Like I said, it will work after I tag it OFF when it’s on. Have not tested ON when it is OFF.

Thanks

opus · November 15, 2020, 8:27am

Actually I do not get what you are trying to do.

That sounds as if you have a device that doesn’t report its state back to openHAB. Is that assumption correct? What kind of device is it? How is it connected to openHAB?

rlkoshak · November 15, 2020, 5:14pm

log out the state of the item. I’ve no idea what getStateAs returns when the Item is NULL or UNDEF. That might explain the other problem.

Watch events.log to see the states of the Item and how is changing.

Post this information here and we can help more. I’m skeptical that the problem is getStateAs itself.

cdstaley · November 17, 2020, 12:07am

Warning, long log. Summary: I fired it up and both the target light and the test light were blinking as seen in the full logs.

2020-11-16 18:55:08.452 [ome.event.ItemCommandEvent] - Item 'Outdoor_Perimeter_Color' received command ON
2020-11-16 18:55:08.498 [ome.event.ItemCommandEvent] - Item 'Test_Color' received command OFF
2020-11-16 18:55:08.680 [vent.ItemStateChangedEvent] - Test_Color changed from 49.6063,100.0,100 to 49.6063,100.0,0
==> /var/log/openhab2/openhab.log <==
2020-11-16 18:55:10.437 [DEBUG] [t.internal.actions.TimerExecutionJob] - Executing timer 'DEFAULT.Timer 28 2020-11-16T18:40:00.220-05:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: [ | {
  <XFeatureCallImplCustom>.sendCommand(<XIfExpressionImpl>)
  <XFeatureCallImplCustom>.sendCommand(<XIfExpressionImpl>)
  org.eclipse.xtext.xbase.impl.XIfExpressionImpl@16de6c2 (conditionalExpression: false)
} ]'
==> /var/log/openhab2/events.log <==
2020-11-16 18:55:10.481 [ome.event.ItemCommandEvent] - Item 'Outdoor_Perimeter_Color' received command ON
2020-11-16 18:55:10.513 [ome.event.ItemCommandEvent] - Item 'Test_Color' received command ON
2020-11-16 18:55:10.699 [vent.ItemStateChangedEvent] - Test_Color changed from 49.6063,100.0,0 to 49.6063,100.0,100
2020-11-16 18:55:10.709 [vent.ItemStateChangedEvent] - Test_Color changed from 49.6063,100.0,100 to 49.6063,100.0,2
2020-11-16 18:55:11.431 [ome.event.ItemCommandEvent] - Item 'Outdoor_Perimeter_Color' received command OFF
==> /var/log/openhab2/openhab.log <==
2020-11-16 18:55:12.467 [DEBUG] [t.internal.actions.TimerExecutionJob] - Executing timer 'DEFAULT.Timer 28 2020-11-16T18:40:00.220-05:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: [ | {
  <XFeatureCallImplCustom>.sendCommand(<XIfExpressionImpl>)
  <XFeatureCallImplCustom>.sendCommand(<XIfExpressionImpl>)
  org.eclipse.xtext.xbase.impl.XIfExpressionImpl@16de6c2 (conditionalExpression: false)
} ]'
==> /var/log/openhab2/events.log <==
2020-11-16 18:55:12.513 [ome.event.ItemCommandEvent] - Item 'Outdoor_Perimeter_Color' received command ON
2020-11-16 18:55:12.542 [ome.event.ItemCommandEvent] - Item 'Test_Color' received command OFF
2020-11-16 18:55:12.799 [vent.ItemStateChangedEvent] - Test_Color changed from 49.6063,100.0,2 to 49.6063,100.0,98
2020-11-16 18:55:12.817 [vent.ItemStateChangedEvent] - Test_Color changed from 49.6063,100.0,98 to 49.6063,100.0,0
2020-11-16 18:55:12.869 [vent.ItemStateChangedEvent] - Outdoor_Perimeter_Color changed from 49.6063,100.0,0 to 49.6063,100.0,100
==> /var/log/openhab2/openhab.log <==
2020-11-16 18:55:14.497 [DEBUG] [t.internal.actions.TimerExecutionJob] - Executing timer 'DEFAULT.Timer 28 2020-11-16T18:40:00.220-05:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: [ | {
  <XFeatureCallImplCustom>.sendCommand(<XIfExpressionImpl>)
  <XFeatureCallImplCustom>.sendCommand(<XIfExpressionImpl>)
  org.eclipse.xtext.xbase.impl.XIfExpressionImpl@16de6c2 (conditionalExpression: false)
} ]'
==> /var/log/openhab2/events.log <==
2020-11-16 18:55:14.532 [ome.event.ItemCommandEvent] - Item 'Outdoor_Perimeter_Color' received command OFF
2020-11-16 18:55:14.561 [ome.event.ItemCommandEvent] - Item 'Test_Color' received command ON
2020-11-16 18:55:14.737 [vent.ItemStateChangedEvent] - Test_Color changed from 49.6063,100.0,0 to 49.6063,100.0,98
2020-11-16 18:55:14.775 [vent.ItemStateChangedEvent] - Test_Color changed from 49.6063,100.0,98 to 49.6063,100.0,1
2020-11-16 18:55:14.810 [vent.ItemStateChangedEvent] - Outdoor_Perimeter_Color changed from 49.6063,100.0,100 to 49.6063,100.0,0
==> /var/log/openhab2/openhab.log <==
2020-11-16 18:55:16.526 [DEBUG] [t.internal.actions.TimerExecutionJob] - Executing timer 'DEFAULT.Timer 28 2020-11-16T18:40:00.220-05:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: [ | {
  <XFeatureCallImplCustom>.sendCommand(<XIfExpressionImpl>)
  <XFeatureCallImplCustom>.sendCommand(<XIfExpressionImpl>)
  org.eclipse.xtext.xbase.impl.XIfExpressionImpl@16de6c2 (conditionalExpression: false)
} ]'
==> /var/log/openhab2/events.log <==
2020-11-16 18:55:16.578 [ome.event.ItemCommandEvent] - Item 'Outdoor_Perimeter_Color' received command ON
2020-11-16 18:55:16.607 [ome.event.ItemCommandEvent] - Item 'Test_Color' received command OFF
2020-11-16 18:55:16.767 [vent.ItemStateChangedEvent] - Test_Color changed from 49.6063,100.0,1 to 49.6063,100.0,0
2020-11-16 18:55:16.833 [vent.ItemStateChangedEvent] - Outdoor_Perimeter_Color changed from 49.6063,100.0,0 to 49.6063,100.0,100
2020-11-16 18:55:16.924 [vent.ItemStateChangedEvent] - Outdoor_Perimeter_Color changed from 49.6063,100.0,100 to 49.6063,100.0,0
2020-11-16 18:55:17.729 [vent.ItemStateChangedEvent] - Outdoor_Perimeter_Color changed from 49.6063,100.0,0 to 49.6063,100.0,100
==> /var/log/openhab2/openhab.log <==
2020-11-16 18:55:18.562 [DEBUG] [t.internal.actions.TimerExecutionJob] - Executing timer 'DEFAULT.Timer 28 2020-11-16T18:40:00.220-05:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: [ | {
  <XFeatureCallImplCustom>.sendCommand(<XIfExpressionImpl>)
  <XFeatureCallImplCustom>.sendCommand(<XIfExpressionImpl>)
  org.eclipse.xtext.xbase.impl.XIfExpressionImpl@16de6c2 (conditionalExpression: false)

This is a section filtered on just command to make it smaller. For some strange reason the Target light starts receiving only ONs. Nothing has been touched. Oddly, the test light is still blinking. I thought that state was an internal representation based on last issued command, not an interrogation of the thing. That is why I’m perplexed as to why it changes it’s state. I suspect I could do a work around possibly test for null, or put in the blinking code if OFF or NULL turn on? Not sure the syntax for that?

2020-11-16 18:56:38.017 [ome.event.ItemCommandEvent] - Item 'Test_Color' received command OFF
  <XFeatureCallImplCustom>.sendCommand(<XIfExpressionImpl>)
  <XFeatureCallImplCustom>.sendCommand(<XIfExpressionImpl>)
2020-11-16 18:56:40.032 [ome.event.ItemCommandEvent] - Item 'Outdoor_Perimeter_Color' received command OFF
2020-11-16 18:56:40.061 [ome.event.ItemCommandEvent] - Item 'Test_Color' received command ON
  <XFeatureCallImplCustom>.sendCommand(<XIfExpressionImpl>)
  <XFeatureCallImplCustom>.sendCommand(<XIfExpressionImpl>)
2020-11-16 18:56:42.063 [ome.event.ItemCommandEvent] - Item 'Outdoor_Perimeter_Color' received command ON
2020-11-16 18:56:42.090 [ome.event.ItemCommandEvent] - Item 'Test_Color' received command ON
  <XFeatureCallImplCustom>.sendCommand(<XIfExpressionImpl>)
  <XFeatureCallImplCustom>.sendCommand(<XIfExpressionImpl>)
2020-11-16 18:56:44.098 [ome.event.ItemCommandEvent] - Item 'Outdoor_Perimeter_Color' received command OFF
2020-11-16 18:56:44.129 [ome.event.ItemCommandEvent] - Item 'Test_Color' received command ON
  <XFeatureCallImplCustom>.sendCommand(<XIfExpressionImpl>)
  <XFeatureCallImplCustom>.sendCommand(<XIfExpressionImpl>)
2020-11-16 18:56:46.120 [ome.event.ItemCommandEvent] - Item 'Outdoor_Perimeter_Color' received command ON
2020-11-16 18:56:46.164 [ome.event.ItemCommandEvent] - Item 'Test_Color' received command OFF
  <XFeatureCallImplCustom>.sendCommand(<XIfExpressionImpl>)
  <XFeatureCallImplCustom>.sendCommand(<XIfExpressionImpl>)
2020-11-16 18:56:48.148 [ome.event.ItemCommandEvent] - Item 'Outdoor_Perimeter_Color' received command OFF
2020-11-16 18:56:48.184 [ome.event.ItemCommandEvent] - Item 'Test_Color' received command ON
  <XFeatureCallImplCustom>.sendCommand(<XIfExpressionImpl>)
  <XFeatureCallImplCustom>.sendCommand(<XIfExpressionImpl>)
2020-11-16 18:56:50.189 [ome.event.ItemCommandEvent] - Item 'Outdoor_Perimeter_Color' received command ON
2020-11-16 18:56:50.221 [ome.event.ItemCommandEvent] - Item 'Test_Color' received command OFF
  <XFeatureCallImplCustom>.sendCommand(<XIfExpressionImpl>)
  <XFeatureCallImplCustom>.sendCommand(<XIfExpressionImpl>)
2020-11-16 18:56:52.222 [ome.event.ItemCommandEvent] - Item 'Outdoor_Perimeter_Color' received command ON
2020-11-16 18:56:52.257 [ome.event.ItemCommandEvent] - Item 'Test_Color' received command ON
  <XFeatureCallImplCustom>.sendCommand(<XIfExpressionImpl>)
  <XFeatureCallImplCustom>.sendCommand(<XIfExpressionImpl>)
2020-11-16 18:56:54.270 [ome.event.ItemCommandEvent] - Item 'Outdoor_Perimeter_Color' received command ON
2020-11-16 18:56:54.303 [ome.event.ItemCommandEvent] - Item 'Test_Color' received command ON
  <XFeatureCallImplCustom>.sendCommand(<XIfExpressionImpl>)
  <XFeatureCallImplCustom>.sendCommand(<XIfExpressionImpl>)
2020-11-16 18:56:56.285 [ome.event.ItemCommandEvent] - Item 'Outdoor_Perimeter_Color' received command ON
2020-11-16 18:56:56.317 [ome.event.ItemCommandEvent] - Item 'Test_Color' received command OFF
  <XFeatureCallImplCustom>.sendCommand(<XIfExpressionImpl>)

As always, thanks!
Cliff

opus · November 17, 2020, 6:54am

How are we supposed to know?
Please post the full rule code, the type of switches used for the light used an the way it is connected to openHAB.

rlkoshak · November 17, 2020, 3:53pm

It doesn’t interrogate the Thing, but what is happening depends on the device, the technology, and the binding.

If you have autoupdate set to false, the Item will not change state in response to a command. it will remain in it’s old state until the binding updates it after the device responds to the latest command.

Note that not all technologies/bindings can respond with the devices actual state. If it’s a technology that takes on polling to find out the devices actual state, there can be quite some time between when the command is sent and the binding updates the item.

I wonder if that’s happening here.

Notice that at 18:55:08 the Outdoor Item receives an ON command but it doesn’t change. Maybe because it was already ON? The Test Item receives the OFF command and you see it changing to OFF (the 0 in the third number indicates OFF).

Then at 18:55:10 it receives an ON command again. That indicates that it isn’t already ON and at 18:55:10 Outdoor is still OFF at that time. And once again, we do not see the Outdoor Item changing. The Test Item receives an ON command and we see it changing first from OFF to full brightness and then back to brightness 2.

At 18:55:11 we see Outdoor receiving an OFF command. Where did that come from? It is not coming from your Rule or the Timer. Did you command it manually? And still, we do not see Outdoor changing in response to the command.

Then at 18:55:12 we see Outdoor receiving an ON command again. This time we actually see it change from OFF to ON. So all this time it’s been OFF all along, or NULL or UNDEF.

At 18:55:14 Outdoor is commanded OFF which is correct because we now know for sure it was ON. And we see it changing from ON to OFF.

At 18:55:16 we see Outdoor commanded ON which is correct because we know it’s OFF. But then we see it flip from OFF to ON, ON to OFF, and OFF to ON again within the space of a second. Notice how we do not have any responses from the first two ON commands, Are these the responses finally? Did you flip it manually?

Anyway, if Outdoor were NULL or UNDEF when all this started what probably happened was:

Time	Outdoor State	Event
08	NULL	The Item is not ON so an ON command was sent
10	Still NULL	The Item is not ON so an ON command was sent
11	Still NULL	The Item is commanded to OFF from somewhere and it actually changes to OFF in response to this command.
12	OFF	The Item is OFF so it’s commanded to ON and we see the Item changing from OFF to ON
14	ON	The Item is ON so it’s commanded to OFF and we see it changing from ON to OFF
16	OFF	The Item is OFF so it’s commanded to ON and we see it changing from OFF to ON
16	ON	The Item changes to OFF in response to something
17	OFF	The Item changes to ON in response to something

The rule is working correctly. There is something else going on here. Why did it not respond to the very first two ON commands by changing the Item’s states? Where did that stray OFF command come from? But once that OFF command was received, at least for awhile, the rule was works as expected. But then there are two state changes coming from nowhere.

Was the device offline perhaps? Are you using autoupdate=false on these Items? What binding is the Outdoor Item linked to? What really is the state of the Outdoor Item before these logs? What logs is the binding producing when the rule isn’t working (you may need to put the binding into debug or trace logging)? These are all questions you will need to answer. But ultimately, I think the problem lies with the binding. Either the binding is not working correctly, or it’s not working the way you expect it to work.

cdstaley · November 17, 2020, 6:22pm

A little clarification:

• The initial ON does turn on the device, I can see it ON. Then for reasons I can’t explain the test thinks it’s OFF so it sends a command ON
• That continues for some time with ON ON ON.
• While this was happening I sent an OFF command (sort of forcing a state change) It worked, the unit went OFF and on the next pass through the loop it went ON OFF ON OFF
• As time goes by the outdoor unit just stays ON? But the rule aka the test thinks its OFF or (not sure NULL) and send another ON command.

I’m pretty sure this is timing, but I found it interesting that the binding does interrogate the device, albeit in its own time. I did observe this when doing a small test and inserting a 1sec delay to get it to update? Not conclusive. I do see that the test light works correctly…until it doesn’t. Have not investigated that, just walked in room saw off. Started looking around and within 10mins started blinking again? Need more work.

Bottom line: can I test for NULL, or can I force the state to be OFF. If so it’s a kludge but if it works sobeit! This is a Sylvania bulb. Rumor has it they are not really good at meeting the standards.

I guess with all the trouble I could spring for a Philips Hue!

I’m open to suggestions on how identify the root cause!

Cds

rlkoshak · November 17, 2020, 10:00pm

Nothing has told openHAB that it’s ON though. Do you have autoupdate=false on this Item? If so it won’t change the Item to ON until the binding does it. And that could take some time for some technologies.

By all appearances the problem is the device is not reporting the state changes in the lights in a timely manner.

Of course

if(MyItem.state == NULL)

Probably not. And you don’t want to anyway because that will even more likely make it such that the Item ends up out of sync with the device.

Ultimately, you will need to generate debug or trace logs from the binding and probably file an issue. It might just be a limitation with the technology or the binding.