Power off issue about homey-webos-plus HOT 22 CLOSED

So here is some info from the log on power down:
state: 'Active',
processing: 'Request Power Off' }
state: 'Active',
processing: 'Request Active Standby' }
state: 'Active',
processing: 'Request Suspend' }
state: 'Active',
processing: 'Prepare Suspend' }

So far seems obvious, but then I get
2020-03-26 23:24:50 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: TV changed to active
2020-03-26 23:24:50 [log] [ManagerDrivers] [webos_plus] [0] powerStateListener: received on
2020-03-26 23:24:50 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.service.tvpower/power/getPowerState
2020-03-26 23:24:50 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Power state changed { returnValue: true,
Between every power state request

And after the last one:

2020-03-26 23:24:50 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: TV changed to active
2020-03-26 23:24:50 [log] [ManagerDrivers] [webos_plus] [0] powerStateListener: received on
2020-03-26 23:24:50 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://system/turnOff
2020-03-26 23:24:50 [log] [ManagerDrivers] [webos_plus] [0] _turnOff: TV turned off successfully
2020-03-26 23:24:50 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.applicationManager/getForegroundAppInfo
2020-03-26 23:24:50 [log] [ManagerDrivers] [webos_plus] [0] _appListener: App/input changed to
2020-03-26 23:24:50 [log] [ManagerDrivers] [webos_plus] [0] appListener: App/input changed from com.webos.app.hdmi2 to
2020-03-26 23:24:50 [log] [ManagerDrivers] [webos_plus] [0] appListener: Store currentApp set to
2020-03-26 23:24:50 [log] [ManagerDrivers] [webos_plus] [0] appListener: Flow trigger app/input changed
2020-03-26 23:24:50 [log] [ManagerDrivers] [webos_plus] [0] appListener: Gather media screen information for
2020-03-26 23:24:50 [log] [ManagerDrivers] [webos_plus] [0] _appList: Send request to retrieve all apps/inputs
2020-03-26 23:25:05 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.applicationManager/listLaunchPoints
2020-03-26 23:25:05 [err] [ManagerDrivers] [webos_plus] [0] ssap://com.webos.applicationManager/listLaunchPoints Error: timeout
at Timeout._onTimeout (/drivers/webos_plus/lgtv2/lgtv2.js:222:18)
at ontimeout (timers.js:498:11)
at tryOnTimeout (timers.js:323:5)
at Timer.listOnTimeout (timers.js:290:5)
2020-03-26 23:25:05 [err] [ManagerDrivers] [webos_plus] [0] _appList: ssap://com.webos.applicationManager/listLaunchPoints with result: undefined
2020-03-26 23:25:05 [err] [ManagerDrivers] [webos_plus] [0] Error: timeout
at Timeout._onTimeout (/drivers/webos_plus/lgtv2/lgtv2.js:222:18)
at ontimeout (timers.js:498:11)
at tryOnTimeout (timers.js:323:5)
at Timer.listOnTimeout (timers.js:290:5)
2020-03-26 23:25:05 [err] [ManagerDrivers] [webos_plus] [0] appListener: No Apps/inputs found

from homey-webos-plus.

@kaohlive Could you try https://github.com/MaxvandeLaar/homey-webos-plus/releases/tag/v2.0.0-rc2?

from homey-webos-plus.

power on seems to work reliable and when its turned on by remote it still is picked up rather quickly (1 sec).
poweroff works through the app ok, inclyding the right state. but it never detects a remote button off

from homey-webos-plus.

@kaohlive, good to hear things at least improved. Do you by any chance have the logs when you power off with the remote? It's possible the logic is still not good enough for your state changes. I have an idea what the issue could be, however I'd like to verify in the logs before tinkering :)

from homey-webos-plus.

@kaohlive, So I might just figured out why your tv is much faster than mine and now I experience the same behaviour as you... the tv is not turned off in the app. I guess you have quick start+ turned on?

from homey-webos-plus.

i do, i love these quick loads 😚

from homey-webos-plus.

on the log, need to wait till my family is asleep, can bother them with that during prime time

from homey-webos-plus.

@kaohlive, that's okay thanks for trying and all the testing. I am amazed with how fast the response time is when quick start+ is turned on. It's pretty much instant detected by the web app. So now I can reproduce it, I can also test it and got a fix already. Currently finetuning the timeout but I suppose it won't be much longer than 1 or 2 seconds. I'll let you know when I have a rc3 released so you can try that instead of uploading logs ☺️

from homey-webos-plus.

@MaxvandeLaar strange, after a while the poweron problem came back, restarting the app made it go away (for now)

from homey-webos-plus.

@kaohlive hmm okay, I first only wanted to set a timeout on the off state check, but this makes me think it's best to just use the timeout for on and off checking. I made the timeout interval a setting so everyone can fine-tune it to their likings. The default value will be 2 seconds (used to be 2 minutes) so still a drastic improvement. I'll test it a bit more before making a new release

from homey-webos-plus.

@kaohlive Here is v2.0.0-rc3 https://github.com/MaxvandeLaar/homey-webos-plus/releases/tag/v2.0.0-rc3

So the major problem with the new state listener is that the TV fires an event even when its processing turning on/off (as you probably noticed in the loggin). This makes the state check unreliable and without knowing the possible states and processes the tv goes through I had to come up with something else.

How it works now, when the stateListener is called a timeout is set for x ms (2000ms default). This timeout is reset for every state change event sent by the tv unless the timeout interval is reached.

This means a lower interval setting will give the tv less time to send events when turning on/off. So checking the actual state will be faster however comes with the cost of being less reliable as the tv might send a delayed event... Setting a higher interval setting gives the check more time between events and it's more certain the tv actually reached its final state.

So I tested by turning the tv on/off with the remote for some time and I hardly notice the 2 second delay there is. Let me know how it works for you

from homey-webos-plus.

Unfortunately it is getting a bit worse for my tv :(.
Now the TV shutdown again and the off state is still missed in any scenario other than shutdown from the app.

from homey-webos-plus.

Shutdown event using the remote:
2020-03-27 22:25:27 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.service.tvpower/power/getPowerState
2020-03-27 22:25:27 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Power state changed { returnValue: true,
state: 'Active',
processing: 'Request Power Off' }
2020-03-27 22:25:27 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Set timeout to 5000 ms and check the state
2020-03-27 22:25:27 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.service.tvpower/power/getPowerState
2020-03-27 22:25:27 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Reset timer
2020-03-27 22:25:27 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Power state changed { returnValue: true,
state: 'Active',
processing: 'Request Active Standby' }
2020-03-27 22:25:27 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Set timeout to 5000 ms and check the state
2020-03-27 22:25:27 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.service.tvpower/power/getPowerState
2020-03-27 22:25:27 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Reset timer
2020-03-27 22:25:27 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Power state changed { returnValue: true,
state: 'Active',
processing: 'Request Suspend' }
2020-03-27 22:25:27 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Set timeout to 5000 ms and check the state
2020-03-27 22:25:27 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.service.tvpower/power/getPowerState
2020-03-27 22:25:27 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Reset timer
2020-03-27 22:25:27 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Power state changed { returnValue: true,
state: 'Active',
processing: 'Prepare Suspend' }
2020-03-27 22:25:27 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Set timeout to 5000 ms and check the state
2020-03-27 22:25:27 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.applicationManager/getForegroundAppInfo
2020-03-27 22:25:27 [log] [ManagerDrivers] [webos_plus] [0] _appListener: App/input changed to
2020-03-27 22:25:27 [log] [ManagerDrivers] [webos_plus] [0] appListener: App/input changed from com.webos.app.hdmi2 to
2020-03-27 22:25:27 [log] [ManagerDrivers] [webos_plus] [0] appListener: Store currentApp set to
2020-03-27 22:25:27 [log] [ManagerDrivers] [webos_plus] [0] appListener: Flow trigger app/input changed
2020-03-27 22:25:27 [log] [ManagerDrivers] [webos_plus] [0] appListener: Gather media screen information for
2020-03-27 22:25:27 [log] [ManagerDrivers] [webos_plus] [0] _appList: Send request to retrieve all apps/inputs
2020-03-27 22:25:27 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.applicationManager/listLaunchPoints
2020-03-27 22:25:27 [log] [ManagerDrivers] [webos_plus] [0] _appList: Retrieved all apps/inputs successfully
2020-03-27 22:25:27 [log] [ManagerDrivers] [webos_plus] [0] _appList: Mapped all apps/inputs and resolve
2020-03-27 22:25:27 [err] [ManagerDrivers] [webos_plus] [0] appListener: No app found for
2020-03-27 22:25:32 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Called timeout active Prepare Suspend
2020-03-27 22:25:32 [log] [ManagerDrivers] [webos_plus] [0] powerStateListener: received on

Final result, the App thinks the TV is still on several minutes after the shutdown event.

Next I correct the app mode by turning it off from the app.

Next turn on from the remote:

2020-03-27 22:28:47 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.service.tvpower/power/getPowerState
2020-03-27 22:28:47 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Power state changed { returnValue: true, state: 'Suspend' }
2020-03-27 22:28:47 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Set timeout to 5000 ms and check the state
2020-03-27 22:28:47 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.service.tvpower/power/getPowerState
2020-03-27 22:28:47 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Reset timer
2020-03-27 22:28:47 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Power state changed { returnValue: true,
state: 'Suspend',
processing: 'Prepare Resume' }
2020-03-27 22:28:47 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Set timeout to 5000 ms and check the state
2020-03-27 22:28:47 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.service.tvpower/power/getPowerState
2020-03-27 22:28:47 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Reset timer
2020-03-27 22:28:47 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Power state changed { returnValue: true,
state: 'Suspend',
processing: 'LastInput Ready',
powerOnReason: 'remoteKey' }
2020-03-27 22:28:47 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Set timeout to 5000 ms and check the state
2020-03-27 22:28:47 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.service.tvpower/power/getPowerState
2020-03-27 22:28:47 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Reset timer
2020-03-27 22:28:47 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Power state changed { returnValue: true, state: 'Suspend', processing: 'Screen On' }
2020-03-27 22:28:47 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Set timeout to 5000 ms and check the state
2020-03-27 22:28:47 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.service.tvpower/power/getPowerState
2020-03-27 22:28:47 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Reset timer
2020-03-27 22:28:47 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Power state changed { returnValue: true, state: 'Active' }
2020-03-27 22:28:47 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Set timeout to 5000 ms and check the state
2020-03-27 22:28:48 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.applicationManager/getForegroundAppInfo
2020-03-27 22:28:48 [log] [ManagerDrivers] [webos_plus] [0] _appListener: App/input changed to com.webos.app.hdmi2
2020-03-27 22:28:48 [log] [ManagerDrivers] [webos_plus] [0] appListener: App/input changed from to com.webos.app.hdmi2
2020-03-27 22:28:48 [log] [ManagerDrivers] [webos_plus] [0] appListener: Store currentApp set to com.webos.app.hdmi2
2020-03-27 22:28:48 [log] [ManagerDrivers] [webos_plus] [0] appListener: Flow trigger app/input changed
2020-03-27 22:28:48 [log] [ManagerDrivers] [webos_plus] [0] appListener: Gather media screen information for com.webos.app.hdmi2
2020-03-27 22:28:48 [log] [ManagerDrivers] [webos_plus] [0] _appList: Send request to retrieve all apps/inputs
2020-03-27 22:28:48 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.service.apiadapter/audio/getSoundOutput
2020-03-27 22:28:48 [log] [ManagerDrivers] [webos_plus] [0] _soundOutputListener: Sound output changed to external_speaker
2020-03-27 22:28:48 [log] [ManagerDrivers] [webos_plus] [0] soundOutputListener: Sound output changed from external_speaker to external_speaker
2020-03-27 22:28:48 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.applicationManager/listLaunchPoints
2020-03-27 22:28:48 [log] [ManagerDrivers] [webos_plus] [0] _appList: Retrieved all apps/inputs successfully
2020-03-27 22:28:48 [log] [ManagerDrivers] [webos_plus] [0] _appList: Mapped all apps/inputs and resolve
2020-03-27 22:28:48 [log] [ManagerDrivers] [webos_plus] [0] appListener: App found for 'com.webos.app.hdmi2' HDMI2
2020-03-27 22:28:48 [log] [ManagerDrivers] [webos_plus] [0] appListener: Try to get the current channel to gather more media screen information for 'com.webos.app.hdmi2' HDMI2
2020-03-27 22:28:48 [log] [ManagerDrivers] [webos_plus] [0] _channelCurrent: Send request to get the current channel
2020-03-27 22:28:48 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://tv/getCurrentChannel
2020-03-27 22:28:48 [log] [ManagerDrivers] [webos_plus] [0] _channelCurrent: Success getting channel
2020-03-27 22:28:48 [log] [ManagerDrivers] [webos_plus] [0] appListener: Channel found for 'com.webos.app.hdmi2' HDMI2. Set capability speaker_track to ''
2020-03-27 22:28:48 [log] [ManagerDrivers] [webos_plus] [0] appListener: Set image for 'com.webos.app.hdmi2' HDMI2 (http://192.168.1.30:3000/resources/1138b87ec3ca90d975b01b854dcf7b21ba06b1da/HDMI_2.png)
2020-03-27 22:28:53 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Called timeout active null
2020-03-27 22:28:53 [log] [ManagerDrivers] [webos_plus] [0] powerStateListener: received on

Ok, TV turned on and stayed on. The app also detected the ON state nicely.

Next turn off from the app:

2020-03-27 22:30:23 [log] [ManagerDrivers] [webos_plus] [0] toggleOnOff: Called false
2020-03-27 22:30:23 [log] [ManagerDrivers] [webos_plus] [0] toggleOnOff: Try to turn the tv off
2020-03-27 22:30:23 [log] [ManagerDrivers] [webos_plus] [0] _turnOff: Send request to turn the TV off
2020-03-27 22:30:23 [log] [ManagerDrivers] [webos_plus] [0] toggleOnOff: TV turned off. Set capability onoff to false
2020-03-27 22:30:23 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.service.tvpower/power/getPowerState
2020-03-27 22:30:23 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Power state changed { returnValue: true,
state: 'Active',
processing: 'Request Power Off' }
2020-03-27 22:30:23 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Set timeout to 5000 ms and check the state
2020-03-27 22:30:23 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.service.tvpower/power/getPowerState
2020-03-27 22:30:23 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Reset timer
2020-03-27 22:30:23 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Power state changed { returnValue: true,
state: 'Active',
processing: 'Request Active Standby' }
2020-03-27 22:30:23 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Set timeout to 5000 ms and check the state
2020-03-27 22:30:23 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.service.tvpower/power/getPowerState
2020-03-27 22:30:23 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Reset timer
2020-03-27 22:30:23 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Power state changed { returnValue: true,
state: 'Active',
processing: 'Request Suspend' }
2020-03-27 22:30:23 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Set timeout to 5000 ms and check the state
2020-03-27 22:30:23 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://system/turnOff
2020-03-27 22:30:23 [log] [ManagerDrivers] [webos_plus] [0] _turnOff: TV turned off successfully
2020-03-27 22:30:23 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.service.tvpower/power/getPowerState
2020-03-27 22:30:23 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Reset timer
2020-03-27 22:30:23 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Power state changed { returnValue: true,
state: 'Active',
processing: 'Prepare Suspend' }
2020-03-27 22:30:23 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Set timeout to 5000 ms and check the state
2020-03-27 22:30:23 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.applicationManager/getForegroundAppInfo
2020-03-27 22:30:23 [log] [ManagerDrivers] [webos_plus] [0] _appListener: App/input changed to
2020-03-27 22:30:23 [log] [ManagerDrivers] [webos_plus] [0] appListener: App/input changed from com.webos.app.hdmi2 to
2020-03-27 22:30:23 [log] [ManagerDrivers] [webos_plus] [0] appListener: Store currentApp set to
2020-03-27 22:30:23 [log] [ManagerDrivers] [webos_plus] [0] appListener: Flow trigger app/input changed
2020-03-27 22:30:23 [log] [ManagerDrivers] [webos_plus] [0] appListener: Gather media screen information for
2020-03-27 22:30:23 [log] [ManagerDrivers] [webos_plus] [0] _appList: Send request to retrieve all apps/inputs
2020-03-27 22:30:23 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.applicationManager/listLaunchPoints
2020-03-27 22:30:23 [log] [ManagerDrivers] [webos_plus] [0] _appList: Retrieved all apps/inputs successfully
2020-03-27 22:30:23 [log] [ManagerDrivers] [webos_plus] [0] _appList: Mapped all apps/inputs and resolve
2020-03-27 22:30:23 [err] [ManagerDrivers] [webos_plus] [0] appListener: No app found for
2020-03-27 22:30:28 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Called timeout active Prepare Suspend
2020-03-27 22:30:28 [log] [ManagerDrivers] [webos_plus] [0] powerStateListener: received on

Result, TV turned off ok, but the app showes the TV as on, the timeout is already set to 5 seconds as your can see.

Now I need to turn the app mode to off:
2020-03-27 22:32:19 [log] [ManagerDrivers] [webos_plus] [0] toggleOnOff: Called false
2020-03-27 22:32:19 [log] [ManagerDrivers] [webos_plus] [0] toggleOnOff: Try to turn the tv off
2020-03-27 22:32:19 [log] [ManagerDrivers] [webos_plus] [0] _turnOff: Send request to turn the TV off
2020-03-27 22:32:19 [log] [ManagerDrivers] [webos_plus] [0] toggleOnOff: TV turned off. Set capability onoff to false
2020-03-27 22:32:34 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://system/turnOff
2020-03-27 22:32:34 [err] [ManagerDrivers] [webos_plus] [0] ssap://system/turnOff Error: timeout
at Timeout._onTimeout (/drivers/webos_plus/lgtv2/lgtv2.js:222:18)
at ontimeout (timers.js:498:11)
at tryOnTimeout (timers.js:323:5)
at Timer.listOnTimeout (timers.js:290:5)
2020-03-27 22:32:34 [err] [ManagerDrivers] [webos_plus] [0] _turnOff: ssap://system/turnOff with result: undefined
2020-03-27 22:32:34 [err] [ManagerDrivers] [webos_plus] [0] Error: timeout
at Timeout._onTimeout (/drivers/webos_plus/lgtv2/lgtv2.js:222:18)
at ontimeout (timers.js:498:11)
at tryOnTimeout (timers.js:323:5)
at Timer.listOnTimeout (timers.js:290:5)

So a timeout since you cant turn off what is already off, makes sense.
Now I want to turn the TV back on from the app:

2020-03-27 22:33:20 [log] [ManagerDrivers] [webos_plus] [0] toggleOnOff: Called true
2020-03-27 22:33:20 [log] [ManagerDrivers] [webos_plus] [0] toggleOnOff: Try to turn the tv on
2020-03-27 22:33:20 [log] [ManagerDrivers] [webos_plus] [0] _turnOn: Send request to turn on (WoL) with mac address 78:5d:c8:14:2e:e3
2020-03-27 22:33:20 [log] [ManagerDrivers] [webos_plus] [0] _turnOn: TV turned on successfully
2020-03-27 22:33:20 [log] [ManagerDrivers] [webos_plus] [0] toggleOnOff: TV turned on. Set capability onoff to true
2020-03-27 22:33:25 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.service.tvpower/power/getPowerState
2020-03-27 22:33:25 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Power state changed { returnValue: true, state: 'Suspend' }
2020-03-27 22:33:25 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Set timeout to 5000 ms and check the state
2020-03-27 22:33:25 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.service.tvpower/power/getPowerState
2020-03-27 22:33:26 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Reset timer
2020-03-27 22:33:26 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Power state changed { returnValue: true,
state: 'Suspend',
processing: 'Prepare Resume' }
2020-03-27 22:33:26 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Set timeout to 5000 ms and check the state
2020-03-27 22:33:26 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.service.tvpower/power/getPowerState
2020-03-27 22:33:26 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Reset timer
2020-03-27 22:33:26 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Power state changed { returnValue: true,
state: 'Suspend',
processing: 'LastInput Ready',
powerOnReason: 'wakeOnLan' }
2020-03-27 22:33:26 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Set timeout to 5000 ms and check the state
2020-03-27 22:33:26 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.service.tvpower/power/getPowerState
2020-03-27 22:33:26 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Reset timer
2020-03-27 22:33:26 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Power state changed { returnValue: true, state: 'Suspend', processing: 'Screen On' }
2020-03-27 22:33:26 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Set timeout to 5000 ms and check the state
2020-03-27 22:33:26 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.service.tvpower/power/getPowerState
2020-03-27 22:33:26 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Reset timer
2020-03-27 22:33:26 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Power state changed { returnValue: true, state: 'Active' }
2020-03-27 22:33:26 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Set timeout to 5000 ms and check the state
2020-03-27 22:33:26 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.applicationManager/getForegroundAppInfo
2020-03-27 22:33:26 [log] [ManagerDrivers] [webos_plus] [0] _appListener: App/input changed to com.webos.app.hdmi2
2020-03-27 22:33:26 [log] [ManagerDrivers] [webos_plus] [0] appListener: App/input changed from to com.webos.app.hdmi2
2020-03-27 22:33:26 [log] [ManagerDrivers] [webos_plus] [0] appListener: Store currentApp set to com.webos.app.hdmi2
2020-03-27 22:33:26 [log] [ManagerDrivers] [webos_plus] [0] appListener: Flow trigger app/input changed
2020-03-27 22:33:26 [log] [ManagerDrivers] [webos_plus] [0] appListener: Gather media screen information for com.webos.app.hdmi2
2020-03-27 22:33:26 [log] [ManagerDrivers] [webos_plus] [0] _appList: Send request to retrieve all apps/inputs
2020-03-27 22:33:26 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.service.apiadapter/audio/getSoundOutput
2020-03-27 22:33:26 [log] [ManagerDrivers] [webos_plus] [0] _soundOutputListener: Sound output changed to external_speaker
2020-03-27 22:33:26 [log] [ManagerDrivers] [webos_plus] [0] soundOutputListener: Sound output changed from external_speaker to external_speaker
2020-03-27 22:33:27 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.service.tvpower/power/getPowerState
2020-03-27 22:33:27 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Reset timer
2020-03-27 22:33:27 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Power state changed { returnValue: true,
state: 'Active',
processing: 'Request Power Off' }
2020-03-27 22:33:27 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Set timeout to 5000 ms and check the state
2020-03-27 22:33:27 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.applicationManager/listLaunchPoints
2020-03-27 22:33:27 [log] [ManagerDrivers] [webos_plus] [0] _appList: Retrieved all apps/inputs successfully
2020-03-27 22:33:27 [log] [ManagerDrivers] [webos_plus] [0] _appList: Mapped all apps/inputs and resolve
2020-03-27 22:33:27 [log] [ManagerDrivers] [webos_plus] [0] appListener: App found for 'com.webos.app.hdmi2' HDMI2
2020-03-27 22:33:27 [log] [ManagerDrivers] [webos_plus] [0] appListener: Try to get the current channel to gather more media screen information for 'com.webos.app.hdmi2' HDMI2
2020-03-27 22:33:27 [log] [ManagerDrivers] [webos_plus] [0] _channelCurrent: Send request to get the current channel
2020-03-27 22:33:27 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.service.tvpower/power/getPowerState
2020-03-27 22:33:27 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Reset timer
2020-03-27 22:33:27 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Power state changed { returnValue: true,
state: 'Active',
processing: 'Request Active Standby' }
2020-03-27 22:33:27 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Set timeout to 5000 ms and check the state
2020-03-27 22:33:27 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.service.tvpower/power/getPowerState
2020-03-27 22:33:27 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Reset timer
2020-03-27 22:33:27 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Power state changed { returnValue: true,
state: 'Active',
processing: 'Request Suspend' }
2020-03-27 22:33:27 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Set timeout to 5000 ms and check the state
2020-03-27 22:33:27 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.service.tvpower/power/getPowerState
2020-03-27 22:33:27 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Reset timer
2020-03-27 22:33:27 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Power state changed { returnValue: true,
state: 'Active',
processing: 'Prepare Suspend' }
2020-03-27 22:33:27 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Set timeout to 5000 ms and check the state
2020-03-27 22:33:27 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.applicationManager/getForegroundAppInfo
2020-03-27 22:33:27 [log] [ManagerDrivers] [webos_plus] [0] _appListener: App/input changed to
2020-03-27 22:33:27 [log] [ManagerDrivers] [webos_plus] [0] appListener: App/input changed from com.webos.app.hdmi2 to
2020-03-27 22:33:27 [log] [ManagerDrivers] [webos_plus] [0] appListener: Store currentApp set to
2020-03-27 22:33:27 [log] [ManagerDrivers] [webos_plus] [0] appListener: Flow trigger app/input changed
2020-03-27 22:33:27 [log] [ManagerDrivers] [webos_plus] [0] appListener: Gather media screen information for
2020-03-27 22:33:27 [log] [ManagerDrivers] [webos_plus] [0] _appList: Send request to retrieve all apps/inputs
2020-03-27 22:33:27 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://tv/getCurrentChannel
2020-03-27 22:33:27 [log] [ManagerDrivers] [webos_plus] [0] _channelCurrent: Success getting channel
2020-03-27 22:33:27 [log] [ManagerDrivers] [webos_plus] [0] appListener: Channel found for 'com.webos.app.hdmi2' HDMI2. Set capability speaker_track to ''
2020-03-27 22:33:27 [log] [ManagerDrivers] [webos_plus] [0] appListener: Set image for 'com.webos.app.hdmi2' HDMI2 (http://192.168.1.30:3000/resources/1138b87ec3ca90d975b01b854dcf7b21ba06b1da/HDMI_2.png)
2020-03-27 22:33:32 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Called timeout active Prepare Suspend
2020-03-27 22:33:32 [log] [ManagerDrivers] [webos_plus] [0] powerStateListener: received on
2020-03-27 22:33:42 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.applicationManager/listLaunchPoints
2020-03-27 22:33:42 [err] [ManagerDrivers] [webos_plus] [0] ssap://com.webos.applicationManager/listLaunchPoints Error: timeout
at Timeout._onTimeout (/drivers/webos_plus/lgtv2/lgtv2.js:222:18)
at ontimeout (timers.js:498:11)
at tryOnTimeout (timers.js:323:5)
at Timer.listOnTimeout (timers.js:290:5)
2020-03-27 22:33:42 [err] [ManagerDrivers] [webos_plus] [0] _appList: ssap://com.webos.applicationManager/listLaunchPoints with result: undefined
2020-03-27 22:33:42 [err] [ManagerDrivers] [webos_plus] [0] Error: timeout
at Timeout._onTimeout (/drivers/webos_plus/lgtv2/lgtv2.js:222:18)
at ontimeout (timers.js:498:11)
at tryOnTimeout (timers.js:323:5)
at Timer.listOnTimeout (timers.js:290:5)
2020-03-27 22:33:42 [err] [ManagerDrivers] [webos_plus] [0] appListener: No Apps/inputs found

Result, TV turned on for a couple of seconds and then turned off again. App thinks it ON now though.

Hope these logs help, if you can get this stable its an amazing app 👍

from homey-webos-plus.

On the poweroff detection:
What strikes me as odd is the line:
2020-03-27 22:25:32 [log] [ManagerDrivers] [webos_plus] [0] powerStateListener: received on

After both shutdown events we still receive an ON. I think that's the main bug. You can see in the first part the remote power off did trigger a Request Power Off event nicely. Then the entire state cycle happens: Request Active Standby/Request Suspend/Prepare Suspend it does this in both cases (from remote and app).
But if we than receive the powerStateListener: received on your code triggers the:
this.log(powerStateListener: received on); //The log entry we see there
this.setCapabilityValue(capabilities.onOff, true); //Setting the capability back to ON, seems wrong

So I do not think you need the polling, since the TV is sending the events properly, but why is the received ON event triggered.

from homey-webos-plus.

On the poweroff while activating the TV, the last log:
2020-03-27 22:33:27 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Power state changed { returnValue: true,
state: 'Active',
processing: 'Request Power Off' }
There is a clear log entry that something seems to perform a request power off. The big question is here, what is now doing that?
As soon as this happens you see the logs mixed with events trying to handle the ON while the OFF is resulting in the power down cycle, including the received on entry.

I see no log that shows the app might be sending the power down, so you would almost think its the remote button. But I promise I am not messing with it ;)

from homey-webos-plus.

Now after writing the above comments, I turned it on with the remote resulting in this log:
2020-03-27 22:51:02 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.service.tvpower/power/getPowerState
2020-03-27 22:51:02 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Power state changed { returnValue: true, state: 'Suspend' }
2020-03-27 22:51:02 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Set timeout to 5000 ms and check the state
2020-03-27 22:51:02 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.service.tvpower/power/getPowerState
2020-03-27 22:51:02 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Reset timer
2020-03-27 22:51:02 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Power state changed { returnValue: true,
state: 'Suspend',
processing: 'Prepare Resume' }
2020-03-27 22:51:02 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Set timeout to 5000 ms and check the state
2020-03-27 22:51:02 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.service.tvpower/power/getPowerState
2020-03-27 22:51:02 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Reset timer
2020-03-27 22:51:02 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Power state changed { returnValue: true,
state: 'Suspend',
processing: 'LastInput Ready',
powerOnReason: 'remoteKey' }
2020-03-27 22:51:02 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Set timeout to 5000 ms and check the state
2020-03-27 22:51:02 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.service.tvpower/power/getPowerState
2020-03-27 22:51:02 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Reset timer
2020-03-27 22:51:02 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Power state changed { returnValue: true, state: 'Suspend', processing: 'Screen On' }
2020-03-27 22:51:02 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Set timeout to 5000 ms and check the state
2020-03-27 22:51:02 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.service.tvpower/power/getPowerState
2020-03-27 22:51:03 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Reset timer
2020-03-27 22:51:03 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Power state changed { returnValue: true, state: 'Active' }
2020-03-27 22:51:03 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Set timeout to 5000 ms and check the state
2020-03-27 22:51:03 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.applicationManager/getForegroundAppInfo
2020-03-27 22:51:03 [log] [ManagerDrivers] [webos_plus] [0] _appListener: App/input changed to com.webos.app.hdmi2
2020-03-27 22:51:03 [log] [ManagerDrivers] [webos_plus] [0] appListener: App/input changed from to com.webos.app.hdmi2
2020-03-27 22:51:03 [log] [ManagerDrivers] [webos_plus] [0] appListener: Store currentApp set to com.webos.app.hdmi2
2020-03-27 22:51:03 [log] [ManagerDrivers] [webos_plus] [0] appListener: Flow trigger app/input changed
2020-03-27 22:51:03 [log] [ManagerDrivers] [webos_plus] [0] appListener: Gather media screen information for com.webos.app.hdmi2
2020-03-27 22:51:03 [log] [ManagerDrivers] [webos_plus] [0] _appList: Send request to retrieve all apps/inputs
2020-03-27 22:51:03 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.service.apiadapter/audio/getSoundOutput
2020-03-27 22:51:03 [log] [ManagerDrivers] [webos_plus] [0] _soundOutputListener: Sound output changed to external_speaker
2020-03-27 22:51:03 [log] [ManagerDrivers] [webos_plus] [0] soundOutputListener: Sound output changed from external_speaker to external_speaker
2020-03-27 22:51:03 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://com.webos.applicationManager/listLaunchPoints
2020-03-27 22:51:03 [log] [ManagerDrivers] [webos_plus] [0] _appList: Retrieved all apps/inputs successfully
2020-03-27 22:51:03 [log] [ManagerDrivers] [webos_plus] [0] _appList: Mapped all apps/inputs and resolve
2020-03-27 22:51:03 [log] [ManagerDrivers] [webos_plus] [0] appListener: App found for 'com.webos.app.hdmi2' HDMI2
2020-03-27 22:51:03 [log] [ManagerDrivers] [webos_plus] [0] appListener: Try to get the current channel to gather more media screen information for 'com.webos.app.hdmi2' HDMI2
2020-03-27 22:51:03 [log] [ManagerDrivers] [webos_plus] [0] _channelCurrent: Send request to get the current channel
2020-03-27 22:51:03 [log] [ManagerDrivers] [webos_plus] [0] _handleResponse: ssap://tv/getCurrentChannel
2020-03-27 22:51:03 [log] [ManagerDrivers] [webos_plus] [0] _channelCurrent: Success getting channel
2020-03-27 22:51:03 [log] [ManagerDrivers] [webos_plus] [0] appListener: Channel found for 'com.webos.app.hdmi2' HDMI2. Set capability speaker_track to ''
2020-03-27 22:51:03 [log] [ManagerDrivers] [webos_plus] [0] appListener: Set image for 'com.webos.app.hdmi2' HDMI2 (http://192.168.1.30:3000/resources/1138b87ec3ca90d975b01b854dcf7b21ba06b1da/HDMI_2.png)
2020-03-27 22:51:08 [log] [ManagerDrivers] [webos_plus] [0] _powerStateListener: Called timeout active null
2020-03-27 22:51:08 [log] [ManagerDrivers] [webos_plus] [0] powerStateListener: received on

And a properly turnon tv.

from homey-webos-plus.

I think I see the issue,
on your state checks during the power down you get:
{ returnValue: true,
state: 'Active',
processing: 'Request Active Standby' }
{ returnValue: true,
state: 'Active',
processing: 'Request Suspend' }
{ returnValue: true,
state: 'Active',
processing: 'Prepare Suspend' }

So this last state check should put the state value to 'Active'
And then you call the timer with the state value and wait x seconds and call Active!
timer = setTimeout(() => {
this.log(_powerStateListener: Called timeout, status, processing);
if (status === 'active') {
handleOn();
}
if (status !== 'active') {
handleOff();
}
clearTimeout(timer);
timer = null;
}, this.getSettings().powerStateTimeout || 2000);

But within the Timer you do not update the state, so you assume an state event will come in with a non active value. So you reset the timer on such a new event, so it gives you 2 seconds to get a new event in. In the hope one will be with the !=== 'active' state. But that never happens, No matter how long I watch the log, no event comes in with after the power down with a state 'suspend' or something like that. That only happens during the poweron.

from homey-webos-plus.

So I changed the code to:
timer = setTimeout(() => {
this.log(_powerStateListener: Called timeout, status, processing);
if (processing === null || processing === 'Screen On') {
handleOn();
} else if (processing === 'Prepare Suspend') {
handleOff();
}
clearTimeout(timer);
timer = null;
}, this.getSettings().powerStateTimeout || 2000);

And for me it seems to work, put the delay down to 500ms and almost instand on and off detection on my screen.
So instead of using the active value I use the processing value to detect what is happening.

from homey-webos-plus.

@kaohlive without checking all the log lines you send (just woke up) I agree with what the actually issue is. I am not yet really sure if the fix you wrote will work. So I have 2 LG tv's one in the living room and one on the second floor. The living room tv works (my rc3.0 code) perfectly, the second floor tv did not registered it going off.

I could not check the log at that time, however I believe it is the same issue as you are experiencing. I will need to do some comparing to create the correct off logic but it looks like LG tv don't share the same off process...

from homey-webos-plus.

@kaohlive can we close this? Or do you still experience issues with the release of v2.0.0?

from homey-webos-plus.

i did not update since my own hotfixed version. ill give the new one a go tonight. but you can close this one, its related to an old versiin anyway 👍

from homey-webos-plus.

@kaohlive, I implemented your hot fix however changed it slightly so I suppose you can upgrade without any issues

from homey-webos-plus.