linux-kernel - Re: [PATCH] printk/console: Do not suppress information about dropped messages

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Message-ID: <87fts9fy5n.fsf@linutronix.de>
Date:   Wed, 27 Feb 2019 09:12:04 +0100
From:   John Ogness <john.ogness@...utronix.de>
To:     Sergey Senozhatsky <sergey.senozhatsky.work@...il.com>
Cc:     Petr Mladek <pmladek@...e.com>,
        Sergey Senozhatsky <sergey.senozhatsky@...il.com>,
        Steven Rostedt <rostedt@...dmis.org>,
        linux-kernel@...r.kernel.org
Subject: Re: [PATCH] printk/console: Do not suppress information about dropped messages

On 2019-02-27, Sergey Senozhatsky <sergey.senozhatsky.work@...il.com> wrote:
>>>  		if (console_seq < log_first_seq) {
>>> -			len = sprintf(text,
>>> -				      "** %llu printk messages dropped **\n",
>>> -				      log_first_seq - console_seq);
>>> +			console_dropped_cnt += log_first_seq - console_seq;
>>>  
>>>  			/* messages are gone, move to first one */
>>>  			console_seq = log_first_seq;
>>>  			console_idx = log_first_idx;
>>> -		} else {
>>> -			len = 0;
>>>  		}
>>>  skip:
>>>  		if (console_seq == log_next_seq)
>>> @@ -2435,6 +2441,13 @@ void console_unlock(void)
>>>  			exclusive_console = NULL;
>>>  		}
>>>  
>>> +		if (unlikely(console_dropped_cnt)) {
>>> +			len = sprintf(text,
>>> +				      "** %llu printk messages dropped **\n",
>>> +				      console_dropped_cnt);
>>> +			console_dropped_cnt = 0;
>>> +		}
>>> +
>> 
>> My only objection to this is that the "messages dropped" only comes if a
>> non-supressed message comes. So information about dropped information
>> may never get printed unless some task prints something non-supressed.
>> 
>> Imagine a situation where I am expecting a message to come, but don't
>> see it because it was dropped. But if no more non-supressed messages
>> come, I see neither the expected message nor the dropped message.
>
> I think this is exactly the problem (and thus the patch) we discussed
> some 3 years ago.

I guess you are referring to this [0] thread.

> I had a number of rather strangely looking serial logs, which clearly
> had lost messages but no "%llu printk messages dropped" markers. So I
> added `static bool lost_messages' to console_unlock(), set it when
> printing loop would discover lost messages, then print "%llu printk
> messages dropped" attached to whatever msg was next in the logbuf,
> regardless of msg->level.  IOW, if lost_messages was set then
> suppress_message_printing(msg->level) was not even invoked. Yes, that
> would sometimes print several "debugging noise" messages, but the main
> part was that I would have "%llu printk messages dropped" markers in
> the logs; which was much more important to me.

I would agree with the proposed solution from 2016. My experience is
that the dropped messages are very important. Yes, printing them could
lead to the loss of even more messages. But still, it is important
information that needs to get out.

John Ogness

[0] https://lkml.kernel.org/r/20161224140902.1962-3-sergey.senozhatsky@gmail.com