Potential use-after-free around QSTRs?

[dos1]

Hello!

I'm trying to debug a peculiar issue where I'm occasionally seeing a cryptic exception being thrown at boot, coming from import os:

Traceback (most recent call last):
  File "/flash/sys/main.py", line 1, in <module>
  File "/flash/sys/st3m/__init__.py", line 1, in <module>
  File "/flash/sys/st3m/reactor.py", line 3, in <module>
  File "/flash/sys/st3m/profiling.py", line 2, in <module>
  File "/flash/sys/st3m/settings.py", line 23, in <module>
  File "", line 2, in <module>
  File "os/__init__.py", line 6, in <module>
ValueError:

The issue is quite hard to debug - adding a bunch of printfs or doing some random changed in listed Python files can make it disappear. I did however manage to actually gather some insight into what's going on.

The exception gets thrown from mp_builtin___import___default while trying to import os.path in this check:

    if (module_name_len == 0) {
        mp_raise_ValueError(NULL);
    }

Turns out that the QSTR that gets passed into mp_builtin___import___default as its first argument contains a proper null-terminated string os.path, but its length field is 0.

When placing a breakpoint on mp_raise_ValueError, I've managed to find out that mp_state_ctx.vm.qstr_last_chunk and mp_state_ctx.vm.last_pool are pointing to the exact same address. Looks like strings started to overwrite the last_pool's structure, which lead to the pointer to lengths array becoming corrupted:

(gdb) p mp_state_ctx.vm.last_pool->qstrs
$67 = 0x3c40a548
(gdb) p mp_state_ctx.vm.last_pool->hashes
$68 = (qstr_hash_t *) 0x3c40aa48
(gdb) p mp_state_ctx.vm.last_pool->qstrs+320
$69 = (const char **) 0x3c40aa48
(gdb) p mp_state_ctx.vm.last_pool->lengths
$70 = (qstr_len_t *) 0x666f6e6f ""

At that point the pool size is 320. As you can see, qstrs and hashes are spaced as expected, by lengths points to some bogus address. Trying to dereference it returns zeros.

(gdb) p mp_state_ctx.vm.last_pool->alloc
$8 = 320
(gdb) p mp_state_ctx.vm.last_pool->len
$9 = 103
(gdb) p mp_state_ctx.vm.last_pool->qstrs[102]
$10 = 0x3c40aa55 "os.path"
(gdb) p mp_state_ctx.vm.last_pool->lengths[102]
$11 = 0 '\000'
(gdb) p mp_state_ctx.vm.last_pool->lengths[101]
$12 = 0 '\000'
(gdb) p mp_state_ctx.vm.last_pool->lengths[100]
$13 = 0 '\000'
(gdb) p mp_state_ctx.vm.last_pool->lengths[1]
$14 = 0 '\000'
(gdb) p mp_state_ctx.vm.last_pool->lengths[0]
$15 = 0 '\000'

After looking a bit closer it appears that the last pool allocation (the one that creates the pool of size 320) triggers GC. What caught my attention is this comment in qstr_add:

        qstr_pool_t *pool = (qstr_pool_t *)m_malloc_maybe(pool_size);
        if (pool == NULL) {
            // Keep qstr_last_chunk consistent with qstr_pool_t: qstr_last_chunk is not scanned
            // at garbage collection since it's reachable from a qstr_pool_t.  And the caller of
            // this function expects q_ptr to be stored in a qstr_pool_t so it can be reached
            // by the collector.  If qstr_pool_t allocation failed, qstr_last_chunk needs to be
            // NULL'd.  Otherwise it may become a dangling pointer at the next garbage collection.
            MP_STATE_VM(qstr_last_chunk) = NULL;
            QSTR_EXIT();
            m_malloc_fail(new_alloc);
        }

Haven't caught it red-handed yet (as mentioned, the problem is pretty hard to trigger at will), but my current suspicion is that:

• qstr_from_strn couldn't grow its qstr_last_chunk, so it allocated a new one
• then it calls qstr_add, which realizes that the pool is full and tries to allocate a new one
• the allocation triggers GC, during which the freshly allocated qstr_last_chunk isn't reachable from any pool, so it gets freed
• the allocation succeeds and returns the same pointer for last_pool that was returned for qstr_last_chunk a few steps above
• things go bad.

I'm not familiar with micropython's code, so I wanted to ask: does that make any sense? Am I missing something? There's a lot of stuff running besides micropython in the project I'm working on, so it could very well be caused by something else. However, my theory with GC freeing the last qstr chunk and leaving it as a dangling pointer appears plausible to me based on what I've read in the code so far, so I've figured it won't hurt to ask for a second look. It feels like someone already familiar with this code should be able to validate this theory much quicker than me:)

In case it's relevant, this is all happening on a ESP32-S3 with PSRAM and auto heap split enabled.

[jimmo]

Thanks for the extremely detailed report @dos1

I will have to investigate in more detail, but your theory that this is a use-after-free of sorts does at least sound plausible given what you're seeing.

during which the freshly allocated qstr_last_chunk isn't reachable from any pool, so it gets freed

FWIW the GC also treats the entire C stack, as well as all registers, as potential root pointers. So even if qstr_last_chunk isn't reachable via the pool, it should be still in a register or on the stack.

We have seen this mechanism go wrong, where e.g. the only thing in a register/stack is an offset from the pointer (and it's quite hard to guard against that), but I'm not sure that's likely to be the issue here.

[dos1]

Thanks for the extremely detailed report

Turns out it wasn't detailed enough 😆 I forgot to mention that I'm seeing this on is a bit older version of mpy (from somewhere around 1.20) with backported auto heap split support. Which leads to...

FWIW the GC also treats the entire C stack, as well as all registers, as potential root pointers. So even if qstr_last_chunk isn't reachable via the pool, it should be still in a register or on the stack.

Thanks for this hint! Turns out the patch from #12229 was missing. While it's hard to be 100% sure that applying it fixed the issue, so far I was unable to reproduce it with it applied and judging from the code it does seem very plausible that this was actually the problem seen here.

[jimmo]

Thanks for this hint! Turns out the patch from #12229 was missing. While it's hard to be 100% sure that applying it fixed the issue, so far I was unable to reproduce it with it applied and judging from the code it does seem very plausible that this was actually the problem seen here.

Ah yes that would definitely explain it! Excellent news.