linux-kernel - Re: [PATCH 2/2] printk: always report lost messages on serial console

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: <20170105105311.GL25166@pathway.suse.cz>
Date:   Thu, 5 Jan 2017 11:53:11 +0100
From:   Petr Mladek <pmladek@...e.com>
To:     Sergey Senozhatsky <sergey.senozhatsky.work@...il.com>
Cc:     Sergey Senozhatsky <sergey.senozhatsky@...il.com>,
        Andrew Morton <akpm@...ux-foundation.org>,
        Steven Rostedt <rostedt@...dmis.org>,
        Peter Hurley <peter@...leysoftware.com>,
        linux-kernel@...r.kernel.org
Subject: Re: [PATCH 2/2] printk: always report lost messages on serial console

On Thu 2017-01-05 11:30:47, Sergey Senozhatsky wrote:
> On (01/04/17 16:26), Petr Mladek wrote:
> > On Wed 2017-01-04 22:34:48, Sergey Senozhatsky wrote:
> > > On (01/04/17 11:52), Petr Mladek wrote:
> > > [..]
> > > > > this is from the real serial logs I'm looking at right now. we attach
> > > > > "bad news" to 'critical' messages only:
> > > > > 
> > > > > ...
> > > > > [   32.941061] bc00: b65dc0d8 b65dc6d0 ae1fbc7c b65c11c5 b563c9c4 00000001 b65dc6d0 b0a62f74
> > > > > ** 150 printk messages dropped ** [   32.941614] cee0: 00000081 ae1fcef0 00000038 00000000 b5369000 ae1fcf00 ae1fd0f0 00000000
> > > > > ** 75 printk messages dropped ** [   32.941892] d860: 00056608 af203848 00000000 0004088c 000000d0 00000000 00000000 00000000
> > > > > ** 12 printk messages dropped ** [   32.941940] ..
> > > > > ** 2 printk messages dropped ** [   32.941951] ..
> > > > > ** 10 printk messages dropped ** [   32.941992] ..
> > > > > ** 1 printk messages dropped ** [   32.941999] ..
> > > > > ...

Please, be more explicit. What exactly was of extreme imporance
in the output above?

Was it the information about lost messages?

    ** XXX printk messages dropped **

Or was is some of the data?

    [   32.941614] cee0: 00000081 ae1fcef0 00000038 00000000 b5369000 ae1fcf00 ae1fd0f0 00000000
    [   32.941892] d860: 00056608 af203848 00000000 0004088c 000000d0 00000000 00000000 00000000


> > OK, it is possible that I miss-interpreted the message. It looked like
> > a random memory dump that did not make sense without a context.
> 
> this is funny. ok... let me tell you my version.
> I saw an incomplete serial log with lost important messages. the serial
> log was nothing but garbage. zero value. I could simply `rm screenlog.0'
> it. end of story.
> 
> and no matter what loglevel we attach the "printk messages dropped"
> to we always will lose XYZ important messages in the given circumstances.
> and that "let's print 1 out of thousands lost critical messages, so the
> serial log will make sense" is a little bit far from being true. sorry,
> it is what it is.

I never claimed that you would see more messages with my patch.
I claimed that you should see messages with the requested severity
level with my patch.

If you get better results with random messages than I see two
possibilities:

  + some/many messages have assigned wrong level

  + the message levels are useless in general


> > > and the options here are
> > > 	"print 1 random message out of XXX or XXXX lost messages"
> > > vs
> > > 	"print 1 random message out of XXX or XXXX lost messages"
> > 
> > And this is not fully correct and probably the root of
> > the misunderstanding. The difference between your patch
> > and mine patch is:
> > 
> > 	"always print '%u printk messages dropped'" +
> > 	"print 1 random message out of XXX or XXXX lost messages"
> > 
> > vs
> > 
> > 	"always print '%u printk messages dropped'" +
> > 	"print 1 random message with level under console_level
> > 	 out of XXX or XXXX lost messages"
> > 
> > and that's it. I am sorry if I was not able to explain this
> > a more clear way.
> 
> 
> ... I understand what your patch is doing. see the serial log atop of
> this message, this is from the 'attach "printk messages dropped to a
> visible loglevel"' approach.

atop? I am lost. There is only one real-life output atop of this
message and you claimed that it was of extreme importance. I thought
that you got it with your patch.


> what I don't understand is why do you
> claim that it produces significantly more meaningful/useful serial logs.
> because it does not. it produces the 'rm screenlog.0' material. we
> can't protect/save/take care of/whatever the logbuf messages once we
> unlock the logbuf lock. and the point is - for a guy who reads the
> incomplete serial log 'print 1 random message out of XXX or XXXX lost
> messages' is pretty much the same as 'print 1 random message of visible
> loglevel out of XXX or XXXX lost messages'. because the really important
> part here is 'you see 1 message out of XXXX', and there is no way to
> reconstruct those XXXX lost messages, no matter how small the XXXX is:

If it does not matter what message we print then why do we have
the log levels in the first place?


> [   x.xxxx] Call Trace:
> ** 9 printk messages dropped ** [   x.xxxx] ---[ end trace ]---

This is unfortunate. This line does not include any useful
information but it is part of an important blob of lines.

A solution might be to proceed more lines of the same level
at once. One line usually is not enough. We will still get
only random blobs of lines but at least some of them should
be more usable than single random lines.

Best Regards,
Petr