llext: flush logging before unloading extensions

[lyakh]

When logging is deferred it can happen that the logger thread attempts to emit a log entry when the memory, containing log data has been unmapped. This can happen e.g. when an LLEXT object was running from dynamically mapped memory, used logging and was unloaded and unmapped before the logger thread had a chance to emit the entry. To avoid this problem, check that the memory, where the format string is residing, hasn't been unmapped. If that does happen, ignore the error and drop the log entry.

This is required to fix thesofproject/sof#9371 . The fix isn't particularly elegant, it's mixing two hardly related APIs: logging and memory mapping. The key problem is that when logging is deferred, memory that it's trying to access might be gone by then. Ideas for a more generic solution are welcome, but - as usually - if properly fixing this requires significant API extensions or changes, maybe we can apply this or something similar as a temporary fix, while working out a generic solution.

[teburd]

This can happen with any extension using logging, not just ones that happen to use memory mapping. @nordic-krch any thoughts?

One option would be for format string in these cases should be copied along with the varargs used. Any pointers in the varargs should likely also be copied over. (E.g. using "%s" with a string parameter in the loaded extensions rodata section)

Alternatively the logging needs to be flushed while unloading an extension perhaps.

So perhaps in llext_unload...

• Lock everything to prevent preemption on all cores
• Flush all logging
• Unmap/release extension memory

[dcpleung]

I support @teburd's suggestion to flush logging. For logging to NOT copy the format strings and parameters into the buffer, there are specific conditions that need to be met first. Maybe avoid those conditions so you don't have to flush?

[lyakh]

I support @teburd's suggestion to flush logging. For logging to NOT copy the format strings and parameters into the buffer, there are specific conditions that need to be met first. Maybe avoid those conditions so you don't have to flush?

@dcpleung @teburd yes, I was also thinking about this as a potentially more universal solution. But AFAICS there's currently no API to do that, right? Would this be enough?

void log_flush(void)
{
    unsigned int n = atomic_get(&buffered_cnt);
    for (unsigned int i = 0; i < n; i++) {
        log_process();
    }
}

[lyakh]

void log_flush(void)
{
    unsigned int n = atomic_get(&buffered_cnt);
    for (unsigned int i = 0; i < n; i++) {
        log_process();
    }
}

hmm, just tested, this doesn't quite work unfortunately. The while (log_process()) ; version doesn't work either

[teburd]

void log_flush(void)
{
    unsigned int n = atomic_get(&buffered_cnt);
    for (unsigned int i = 0; i < n; i++) {
        log_process();
    }
}

hmm, just tested, this doesn't quite work unfortunately

This seems to be used in a few places...

while (log_process()) {}

You'd also need to perhaps disable interrupts while flushing though to avoid issues

key = irq_lock();
while (log_process()) {}
irq_unlock(key);

[lyakh]

key = irq_lock();
while (log_process()) {}
irq_unlock(key);

no, didn't help either, unfortunately

[lyakh]

This seems to be used in a few places...

@teburd btw, where do you see such examples? I only see this when panicking and in a user-space logging test

[teburd]

Ok maybe a new, possibly pointless idea...

Temporarily boost the priority of the logging thread and tell it to run, locking all the interrupts and junk while unloading the extension.

#include <zephyr/logging/log_ctrl.h>

extern k_thread logging_thread;

void llext_log_flush(void)
{
   int cur_prio;

   /* boost logging thread prio */
   cur_prio = k_thread_priority_get(&logging_thread);
   k_thread_priority_set(&logging_thread, K_HIGHEST_THREAD_PRIO);
   log_thread_trigger();
   k_thread_priority_set(&logging_thread, cur_prio);

}

void llext_unload(...)
{
  int key, cur_prio;

  key = irq_lock();

  /* boost current thread priority */
  cur_prio = k_thread_get_priority(&k_current_get());
  k_thread_set_priority(&k_current_get(), K_HIGHEST_THREAD_PRIO+1);

  llext_log_flush();

  /* unload work done here */

  k_thread_set_priority(&k_current_get(), cur_prio);
  irq_unlock(key);
}

[teburd]

Re-assigned as this now no longer modifies logging code, but I'd still appreciate feedback from @nordic-krch on the approach

[pillo79]

LGTM!
I would also be in favor of moving it to a log_flush function so that it would be universally available, if the approach is acceptable to the logging subsystem.

[lyakh]

https://github.com/zephyrproject-rtos/zephyr/actions/runs/10597173924/job/29368081193?pr=77289 looks like a regression, possibly from #76820

[dcpleung]

I think this should only be done when CONFIG_LOG_MODE_DEFERRED is enabled. Both minimal and immediate modes do not have log processing thread.

[lyakh]

@dcpleung you're right!