Received: from ilport.com.ua (167.imtp.Ilyichevsk.Odessa.UA [195.66.192.167] (may be forged)) by krbdev.mit.edu (8.9.3p2) with SMTP id DAA22525; Wed, 7 Dec 2005 03:44:26 -0500 (EST)
Received: (qmail 14870 invoked by alias); 7 Dec 2005 08:43:55 -0000
Received: by simscan 1.1.0 ppid: 14863, pid: 14865, t: 6.7933s scanners:none
Received: from unknown (172.17.2.38) by 0 (172.16.22.5) with ESMTP; 07 Dec 2005 08:43:48 -0000
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 10:43:40 +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-Transfer-Encoding: 7bit
Content-Disposition: inline
Message-Id: <200512071043.40934.vda@ilport.com.ua>
X-Spam-Checker-Version: SpamAssassin 3.0.2 (2004-11-16) on logic
X-Spam-Level: 
X-Spam-Status: No, score=-4.5 required=4.0 tests=ALL_TRUSTED,BAYES_00  autolearn=ham version=3.0.2
RT-Send-Cc: 
X-RT-Original-Encoding: koi8-r
Content-Length: 2668

On Wednesday 07 December 2005 02:01, Tom Yu via RT wrote:
> 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.
>
...
> 
> 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
> configurations.  What flags did you pass to configure when you built
> the source?

I instrumented code with a few a bit:

lib/kadm5/logger.c

    /*
     * Look up [logging]-><ename> in the profile.  If that doesn't
     * succeed, then look for [logging]->default.
     */
write(2, ename, strlen(ename));
write(2, "\n", strlen("\n"));
write(2, whoami, strlen(whoami));
write(2, "\n", strlen("\n"));
    logging_profent[0] = "logging";
    logging_profent[1] = ename;
    logging_profent[2] = (char *) NULL;
    logging_defent[0] = "logging";
    logging_defent[1] = "default";
    logging_defent[2] = (char *) NULL;
    logging_specs = (char **) NULL;
    ngood = 0;
    log_control.log_nentries = 0;
    if (/*!profile_get_values(kcontext->profile,
                            logging_profent,
                            &logging_specs) ||*/
        !profile_get_values(kcontext->profile,
                            logging_defent,
                            &logging_specs)) {
        /*
         * We have a match, so we first count the number of elements
         */
        for (log_control.log_nentries = 0;
             logging_specs[log_control.log_nentries];
             log_control.log_nentries++)
{
if(logging_specs[log_control.log_nentries]) write(2, logging_specs[log_control.log_nentries], strlen(logging_specs[log_control.log_nentries]));
write(2, "\n", strlen("\n"));
}
;

This is what my write's print:

kdc
krb5kdc
FILE:/proc/self/fd/2
FILE:/proc/self/fd/2

Obviously profile_get_values(kcontext->profile,
                            logging_defent,
                            &logging_specs) produces duplicates.
--
vda