From: Denis Vlasenko <vda@ilport.com.ua>
To: krb5-bugs@mit.edu
Date: Tue, 6 Dec 2005 17:18:40 +0200
User-Agent: KMail/1.8.2
MIME-Version: 1.0
Content-Type: text/plain; charset="iso-8859-1"
Content-Disposition: inline
Message-Id: <200512061718.40652.vda@ilport.com.ua>
Content-Transfer-Encoding: 8bit
Subject: doubled kerberos logging to stderr
Precedence: list
Sender: krb5-bugs-incoming-bounces@PCH.mit.edu
Errors-To: krb5-bugs-incoming-bounces@PCH.mit.edu
Content-Length: 6464

My krb5.conf:

[logging]
    default = STDERR

...

When I start "krb5kdc -n"  from the shell, I am getting:

2005-12-06 16:04:06 Dec 06 16:04:06 firebird krb5kdc[21670](info): setting up network...
2005-12-06 16:04:06 Dec 06 16:04:06 firebird krb5kdc[21670](info): setting up network...
2005-12-06 16:04:06 Dec 06 16:04:06 firebird krb5kdc[21670](info): listening on fd 7: udp 172.17.2.38.750
2005-12-06 16:04:06 Dec 06 16:04:06 firebird krb5kdc[21670](info): listening on fd 7: udp 172.17.2.38.750
2005-12-06 16:04:06 Dec 06 16:04:06 firebird krb5kdc[21670](info): listening on fd 8: udp 172.17.2.38.88
2005-12-06 16:04:06 Dec 06 16:04:06 firebird krb5kdc[21670](info): listening on fd 8: udp 172.17.2.38.88
2005-12-06 16:04:06 Dec 06 16:04:06 firebird krb5kdc[21670](info): set up 2 sockets
2005-12-06 16:04:06 Dec 06 16:04:06 firebird krb5kdc[21670](info): set up 2 sockets
2005-12-06 16:04:06 Dec 06 16:04:06 firebird krb5kdc[21670](info): commencing operation
2005-12-06 16:04:06 Dec 06 16:04:06 firebird krb5kdc[21670](info): commencing operation

Looks like krb5-1.4.3/src/lib/kadm5/logger.c:klog_vsyslog(...) routine, which
formats these messages, outputs them twice.

Next, when I run exactly the same command, "krb5kdc -n", under daemontools,
it gets unhappy:

2005-12-04 22:05:34 krb5kdc: cannot parse <STDERR>
2005-12-04 22:05:34 krb5kdc: warning - logging entry syntax error
2005-12-04 22:05:34 krb5kdc: cannot parse <STDERR>
2005-12-04 22:05:34 krb5kdc: warning - logging entry syntax error

Replacing "default = STDERR" with "default = FILE:/proc/self/fd/2"
helps.

Fragment of strace output where it happens:

access("/etc/krb5.conf", R_OK)          = 0
time(NULL)                              = 1133726936
open("/dev/urandom", O_RDONLY)          = 3
fstat64(3, {st_mode=S_IFCHR|0444, st_rdev=makedev(1, 9), ...}) = 0
read(3, "%\331\304\317@:\372\\\257\317\203\222u\22\341\3\237\4\340"..., 20) = 20
close(3)                                = 0
getpid()                                = 2855
gettimeofday({1133726936, 181336}, NULL) = 0
getpid()                                = 2855
time(NULL)                              = 1133726936
time(NULL)                              = 1133726936
time(NULL)                              = 1133726936
time(NULL)                              = 1133726936
time(NULL)                              = 1133726936
time(NULL)                              = 1133726936
time(NULL)                              = 1133726936
time(NULL)                              = 1133726936
time(NULL)                              = 1133726936
time(NULL)                              = 1133726936
time(NULL)                              = 1133726936
time(NULL)                              = 1133726936
time(NULL)                              = 1133726936
time(NULL)                              = 1133726936
time(NULL)                              = 1133726936
time(NULL)                              = 1133726936
time(NULL)                              = 1133726936
time(NULL)                              = 1133726936
fcntl64(2, F_GETFL)                     = 0x1 (flags O_WRONLY)
write(2, "krb5kdc: cannot parse <STDERR>\n", 31) = 31
write(2, "krb5kdc: warning - logging entry"..., 46) = 46
fcntl64(2, F_GETFL)                     = 0x1 (flags O_WRONLY)
write(2, "krb5kdc: cannot parse <STDERR>\n", 31) = 31
write(2, "krb5kdc: warning - logging entry"..., 46) = 46

Looks like something fails here:

krb5-1.4.3/src/lib/kadm5/logger.c
...
                else if (!strcasecmp(cp, "STDERR")) {
                    log_control.log_entries[i].lfu_filep =
                        fdopen(fileno(stderr), "a+");
                    if (log_control.log_entries[i].lfu_filep) {
is not set somehow ===> log_control.log_entries[i].log_type = K_LOG_STDERR;
                        log_control.log_entries[i].lfu_fname =
                            "standard error";
                    }
                }
                /*
                 * Is this a specification of the console?
                 */
                else if (!strcasecmp(cp, "CONSOLE")) {...}
                /*
                 * Is this a specification of a device?
                 */
                else if (!strncasecmp(cp, "DEVICE", 6)) {...}

                /*
                 * See if we successfully parsed this specification.
                 */
                if (log_control.log_entries[i].log_type == K_LOG_NONE) {
prints "cannot parse <STDERR>" ==>
                    fprintf(stderr, lspec_parse_err_1, whoami, cp);
                    fprintf(stderr, lspec_parse_err_2, whoami);
                }
                else
                    ngood++;

--
vda