CEC standby/wake Fails intermittently, works with cec-client command

tempestnano · December 21, 2019 at 11:01 PM

Raspberry Pi 4, 9.2.0.

Cec standby and wake works like a charm for the first few minutes after restarting the Kodi service or manually powering on the TV, but it stops working altogether after a few minutes. The TV will stubbornly stay away or asleep despite what Kodi thinks it is telling it to do. However, if I then go to the command line and manually tell the TV to power on via:

Code

LibreELEC:~ # echo 'on 0' | cec-client -s -d 1
opening a connection to the CEC adapter...

The TV responds properly and wakes up. Which makes me think that I can rule out the TV as the source of the problem.

Any help parsing the following debug logs would be appreciated.

Normal wake from standby

2019-12-21 17:37:51.371 T:2560471920 DEBUG: CecLogMessage - GetPhysicalAddress - physical address = 1000

2019-12-21 17:37:51.371 T:2560471920 DEBUG: CecLogMessage - physical address unchanged (1000)

2019-12-21 17:37:51.996 T:2560471920 DEBUG: CecLogMessage - << powering on 'TV' (0)

2019-12-21 17:37:51.997 T:2560471920 DEBUG: CecLogMessage - << 10:04

2019-12-21 17:37:52.057 T:2560471920 DEBUG: CecLogMessage - << Recorder 1 (1) -> broadcast (F): active source (1000)

2019-12-21 17:37:52.057 T:2560471920 DEBUG: CecLogMessage - << 1f:82:10:00

2019-12-21 17:37:52.177 T:2560471920 DEBUG: CecLogMessage - << Recorder 1 (1) -> TV (0): menu state 'activated'

2019-12-21 17:37:52.177 T:2560471920 DEBUG: CecLogMessage - 'menu status' is marked as unsupported feature for device 'TV'

2019-12-21 17:37:52.711 T:2560471920 DEBUG: CecLogMessage - >> 0f:80:00:00:10:00

2019-12-21 17:37:52.711 T:2560471920 DEBUG: CecLogMessage - Recorder 1 (1) was already marked as active source

2019-12-21 17:37:52.711 T:2560471920 DEBUG: CecLogMessage - >> source activated: Recorder 1 (1)

2019-12-21 17:37:52.712 T:2560471920 DEBUG: CecLogMessage - sending active source message for 'Recorder 1'

2019-12-21 17:37:52.712 T:2560471920 DEBUG: CecLogMessage - << powering on 'TV' (0)

2019-12-21 17:37:52.712 T:2560471920 DEBUG: CecLogMessage - << 10:04

2019-12-21 17:37:52.712 T:2560471920 DEBUG: CecLogMessage - >> TV (0) -> Broadcast (F): routing change (80)

2019-12-21 17:37:52.802 T:2560471920 DEBUG: CecLogMessage - << Recorder 1 (1) -> broadcast (F): active source (1000)

2019-12-21 17:37:52.802 T:2560471920 DEBUG: CecLogMessage - << 1f:82:10:00

2019-12-21 17:37:52.922 T:2560471920 DEBUG: CecLogMessage - << Recorder 1 (1) -> TV (0): menu state 'activated'

2019-12-21 17:37:52.922 T:2560471920 DEBUG: CecLogMessage - 'menu status' is marked as unsupported feature for device 'TV'

2019-12-21 17:37:53.368 T:2560471920 DEBUG: CecLogMessage - >> 01:00:04:00

2019-12-21 17:37:53.368 T:2560471920 DEBUG: CecLogMessage - marking opcode 'image view on' as unsupported feature for device 'TV'

2019-12-21 17:37:53.368 T:2560471920 DEBUG: CecLogMessage - >> TV (0) -> Recorder 1 (1): feature abort ( 0)

2019-12-21 17:37:53.551 T:2560471920 DEBUG: CecLogMessage - >> 0f:84:00:00:00

2019-12-21 17:37:53.551 T:2560471920 DEBUG: CecLogMessage - << Recorder 1 (1) -> broadcast (F): physical address 1000

2019-12-21 17:37:53.551 T:2560471920 DEBUG: CecLogMessage - << 1f:84:10:00:01

2019-12-21 17:37:53.551 T:2560471920 DEBUG: CecLogMessage - >> TV (0) -> Broadcast (F): report physical address (84)

2019-12-21 17:37:53.898 T:2560471920 DEBUG: CecLogMessage - >> 0f:87:6d:74:6b

2019-12-21 17:37:53.898 T:2560471920 DEBUG: CecLogMessage - << Recorder 1 (1) -> Broadcast (F): vendor id Pulse Eight (1582)

2019-12-21 17:37:53.898 T:2560471920 DEBUG: CecLogMessage - << 1f:87:00:15:82

2019-12-21 17:37:53.898 T:2560471920 DEBUG: CecLogMessage - >> TV (0) -> Broadcast (F): device vendor id (87)

2019-12-21 17:37:55.842 T:2560471920 DEBUG: CecLogMessage - >> 4f:84:20:00:04

2019-12-21 17:37:55.842 T:2560471920 DEBUG: CecLogMessage - >> Playback 1 (4) -> Broadcast (F): report physical address (84)

2019-12-21 17:37:55.909 T:2560471920 DEBUG: CecLogMessage - >> 01:83

2019-12-21 17:37:55.909 T:2560471920 DEBUG: CecLogMessage - << Recorder 1 (1) -> broadcast (F): physical address 1000

2019-12-21 17:37:55.910 T:2560471920 DEBUG: CecLogMessage - << 1f:84:10:00:01

2019-12-21 17:37:55.910 T:2560471920 DEBUG: CecLogMessage - >> TV (0) -> Recorder 1 (1): give physical address (83)

2019-12-21 17:37:56.615 T:2560471920 DEBUG: CecLogMessage - >> 01:46

2019-12-21 17:37:56.615 T:2560471920 DEBUG: CecLogMessage - << Recorder 1 (1) -> TV (0): OSD name 'Kodi'

2019-12-21 17:37:56.616 T:2560471920 DEBUG: CecLogMessage - << 10:47:4b:6f:64:69

2019-12-21 17:37:56.616 T:2560471920 DEBUG: CecLogMessage - >> TV (0) -> Recorder 1 (1): give osd name (46)

2019-12-21 17:37:56.985 T:2560471920 DEBUG: CecLogMessage - >> 4f:87:08:00:46

2019-12-21 17:37:56.985 T:2560471920 DEBUG: CecLogMessage - >> Playback 1 (4) -> Broadcast (F): device vendor id (87)

2019-12-21 17:37:57.052 T:2560471920 DEBUG: CecLogMessage - >> 01:8c

2019-12-21 17:37:57.052 T:2560471920 DEBUG: CecLogMessage - << Recorder 1 (1) -> TV (0): vendor id Pulse Eight (1582)

2019-12-21 17:37:57.052 T:2560471920 DEBUG: CecLogMessage - << 1f:87:00:15:82

2019-12-21 17:37:57.052 T:2560471920 DEBUG: CecLogMessage - >> TV (0) -> Recorder 1 (1): give device vendor id (8C)

2019-12-21 17:37:57.455 T:2560471920 DEBUG: CecLogMessage - >> 01:8f

2019-12-21 17:37:57.455 T:2560471920 DEBUG: CecLogMessage - << Recorder 1 (1) -> TV (0): on

2019-12-21 17:37:57.455 T:2560471920 DEBUG: CecLogMessage - << 10:90:00

2019-12-21 17:37:57.455 T:2560471920 DEBUG: CecLogMessage - >> TV (0) -> Recorder 1 (1): give device power status (8F)

2019-12-21 17:37:57.610 T:2560471920 DEBUG: CecLogMessage - >> 01:8f

2019-12-21 17:37:57.610 T:2560471920 DEBUG: CecLogMessage - << Recorder 1 (1) -> TV (0): on

2019-12-21 17:37:57.610 T:2560471920 DEBUG: CecLogMessage - << 10:90:00

2019-12-21 17:37:57.610 T:2560471920 DEBUG: CecLogMessage - >> TV (0) -> Recorder 1 (1): give device power status (8F)

2019-12-21 17:37:57.994 T:2560471920 DEBUG: CecLogMessage - >> 01:8f

2019-12-21 17:37:57.994 T:2560471920 DEBUG: CecLogMessage - << Recorder 1 (1) -> TV (0): on

2019-12-21 17:37:57.994 T:2560471920 DEBUG: CecLogMessage - << 10:90:00

2019-12-21 17:37:57.994 T:2560471920 DEBUG: CecLogMessage - >> TV (0) -> Recorder 1 (1): give device power status (8F)

2019-12-21 17:37:58.230 T:2560471920 DEBUG: CecLogMessage - >> 0f:86:10:00

2019-12-21 17:37:58.230 T:2560471920 DEBUG: CecLogMessage - >> TV (0) sets stream path to physical address 1000

2019-12-21 17:37:58.230 T:2560471920 DEBUG: CecLogMessage - Recorder 1 (1) was already marked as active source

2019-12-21 17:37:58.230 T:2560471920 DEBUG: CecLogMessage - >> source activated: Recorder 1 (1)

2019-12-21 17:37:58.230 T:2560471920 DEBUG: CecLogMessage - << Recorder 1 (1) -> broadcast (F): active source (1000)

2019-12-21 17:37:58.231 T:2560471920 DEBUG: CecLogMessage - << 1f:82:10:00

2019-12-21 17:37:58.231 T:2560471920 DEBUG: CecLogMessage - >> TV (0) -> Broadcast (F): set stream path (86)

Failed wake from standby

2019-12-21 17:43:16.846 T:2560471920 DEBUG: CecLogMessage - Recorder 1 (1) was already marked as active source

2019-12-21 17:43:16.846 T:2560471920 DEBUG: CecLogMessage - >> source activated: Recorder 1 (1)

2019-12-21 17:43:16.846 T:2560471920 DEBUG: CecLogMessage - sending active source message for 'Recorder 1'

2019-12-21 17:43:16.847 T:2560471920 DEBUG: CecLogMessage - << powering on 'TV' (0)

2019-12-21 17:43:16.847 T:2560471920 DEBUG: CecLogMessage - 'image view on' is marked as unsupported feature for device 'TV'

2019-12-21 17:43:16.847 T:2560471920 DEBUG: CecLogMessage - << Recorder 1 (1) -> broadcast (F): active source (1000)

2019-12-21 17:43:16.847 T:2560471920 DEBUG: CecLogMessage - << 1f:82:10:00

2019-12-21 17:43:16.876 T:3011833872 DEBUG: ToggleDeviceState - waking up CEC device...

2019-12-21 17:43:16.966 T:2560471920 DEBUG: CecLogMessage - << Recorder 1 (1) -> TV (0): menu state 'activated'

2019-12-21 17:43:16.966 T:2560471920 DEBUG: CecLogMessage - 'menu status' is marked as unsupported feature for device 'TV'

2019-12-21 17:43:16.971 T:2560471920 DEBUG: CecLogMessage - Recorder 1 (1) was already marked as active source

2019-12-21 17:43:16.971 T:2560471920 DEBUG: CecLogMessage - >> source activated: Recorder 1 (1)

2019-12-21 17:43:16.971 T:2560471920 DEBUG: CecLogMessage - sending active source message for 'Recorder 1'

2019-12-21 17:43:16.971 T:2560471920 DEBUG: CecLogMessage - << powering on 'TV' (0)

2019-12-21 17:43:16.971 T:2560471920 DEBUG: CecLogMessage - 'image view on' is marked as unsupported feature for device 'TV'

2019-12-21 17:43:16.971 T:2560471920 DEBUG: CecLogMessage - << Recorder 1 (1) -> broadcast (F): active source (1000)

2019-12-21 17:43:16.971 T:2560471920 DEBUG: CecLogMessage - << 1f:82:10:00

2019-12-21 17:43:17.091 T:2560471920 DEBUG: CecLogMessage - << Recorder 1 (1) -> TV (0): menu state 'activated'

2019-12-21 17:43:17.091 T:2560471920 DEBUG: CecLogMessage - 'menu status' is marked as unsupported feature for device 'TV'

Failed when using: kodi-send --action=CECActivateSource