svn commit: r231923 - head/sys/kern

Bruce Evans brde at optusnet.com.au
Mon Feb 20 16:26:24 UTC 2012


On Mon, 20 Feb 2012, Xin Li wrote:

> On 02/19/12 21:55, Bruce Evans wrote:
>> On Mon, 20 Feb 2012, Xin LI wrote:
>>
>>> Log: Use uprintf instead of printf for the reason why a kernel
>>> module can not be loaded.  This way, the administrator can get
>>> response immediately from the shell session rather than relying
>>> on dmesg.
>
> First of all thanks for your comments!
>
>> But this way, the message doesn't get logged, and in fact doesn't
>> go to either of the places where it went before (the
>> low-level-console and the log).
>
> The old behavior seems to be a little bit contradict with intuition,
> as the error message could be shown on a different TTY.  What happens
> here would be, let's say the user is on ttyv1, and do a 'kldload foo'
> where foo.ko depends on a non-existent kernel module, the system would
> spit error on console (not ttyv1) and log it.

Yes, this is a general problem with printf.

>> Its hard to think of many cases where either printf() or uprintf()
>> is correct for system-related or security-related messages
>> generated by applications.  printf() spams the console, and
>> uprintf() isn't logged. tprintf() would go to a slightly different
>> controlling terminal than uprintf(), and optionally to the log.
>> ...
>
> I have found another issue so I've reverted this revision for now.
> I'll put together a new patchset for review.  I'm not quite convinced
> with logging these events, though, since the kernel linker would
> return a error value if load is not successful, and we do not log e.g.
> ELF format errors, should kernel modules be treated differently here?
> Or should I use tprintf(.., LOG_ERR, ..) for these cases?

tprintf() (or a separate log()) lets you control the priority.  printf()
gives a high priority and LOG_ERR may be too high too.  (BTW, there is
a lot of magic for printf()'s priority.  syslog.h defines LOG_PRINTF as
-1 (without the necessary parentheses).  I thought that nothing used this
any more, but printf() actually hard-codes the -1.)

I don't know why we print anything at all in the kernel about this and
other errors.  Why not let the application print something?  kern_linker.c
has lots of other printf()s.  Well, the printf()s give more detail than
a single error can give.  But most other subsystems don't use printf()s
for syscalls.  kern_linker.c also does some boot-time loading where there
is no syscall or terminal, so it must use printf() or log().

I don't believe in modules and haven't used one for years, so I
shouldn't be talking about this :-).  But I have been looking at the
printf() plumbing a lot lately.  Another thing that seems wrong, is
that log() prints only to the log if the log is open, and only to the
console if the log is not open.  This seems to mainly break boot code
that wants to use log() instead of printf() so as to get better
filtering for the log and doesn't care if the console is not used.
Why not always print to the message buffer in log(), and also to
the console if the log is not open?  Well, we risk filling up the
log if we write to it when it is not open.  But printf() does that
anyway, and in practice boot code writes a lot to the log via
printf().  Some consider the console part of this to be spam, but
everyone wants the log part.  So we now have a very large message
buffer (up from a whole 4K (non-configurable, MI) in 4.4BSDLite2
to 96K (configurable, MI default)) to hold the non-spam.  It can
hold a few log() messages too.  Boot code apparently knows a little
about this problem, so it always uses printf().  Thus the only
case where log() is likely to cycle the message buffer when it is
not open and doesn't cycle now is after the system is up, but someone
kills syslogd and then spams with log().  The correct treatment seems
to be:
- never write nil priority messages to the message buffer
- always write high priority messages to it
- otherwise, write to it if it has plenty of space free
- otherwise, leave some space for high-priority messages.  Do this
   even of the log is open.
- all printf()s probably need to be considered high priority, since
   there is no way to specify their priority.  Change some low priority
   and/or spammish ones to use log(), although this loses their console
   printing when the log is open.
- abuse the priority field some more to tell log() to print to the
   console too, so that it can be a full replacement for printf(),
   with optional printing to the log.  Use this to recover console
   printing for low priority messages and to force logging for
   high priority ones.  An average printf() hopefully doesn't need
   to be changed to control its logging, so the default for printf()
   would become to not log it if the log almost full.

I often use spammish printf()s in debugging code, and in most cases I
don't want them to fill up log files although I might want them to go
to the message buffer.  Large histories help here too.  After a crash
that breaks syslogd and/or more, it is often possible to see all the
messages in either a large console driver history buffer or in the
message buffer.  The history sizes are slightly different, so in rare
cases you might find useful stuff in the message buffer that is not
on the console.  But there is currently no way to get low-level console
output without also spamming the message buffer, and also the log files
if you forget to kill syslogd.

Bruce


More information about the svn-src-head mailing list