[cujomalainey]

We are leaking memory if the host sends bad messages to the firmware
since we are not freeing the buffer.

Signed-off-by: Curtis Malainey cujomalainey@chromium.org

[lgirdwood]

@kv2019i @plbossart fyi - Looks like the driver should handle the -1 traces messages and not report the overflow ?

2020-10-28 21:28:24 UTC [REMOTE_INFO] ===== Round(4/5) =====
2020-10-28 21:28:24 UTC [REMOTE_COMMAND] Run the command: rtcwake -m mem -s 5
rtcwake: assuming RTC uses UTC ...
rtcwake: wakeup from "mem" using /dev/rtc0 at Wed Oct 28 21:28:30 2020
2020-10-28 21:28:30 UTC [REMOTE_COMMAND] sleep for 5
2020-10-28 21:28:35 UTC [REMOTE_INFO] Check for the kernel log status
2020-10-28 21:28:35 UTC [ERROR] Caught dmesg error
===========================>>
[ 1006.726272] sof-audio-pci 0000:00:1f.3: error: DSP trace buffer overflow 4294967295 bytes. Total messages -1
<<===========================
2020-10-28 21:28:35 UTC [REMOTE_ERROR] Catch error in dmesg
2020-10-28 21:28:35 UTC [REMOTE_ERROR] Starting func_exit_handler(), exit status=1, FUNCNAME stack:
2020-10-28 21:28:35 UTC [REMOTE_ERROR]  die()  @  /home/ubuntu/sof-test/test-case/../case-lib/lib.sh
2020-10-28 21:28:35 UTC [REMOTE_ERROR]  main()  @  /home/ubuntu/sof-test/test-case/check-suspend-resume.sh:88
2020-10-28 21:28:35 UTC [REMOTE_INFO] Test Result: FAIL!

[plbossart]

@kv2019i @plbossart fyi - Looks like the driver should handle the -1 traces messages and not report the overflow ?

2020-10-28 21:28:24 UTC [REMOTE_INFO] ===== Round(4/5) =====
2020-10-28 21:28:24 UTC [REMOTE_COMMAND] Run the command: rtcwake -m mem -s 5
rtcwake: assuming RTC uses UTC ...
rtcwake: wakeup from "mem" using /dev/rtc0 at Wed Oct 28 21:28:30 2020
2020-10-28 21:28:30 UTC [REMOTE_COMMAND] sleep for 5
2020-10-28 21:28:35 UTC [REMOTE_INFO] Check for the kernel log status
2020-10-28 21:28:35 UTC [ERROR] Caught dmesg error
===========================>>
[ 1006.726272] sof-audio-pci 0000:00:1f.3: error: DSP trace buffer overflow 4294967295 bytes. Total messages -1
<<===========================
2020-10-28 21:28:35 UTC [REMOTE_ERROR] Catch error in dmesg
2020-10-28 21:28:35 UTC [REMOTE_ERROR] Starting func_exit_handler(), exit status=1, FUNCNAME stack:
2020-10-28 21:28:35 UTC [REMOTE_ERROR]  die()  @  /home/ubuntu/sof-test/test-case/../case-lib/lib.sh
2020-10-28 21:28:35 UTC [REMOTE_ERROR]  main()  @  /home/ubuntu/sof-test/test-case/check-suspend-resume.sh:88
2020-10-28 21:28:35 UTC [REMOTE_INFO] Test Result: FAIL!

I have zero understanding of all this. We've had this issue for MONTHS, and no one has a rational explanation for what happens, and if it's an error.

[lgirdwood]

@plbossart The sram reads back 0xffffffff during pm ops when sram is off so this would explain the -1 size and offset.

[plbossart]

@plbossart The sram reads back 0xffffffff during pm ops when sram is off so this would explain the -1 size and offset.

That message is printed as a result of an IPC_TRACE_MESSAGE coming from the DSP.

Are you saying it's possible that this message is sent and somehow the DSP still turns its SRAM off?

That would be an interesting race condition.

[kv2019i]

As both posn->overflow ("4294967295 bytes") and posn->messages ("Total messages -1") are all ones, it indeed seems we are reading IPC payload when the DSP is of and get all-ones values and that gets parsed as a trace message.

It's quite an interesting race indeed. SOF_IPC_GLB_TRACE_MSG is 0x9, so odds are very low we are parsing random garbage as a trace IPC. So more likely DSP is sending out a DMA trace just before powering off. Seems like a FW side issue, right @lgirdwood @plbossart ?

[cujomalainey]

@kv2019i what if the trace is sent before DSP is shutdown and is just stuck in what ever event queue we have? I dont know what the current state of the control mechanism is, but just a thought that the kernel might not be flushing its inbox before powering off.

[lgirdwood]

So the sequence is

1. FW copies message to mailbox and sends IRQ to host
2. Host gets IRQ and spawns IRQ handler thread.
3. Host IRQ thread runs and copies mailbox SRAM data to host RAM then handles message.
4. Host sends "msg done" IRQ to FW after completing 3)

So it looks like FW is powering OFF between 1 & 3. The solution is to prevent DSP D3 entry is IPC is pending. @slawblauciak can we add a flag here to wait on IPC completion before FW D3 entry

[cujomalainey]

Is the above discussion blocking this PR? This PR is blocking oss-fuzz integration as it crashes the fuzzer very early.

[kv2019i]

@cujomalainey wrote:

Is the above discussion blocking this PR? This PR is blocking oss-fuzz integration as it crashes the fuzzer very early.

I don't think so, agreed we should proceed to merge. Actually, where is this log from #3562 (comment) , @lgirdwood -> we could file a separarte bug just for this?
UPDATE: there is a bug for this already -> thesofproject/linux#2334

@kv2019i what if the trace is sent before DSP is shutdown and is just stuck in what ever event queue we have?

We should have protections in place for this. This error is printed on host side in middle of IPC RX processing, before host acks the IPC reception (by writing HIPCT_BUSY to doorbell register). And when we power down, host sends explicit CTX_SAVE and disables IRQs, so after this, kernel won't handle any IPC RX. On FW side, ipc_pm_gate() calls trace_off() and there the DMA trace work queue is cancelled. One place that is a bit more complicated to validate is if the call to "schedule_task_cancel(&trace_data->dmat_work);" could stop IPC transaction in the middle (FW is cleaned up before host sets BUSY).

[cujomalainey]

@lgirdwood are we ok to merge?

[lgirdwood]

@cujomalainey merged.