From: Denis Vlasenko <vda@ilport.com.ua>
To: rt-comment@krbdev.mit.edu
Subject: Re: [krbdev.mit.edu #3277] doubled kerberos logging to stderr
Date: Wed, 7 Dec 2005 09:36:34 +0200
User-Agent: KMail/1.8.2
References: <rt-3277-15211.11.028899280163@krbdev.mit.edu>
In-Reply-To: <rt-3277-15211.11.028899280163@krbdev.mit.edu>
MIME-Version: 1.0
Content-Type: text/plain; charset="koi8-r"
Content-Disposition: inline
Message-Id: <200512070936.34921.vda@ilport.com.ua>
Content-Transfer-Encoding: 8bit
RT-Send-Cc: 
Content-Length: 6031

On Wednesday 07 December 2005 02:01, Tom Yu via RT wrote:
> >>>>> "Denis" == Denis Vlasenko via RT <rt-comment@krbdev.mit.edu> writes:
> 
> Denis> Looks like krb5-1.4.3/src/lib/kadm5/logger.c:klog_vsyslog(...) routine, which
> Denis> formats these messages, outputs them twice.
> 
> Denis> Next, when I run exactly the same command, "krb5kdc -n", under daemontools,
> Denis> it gets unhappy:
> 
> Denis> 2005-12-04 22:05:34 krb5kdc: cannot parse <STDERR>
> Denis> 2005-12-04 22:05:34 krb5kdc: warning - logging entry syntax error
> Denis> 2005-12-04 22:05:34 krb5kdc: cannot parse <STDERR>
> Denis> 2005-12-04 22:05:34 krb5kdc: warning - logging entry syntax error
> 
> Denis> Replacing "default = STDERR" with "default = FILE:/proc/self/fd/2"
> Denis> helps.
> 
> Denis> Fragment of strace output where it happens:
> 
> [...]
> 
> Denis> fcntl64(2, F_GETFL) ═ ═ ═ ═ ═ ═ ═ ═ ═ ═ = 0x1 (flags O_WRONLY)
> Denis> write(2, "krb5kdc: cannot parse <STDERR>\n", 31) = 31
> Denis> write(2, "krb5kdc: warning - logging entry"..., 46) = 46
> Denis> fcntl64(2, F_GETFL) ═ ═ ═ ═ ═ ═ ═ ═ ═ ═ = 0x1 (flags O_WRONLY)
> Denis> write(2, "krb5kdc: cannot parse <STDERR>\n", 31) = 31
> Denis> write(2, "krb5kdc: warning - logging entry"..., 46) = 46
> 
> Denis> Looks like something fails here:
> 
> Denis> krb5-1.4.3/src/lib/kadm5/logger.c
> Denis> ...
> Denis> ═ ═ ═ ═ ═ ═ ═ ═ else if (!strcasecmp(cp, "STDERR")) {
> Denis> ═ ═ ═ ═ ═ ═ ═ ═ ═ ═ log_control.log_entries[i].lfu_filep =
> Denis> ═ ═ ═ ═ ═ ═ ═ ═ ═ ═ ═ ═ fdopen(fileno(stderr), "a+");
> Denis> ═ ═ ═ ═ ═ ═ ═ ═ ═ ═ if (log_control.log_entries[i].lfu_filep) {
> Denis> is not set somehow ===> log_control.log_entries[i].log_type = K_LOG_STDERR;
> Denis> ═ ═ ═ ═ ═ ═ ═ ═ ═ ═ ═ ═ log_control.log_entries[i].lfu_fname =
> Denis> ═ ═ ═ ═ ═ ═ ═ ═ ═ ═ ═ ═ ═ ═ "standard error";
> Denis> ═ ═ ═ ═ ═ ═ ═ ═ ═ ═ }

Sorry about those "= = ="s, it's my KMail misbehaving...

> While the error message is somewhat unhelpful, I suspect that the
> actual error is that fdopen(fileno(stderr)) is failing for some
> reason.  Fredrik Tolf, in a message to the kerberos mailing list,
> appears to have discovered the actual reason for the doubled logs,
> which is a configuration file being read twice under some

It doesn't seem to be the case:

# grep open krb5kdc-n.strace
open("/etc/ld.so.preload", O_RDONLY)    = -1 ENOENT (No such file or directory)
open("/usr/app/krb5-1.4.3/lib/i686/mmx/libkadm5srv.so.5", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/app/krb5-1.4.3/lib/i686/libkadm5srv.so.5", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/app/krb5-1.4.3/lib/mmx/libkadm5srv.so.5", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/app/krb5-1.4.3/lib/libkadm5srv.so.5", O_RDONLY) = 3
open("/usr/app/krb5-1.4.3/lib/libkdb5.so.4", O_RDONLY) = 3
open("/usr/app/krb5-1.4.3/lib/libgssrpc.so.4", O_RDONLY) = 3
open("/usr/app/krb5-1.4.3/lib/libgssapi_krb5.so.2", O_RDONLY) = 3
open("/usr/app/krb5-1.4.3/lib/libkrb4.so.2", O_RDONLY) = 3
open("/usr/app/krb5-1.4.3/lib/libdes425.so.3", O_RDONLY) = 3
open("/usr/app/krb5-1.4.3/lib/libkrb5.so.3", O_RDONLY) = 3
open("/usr/app/krb5-1.4.3/lib/libk5crypto.so.3", O_RDONLY) = 3
open("/usr/app/krb5-1.4.3/lib/libcom_err.so.3", O_RDONLY) = 3
open("/usr/app/krb5-1.4.3/lib/libkrb5support.so.0", O_RDONLY) = 3
open("/usr/app/krb5-1.4.3/lib/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY)      = 3
open("/lib/libc.so.6", O_RDONLY)        = 3
open("/etc/krb5.conf", O_RDONLY)        = 3
open("/dev/urandom", O_RDONLY)          = 3
open("/proc/self/fd/2", O_RDWR|O_APPEND|O_CREAT, 0666) = 3
open("/proc/self/fd/2", O_RDWR|O_APPEND|O_CREAT, 0666) = 4
open("/usr/app/krb5-1.4.3/var/krb5kdc/kdc.conf", O_RDONLY) = 5
open("/dev/urandom", O_RDONLY)          = 5
open("/usr/app/krb5-1.4.3/var/krb5kdc/kdc.conf", O_RDONLY) = 5
open("/var/service/kdc/.k5.LOCAL.NET", O_RDONLY) = 5
open("/var/service/kdc/principal", O_RDONLY) = 5
open("/var/service/kdc/principal.ok", O_RDWR) = 5
open("/var/service/kdc/principal", O_RDONLY) = 6
open("/var/tmp/krb5kdc_rcache", O_RDWR) = 6
open("/var/tmp/krb5kdc_rcache", O_RDWR) = 6
open("/var/tmp/krb5_RC1038aaa", O_WRONLY|O_CREAT|O_TRUNC|O_EXCL, 0600) = 7
open("/etc/localtime", O_RDONLY)        = 7

IOW, /etc/krb5.conf is read once, yet "default = FILE:/proc/self/fd/2"
directive seems to be processed twice.

> configurations.  What flags did you pass to configure when you built
> the source?

My configure invocation is:

SRC=..
STATIC=/usr/app/krb5-1.4.3
CFLAGS="-Os -falign-functions=1 -falign-labels=1 -falign-loops=1 -falign-jumps=1 -mtune=i386 -march=i386"
$SRC/configure \
--prefix=$STATIC                        \
--exec-prefix=$STATIC                   \
--bindir=$STATIC/bin                    \
--sbindir=$STATIC/sbin                  \
--libexecdir=$STATIC/libexec            \
--datadir=$STATIC/share                 \
--sysconfdir=/etc                       \
--sharedstatedir=$STATIC/var/com        \
--localstatedir=$STATIC/var             \
--libdir=$STATIC/lib                    \
--includedir=$STATIC/include            \
--infodir=$STATIC/info                  \
--mandir=$STATIC/man                    \
\
--oldincludedir=/usr/include            \
\
--build=i386-pc-linux-gnu               \
--disable-rpath                         \
--disable-nls

--
vda