De-activated or "forgotten" rules

Hello,
I am using LG webOS binding to control my TV. Unfortunately it can only switch power off, but not on.
This is where the “Wake on LAN” binding comes to play (not my idea…). It works like a charm and it works reliably so far.

But what does not work reliably for me is the combination. I have a rule for that (not my idea…):

rule "Power on TV via Wake on LAN"
when 
Item LG_TV0_Power received command ON
then
	sendCommand( Network_WOL_LGTV, ON) 
end

So my sitemap has onl a single switch for LG_TV0_Power, and when I switch ON, it automagically generates a Wake On LAN and TV starts.

This rule works initially (for some hours I can switch on/off my TV reliably.
But after 24 hours it does not work anymore.
When I now “touch” the rule via ssh, openhab “remembers” (re-reads) it and it works again.

This is only the ruly which fails, directly triggering the WOL command works at any time.

Any ideas what is going on here?

Best regards,
Michael

Add some logging to the rule so you can see if the problem is with your Rule or with the WOL binding. If you see your log statement in the logs but the TV doesn’t wake up then you know the problem is with the WOL.

OK, did it. So far it works; in openhab.log I get::

2017-11-02 07:48:57.563 [INFO ] [eclipse.smarthome.model.script.myWOL] - Before sending WOL
2017-11-02 07:48:57.574 [INFO ] [nhab.binding.wol.internal.WolBinding] - Wake-on-LAN packet sent [broadcastIp=192.168.1.255, macaddress=14c9138df6cd]
2017-11-02 07:48:57.574 [INFO ] [eclipse.smarthome.model.script.myWOL] - After sending WOL

and in events.log I get:

2017-11-02 07:48:57.573 [ItemCommandEvent ] - Item ‘Network_WOL_LGTV’ received command ON
2017-11-02 07:48:57.597 [ItemStateChangedEvent ] - Network_WOL_LGTV changed from OFF to ON
2017-11-02 07:49:03.151 [ItemStateChangedEvent ] - Network_WOL_LGTV changed from ON to OFF
2017-11-02 07:49:05.608 [hingStatusInfoChangedEvent] - ‘lgwebos:WebOSTV:192_168_1_134’ changed from OFFLINE: TV is off to ONLINE: Device Ready
2017-11-02 07:49:05.931 [hingStatusInfoChangedEvent] - ‘lgwebos:WebOSTV:192_168_1_134’ changed from ONLINE: Device Ready to ONLINE: Connected
2017-11-02 07:49:05.967 [ItemStateChangedEvent ] - LG_TV0_Power changed from OFF to ON

so everything runs smoothly. I’ll dump the logs again once it wont work.

Here we are again: I just tried to switch the TV on and only got (in events.log):

2017-11-03 07:26:28.521 [ItemCommandEvent ] - Item 'LG_TV0_Power' received command ON

and nothig else in openhab.log.

Now I do:

[19:49:12] openhabian@openHABianPi:~$ touch /etc/openhab2/rules/lg.rules

Now openhab,log states this single line:

2017-11-03 07:32:10.884 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'lg.rules'

And everything works again. When I now switch on the TV I get in openhab.log:

2017-11-03 07:32:59.197 [INFO ] [eclipse.smarthome.model.script.myWOL] - Before sending WOL
2017-11-03 07:32:59.206 [INFO ] [eclipse.smarthome.model.script.myWOL] - After sending WOL
2017-11-03 07:32:59.226 [INFO ] [nhab.binding.wol.internal.WolBinding] - Wake-on-LAN packet sent [broadcastIp=192.168.1.255, macaddress=14c9138df6cd]

and in events,log:

2017-11-03 07:32:58.290 [ItemCommandEvent          ] - Item 'LG_TV0_Power' received command ON
2017-11-03 07:32:59.206 [ItemCommandEvent          ] - Item 'Network_WOL_LGTV' received command ON
2017-11-03 07:32:59.215 [ItemStateChangedEvent     ] - Network_WOL_LGTV changed from NULL to ON
2017-11-03 07:33:03.826 [hingStatusInfoChangedEvent] - 'lgwebos:WebOSTV:192_168_1_134' changed from OFFLINE: TV is off to ONLINE: Device Ready
2017-11-03 07:33:04.812 [ItemStateChangedEvent     ] - Network_WOL_LGTV changed from ON to OFF
2017-11-03 07:33:05.455 [hingStatusInfoChangedEvent] - 'lgwebos:WebOSTV:192_168_1_134' changed from ONLINE: Device Ready to ONLINE: Connected
2017-11-03 07:33:05.477 [ItemStateChangedEvent     ] - LG_TV0_Power changed from OFF to ON
.

I’ve done nothing else to the system, only touched the rules file. I didnt even have to login or so, all ssh connections with “tail-f” etc. were already up and running.

Maybe you understand my impressions that my problem relates to rules processing.

Kind regards, Michael

Hmmm. I still have one idea I didn’t check. But I can only check later today…

I suspected there might be issues with having switched off the TV manually and openHAB “didn’t know”, so switching it on again might not have triggered a change. But as you can see in my previous posts, it is not a “on change” rule. And I have the trigger condition clearly in the logfile. Still I have some doubts, as the item file states:

Switch LG_TV0_Power "Fernseher Wohnzimmer" <television> (Group_Wohnzimmer) ["Switchable"] { autoupdate="false", channel="lgwebos:WebOSTV:192_168_1_134:power" }

OK, the problem is clearly the Rules. That is good. We might have a chance at figuring it out without needing to modify the WOL binding.

The behavior is indeed odd to me. Even though LG_TV0_Power is already ON the rule should trigger when the Item receives another ON command. I do this pretty routinely.

When your TV powers down, does it stop responding to a ping? You could set up a Network binding and use when it stops responding to turn off the LG_TV0_Power Item. Assuming that is the problem that would be a workaround. Plus it gives you a way to keep that Item up to date.

The autoupdate=false could potentially be causing some issues. I’m not fully up on how that binding works. Since you only have one channel linked to this Item, you shouldn’t need to use autoupdate. The purpose of that binding is to help avoid feedback loops when you have more than one binding or channel linked to the same Item.

My explanation for the autoupdate=false was that maybe the binding is not good at figuring out the current state, so it simply relies only on the bookkeeping of the item.

When I switch off the TV manually (w/o openHAB), openHAB still “thinks” the TV is on. This is probably a consequence of the autoupdate=false. But it logs some connection errors:

2017-11-03 21:37:18.950 [WARN ] [.lgwebos.handler.VolumeControlVolume] - 0 null connection lost
2017-11-03 21:37:18.951 [WARN ] [lgwebos.handler.TVControlChannelName] - 0 null connection lost
2017-11-03 21:37:18.954 [WARN ] [.lgwebos.handler.LauncherApplication] - 0 null connection lost
2017-11-03 21:37:18.950 [WARN ] [ng.lgwebos.handler.VolumeControlMute] - 0 null connection lost
2017-11-03 21:37:21.498 [WARN ] [lgwebos.handler.TVControlChannelName] - 500 {"errorText":"handler_broadcast_setPIPon Error","returnValue":false,"errorCode":"BROADCAST_ERROR_06"} Application error

The switch stays “ON”: No further output in events.log.

The device indeed keeps responding to ICMP echo (ping) requests.

[07:32:09] openhabian@openHABianPi:~$ ping 192.168.1.134
PING 192.168.1.134 (192.168.1.134) 56(84) bytes of data.
64 bytes from 192.168.1.134: icmp_seq=1 ttl=64 time=0.564 ms
64 bytes from 192.168.1.134: icmp_seq=2 ttl=64 time=0.580 ms
64 bytes from 192.168.1.134: icmp_seq=3 ttl=64 time=0.589 ms

After 5 more minutes, the binding seems to get nervous, and now it finally changes state (events.log):

2017-11-03 21:42:08.287 [InboxRemovedEvent         ] - Discovery Result with UID 'samsungtv:tv:2ae59f4a_8003_6c98_75c1_00b108b13874' has been removed.
2017-11-03 21:42:08.296 [hingStatusInfoChangedEvent] - 'samsungtv:tv:tv9070' changed from ONLINE to OFFLINE
2017-11-03 21:43:46.761 [ItemStateChangedEvent     ] - LG_TV0_Power changed from ON to OFF
2017-11-03 21:43:46.770 [hingStatusInfoChangedEvent] - 'lgwebos:WebOSTV:192_168_1_134' changed from ONLINE: Connected to OFFLINE: TV is off

But when I now switch it back on, the WOL rule works, and it comes back to life.

When I now restart openhab2.service, it has the TV in undefined state. When I now try to switch it on and off again I get:

2017-11-03 22:01:39.646 [WARN ] [nding.lgwebos.handler.LGWebOSHandler] - Unable to handle command ON for channel lgwebos:WebOSTV:192_168_1_134:power. Device lgwebos:WebOSTV:192_168_1_134 not found. This should not happen at this point.
2017-11-03 22:01:46.130 [WARN ] [nding.lgwebos.handler.LGWebOSHandler] - Unable to handle command OFF for channel lgwebos:WebOSTV:192_168_1_134:power. Device lgwebos:WebOSTV:192_168_1_134 not found. This should not happen at this point.

Paper UI has the thing in “offline” state. But this is different from the problem discribed above, because there is no state change to trigger the rule.

When I trigger WOL now manually, TV goes back on. Maybe the rule could be formulated so that it triggers in this situation. But like said: the “original” bug comes when I really get the state change in the log but the rule does not fire. And as long as I cannot trust the rule itself, how could I trust any other “workaround” rule?

The workaround is probably something you need to do anyway but the main point is not to use the workaround as a solution but to figure out more details about when and how the rule is failing to run.

Yours is the first report I’ve seen in all the years I’ve been on this forum (and the Google forums before that) that is anything like this. I’m frankly incredulous that the problem really is that the Rule isn’t triggering and I’m thinking the problem must have something to do with the bindings involved or something else is going on (e.g. the autoupdate=false is suppressing the event from getting to the Rule).

Yes, it seems somehow improbable that if we had such a bug in openHAB, I would be the only one to stumble into it. So the circumstance with autoupdate might play a role. Maybe it still is a bug, but some bug which only shows under these special circumstances.

If you have an idea what else could be logged to nail down the problem, just give me a hint.

There are still other things which do not fully work as intended, but stuff I only wanted to start discussion once this WOL-rule stuff is under control. But now I ask myself how “unrelated” other effects really are. E.g. my homegear connection seems to be unstable. Homegear runs on the same Raspi, and 127.0.0.1 should be a quite reliable interface. Still I very regularly get:

2017-11-02 00:20:48.033 [INFO ] [ommunicator.AbstractHomematicGateway] - No event since 346 seconds from gateway 'ccu', restarting RPC server
2017-11-02 00:26:48.059 [INFO ] [ommunicator.AbstractHomematicGateway] - No event since 325 seconds from gateway 'ccu', restarting RPC server
2017-11-02 00:42:48.093 [INFO ] [ommunicator.AbstractHomematicGateway] - No event since 337 seconds from gateway 'ccu', restarting RPC server
2017-11-02 00:42:48.695 [WARN ] [ommunicator.AbstractHomematicGateway] - Address already in use (Bind failed)
2017-11-02 00:43:48.699 [INFO ] [ommunicator.AbstractHomematicGateway] - No event since 398 seconds from gateway 'ccu', restarting RPC server
2017-11-02 00:44:48.722 [INFO ] [ommunicator.AbstractHomematicGateway] - No event since 458 seconds from gateway 'ccu', restarting RPC server

When some subsystems are restarted, might this be related to “forgotten rules”? Normally not, so this issue is maybe a topic for a future thread (I read other threads with this error, but the solutions there didn’t apply to my situaton; especailly th “Address already in use” is frightening).

There is another thing I’d like to mention: I mostly change sitemaps and item-files with openhab running. This often seems to have some timing problem, when the autodetect mechanism tries to read the file, but hits EOF right at the start. Quite oftern and reproducible if I change the file using SMB protocoll, less often but still regularly if I change the file using WinSCP over ssh. In many cases the system re-read and stabilizes immediately afterwards, in some cases not. Then I “touch” the file from a ssh-shell of the raspberry, and everything is fine again. I am noit sure if this is the normal behaviour of openHAB redeployment mechanism.

This is a known thing, particularly over samba. OH subscribes to file system events. Samba, and perhaps WinSCP generates two file events when you save a file, one when it first starts and another when it is done writing. Both events trigger OH to try and load the file. The first event causes OH to read an empty or potentially a partial file and then OH reads the full file when the second event occurs.

This is unrelated to your Rule problem.

The Bind fail means that there is already something running on the port that the HomematiceGateway (or whatever, I don’t know this binding) is trying to open and listen on. This could be caused by an old instance of the binding still somehow hanging aroud bound to that port or you have some other service or daemon bound to the port.

This could be related to your rule problem but it doesn’t seem like it should be.

The instability of the connection though probably has more to do with problems with the service itself and not the network. Like I said, I don’t know this binding or technology so can’t be any more specific.

Out of curiosity:

  • when the rule doesn’t work, does the TV still respond to pings?
  • does the TV remain on the same IP address?
  • if you remove the autoupdate=false does that change anything at all behavior wise?
  • if you create a rule to set LG_TV0_Power to OFF before you send the command to turn it back ON (maybe have a rule that triggers an hour after the last time you turn it ON to turn it OFF using postUpdate)?
  • what happens when you use postUpdate?

Those are the things I’d try next.

Don’t know, need to check next time.

Yes, definitely.

I would have to check all of these; but a rule to switch off TV one hour after it was switched on might drastically reduce the tolerance of my family towards home automation…

Don’t actually switch off the TV. Just change the power Item to OFF using postUpdate. Only OH’s internal state will change. The TV itself will remain on.

When I run into situations like this, I usually try to change the rule triggers to make sure things are working like I’m assuming. In your case maybe the item is getting an update vs a command or vice versa.

I’d be interested to see what happens if you add rules just containing log statements for both LG_TV0_Power and Network_WOL_LGTV using the triggers “received command” (without the ON you currently have), “received update”, and “changed”.

If you do 6 rules with each pair of item and trigger, each containing a lot statement, it should be educational about what’s going on internally and may be enough info to solve the issue.

I like this idea. I’ll put something together later today.

BTW: Found out that I can more or less reliably stop that rule from triggering, just by restarting openhab.
(The details are different from those states I get when switching off the TV manually or wait 24h.)

sudo systemctl restart openhab2.service

Other rules (like the one that links my front door motion detector with the front door light) always “survive” a restart; the WOL rule doesn’t…

I didn’t expect it but when TV is switched off (awaiting WOL) it still reacts to PING.

OK. Added additional debugging rules:

rule "LG_TV0_Power received command"
when 
Item LG_TV0_Power received command
then
	logInfo("myWOL", "!!! LG_TV0_Power received command")
end

rule "LG_TV0_Power received update"
when 
Item LG_TV0_Power received update
then
	logInfo("myWOL", "!!! LG_TV0_Power received update")
end

rule "LG_TV0_Power changed"
when 
Item LG_TV0_Power changed
then
	logInfo("myWOL", "!!! LG_TV0_Power changed")
end

rule "Network_WOL_LGTV received command"
when 
Item Network_WOL_LGTV received command
then
	logInfo("myWOL", "!!! Network_WOL_LGTV received command")
end

rule "Network_WOL_LGTV received update"
when 
Item Network_WOL_LGTV received update
then
	logInfo("myWOL", "!!! Network_WOL_LGTV received update")
end

rule "Network_WOL_LGTV changed"
when 
Item Network_WOL_LGTV changed
then
	logInfo("myWOL", "!!! Network_WOL_LGTV changed")
end

This is what gets logged to openhab.log (in the “everything ok” case):

2017-11-06 22:39:08.297 [INFO ] [eclipse.smarthome.model.script.myWOL] - Before sending WOL
2017-11-06 22:39:08.297 [INFO ] [eclipse.smarthome.model.script.myWOL] - !!! LG_TV0_Power received command
2017-11-06 22:39:08.321 [INFO ] [eclipse.smarthome.model.script.myWOL] - After sending WOL
2017-11-06 22:39:08.436 [INFO ] [eclipse.smarthome.model.script.myWOL] - !!! Network_WOL_LGTV received command
2017-11-06 22:39:08.462 [INFO ] [eclipse.smarthome.model.script.myWOL] - !!! Network_WOL_LGTV changed
2017-11-06 22:39:08.479 [INFO ] [eclipse.smarthome.model.script.myWOL] - !!! Network_WOL_LGTV received update
2017-11-06 22:39:08.485 [INFO ] [nhab.binding.wol.internal.WolBinding] - Wake-on-LAN packet sent [broadcastIp=192.168.1.255, macaddress=14c9138df6cd]
2017-11-06 22:39:13.665 [INFO ] [eclipse.smarthome.model.script.myWOL] - !!! LG_TV0_Power received update
2017-11-06 22:39:13.688 [INFO ] [eclipse.smarthome.model.script.myWOL] - !!! LG_TV0_Power changed
2017-11-06 22:39:14.456 [INFO ] [eclipse.smarthome.model.script.myWOL] - !!! Network_WOL_LGTV received update
2017-11-06 22:39:14.468 [INFO ] [eclipse.smarthome.model.script.myWOL] - !!! Network_WOL_LGTV changed

and the following is logged to “events.log” (still the “everything ok” case):

2017-11-06 22:39:08.328 [ItemCommandEvent          ] - Item 'Network_WOL_LGTV' received command ON
2017-11-06 22:39:08.444 [ItemStateChangedEvent     ] - Network_WOL_LGTV changed from NULL to ON
2017-11-06 22:39:13.189 [hingStatusInfoChangedEvent] - 'lgwebos:WebOSTV:192_168_1_134' changed from OFFLINE: TV is off to ONLINE: Device Ready
2017-11-06 22:39:13.590 [hingStatusInfoChangedEvent] - 'lgwebos:WebOSTV:192_168_1_134' changed from ONLINE: Device Ready to ONLINE: Connected
2017-11-06 22:39:13.609 [ItemStateChangedEvent     ] - LG_TV0_Power changed from OFF to ON
2017-11-06 22:39:13.653 [ItemStateChangedEvent     ] - LG_TV0_Application changed from  to com.webos.app.livetv
2017-11-06 22:39:14.448 [ItemStateChangedEvent     ] - Network_WOL_LGTV changed from ON to OFF
2017-11-06 22:40:18.720 [ItemStateChangedEvent     ] - LG_TV0_Power changed from ON to OFF
2017-11-06 22:40:18.757 [hingStatusInfoChangedEvent] - 'lgwebos:WebOSTV:192_168_1_134' changed from ONLINE: Connected to OFFLINE: TV is off
2017-11-06 22:40:50.729 [hingStatusInfoChangedEvent] - 'lgwebos:WebOSTV:192_168_1_134' changed from OFFLINE: TV is off to ONLINE: Device Ready
2017-11-06 22:40:51.070 [hingStatusInfoChangedEvent] - 'lgwebos:WebOSTV:192_168_1_134' changed from ONLINE: Device Ready to ONLINE: Connected
2017-11-06 22:40:51.090 [ItemStateChangedEvent     ] - LG_TV0_Power changed from OFF to ON

now I restart the openhab2.service and try to “switch on” TV using BasicUI. No go. Logged in “openhab.log”:

2017-11-06 22:51:42.930 [WARN ] [nding.lgwebos.handler.LGWebOSHandler] - Unable to handle command ON for channel lgwebos:WebOSTV:192_168_1_134:power. Device lgwebos:WebOSTV:192_168_1_134 not found. This should not happen at this point.
2017-11-06 22:51:43.677 [INFO ] [eclipse.smarthome.model.script.myWOL] - !!! LG_TV0_Power received command

logged in events.log:

2017-11-06 22:51:42.904 [ItemCommandEvent ] - Item 'LG_TV0_Power' received command ON

(yes, only this single line…)

EDIT (more info:)

Now I use a separate switch in BasicUI to trigger WOL directly. TV goes on. Logged in openhab.log:

2017-11-06 23:05:26.971 [INFO ] [eclipse.smarthome.model.script.myWOL] - !!! Network_WOL_LGTV received command
2017-11-06 23:05:26.989 [INFO ] [nhab.binding.wol.internal.WolBinding] - Wake-on-LAN packet sent [broadcastIp=192.168.1.255, macaddress=14c9138df6cd]
2017-11-06 23:05:27.017 [INFO ] [eclipse.smarthome.model.script.myWOL] - !!! Network_WOL_LGTV received update
2017-11-06 23:05:27.017 [INFO ] [eclipse.smarthome.model.script.myWOL] - !!! Network_WOL_LGTV changed
2017-11-06 23:05:32.908 [INFO ] [eclipse.smarthome.model.script.myWOL] - !!! Network_WOL_LGTV received update
2017-11-06 23:05:32.914 [INFO ] [eclipse.smarthome.model.script.myWOL] - !!! Network_WOL_LGTV changed
2017-11-06 23:05:35.562 [INFO ] [eclipse.smarthome.model.script.myWOL] - !!! LG_TV0_Power received update
2017-11-06 23:05:35.616 [INFO ] [eclipse.smarthome.model.script.myWOL] - !!! LG_TV0_Power changed

and in events.log:

2017-11-06 23:05:26.950 [ItemCommandEvent          ] - Item 'Network_WOL_LGTV' received command ON
2017-11-06 23:05:27.000 [ItemStateChangedEvent     ] - Network_WOL_LGTV changed from NULL to ON
2017-11-06 23:05:32.809 [hingStatusInfoChangedEvent] - 'lgwebos:WebOSTV:192_168_1_134' changed from OFFLINE: TV is off to ONLINE: Device Ready
2017-11-06 23:05:32.844 [ItemStateChangedEvent     ] - Network_WOL_LGTV changed from ON to OFF
2017-11-06 23:05:35.381 [hingStatusInfoChangedEvent] - 'lgwebos:WebOSTV:192_168_1_134' changed from ONLINE: Device Ready to ONLINE: Connected
2017-11-06 23:05:35.454 [ItemStateChangedEvent     ] - LG_TV0_Volume changed from NULL to 15
2017-11-06 23:05:35.477 [ItemStateChangedEvent     ] - LG_TV0_Power changed from NULL to ON
2017-11-06 23:05:35.523 [ItemStateChangedEvent     ] - LG_TV0_Mute changed from NULL to OFF
2017-11-06 23:05:35.523 [ItemStateChangedEvent     ] - LG_TV0_Channel changed from NULL to RTL
2017-11-06 23:05:35.565 [ItemStateChangedEvent     ] - LG_TV0_Application changed from NULL to com.webos.app.livetv

But when I switch power TV power off, I can see that I am still in a state where the rule is dead. Subsequent attempts to switch on the TV logs to openhab.log:

2017-11-06 23:13:26.451 [INFO ] [eclipse.smarthome.model.script.myWOL] - !!! LG_TV0_Power received command

and to eventls.log:

2017-11-06 23:13:26.435 [ItemCommandEvent ] - Item 'LG_TV0_Power' received command ON

It still seems to me the first warning of the binding “this should not happen”… somehow crashed the rule and deactivated it!

When I now enter the ssh-shell:

[23:14:05] openhabian@openHABianPi:~$ touch /etc/openhab2/rules/lg.rules

everything goes back to normal and I can switch on/off the TV repeatedly without issues with logs similar to the ones at the start of this post.

@sprehn Can you please have a look on this? Could it be that some problem with lgwebos binding, possibly some exception, deactivates a rule? Maybe there is some misconfiguration on my behalf. I always try to have at much as possible in files (I do not trust PaperUI). I have all the items configured in a file, but the TV-thing is still detected and “managed” by PaperUI (didn’t find a description about how to setup the thing in a file).

Edit: Specifically I am a bit nervous about the:

2017-11-06 22:51:42.930 [WARN ] [nding.lgwebos.handler.LGWebOSHandler] - Unable to handle command ON for channel lgwebos:WebOSTV:192_168_1_134:power. Device lgwebos:WebOSTV:192_168_1_134 not found. This should not happen at this point.

Hi,

that message should not be concerning. In the next version it will be changed to debug and read : Device {} not found - most likely is is currently offline. Details: Channel {}, Command {}.

It just means that the TV is currently offline.

Have you tried without autoupdate ?

That is really just added, so that no incorrect item state is displayed. It actually takes some time until the TV wakes up and is fully connected. Once that is the case this channel gets updated with ON.

Kind Regards
Sebastian