LibreELEC 9 / RPi3: TV constantly being turned on by CEC / TV does not remain in standby

noop · March 9, 2019 at 10:01 PM

Hardware: RPi 3 Model B v1.2 (not the B+)

LibreELEC version: 9.0.1 & 9.0.0

Ever since upgrading from LibreELEC 8.x to 9 on my RPi3B (not B+), my Sony TV will not remain off for more than 5-10 minutes. Physically pressing the power button on the TV to activate standby mode works fine, but the TV will power on again after a short time. I have disabled everything power-on related that is possible in the libCEC config in the GUI. The xml config for CEC is below. The "wake_devices" aspect seems to be overwritten by Kodi even if the file is manually edited while the kodi.service is not running.

I am confident that this is caused by the LibreELEC device. Below is the cec-client log output indicating that the TV is being powered on in response to a command sent by the LibreELEC device. Kodi debug logging is enabled, but the logs are *completely* silent when this event occurs, and remain silent until the screensaver kicks in 16 minutes later.

What I am observing on my device appears to be this issue: AVR keeps turning on after turning off TV

...with a potential patch: AVR keeps turning on after turning off TV · Issue #403 · Pulse-Eight/libcec · GitHub

Anything obvious I have overlooked? Any known solution?

I'm trying to avoid posting an X-Y problem, but at this point I wanted to try that patched version of libcec.so.4.0.2 to see if it would fix my issue, but then I noticed that the device is booted from a squashfs root filesystem. Is there a simple way for me to test this patched library without repacking my libreelec image?

cec-client log excerpt:

TRAFFIC: [342010] >> 0f:84:00:00:00

DEBUG: [342010] << Recorder 1 (1) -> broadcast (F): physical address 1000

TRAFFIC: [342010] << 1f:84:10:00:01

DEBUG: [342010] >> TV (0) -> Broadcast (F): report physical address (84)

WARNING: [342430] unhandled response received: opcode=84 initiator=1 destination=f response=0

TRAFFIC: [342430] >> 0f:87:08:00:46

DEBUG: [342431] << Recorder 1 (1) -> Broadcast (F): vendor id Pulse Eight (1582)

TRAFFIC: [342431] << 1f:87:00:15:82

DEBUG: [342431] >> TV (0) -> Broadcast (F): device vendor id (87)

TRAFFIC: [342792] >> 0f:a0:08:00:46:00:04:00:01

DEBUG: [342792] >> TV (0) -> Broadcast (F): vendor command with id (A0)

WARNING: [343062] unhandled response received: opcode=87 initiator=1 destination=f response=0

TRAFFIC: [343063] >> 0f:80:00:00:10:00

DEBUG: [343063] TV (0): power status changed from 'standby' to 'on'

DEBUG: [343063] making Recorder 1 (1) the active source

NOTICE: [343063] >> source activated: Recorder 1 (1)

DEBUG: [343063] sending active source message for 'Recorder 1'

NOTICE: [343063] << powering on 'TV' (0)

TRAFFIC: [343063] << 10:04

lib-cec config:

</settings>

noop · March 9, 2019 at 10:13 PM

Should anyone prefer the unabridged cec-client log that captured the issue:

Code

No device type given. Using 'recording device'
CEC Parser created - libCEC version 4.0.4
no serial port given. trying autodetect: 
 path:     Raspberry Pi
 com port: RPI

opening a connection to the CEC adapter...
DEBUG:   [             345]    Broadcast (F): osd name set to 'Broadcast'
DEBUG:   [             345]    Open - vc_cec initialised
DEBUG:   [             345]    logical address changed to Free use (e)
NOTICE:  [             346]    connection opened
DEBUG:   [             347]    << Broadcast (F) -> TV (0): POLL
DEBUG:   [             347]    initiator 'Broadcast' is not supported by the CEC adapter. using 'Free use' instead
TRAFFIC: [             347]    << e0
DEBUG:   [             347]    processor thread started
DEBUG:   [             377]    >> POLL sent
DEBUG:   [             377]    TV (0): device status changed into 'present'
DEBUG:   [             377]    << requesting vendor ID of 'TV' (0)
TRAFFIC: [             378]    << e0:8c
TRAFFIC: [             574]    >> 0f:87:08:00:46
DEBUG:   [             574]    TV (0): vendor = Sony (080046)
DEBUG:   [             575]    expected response received (87: device vendor id)
NOTICE:  [             575]    registering new CEC client - v4.0.4
DEBUG:   [             575]    detecting logical address for type 'recording device'
DEBUG:   [             575]    trying logical address 'Recorder 1'
DEBUG:   [             575]    << Recorder 1 (1) -> Recorder 1 (1): POLL
TRAFFIC: [             575]    << 11
DEBUG:   [             575]    >> TV (0) -> Broadcast (F): device vendor id (87)
TRAFFIC: [             995]    << 11
DEBUG:   [            1266]    >> POLL not sent
DEBUG:   [            1266]    using logical address 'Recorder 1'
DEBUG:   [            1266]    Recorder 1 (1): device status changed into 'handled by libCEC'
DEBUG:   [            1266]    Recorder 1 (1): power status changed from 'unknown' to 'on'
DEBUG:   [            1266]    Recorder 1 (1): vendor = Pulse Eight (001582)
DEBUG:   [            1266]    Recorder 1 (1): CEC version 1.4
DEBUG:   [            1266]    AllocateLogicalAddresses - device '0', type 'recording device', LA '1'
DEBUG:   [            1267]    logical address changed to Recorder 1 (1)
DEBUG:   [            1267]    Recorder 1 (1): osd name set to 'CECTester'
DEBUG:   [            1268]    Recorder 1 (1): menu language set to 'eng'
DEBUG:   [            1268]    GetPhysicalAddress - physical address = 1000
DEBUG:   [            1268]    AutodetectPhysicalAddress - autodetected physical address '1000'
DEBUG:   [            1268]    Recorder 1 (1): physical address changed from ffff to 1000
DEBUG:   [            1268]    << Recorder 1 (1) -> broadcast (F): physical address 1000
TRAFFIC: [            1269]    << 1f:84:10:00:01
NOTICE:  [            1419]    CEC client registered: libCEC version = 4.0.4, client version = 4.0.4, firmware version = 1, logical address(es) = Recorder 1 (1) , physical address: 1.0.0.0,  compiled on Thu Feb 21 06:15:30 UTC 2019 by jenkins@tsuboi on Linux 4.9.0-8-amd64 (x86_64), features: P8_USB, DRM, P8_detect, RPi
DEBUG:   [            1419]    << Recorder 1 (1) -> TV (0): OSD name 'CECTester'
TRAFFIC: [            1419]    << 10:47:43:45:43:54:65:73:74:65:72
DEBUG:   [            1720]    << requesting power status of 'TV' (0)
TRAFFIC: [            1720]    << 10:8f
TRAFFIC: [            1870]    >> 01:00:47:04
DEBUG:   [            1870]    marking opcode 'set osd name' as unsupported feature for device 'TV'
DEBUG:   [            1870]    >> TV (0) -> Recorder 1 (1): feature abort ( 0)
waiting for input
TRAFFIC: [            1947]    >> 01:90:01
DEBUG:   [            1947]    TV (0): power status changed from 'unknown' to 'standby'
DEBUG:   [            1947]    expected response received (90: report power status)
DEBUG:   [            1947]    >> TV (0) -> Recorder 1 (1): report power status (90)
WARNING: [            2225]    unhandled response received: opcode=87 initiator=1 destination=f response=0
TRAFFIC: [          342010]    >> 0f:84:00:00:00
DEBUG:   [          342010]    << Recorder 1 (1) -> broadcast (F): physical address 1000
TRAFFIC: [          342010]    << 1f:84:10:00:01
DEBUG:   [          342010]    >> TV (0) -> Broadcast (F): report physical address (84)
WARNING: [          342430]    unhandled response received: opcode=84 initiator=1 destination=f response=0
TRAFFIC: [          342430]    >> 0f:87:08:00:46
DEBUG:   [          342431]    << Recorder 1 (1) -> Broadcast (F): vendor id Pulse Eight (1582)
TRAFFIC: [          342431]    << 1f:87:00:15:82
DEBUG:   [          342431]    >> TV (0) -> Broadcast (F): device vendor id (87)
TRAFFIC: [          342792]    >> 0f:a0:08:00:46:00:04:00:01
DEBUG:   [          342792]    >> TV (0) -> Broadcast (F): vendor command with id (A0)
WARNING: [          343062]    unhandled response received: opcode=87 initiator=1 destination=f response=0
TRAFFIC: [          343063]    >> 0f:80:00:00:10:00
DEBUG:   [          343063]    TV (0): power status changed from 'standby' to 'on'
DEBUG:   [          343063]    making Recorder 1 (1) the active source
NOTICE:  [          343063]    >> source activated: Recorder 1 (1)
DEBUG:   [          343063]    sending active source message for 'Recorder 1'
NOTICE:  [          343063]    << powering on 'TV' (0)
TRAFFIC: [          343063]    << 10:04
DEBUG:   [          343063]    >> TV (0) -> Broadcast (F): routing change (80)
NOTICE:  [          343213]    << Recorder 1 (1) -> broadcast (F): active source (1000)
TRAFFIC: [          343213]    << 1f:82:10:00
WARNING: [          343333]    unhandled response received: opcode=4 initiator=1 destination=0 response=0
DEBUG:   [          343453]    << Recorder 1 (1) -> TV (0): menu state 'activated'
TRAFFIC: [          343453]    << 10:8e:00
WARNING: [          343783]    unhandled response received: opcode=82 initiator=1 destination=f response=0
TRAFFIC: [          343963]    >> 0f:a0:08:00:46:00:08:00:00
TRAFFIC: [          343963]    >> 01:83
DEBUG:   [          343963]    << Recorder 1 (1) -> broadcast (F): physical address 1000
TRAFFIC: [          343963]    << 1f:84:10:00:01
DEBUG:   [          343963]    >> TV (0) -> Broadcast (F): vendor command with id (A0)
DEBUG:   [          343963]    >> TV (0) -> Recorder 1 (1): give physical address (83)
WARNING: [          344354]    unhandled response received: opcode=84 initiator=1 destination=f response=0
TRAFFIC: [          344354]    >> 01:83
DEBUG:   [          344354]    << Recorder 1 (1) -> broadcast (F): physical address 1000
TRAFFIC: [          344354]    << 1f:84:10:00:01

Display More

noop · March 10, 2019 at 1:41 AM

Okay, I shaved many yaks. I modified the shared library in LibreELEC at runtime using an overlayfs and (perhaps unsurprisingly) found that the given compiled binary targeted for raspbian is not loadable. In other news, at least now I know how to use a Magisk-style approach to modify LibreELEC.

I guess I would have to patch the source in the LibreELEC repo and build a patched library to test it.

noop · March 10, 2019 at 4:20 AM

After overlaying /usr/lib and /usr/bin at runtime and loading in the libcec 4.0.1 library/client from LibreELEC 8.x onto my running 9.0.1 system, the issue persists. I confirmed that the issue is absent if the Kodi service is stopped. As this issue was not present before I installed 9.0.0, it appears to be within Kodi. I have been perusing the Cec adapter code in Kodi for what caused this bug. For some reason the Kodi CEC adapter seems to be disregarding/overwriting the xml config that is set, even if Kodi is stopped. Based on reading the CEC code it should not be sending these responses to turn on the TV

I still believe that patch for libcec would work, though, as it serves as a filter to abort unwanted responses.