klog message buffer full

classic Classic list List threaded Threaded
5 messages Options
Reply | Threaded
Open this post in threaded view
|

klog message buffer full

Alexander Bluhm
Hi,

When doing usb debugging with a lot of kernel printfs, the dmesg
buffer can overflow easily.  It is annoying that you don't notice
this.  Then it is hard to correlate the messages.

So to make clear what happens, I would like to write such a message
to syslogd:
Jun 22 21:58:16 t430s /bsd: usbd_start_next: pipe=0xffff8000003cf
Jun 22 21:58:16 t430s /bsd: klog: dropped 75602 bytes, message buffer full
Jun 22 21:58:16 t430s /bsd: b_transfer_complete: repeat=0 new head=0x0

This also gets me closer to my goal of reliable logging.

Do we want this feature?

bluhm

Index: kern/subr_log.c
===================================================================
RCS file: /data/mirror/openbsd/cvs/src/sys/kern/subr_log.c,v
retrieving revision 1.46
diff -u -p -r1.46 subr_log.c
--- kern/subr_log.c 8 Jun 2016 11:11:47 -0000 1.46
+++ kern/subr_log.c 22 Jun 2016 20:09:08 -0000
@@ -155,6 +155,7 @@ msgbuf_putchar(struct msgbuf *mbp, const
  if (mbp->msg_bufr == mbp->msg_bufx) {
  if (++mbp->msg_bufr >= mbp->msg_bufs)
  mbp->msg_bufr = 0;
+ mbp->msg_bufd++;
  }
  splx(s);
 }
@@ -200,6 +201,21 @@ logread(dev_t dev, struct uio *uio, int
  goto out;
  }
  logsoftc.sc_state &= ~LOG_RDWAIT;
+
+#ifndef SMALL_KERNEL
+ if (mbp->msg_bufd > 0) {
+ char buf[64];
+
+ l = snprintf(buf, sizeof(buf),
+    "<%d>klog: dropped %ld byte%s, message buffer full\n",
+    LOG_KERN|LOG_WARNING, mbp->msg_bufd,
+                    mbp->msg_bufd == 1 ? "" : "s");
+ error = uiomove(buf, ulmin(l, sizeof(buf) - 1), uio);
+ if (error)
+ goto out;
+ mbp->msg_bufd = 0;
+ }
+#endif
 
  while (uio->uio_resid > 0) {
  if (mbp->msg_bufx >= mbp->msg_bufr)
Index: sys/msgbuf.h
===================================================================
RCS file: /data/mirror/openbsd/cvs/src/sys/sys/msgbuf.h,v
retrieving revision 1.10
diff -u -p -r1.10 msgbuf.h
--- sys/msgbuf.h 13 Jan 2015 18:51:27 -0000 1.10
+++ sys/msgbuf.h 22 Jun 2016 19:45:10 -0000
@@ -39,6 +39,7 @@ struct msgbuf {
  long msg_bufr; /* read pointer */
  long msg_bufs; /* real msg_bufc size (bytes) */
  long msg_bufl; /* # chars, <= msg_bufs */
+ long msg_bufd; /* number of dropped bytes */
  char msg_bufc[1]; /* buffer */
 };
 #ifdef _KERNEL

Reply | Threaded
Open this post in threaded view
|

Re: klog message buffer full

Todd C. Miller
On Wed, 22 Jun 2016 22:14:19 +0200, Alexander Bluhm wrote:

> When doing usb debugging with a lot of kernel printfs, the dmesg
> buffer can overflow easily.  It is annoying that you don't notice
> this.  Then it is hard to correlate the messages.
>
> So to make clear what happens, I would like to write such a message
> to syslogd:
> Jun 22 21:58:16 t430s /bsd: usbd_start_next: pipe=0xffff8000003cf
> Jun 22 21:58:16 t430s /bsd: klog: dropped 75602 bytes, message buffer full
> Jun 22 21:58:16 t430s /bsd: b_transfer_complete: repeat=0 new head=0x0
>
> This also gets me closer to my goal of reliable logging.
>
> Do we want this feature?

I think so.  Ultimately it would be nice to queue up messages in
the kernel for later delivery but for now just logging that messages
were dropped is an improvement.

 - todd

Reply | Threaded
Open this post in threaded view
|

Re: klog message buffer full

Ted Unangst-6
In reply to this post by Alexander Bluhm
Alexander Bluhm wrote:
> This also gets me closer to my goal of reliable logging.
>
> Do we want this feature?

yes, and I'd say always.

> +#ifndef SMALL_KERNEL
> + if (mbp->msg_bufd > 0) {
> + char buf[64];

This is not so much code that I'm worried about it on small kernels. Rather,
now you have the same problem where some kernels print correct information and
some don't. I guess there's no syslog on ramdisk, so moot point? But I've been
aggravated before by unexpected small kernel differences.

Reply | Threaded
Open this post in threaded view
|

Re: klog message buffer full

Alexander Bluhm
On Wed, Jun 22, 2016 at 05:08:24PM -0400, Ted Unangst wrote:
> Alexander Bluhm wrote:
> > +#ifndef SMALL_KERNEL
> > + if (mbp->msg_bufd > 0) {
> > + char buf[64];
>
> This is not so much code that I'm worried about it on small kernels. Rather,
> now you have the same problem where some kernels print correct information and
> some don't. I guess there's no syslog on ramdisk, so moot point? But I've been
> aggravated before by unexpected small kernel differences.

I have the #ifndef SMALL_KERNEL also in sendsyslog counting and I
wanted to be consistent.  There is no syslogd on ramdisk, so the
feature is useless there.  Besides code we also save the size of
the format strings.

But if install kernel size is not that important, I can remove both
ifdefs.

bluhm

Reply | Threaded
Open this post in threaded view
|

Re: klog message buffer full

Theo de Raadt
> But if install kernel size is not that important, I can remove both
> ifdefs.

Kernel size does matter on the ramdisks.  But excessive sprinkling of
#ifdef gets out of control in some types of code.  Then it better to
forego it, and find a different target where it is less gross.   As
long as we have some anti-growth discipline, bsd.rd ends up being a
fairly full featured kernel, and we won't eventually hit a mistake of
"oh shit, the script needs this thing and we killed it on bsd.rd.."
(and btw, that tends to matter more for upgrades, than installs)