Null pointer dereference on concurrent VC_SM_CMA_IOCTL_MEM_IMPORT_DMABUF ioctl

[dividuum]

Describe the bug

I've observed kernel null pointer dereferences while using the VC_SM_CMA_IOCTL_MEM_IMPORT_DMABUF ioctl. A traceback might look like this:

[  634.185377] ---[ end trace 0000000000000000 ]---
[  634.185400] hwmon hwmon1: Failed to get throttled (-110)
[  645.781772] Unable to handle kernel NULL pointer dereference at virtual address 0000000000000008
[  645.781801] Mem abort info:
[  645.781806]   ESR = 0x0000000096000046
[  645.781812]   EC = 0x25: DABT (current EL), IL = 32 bits
[  645.781819]   SET = 0, FnV = 0
[  645.781826]   EA = 0, S1PTW = 0
[  645.781831]   FSC = 0x06: level 2 translation fault
[  645.781840] Data abort info:
[  645.781844]   ISV = 0, ISS = 0x00000046, ISS2 = 0x00000000
[  645.781850]   CM = 0, WnR = 1, TnD = 0, TagAccess = 0
[  645.781856]   GCS = 0, Overlay = 0, DirtyBit = 0, Xs = 0
[  645.781866] user pgtable: 4k pages, 39-bit VAs, pgdp=00000000484d5000
[  645.781873] [0000000000000008] pgd=080000004c6eb003, p4d=080000004c6eb003, pud=080000004c6eb003, pmd=0000000000000000
[  645.781896] Internal error: Oops: 0000000096000046 [#1] PREEMPT SMP
[  645.781905] Modules linked in: bcm2835_codec(C) bcm2835_mmal_vchiq(C) vc_sm_cma(C) dwc2 edt_ft5x06 tc358762 drm_mipi_dbi simple_bridge panel_raspberrypi_touchscreen rpi_panel_attiny_regulator rpi_panel_v2_regulator panel_ilitek_ili9881c panel_simple nvmem_rmem drm_rp1_dsi drm_ttm_helper ttm snd_soc_hdmi_codec rpivid_hevc(C) pisp_be vc4 v4l2_mem2mem videobuf2_dma_contig videobuf2_v4l2 videobuf2_memops v3d drm_dma_helper videobuf2_common gpu_sched drm_shmem_helper drm_kms_helper drm_display_helper videodev drm backlight mc cec i2c_mux_pinctrl i2c_mux i2c_designware_platform i2c_designware_core i2c_brcmstb drm_panel_orientation_quirks raspberrypi_gpiomem uinput enc28j60 pwm_bcm2835 rpi_poe_power pwm_raspberrypi_poe gpio_fan simple_mfd_i2c raspberrypi_hwmon rtc_ds1307 rtc_pcf8523 i2c_bcm2708 i2c_dev regmap_i2c cdc_acm ftdi_sio pl2303 cp210x usbserial dm_crypt dm_mod hid_multitouch goodix_ts snd_soc_core snd_pcm_dmaengine snd_compress snd_bcm2835(C) snd_pcm snd_timer snd rt2800usb rt2800lib rt2x00usb rt2x00lib brcmfmac_wcc
[  645.782079]  brcmfmac brcmutil rtl8xxxu rtl8192cu rtl8192c_common rtl_usb rtlwifi xpad ff_memless tun i2c_bcm2835 overlay lib80211 mac80211 cfg80211 rfkill xt_owner xt_REDIRECT iptable_nat xt_MASQUERADE nf_nat xt_state nf_conntrack ipt_REJECT nf_reject_ipv4 nf_defrag_ipv6 nf_defrag_ipv4 xt_tcpudp iptable_filter ip_tables x_tables crc_ccitt squashfs fuse libarc4 ctr ccm cryptd sha256_arm64 aes_arm64 aes_generic libaes
[  645.782228] CPU: 0 UID: 0 PID: 297 Comm: SMIO Tainted: G        WC         6.12.16-v8+ #1859
[  645.782242] Tainted: [W]=WARN, [C]=CRAP
[  645.782248] Hardware name: Raspberry Pi 4 Model B Rev 1.1 (DT)
[  645.782255] pstate: 20000005 (nzCv daif -PAN -UAO -TCO -DIT -SSBS BTYPE=--)
[  645.782265] pc : vc_sm_release_resource+0x54/0xf8 [vc_sm_cma]
[  645.782285] lr : vc_sm_release_resource+0x50/0xf8 [vc_sm_cma]
[  645.782296] sp : ffffffc080d63cf0
[  645.782302] x29: ffffffc080d63cf0 x28: ffffffc080a19da8 x27: ffffffac44f054d0
[  645.782317] x26: ffffffeb02f96cf0 x25: ffffffc080a19da0 x24: ffffffac44f05f98
[  645.782330] x23: ffffffac44f05908 x22: ffffffac4c854c20 x21: ffffffeb02f1b000
[  645.782344] x20: ffffffeb02f1b000 x19: ffffffac4c854c00 x18: ffffffffffffffff
[  645.782357] x17: ffffffc1499e7000 x16: ffffffeb33f8c698 x15: ffffffc080d63c75
[  645.782370] x14: 0000000000000032 x13: ffffffac4025eae8 x12: 0000000000000000
[  645.782383] x11: ffffffac414b53f8 x10: ffffffac414b5240 x9 : ffffffeb03066288
[  645.782397] x8 : ffffffac414b5268 x7 : 0000000000000034 x6 : 000000000000000c
[  645.782410] x5 : 0000000000000000 x4 : 0000000000000000 x3 : 0000000000000000
[  645.782423] x2 : 0000000000000000 x1 : 0000000000000000 x0 : ffffffac4025eb00
[  645.782436] Call trace:
[  645.782442]  vc_sm_release_resource+0x54/0xf8 [vc_sm_cma]
[  645.782454]  vc_sm_vpu_event+0x42c/0x508 [vc_sm_cma]
[  645.782464]  vc_sm_cma_vchi_videocore_io+0x1dc/0x398 [vc_sm_cma]
[  645.782475]  kthread+0x120/0x130
[  645.782488]  ret_from_fork+0x10/0x20
[  645.782502] Code: f9438280 91020000 94000c3f a9400662 (f9000441) 
[  645.782512] ---[ end trace 0000000000000000 ]---

Once that happened, other calls interfacing with the hardware might lock up and in my case the hardware watchdog resets the CPU. See also the discussion on the Pi forum.

Steps to reproduce the behaviour

On a Pi4, run the code from https://gist.github.com/dividuum/da0a9a7038b592898ea269f19917e438. After a few seconds, the program will stop showing output and the kernel log will likely show a traceback similar to the one above. Using more threads seems to speed up the time it takes to crash.

Device (s)

Raspberry Pi 4 Mod. B

System

Tested on

Revision        : b03111
Model           : Raspberry Pi 4 Model B Rev 1.1

 # uname -a (Kernel from raspberrypi/rpi-firmware)
Linux info-beamer-x 6.12.16-v8+ #1859 SMP PREEMPT Mon Feb 24 13:14:16 GMT 2025 aarch64 GNU/Linux

# vcgencmd bootloader_version
2025/02/11 17:00:13
version 75c1e570e99e14684e79e6ab8f5355d831440c71 (release)
timestamp 1739293213
update-time 1741025244
capabilities 0x0000007f

# vcgencmd version
Feb 17 2025 20:03:07 
Copyright (c) 2012 Broadcom
version da7125f985dfe3cb0cf91e3c47f1ace88018e466 (clean) (release) (start)

Logs

No response

Additional context

No response

[6by9]

Investigating.

It looks like it fails and is still holding sm_state->lock, so cat /sys/kernel/debug/vcsm-cma blocks.

[6by9]

#6703 fixes one issue.

Allocating and freeing kernel IDs took the spinlock, but looking up the value didn't. Another thread importing or freeing could therefore corrupt the idr whilst a thread was doing a lookup, resulting in a duff buffer pointer.

Your test case ran for just over 100000 iterations (compared to a few thousands before), but still failed.

[6by9]

Definitely timing related as adding logging reduces the rate of reproduction :-/
So it is almost certainly a thread safety issue, but I'm not seeing it at the moment.

[6by9]

The logging output is leaving me confused at the moment.

I've tweaked the test case to have a separate dmabuf with a different size per thread, so that I can identify which log messages are associated to which thread.

In the failure case I have the "attempt to import" message, but I don't get the log line from vc_sm_add_resource at the end of the function, so it does seem reasonable that the lookup fails when we then get the release.
However the ioctl call from the allocation shouldn't have completed until vc_sm_cma_import_dmabuf_internal and added the resource (or the error handling), so I can't see how we get to the vpu free complete message without any of the error paths.

One to look at further tomorrow.

[dividuum]

Ok. This is a long shot, but what about this:

1. This fails for some reason: https://github.com/raspberrypi/linux/blob/rpi-6.12.y/drivers/staging/vc04_services/vc-sm-cma/vc_sm.c#L780
2. Results in https://github.com/raspberrypi/linux/blob/rpi-6.12.y/drivers/staging/vc04_services/vc-sm-cma/vc_sm.c#L842 calling vc_sm_cma_vchi_free
3. Which if I understand correctly triggers a callback resulting in the code getting here: https://github.com/raspberrypi/linux/blob/rpi-6.12.y/drivers/staging/vc04_services/vc-sm-cma/vc_sm.c#L971
4. This looks up the buffer again using https://github.com/raspberrypi/linux/blob/rpi-6.12.y/drivers/staging/vc04_services/vc-sm-cma/vc_sm.c#L974
5. And locks it https://github.com/raspberrypi/linux/blob/rpi-6.12.y/drivers/staging/vc04_services/vc-sm-cma/vc_sm.c#L981

But the lock is first initialized here: https://github.com/raspberrypi/linux/blob/rpi-6.12.y/drivers/staging/vc04_services/vc-sm-cma/vc_sm.c#L796, which is after the vc_sm_cma_vchi_import call that fails? It also seems to then result in using the buffer to call vc_sm_release_resource in a state that is before a vc_sm_add_resource was issued. So it seems buffer->global_buffer_list might be NULL?

This assumes https://github.com/raspberrypi/linux/blob/rpi-6.12.y/drivers/staging/vc04_services/vc-sm-cma/vc_sm.c#L789 is reached with status being != 0 while result.res_handle is set. Not sure if this is something that can happen.

Sorry if this is wasting your time. I don't quite understand how this all works together or how threading the kernel works exactly.

[6by9]

Not wasting my time at all - more eyes on code is always a good thing.
I still remember the hours wasted much earlier in my career trying to find an issue in an error path which ended up being

if (error occurred)
{
  for (i=0;  i<limit; i++)
  {
    if (i happens to be affected by this error);
    {
      clean_up(i);
    }
  }
}

The error was fairly infrequent (every few days), but when triggered resulted in all the monitors on a police CCTV system being blanked! They weren't too happy to say the least.

Although in this case I've already been down that path in trying to work out how we can have skipped the vc_sm_add_resource call.

Neither of the pr_debug messages from vc_sm_cma_vchi_import failing appear in my logs, and I've added a log message if dma_buf_export fails at line 826. I've even gone as far as a WARN_ON at line 839 to ensure we're not going through the error handling path.
Time to rework the logging to only give the couple of log points that are of interest here.

Regarding threading, the userspace ioctl call will call vc_sm_cma_import_dmabuf_internal and then vc_sm_cma_import_dmabuf_internal in effectively the userspace applications context, blocking userspace until it returns.

On close of the fd, vc_sm_dma_buf_release gets called. That tells the VPU to drop the mapping and completes the close call, but the kernel for the VC_SM_MSG_TYPE_RELEASED event being returned to confirm that it has unmapped before releasing the dma_buf.

[dividuum]

I did a bit of debugging and found the following:

[   28.932648] vc_sm_cma_import_dmabuf_internal import 00000000d8b39ad1 1/4
[   28.932927] vc_sm_vpu_event callback RELEASED 00000000d8b39ad1
[   28.932931] vc_sm_release_resource: Release 00000000d8b39ad1: 0 0 0 0000000000000000 0000000000000000->0000000000000000
[   31.271806] vc_sm_cma_import_dmabuf_internal import 00000000d8b39ad1 2/4

• The first line is a printk right before the vc_sm_cma_vchi_import.
• The second line within is vc_sm_vpu_event to confirm the next line is triggered by a event callback
• The third line is at the start of vc_sm_release_resource, called by the event. Most struct values are still NULL or 0, including buffer->global_buffer_list which then ultimately triggers the NULL pointer dereference when list_del is called.
• The fourth line is now back at vc_sm_cma_import_dmabuf_internal, this time directly after the vc_sm_cma_vchi_import from the first line.

I explicitly removed the kfree(buffer), so addresses should be unique and not identical due to reuse.

Two things:

• It seems the release event can happen before the vc_sm_cma_vchi_import completes.
• The vc_sm_cma_vchi_import took looong.

[dividuum]

Continuing:

[   51.197754] vc_sm_cma_import_dmabuf_internal import 000000009518ea1b 1/4 import=00000000c1899259
[   51.197760] vc_sm_cma_vchi_send_msg: 00000000c1899259 entry
[   51.197763] vc_sm_cma_vchi_send_msg: 00000000c1899259 create cmd blk 1/2
[   51.199536] vc_sm_cma_vchi_send_msg: 00000000c1899259 create cmd blk 2/2
[   51.199540] vc_sm_cma_vchi_send_msg: 00000000c1899259 cmd blk 370477
[   51.199544] vc_sm_cma_vchi_send_msg: 00000000c1899259 wait for completion
[   51.201862] vc_sm_vpu_event callback RELEASED 000000009518ea1b
[   51.201866] vc_sm_release_resource: Release 000000009518ea1b: 0 0 0 0000000000000000 0000000000000000->0000000000000000
[   51.201888] Unable to handle kernel NULL pointer dereference at virtual address 0000000000000008
[   51.214659] vc_sm_cma_vchi_send_msg: 00000000c1899259 copy result: cmd blk 370477
[   51.214670] vc_sm_cma_vchi_send_msg: 00000000c1899259, wait msg: return 0
[   51.214673] vc_sm_cma_import_dmabuf_internal import 000000009518ea1b 2/4 status 0
[   51.214707] vc_sm_cma_import_dmabuf_internal import 000000009518ea1b 3/4
[   51.214711] vc_sm_cma_import_dmabuf_internal import 000000009518ea1b 4/4
[   51.214714] vc_sm_add_resource: Add 000000009518ea1b

I traced further into vc_sm_cma_vchi_send_msg. It allocates a cmd_blk via vc_vchi_cmd_create and control reaches up to the wait_for_completion_interruptible line. Then the callback event triggers and causes the NULL-deref. After that the completion returns, follows the result && result_size path and exists with status 0.

[dividuum]

I give up for today. After staring at the code for the last two hours I tried replacing idr_alloc with idr_alloc_cyclic, now vc_sm_cma_vchi_send_msg starts returning EINTR or ENXIO after 1.2 million imports and no progress gets made. I don't get it.

[6by9]

I traced further into vc_sm_cma_vchi_send_msg. It allocates a cmd_blk via vc_vchi_cmd_create and control reaches up to the wait_for_completion_interruptible line. Then the callback event triggers and causes the NULL-deref. After that the completion returns, follows the result && result_size path and exists with status 0.

The weird part is that the vpu_event call shouldn't happen until all firmware references to the memory block have been released, and that includes the one that vc-sm-cma has just taken whilst importing the dmabuf.

I have just spotted that there is a slightly surprising loop in vchiq_queue_kernel_message. If vchiq_queue_message returns -EAGAIN, then it does an msleep(1) and tries again.
vc_sm_cma_vchi_free doesn't require a response from the firmware directly, and so that release could be delayed. However all the resources behind the allocation (dmabuf and kernel_id values) shouldn't be released and reused until we get the vpu_event back, so on the surface that would imply that everything should still be safe.

I'm adding logging / error handling to check that vc_sm_release_resource is given a buffer that has had both get_kernel_id to allocate the kernel_id, and vc_sm_add_resource called for it, and scream if not.

[dividuum]

I have just spotted that there is a slightly surprising loop in vchiq_queue_kernel_message. If vchiq_queue_message returns -EAGAIN, then it does an msleep(1) and tries again.

I guess that's the one mentioned here?

[6by9]

Yes, it's at https://github.com/raspberrypi/linux/blob/rpi-6.6.y/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_core.c#L3227-L3240

[6by9]

So switching to idr_alloc_cyclic does give me a number of log messages of "VC released a buffer that is already released" (technically it's that we can't match the kernel_id value in the idr).

With idr_alloc that is likely to hit a kernel_id value that has been freshly reused and is in the process of being allocated.

The bit I still don't understand is how we're getting that callback twice (I think that's more likely than the sequencing getting messed up during allocation).

I am also seeing numerous mailbox calls timing out, but checking the VPU logs it is maxed out dealing with all these buffer mapping calls, so that's not so unsurprising.

[6by9]

Something is certainly going wrong and stopping messages being handled.
I have the VPU stuck waiting to send MSG_TYPE_RELEASED message, which is blocking the thread that processes any of the messages from vcsm-cma.

[dividuum]

So this might not even be a Linux-side bug but something in whatever is handling the mailbox replies on the other end? I would assume that the part responsible for handling the 'import' or 'release' message also doesn't accidentally produce two responses.

[6by9]

It's something in the handling of VCHI. It's most likely that "slots" aren't getting freed under some conditions, and we end up with none available.

I'll be talking to pelwell in the morning over it - he's the man who knows how that is meant to all work.