glibc error reports go to the bit bucket in koji

[Tom Lane]

I've been poking away at the mysql crashes I mentioned a few days ago,
and have just realized something that explains why I've been at such a
loss to interpret the failure reports from koji.  It seems that what
has been getting triggered is glibc's malloc-error aborts, the ones that
look like

*** glibc detected *** /home/tgl/rpmwork/BUILD/mysql-5.1.37/client/.libs/lt-mysqlslap:
free(): invalid pointer: 0x0000000001dc6eb0 ***
======= Backtrace: =========
/lib64/libc.so.6[0x309a275a96]
/home/tgl/rpmwork/BUILD/mysql-5.1.37/libmysql_r/.libs/libmysqlclient_r.so.16(my_thread_end+0x62)[0x7fb1910b9612]
/home/tgl/rpmwork/BUILD/mysql-5.1.37/client/.libs/lt-mysqlslap(run_task+0x2df)[0x4033ef]
/lib64/libpthread.so.0[0x309ae0686a]
/lib64/libc.so.6(clone+0x6d)[0x309a2de39d]
======= Memory map: ========
00400000-00408000 r-xp 00000000 fd:01 1522370                           
/home/tgl/rpmwork/BUILD/mysql-5.1.37/client/.libs/lt-mysqlslap
00608000-0060a000 rw-p 00008000 fd:01 1522370                           
/home/tgl/rpmwork/BUILD/mysql-5.1.37/client/.libs/lt-mysqlslap
.. etc etc ..

**The build logs from koji do not contain this rather critical
information**.  I haven't dug into the glibc sources, but what it
looks like on my own machine is that these reports go to /dev/tty
not to stderr (and thus not into any log file).

I will not presume to question the sanity of the /dev/tty default,
but surely this is a *completely* undesirable behavior within the
koji environment.  Can't we fix things so that such reports show up
in the build.log?

			regards, tom lane

[Mike Bonnet]

On 08/18/2009 06:14 PM, Tom Lane wrote:
>  I've been poking away at the mysql crashes I mentioned a few days
> ago,
>  and have just realized something that explains why I've been at such a
>  loss to interpret the failure reports from koji.  It seems that what
>  has been getting triggered is glibc's malloc-error aborts, the ones that
>  look like
>
>  *** glibc detected *** /home/tgl/rpmwork/BUILD/mysql-5.1.37/client/.libs/lt-mysqlslap:
> free(): invalid pointer: 0x0000000001dc6eb0 ***
>  ======= Backtrace: =========
>  /lib64/libc.so.6[0x309a275a96]
>
> /home/tgl/rpmwork/BUILD/mysql-5.1.37/libmysql_r/.libs/libmysqlclient_r.so.16(my_thread_end+0x62)[0x7fb1910b9612]
>  /home/tgl/rpmwork/BUILD/mysql-5.1.37/client/.libs/lt-mysqlslap(run_task+0x2df)[0x4033ef]
>  /lib64/libpthread.so.0[0x309ae0686a]
>  /lib64/libc.so.6(clone+0x6d)[0x309a2de39d]
>  ======= Memory map: ========
>  00400000-00408000 r-xp 00000000 fd:01 1522370                           
> /home/tgl/rpmwork/BUILD/mysql-5.1.37/client/.libs/lt-mysqlslap
>  00608000-0060a000 rw-p 00008000 fd:01 1522370                           
> /home/tgl/rpmwork/BUILD/mysql-5.1.37/client/.libs/lt-mysqlslap
>  .. etc etc ..
>
>  **The build logs from koji do not contain this rather critical
>  information**.  I haven't dug into the glibc sources, but what it
>  looks like on my own machine is that these reports go to /dev/tty
>  not to stderr (and thus not into any log file).
>
>  I will not presume to question the sanity of the /dev/tty default,
>  but surely this is a *completely* undesirable behavior within the
>  koji environment.  Can't we fix things so that such reports show up
>  in the build.log? 
This is more of a mock issue, since mock is responsible for capturing 
the output of the build process and directing it to build.log, which 
koji simply stores.  Is this reproduceable in mock on a local machine?

How would mock go about capturing output sent directly to /dev/tty? 
Could we get away with hard/sym-linking it to /dev/stderr?  Does this 
have the potential to break other things?

[Roland McGrath]

>  How would mock go about capturing output sent directly to /dev/tty? 
forkpty from <pty.h> is handy.  In pythonland there is probably some other
simple canonical way to run a child in a pty.

>  Could we get away with hard/sym-linking it to /dev/stderr?  Does this
>
>  have the potential to break other things? 
Your kneecaps, fella, just try it.

[Tom Lane]

Mike Bonnet <mikeb(a)redhat.com&gt; writes:
>  On 08/18/2009 06:14 PM, Tom Lane wrote:
> > **The build logs from koji do not contain this rather critical
> > information**.  I haven't dug into the glibc sources, but what it
> > looks like on my own machine is that these reports go to /dev/tty
> > not to stderr (and thus not into any log file). 
>  This is more of a mock issue, since mock is responsible for capturing
>
>  the output of the build process and directing it to build.log, which 
>  koji simply stores.  Is this reproduceable in mock on a local machine? 
I think so, but the last few days are kind of a haze of irreproducible
crashes :-(.  And it was only just now that I realized that the logs
showing mysql terminating for no apparent reason looked exactly like
my stdout/stderr captures from terminal sessions that included glibc
reports.  I don't have any way to prove that those sessions actually
included some glibc output that I never saw ... it just seems pretty
likely.  Anyway, given other comments, it seems clear that (1) glibc
does send these things to /dev/tty by default, and (2) nothing in the
koji environment is doing anything to capture such output.

			regards, tom lane

[Roland McGrath]

IMHO koji (and mock for that matter) ought to be running the builds inside
a captive pty whose ouytput it logs anyway, even if they redirect
everything.  You never know what crazy nonsense some package is going to try.

You can put LIBC_FATAL_STDERR_=1 in the environment to get those messages
to stderr instead of /dev/tty.  setuid programs will still use /dev/tty.
Or, it would use stderr by default if there was no /dev/tty.

If you're not going to capture the tty output, then you really should
disassociate from the tty (setsid) so /dev/tty does not work at all.
I'd call the failure to do one or the other of these a bug in mock or koji.


Thanks,
Roland

[Jesse Keating]

On Tue, 2009-08-18 at 15:36 -0700, Roland McGrath wrote:
>  IMHO koji (and mock for that matter) ought to be running the builds
> inside
>  a captive pty whose ouytput it logs anyway, even if they redirect
>  everything.  You never know what crazy nonsense some package is going to try. 
How does one setup one of these things?

-- 
Jesse Keating
Fedora -- Freedom² is a feature!
identi.ca: http://identi.ca/jkeating

[Roland McGrath]

>  How does one setup one of these things? 
Since I assume you are implementing it in Python, you might have to ask,
you know, someone who knows Python.  I don't, but I have a web browser.
I even have "locate '*python*pty*'".  So maybe:

import pty

(pid, fd) = pty.fork()

or pty.spawn(...)

[Jakub Jelinek]

On Tue, Aug 18, 2009 at 06:14:20PM -0400, Tom Lane wrote:
>  I've been poking away at the mysql crashes I mentioned a few days
> ago,
>  and have just realized something that explains why I've been at such a
>  loss to interpret the failure reports from koji.  It seems that what
>  has been getting triggered is glibc's malloc-error aborts, the ones that
>  look like
>  
>  *** glibc detected *** /home/tgl/rpmwork/BUILD/mysql-5.1.37/client/.libs/lt-mysqlslap:
> free(): invalid pointer: 0x0000000001dc6eb0 ***
>  ======= Backtrace: =========
>  /lib64/libc.so.6[0x309a275a96]
>
> /home/tgl/rpmwork/BUILD/mysql-5.1.37/libmysql_r/.libs/libmysqlclient_r.so.16(my_thread_end+0x62)[0x7fb1910b9612]
>  /home/tgl/rpmwork/BUILD/mysql-5.1.37/client/.libs/lt-mysqlslap(run_task+0x2df)[0x4033ef]
>  /lib64/libpthread.so.0[0x309ae0686a]
>  /lib64/libc.so.6(clone+0x6d)[0x309a2de39d]
>  ======= Memory map: ========
>  00400000-00408000 r-xp 00000000 fd:01 1522370                           
> /home/tgl/rpmwork/BUILD/mysql-5.1.37/client/.libs/lt-mysqlslap
>  00608000-0060a000 rw-p 00008000 fd:01 1522370                           
> /home/tgl/rpmwork/BUILD/mysql-5.1.37/client/.libs/lt-mysqlslap
>  .. etc etc ..
>  
>  **The build logs from koji do not contain this rather critical
>  information**.  I haven't dug into the glibc sources, but what it
>  looks like on my own machine is that these reports go to /dev/tty
>  not to stderr (and thus not into any log file). 
One of koji/mock/rpm could export
LIBC_FATAL_STDERR_=1
in the environment to force this to go to stdout for non-setuid/setgid
processes.

	Jakub