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.