[GIT PULL] printk for 4.13

[GIT PULL] printk for 4.13

[Petr Mladek]

Linus,

please pull the latest printk changes from

  git://git.kernel.org/pub/scm/linux/kernel/git/pmladek/printk.git for-linus


==========

- Store printk() messages into the main log buffer directly even in NMI
  when the lock is available. It is the best effort to print even large
  chunk of text. It is handy, for example, when all ftrace messages
  are printed during the system panic in NMI.

- Add missing annotations to calm down compiler warnings.

----------------------------------------------------------------

Nicolas Iooss (1):
      printk: add __printf attributes to internal functions

Petr Mladek (2):
      printk: Use the main logbuf in NMI when logbuf_lock is available
      Merge branch 'for-4.13' into for-linus

 kernel/printk/internal.h    |  6 ++++--
 kernel/printk/printk.c      | 19 ++++++++++++++-----
 kernel/printk/printk_safe.c | 36 +++++++++++++++++++++++++++++-------
 lib/nmi_backtrace.c         |  3 +++
 4 files changed, 50 insertions(+), 14 deletions(-)


Best Regards,
Petr Mladek

Re: [GIT PULL] printk for 4.13

[Linus Torvalds]

On Mon, Jul 3, 2017 at 7:24 AM, Petr Mladek <pmladek@suse.com> wrote:
>
> - Store printk() messages into the main log buffer directly even in NMI
>   when the lock is available. It is the best effort to print even large
>   chunk of text. It is handy, for example, when all ftrace messages
>   are printed during the system panic in NMI.

No, this is entirely buggered.

You can't just do

   raw_spin_is_locked(&logbuf_lock)

to test whether you can get the logbuf_lock and then call vprintk_default().

It's not just about deadlock avoidance, the code will call things like
down_trylock() on the console semaphore, and that operation is
fundamentally not NMI-safe. The semaphore count is literally protected
by a irq-safe (BUT NOT NMI-SAFE!) semaphore spinlock.

So now you can instead deadlock just on the internal console semaphore
spinlock (ie somebody is doing "console_lock()", NMI comes in, *BOOM*.

Maybe I'm missing something, but I'm skipping this pull request as
"completely broken".

                     Linus

Re: [GIT PULL] printk for 4.13

[Sergey Senozhatsky]

Hello,

On (07/05/17 11:23), Linus Torvalds wrote:
> On Mon, Jul 3, 2017 at 7:24 AM, Petr Mladek <pmladek@suse.com> wrote:
> >
> > - Store printk() messages into the main log buffer directly even in NMI
> >   when the lock is available. It is the best effort to print even large
> >   chunk of text. It is handy, for example, when all ftrace messages
> >   are printed during the system panic in NMI.
> 
> No, this is entirely buggered.
> 
> You can't just do
> 
>    raw_spin_is_locked(&logbuf_lock)
> 
> to test whether you can get the logbuf_lock and then call vprintk_default().
> 
> It's not just about deadlock avoidance, the code will call things like
> down_trylock() on the console semaphore, and that operation is
> fundamentally not NMI-safe. The semaphore count is literally protected
> by a irq-safe (BUT NOT NMI-SAFE!) semaphore spinlock.
>
> So now you can instead deadlock just on the internal console semaphore
> spinlock (ie somebody is doing "console_lock()", NMI comes in, *BOOM*.

you are right. but

PRINTK_NMI_DEFERRED_CONTEXT_MASK calls into vprintk_deferred(), which
does vprintk_emit(0, LOGLEVEL_SCHED, NULL, 0, fmt, args). and
vprintk_emit() LOGLEVEL_SCHED is nothing, but printk_deferred(), which
never calls into the scheduler and does not even try to lock console_sem.
the only lock it takes is logbuf_lock, and the idea behind those checks
in printk_nmi_enter() is to make sure that we can safely call
vprintk_deferred() from NMI on that CPU.

printk_safe context is per-CPU, so if we see at NMI entry that this_cpu
has PRINTK_SAFE_CONTEXT_MASK set, then it means that NMI is preempting
printk-safe context on this_cpu, which is already alarming, because we
switch to printk-safe context *mostly* in places where printk recursion
can deadlock us (console_sem up/down/try_down and logbuf_lock lock/unlock).

why *mostly*... because we are also in printk-safe context during the
call_console_drivers() call.

so this is why we also check raw_spin_is_locked(&logbuf_lock). by the
time we do raw_spin_is_locked(&logbuf_lock) we already know that
this_cpu is in printk-safe, so it is _potentially_ unsafe to call
vprintk_emit(), unless we are printk-safe for call_console_drivers(),
which means that logbuf_lock is not lockde by this_cpu.

so what printk_nmi_enter() does

- this_cpu_read(printk_context) & PRINTK_SAFE_CONTEXT_MASK

  if we are NOT in printk-safe then we know that from this CPU we can
  call printk_deferred().

  otherwise, we need to make sure that it is safe to call printk_deferred().

- raw_spin_is_locked(&logbuf_lock)

  if the lock is not locked -- we can printk_deferred() from that CPU.

  otherwise, we use printk-nmi buffer and flush the messages to logbuf
  later from irq_work.


does this make sense?

	-ss

Re: [GIT PULL] printk for 4.13

[Sergey Senozhatsky]

On (07/06/17 09:44), Sergey Senozhatsky wrote:
> > No, this is entirely buggered.
> > 
> > You can't just do
> > 
> >    raw_spin_is_locked(&logbuf_lock)
> > 
> > to test whether you can get the logbuf_lock and then call vprintk_default().
> > 
> > It's not just about deadlock avoidance, the code will call things like
> > down_trylock() on the console semaphore, and that operation is
> > fundamentally not NMI-safe. The semaphore count is literally protected
> > by a irq-safe (BUT NOT NMI-SAFE!) semaphore spinlock.
> >
> > So now you can instead deadlock just on the internal console semaphore
> > spinlock (ie somebody is doing "console_lock()", NMI comes in, *BOOM*.
> 
> you are right. but
> 

just in case if my previous email was too hard to follow, may be the
link below will explain it in a less broken language. (I'm sorry, I'm
on medication now and didn't have enough coffee yet.)

https://marc.info/?l=linux-kernel&m=149265908228203&w=2

	-ss

Re: [GIT PULL] printk for 4.13

[Linus Torvalds]

On Wed, Jul 5, 2017 at 5:44 PM, Sergey Senozhatsky
<sergey.senozhatsky.work@gmail.com> wrote:
>
> PRINTK_NMI_DEFERRED_CONTEXT_MASK calls into vprintk_deferred(), which
> does vprintk_emit(0, LOGLEVEL_SCHED, NULL, 0, fmt, args). and
> vprintk_emit() LOGLEVEL_SCHED is nothing, but printk_deferred(), which
> never calls into the scheduler and does not even try to lock console_sem.

Hmm. Ok. I think I see what you're saying. We're just adding it to the
log buffer, but not actually going through the whole "lets see if we
can push it further".

So I will take another look tomorrow, right now I'm feeling a bit
merged out for the day,

               Linus

Re: [GIT PULL] printk for 4.13

[Sergey Senozhatsky]

On (07/05/17 18:15), Linus Torvalds wrote:
> On Wed, Jul 5, 2017 at 5:44 PM, Sergey Senozhatsky
> <sergey.senozhatsky.work@gmail.com> wrote:
> >
> > PRINTK_NMI_DEFERRED_CONTEXT_MASK calls into vprintk_deferred(), which
> > does vprintk_emit(0, LOGLEVEL_SCHED, NULL, 0, fmt, args). and
> > vprintk_emit() LOGLEVEL_SCHED is nothing, but printk_deferred(), which
> > never calls into the scheduler and does not even try to lock console_sem.
> 
> Hmm. Ok. I think I see what you're saying. We're just adding it to the
> log buffer, but not actually going through the whole "lets see if we
> can push it further".

yep ;)

> So I will take another look tomorrow, right now I'm feeling a bit
> merged out for the day,

sure. thanks.

	-ss