vc4-kms: Rework HPD

[6by9]

Patches 1 & 3 should probably be applied anyway, but patch 2 is for @popcornmix to test for his weird CEC/power cycling issue.

[popcornmix]

@6by9 tested at the weekend and cec was fine, and after switching off the TV, it (or receiver) didn't switch back on.

[6by9]

As discussed with @mripard in #4371, reinstating the ddc_probe will break scrambling being reset after power off if the monitor still reports the EDID, therefore it is not a solution.

#4371 (comment)
Logs needed, and some information on what CEC actions (if any) userspace is taking on seeing the connection being re-established.

[mripard]

Yeah, I think we need to figure out what happens on the CEC bus in such a case to find a good solution

[popcornmix]

With default 5.10 kernel here are logs of:
dmesg, cec-ctl, and kodi.log
My AVR switches back on unwantedly here.

With this PR added, which avoids the AVR switching back on the logs look like:
dmesg, cec-ctl, and kodi.log

[6by9]

Looking at those logs confirms that the AVR deasserts HPD, but the EDID is still readable.

[   21.453379] [drm:_drm_connector_helper_hpd_irq_event] [CONNECTOR:32:HDMI-A-1] status updated from connected to disconnected

in the 5.10 kernel logs, vs numerous

[drm:_drm_connector_helper_hpd_irq_event] [CONNECTOR:32:HDMI-A-1] status updated from connected to connected

messages in the normal log ie the IRQ has triggered, but no change has been reported, presumably as it read the EDID.

In both Kodi logs we have:
CecLogMessage - << powering on 'TV' (0)
but I'm guessing that's a start of day power on.

With PR

2021-11-23 11:36:00.136 T:836     DEBUG <general>: CecLogMessage - CLinuxCECAdapterCommunication::Process - ioctl CEC_RECEIVE - rx_status=01 len=8 addr=0f opcode=a0
2021-11-23 11:36:00.136 T:836     DEBUG <general>: CecLogMessage - >> 0f:a0:00:80:45:20:01:11
2021-11-23 11:36:00.136 T:836     DEBUG <general>: CecLogMessage - TV (0): power status changed from 'on' to 'standby'
2021-11-23 11:36:00.136 T:836     DEBUG <general>: CecLogMessage - >> TV (0) -> Broadcast (F): vendor command with id (A0)
2021-11-23 11:36:00.205 T:836     DEBUG <general>: CecLogMessage - CLinuxCECAdapterCommunication::Process - ioctl CEC_RECEIVE - rx_status=01 len=2 addr=0f opcode=36
2021-11-23 11:36:00.205 T:836     DEBUG <general>: CecLogMessage - >> 0f:36
2021-11-23 11:36:00.205 T:836     DEBUG <general>: CecLogMessage - >> TV (0) -> Broadcast (F): standby (36)
2021-11-23 11:36:00.659 T:833     DEBUG <general>: [plugin.video.youtube] send_notification: |check_settings| -> |{"use_httpd": true, "httpd_port": 50152, "whitelist": "", "httpd_address": "0.0.0.0"}|
2021-11-23 11:36:00.673 T:836     DEBUG <general>: CecLogMessage - CLinuxCECAdapterCommunication::Process - ioctl CEC_RECEIVE - rx_status=01 len=2 addr=0f opcode=36
2021-11-23 11:36:00.676 T:836     DEBUG <general>: CecLogMessage - >> 0f:36

Without PR

021-11-23 11:02:24.034 T:833     DEBUG <general>: CecLogMessage - >> 0f:a0:00:80:45:20:01:11
2021-11-23 11:02:24.034 T:833     DEBUG <general>: CecLogMessage - TV (0): power status changed from 'on' to 'standby'
2021-11-23 11:02:24.034 T:833     DEBUG <general>: CecLogMessage - >> TV (0) -> Broadcast (F): vendor command with id (A0)
2021-11-23 11:02:24.087 T:833     DEBUG <general>: CecLogMessage - CLinuxCECAdapterCommunication::Process - ioctl CEC_RECEIVE - rx_status=01 len=2 addr=0f opcode=36
2021-11-23 11:02:24.087 T:833     DEBUG <general>: CecLogMessage - >> 0f:36
2021-11-23 11:02:24.087 T:833     DEBUG <general>: CecLogMessage - >> TV (0) -> Broadcast (F): standby (36)
...
2021-11-23 11:02:24.277 T:833     DEBUG <general>: CecLogMessage - CLinuxCECAdapterCommunication::Process - ioctl CEC_RECEIVE - rx_status=01 len=7 addr=04 opcode=a0
2021-11-23 11:02:24.285 T:833     DEBUG <general>: CecLogMessage - >> 04:a0:00:80:45:06:05
2021-11-23 11:02:24.285 T:833     DEBUG <general>: CecLogMessage - >> TV (0) -> Playback 1 (4): vendor command with id (A0)
2021-11-23 11:02:24.286 T:833     DEBUG <general>: CecLogMessage - TV (0): power status changed from 'standby' to 'on'
2021-11-23 11:02:24.287 T:833     DEBUG <general>: CecLogMessage - << Playback 1 (4) -> broadcast (F): active source (2400)
2021-11-23 11:02:24.288 T:833     DEBUG <general>: CecLogMessage - << 4f:82:24:00
2021-11-23 11:02:24.390 T:833     DEBUG <general>: CecLogMessage - CLinuxCECAdapterCommunication::Write - ioctl CEC_TRANSMIT - tx_status=01 len=4 addr=4f opcode=82
2021-11-23 11:02:24.421 T:833     DEBUG <general>: CecLogMessage - CLinuxCECAdapterCommunication::Process - CEC_DQEVENT - CEC_EVENT_STATE_CHANGE - log_addr_mask=0000 phys_addr=ffff

Does the AVR turn back on if Kodi isn't running? Is it the kernel actions, or related to having CEC active?
HPD disconnect calls cec_phys_addr_invalidate, and connection calls cec_s_phys_addr_from_edid (although you appear to be using a static EDID - drm.edid_firmware=HDMI-A-1:edid/edid-HDMI-A-1.bin video=HDMI-A-1:D). cec_s_phys_addr_from_edid certainly triggers a notification to userspace.
Time to read the CEC spec to work out whether that is the correct behaviour.

If you disconnect the HDMI lead from the Pi, turn the AVR and TV off, then plug back in, does the AVR/TV wake up?

I'm definitely agreeing with mripard though - reinstating that ddc_probe is the wrong solution and will cause issues with scrambling. This looks to be a CEC connection issue that the ddc_probe was masking.

[6by9]

Kodi has done it

2021-11-23 11:02:24.287 T:833     DEBUG <general>: CecLogMessage - << Playback 1 (4) -> broadcast (F): active source (2400)
2021-11-23 11:02:24.288 T:833     DEBUG <general>: CecLogMessage - << 4f:82:24:00
2021-11-23 11:02:24.390 T:833     DEBUG <general>: CecLogMessage - CLinuxCECAdapterCommunication::Write - ioctl CEC_TRANSMIT - tx_status=01 len=4 addr=4f opcode=82

HDMI 1.4 spec. Supplement 1. CEC Table 8 Message Descriptions for the One Touch Play Feature
Opcode:
Value: 0x82
Description: "Used by a new source to indicate that it has started to transmit a stream OR used in response to a "
Response: "A current active source should take appropriate action. TV should switch to the appropriate input. Any CEC switches between source and root shall switch to the appropriate input and come out of the Standby state if necessary"

The TV and CEC switch have therefore done the appropriate thing and come out of standby.

[popcornmix]

This will be libcec rather than kodi. I'm guessing it is thinking things have powered on (rather than off) and is sending the active source. But we weren't really powering on.

[6by9]

A backtrace in CCECBusDevice::SetPowerStatus to see why we get
CecLogMessage - TV (0): power status changed from 'standby' to 'on'
logged would tell us a lot.

The log lines just before the are

2021-11-23 11:02:24.277 T:833     DEBUG <general>: CecLogMessage - CLinuxCECAdapterCommunication::Process - ioctl CEC_RECEIVE - rx_status=01 len=7 addr=04 opcode=a0
2021-11-23 11:02:24.285 T:833     DEBUG <general>: CecLogMessage - >> 04:a0:00:80:45:06:05
2021-11-23 11:02:24.285 T:833     DEBUG <general>: CecLogMessage - >> TV (0) -> Playback 1 (4): vendor command with id (A0)
2021-11-23 11:02:24.286 T:833     DEBUG <general>: CecLogMessage - TV (0): power status changed from 'standby' to 'on'
2021-11-23 11:02:24.287 T:833     DEBUG <general>: CecLogMessage - << Playback 1 (4) -> broadcast (F): active source (2400)
2021-11-23 11:02:24.288 T:833     DEBUG <general>: CecLogMessage - << 4f:82:24:00

I don't see that vendor command triggering an message or power status change, but it's also not easy to follow the flow from just reading the source.

[popcornmix]

Does the AVR turn back on if Kodi isn't running?

No.

If you disconnect the HDMI lead from the Pi, turn the AVR and TV off, then plug back in, does the AVR/TV wake up?

TV and AVR on. Disconnected HDMI lead. Switched off TV (AVR switched off automatically). Plugged back in hdmi and TV and AVR came on automatically.

[popcornmix]

CCECBusDevice::SetPowerStatus gets called very frequently, without a change.
Just breakpointing within the if ( changed ) code it gets called twice when I power off TV

Thread 79 "CECAdapter" hit Breakpoint 2, CEC::CCECBusDevice::SetPowerStatus (this=0xede2cc70, powerStatus=CEC::CEC_POWER_STATUS_STANDBY) at ../src/libcec/devices/CECBusDevice.cpp:699
699	in ../src/libcec/devices/CECBusDevice.cpp
#0  CEC::CCECBusDevice::SetPowerStatus (this=0xede2cc70, powerStatus=CEC::CEC_POWER_STATUS_STANDBY) at ../src/libcec/devices/CECBusDevice.cpp:699
#1  0xf7d6e8c4 in CEC::CVLCommandHandler::HandleDeviceVendorCommandWithId (this=0xee8b1e40, command=...) at ../src/libcec/implementations/VLCommandHandler.cpp:165
#2  0xf7d6a0d8 in CEC::CCECCommandHandler::HandleCommand (command=..., this=<optimized out>) at ../src/libcec/implementations/CECCommandHandler.cpp:188
#3  CEC::CCECCommandHandler::HandleCommand (this=0xee8b1e40, command=...) at ../src/libcec/implementations/CECCommandHandler.cpp:71
#4  0xf7d65734 in CEC::CCECBusDevice::HandleCommand (this=0xede2cc70, command=...) at ../src/libcec/devices/CECBusDevice.cpp:269
#5  0xf7d55000 in CEC::CCECProcessor::Process (this=0xc907b360) at ../src/libcec/CECProcessor.cpp:278
#6  0xf7d51ad4 in P8PLATFORM::CThread::ThreadHandler (_thread=0xc907b360) at /home/dom/projects/LibreELEC.tv/build.LibreELEC-RPi4.arm-10.0-devel-debug/toolchain/armv8a-libreelec-linux-gnueabihf/sysroot/usr/include/p8-platform/threads/threads.h:65
#7  0xf7e89d64 in start_thread (arg=0xea309200) at pthread_create.c:463

Thread 79 "CECAdapter" hit Breakpoint 2, CEC::CCECBusDevice::SetPowerStatus (this=0xede2cc70, powerStatus=CEC::CEC_POWER_STATUS_ON) at ../src/libcec/devices/CECBusDevice.cpp:699
699	in ../src/libcec/devices/CECBusDevice.cpp
#0  CEC::CCECBusDevice::SetPowerStatus (this=0xede2cc70, powerStatus=CEC::CEC_POWER_STATUS_ON) at ../src/libcec/devices/CECBusDevice.cpp:699
#1  0xf7d6e768 in CEC::CVLCommandHandler::HandleDeviceVendorCommandWithId (this=0xee8b1e40, command=...) at ../src/libcec/implementations/VLCommandHandler.cpp:126
#2  0xf7d6a0d8 in CEC::CCECCommandHandler::HandleCommand (command=..., this=<optimized out>) at ../src/libcec/implementations/CECCommandHandler.cpp:188
#3  CEC::CCECCommandHandler::HandleCommand (this=0xee8b1e40, command=...) at ../src/libcec/implementations/CECCommandHandler.cpp:71
#4  0xf7d65734 in CEC::CCECBusDevice::HandleCommand (this=0xede2cc70, command=...) at ../src/libcec/devices/CECBusDevice.cpp:269
#5  0xf7d55000 in CEC::CCECProcessor::Process (this=0xc907b360) at ../src/libcec/CECProcessor.cpp:278
#6  0xf7d51ad4 in P8PLATFORM::CThread::ThreadHandler (_thread=0xc907b360) at /home/dom/projects/LibreELEC.tv/build.LibreELEC-RPi4.arm-10.0-devel-debug/toolchain/armv8a-libreelec-linux-gnueabihf/sysroot/usr/include/p8-platform/threads/threads.h:65
#7  0xf7e89d64 in start_thread (arg=0xea309200) at pthread_create.c:463

[6by9]

HandleDeviceVendorCommandWithId looks weird.
Analysing the command 04:a0:00:80:45:06:05. 4 payload bytes, opcode 0xa0 (vendor command with ID).
CEC_VENDOR_PANASONIC = 0x008045,
0x06 then appears to be VL_UNKNOWN1, and 0x05 some parameter.

Why libcec has specific handling for this Panasonic specific vendor command is odd, but it seems to date back to
Pulse-Eight/libcec@b78b4e3,
Pulse-Eight/libcec@344cddb, Pulse-Eight/libcec@9ee5e8f and
Pulse-Eight/libcec@a085bea ("vendor command 06:05 was commented out for panasonic because it was reported to be sent on power off too. i don't see that in the field, and it prevented resume from standby from working correctly.")

I'll hook the LG up again with a LibreElec image and see what it does.

[6by9]

So the LG uses a different command handler in the src/libcec/implementations directory - these appear to be the vendor specific implementations, and https://github.com/Pulse-Eight/libcec/blob/master/src/libcec/devices/CECBusDevice.cpp#L198 chooses which one based on the vendor.

Looking at the cec-ctl logs when connecting a powered off TV and AVR to the Pi, the LibCEC powers both up immediately without receiving any messages from either.

Initial Event: State Change: PA: f.f.f.f, LA mask: 0x0000, Conn Info: yes



Event: State Change: PA: 1.1.0.0, LA mask: 0x0000, Conn Info: yes
Transmitted by Recording Device 1 to Recording Device 1 (1 to 1): POLL
Tx, Not Acknowledged (4), Max Retries

Event: State Change: PA: 1.1.0.0, LA mask: 0x0002, Conn Info: yes
Transmitted by Recording Device 1 to all (1 to 15): REPORT_PHYSICAL_ADDR (0x84):
phys-addr: 1.1.0.0
prim-devtype: record (0x01)
Transmitted by Recording Device 1 to all (1 to 15): DEVICE_VENDOR_ID (0x87):
vendor-id: 5506 (0x00001582)
Transmitted by Recording Device 1 to all (1 to 15): REPORT_PHYSICAL_ADDR (0x84):
phys-addr: 1.1.0.0
prim-devtype: record (0x01)
Transmitted by Recording Device 1 to TV (1 to 0): IMAGE_VIEW_ON (0x04)
Transmitted by Recording Device 1 to all (1 to 15): ACTIVE_SOURCE (0x82):
phys-addr: 1.1.0.0

(warn: State Change events were lost)
Event: State Change: PA: f.f.f.f, LA mask: 0x0000, Conn Info: yes

Event: State Change: PA: 1.1.0.0, LA mask: 0x0000, Conn Info: yes
Transmitted by Recording Device 1 to Recording Device 1 (1 to 1): POLL
Tx, Aborted, Max Retries

(warn: State Change events were lost)
Event: State Change: PA: f.f.f.f, LA mask: 0x0000, Conn Info: yes

IMAGE_VIEW_ON and ACTIVE_SOURCE oblige the TV to wake up.
Knowing why libCEC sends those commands needs extra logging or a debugger connected to libcec.

There is a Kodi option called something like "Wake devices up on startup", which may be what is causing libcec to be tricked by the HPD signal.

[6by9]

Rebased and dropped patch 2 (adding back the ddc_probe).

@mripard could you give a quick review to ensure you agree with these?

[mripard]

The code looks good to me

Your second patch is going to conflict with https://lore.kernel.org/dri-devel/[email protected]/

Both are serving a similar purpose, but the upstream one is probably going to be easier to deal with when rebasing? Anyway, your call :)

[6by9]

OK, I'll drop patch 2 as your version (which it looks like I still need to review!) does do the same job. It was only a cleanup anyway.

[6by9]

Patch 2 dropped. Good to go it seems.