Date: Tue, 21 Feb 2012 03:26:13 +1100 (EST) From: Bruce Evans <brde@optusnet.com.au> To: d@delphij.net Cc: svn-src-head@FreeBSD.org, svn-src-all@FreeBSD.org, src-committers@FreeBSD.org, Xin LI <delphij@FreeBSD.org> Subject: Re: svn commit: r231923 - head/sys/kern Message-ID: <20120221023401.B1246@besplex.bde.org> In-Reply-To: <4F4215E0.20908@delphij.net> References: <201202200105.q1K15HRB024037@svn.freebsd.org> <20120220154900.R3579@besplex.bde.org> <4F4215E0.20908@delphij.net>
next in thread | previous in thread | raw e-mail | index | archive | help
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
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?20120221023401.B1246>