Date: Fri, 20 Jul 2007 22:44:51 +0100 From: Tom Judge <tom@tomjudge.com> To: freebsd-hackers <freebsd-hackers@freebsd.org> Subject: Re: Insufficient locking in log() / kvprintf() / somewhere? Message-ID: <46A12CD3.4000600@tomjudge.com> In-Reply-To: <20070720185009.GA79090@marvin.blogreen.org> References: <20070720185009.GA79090@marvin.blogreen.org>
next in thread | previous in thread | raw e-mail | index | archive | help
Romain Tartière wrote:
> Hello FreeBSD hackers!
>
> I recently got some apache problems (maybe just forgetting to restart it
> after an update, but it is not the interest of this e-mail) and each
> httpd process was segfaulting as soon as created. I got surprising
> things like that in my systems log:
>
> === begin snippet ===
>> pid 85055 (httpd), uid 80: exited on signal 11
>> pid 85063 (httpd), uid 80: exited on signal 11
>> pid 85064 (httpd), uid 80: exited on signal 11
>> pid 85066 (httpd), uid 80: exited on signal 11
>> pid 85065 (httpd), uid 80: exited on signal 11
>> <<66>>ppiidd 8580506678 ((hhtttptdp)d,), uuid id8 0: 8ex0: eixteidt eod no ns isginganla l 111
>> 1
>>
>> pid 85070 (httpd), uid 80: exited on signal 11
>> pid 85069 (httpd), uid 80: exited on signal 11
> === end snippet ===
>
> (uname: FreeBSD 6.2-STABLE #4: Thu Jun 7 00:56:26 CEST 2007 i386)
>
> Obviously, having two processes on a dual core machine crashing
> simultaneously produce weird stuff. I poked a bit around in
> /usr/src/sys/kern:
>
>> % grep -n 'exited on signal' *
>> kern_sig.c:2452: "pid %d (%s), uid %d: exited on signal %d%s\n",
>
> The code in void sigexit(td, sig) is as follow:
>> if (kern_logsigexit)
>> log(LOG_INFO,
>> "pid %d (%s), uid %d: exited on signal %d%s\n",
>> p->p_pid, p->p_comm,
>> td->td_ucred ? td->td_ucred->cr_uid : -1,
>> sig &~ WCOREFLAG,
>> sig & WCOREFLAG ? " (core dumped)" : "");
>
> The log() function is declared in /usr/src/sys/kern/subr_prf.c:229 as this:
>> void
>> log(int level, const char *fmt, ...)
>> {
>> va_list ap;
>> struct putchar_arg pca;
>>
>> pca.tty = NULL;
>> pca.pri = level;
>> pca.flags = log_open ? TOLOG : TOCONS;
>>
>> va_start(ap, fmt);
>> kvprintf(fmt, putchar, &pca, 10, ap);
>> va_end(ap);
>>
>> msgbuftrigger = 1;
>> }
> ... so basically is calls kvprintf witch actually writes the message
> AFAIK.
>
> The issue is maybe a weird case-corner, but maybe some kind of locking
> may have sense to avoid this?
>
> Kind regards,
> Romain
>
I have seen this problem a lot where certain apache server modules have
been miss configured causing apache children to call abort and dump core
as soon as they are spawned. (Makes for a lot of messages) I have also
seen it produced by network drivers with large quantities of debug
messages enabled.
Its kind of annoying to see messages interleaved like this.
Tom
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?46A12CD3.4000600>