Skip Menu |
 

History Show all quoted text — Show full headers
# Tue Dec 06 18:08:47 2005 Denis Vlasenko <vda@ilport.com.ua> - Ticket created
From: Denis Vlasenko <vda@ilport.com.ua>
To: krb5-bugs@mit.edu
Date: Tue, 6 Dec 2005 17:18:40 +0200
Subject: doubled kerberos logging to stderr
Download (untitled) / with headers
text/plain 6.3KiB
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
# Tue Dec 06 19:01:15 2005 tlyu (Taylor Yu) - Correspondence added
To: rt@krbdev.mit.edu
Subject: Re: [krbdev.mit.edu #3277] doubled kerberos logging to stderr
From: Tom Yu <tlyu@MIT.EDU>
Date: Tue, 06 Dec 2005 19:01:05 -0500
RT-Send-Cc:
Download (untitled) / with headers
text/plain 2.3KiB
Show quoted text
>>>>> "Denis" == Denis Vlasenko via RT <rt-comment@krbdev.mit.edu> writes:

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

Show quoted text
Denis> Next, when I run exactly the same command, "krb5kdc -n", under daemontools,
Denis> it gets unhappy:

Show quoted text
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

Show quoted text
Denis> Replacing "default = STDERR" with "default = FILE:/proc/self/fd/2"
Denis> helps.

Show quoted text
Denis> Fragment of strace output where it happens:

[...]

Show quoted text
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

Show quoted text
Denis> Looks like something fails here:

Show quoted text
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>                     }

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?

---Tom
# Wed Dec 07 02:37:58 2005 Denis Vlasenko <vda@ilport.com.ua> - Comments added
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
RT-Send-Cc:
Download (untitled) / with headers
text/plain 5.8KiB
On Wednesday 07 December 2005 02:01, Tom Yu via RT wrote:
Show quoted text
> >>>>> "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...

Show quoted text
> 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.

Show quoted text
> 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
# Wed Dec 07 03:44:46 2005 Denis Vlasenko <vda@ilport.com.ua> - Comments added
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
RT-Send-Cc:
Download (untitled) / with headers
text/plain 2.6KiB
On Wednesday 07 December 2005 02:01, Tom Yu via RT wrote:
Show quoted text
> 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.
>
...
Show quoted text
>
> 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
# Wed Dec 07 05:12:58 2005 raeburn (Ken Raeburn) - Correspondence added
From: Ken Raeburn <raeburn@MIT.EDU>
Subject: Re: [krbdev.mit.edu #3277] doubled kerberos logging to stderr
Date: Wed, 7 Dec 2005 05:12:47 -0500
To: rt@krbdev.mit.edu
RT-Send-Cc:
Download (untitled) / with headers
text/plain 878B
On Dec 7, 2005, at 02:38, Denis Vlasenko via RT wrote:
Show quoted text
> On Wednesday 07 December 2005 02:01, Tom Yu via RT wrote:
>> 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:

Actually, I think some of the code we've put into the profile library
would prevent the file from being read twice if the stat data
indicated it hadn't changed, even if the profile file names
($KRB5_CONFIG or compiled-in) listed the same file twice. The file
would be read once, but its data would be used twice.

I'd be interested in seeing what profile_init is called with.

Ken
# Thu Dec 08 12:39:16 2005 tlyu (Taylor Yu) - Correspondence added
To: rt@krbdev.mit.edu
Subject: Re: [krbdev.mit.edu #3277] doubled kerberos logging to stderr
From: Tom Yu <tlyu@MIT.EDU>
Date: Thu, 08 Dec 2005 12:39:05 -0500
RT-Send-Cc:
Download (untitled) / with headers
text/plain 311B
Show quoted text
>>>>> "Denis" == Denis Vlasenko via RT <rt-comment@krbdev.mit.edu> writes:

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

If you set the KRB5_CONFIG environment variable to "/etc/krb5.conf",
do you still get the duplicates?

---Tom
# Fri Dec 09 03:09:07 2005 Denis Vlasenko <vda@ilport.com.ua> - Comments added
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: Fri, 9 Dec 2005 10:08:29 +0200
RT-Send-Cc:
Download (untitled) / with headers
text/plain 1.8KiB
On Thursday 08 December 2005 19:39, Tom Yu via RT wrote:
Show quoted text
> >>>>> "Denis" == Denis Vlasenko via RT <rt-comment@krbdev.mit.edu> writes:
>
> Denis> IOW, /etc/krb5.conf is read once, yet "default = FILE:/proc/self/fd/2"
> Denis> directive seems to be processed twice.
>
> If you set the KRB5_CONFIG environment variable to "/etc/krb5.conf",
> do you still get the duplicates?

No, I do not. This is instrumented version of kdc running:

2005-12-09 10:02:54.655785500 kdc
2005-12-09 10:02:54.656054500 krb5kdc
2005-12-09 10:02:54.656147500 FILE:/proc/self/fd/2 <=== parses config
2005-12-09 10:02:54.656335500 FILE
2005-12-09 10:02:55.046682500 ! <=== about to emit message
2005-12-09 10:02:55.046787500 * <=== one and only log destination
2005-12-09 10:02:55.046991500 Dec 09 10:02:55 logic krb5kdc[4905](info): setting up network...
2005-12-09 10:02:55.047331500 !
2005-12-09 10:02:55.047390500 *
2005-12-09 10:02:55.047447500 Dec 09 10:02:55 logic krb5kdc[4905](info): listening on fd 6: udp 172.16.22.2.750
2005-12-09 10:02:55.047551500 !
2005-12-09 10:02:55.047632500 *
2005-12-09 10:02:55.047688500 Dec 09 10:02:55 logic krb5kdc[4905](info): listening on fd 7: udp 172.16.22.2.88
...

Without KRB5_CONFIG:

2005-12-08 14:46:04.467856500 kdc
2005-12-08 14:46:04.468130500 krb5kdc
2005-12-08 14:46:04.468231500 FILE:/proc/self/fd/2 <=== parses config, gets FILE:... twice
2005-12-08 14:46:04.468306500 FILE:/proc/self/fd/2
2005-12-08 14:46:04.468521500 FILE
2005-12-08 14:46:04.468613500 FILE
2005-12-08 14:46:04.814418500 ! <=== about to emit message
2005-12-08 14:46:04.814508500 * <=== log to first FILE:
2005-12-08 14:46:04.814616500 Dec 08 14:46:04 logic krb5kdc[31794](info): setting up network...
2005-12-08 14:46:04.814678500 * <=== log to second FILE:
2005-12-08 14:46:04.814758500 Dec 08 14:46:04 logic krb5kdc[31794](info): setting up network...
...

--
vda
# Fri Dec 16 21:20:14 2005 raeburn (Ken Raeburn) - Comments added
Cc: rt-comment@krbdev.mit.edu
From: Ken Raeburn <raeburn@MIT.EDU>
Subject: Re: [krbdev.mit.edu #3277] doubled kerberos logging to stderr
Date: Fri, 16 Dec 2005 21:19:58 -0500
To: vda@ilport.com.ua
RT-Send-Cc:
Download (untitled) / with headers
text/plain 485B
Could you try setting a breakpoint (or instrumenting the code) to see
what profile_init is getting called with? (The first argument is
char **, points to a null-terminated list of string pointers.)

It should be a list of filenames; my hunch is somehow you've got the
same file being used twice, or the same data in two files. (They're
merged, it's not using just the first one found.) If you could show
us the names and the files, that may help solve the problem...

Ken
# Sun Dec 18 07:35:31 2005 Denis Vlasenko <vda@ilport.com.ua> - Comments added
From: Denis Vlasenko <vda@ilport.com.ua>
To: Ken Raeburn <raeburn@mit.edu>
Subject: Re: [krbdev.mit.edu #3277] doubled kerberos logging to stderr
Date: Sun, 18 Dec 2005 14:35:07 +0200
Cc: rt-comment@krbdev.mit.edu
RT-Send-Cc:
Download (untitled) / with headers
text/plain 2.8KiB
On Saturday 17 December 2005 04:19, Ken Raeburn wrote:
Show quoted text
> Could you try setting a breakpoint (or instrumenting the code) to see
> what profile_init is getting called with? (The first argument is
> char **, points to a null-terminated list of string pointers.)
>
> It should be a list of filenames; my hunch is somehow you've got the
> same file being used twice, or the same data in two files. (They're
> merged, it's not using just the first one found.) If you could show
> us the names and the files, that may help solve the problem...

I instrumented code as shown in attached patch.

log of "env - krb5kdc -n" running (failing to start, in fact, because
of misconfiguration). Timestamps are added by logging daemon:

2005-12-18 14:26:49.560868500 conf_files
2005-12-18 14:26:49.561030500 conf_file:/etc/krb5.conf
2005-12-18 14:26:49.561846500 conf_file:/etc/krb5.conf
2005-12-18 14:26:49.562310500 kdc
2005-12-18 14:26:49.562357500 krb5kdc
2005-12-18 14:26:49.562407500 FILE:/proc/self/fd/2
2005-12-18 14:26:49.562564500 FILE:/proc/self/fd/2
2005-12-18 14:26:49.562744500 FILE
2005-12-18 14:26:49.562795500 FILE
2005-12-18 14:26:49.562928500 conf_files
2005-12-18 14:26:49.562954500 conf_file:/usr/app/krb5-1.4.3/var/krb5kdc/kdc.conf - can't read it
2005-12-18 14:26:49.563218500 conf_files
2005-12-18 14:26:49.563244500 conf_file:/etc/krb5.conf
2005-12-18 14:26:49.563313500 conf_file:/etc/krb5.conf
2005-12-18 14:26:49.563485500 conf_files
2005-12-18 14:26:49.563509500 conf_file:/usr/app/krb5-1.4.3/var/krb5kdc/kdc.conf - can't read it
2005-12-18 14:26:49.564024500 krb5kdc: Cannot find/read stored master key - while fetching master key K/M for realm ILPORT.INTERNAL
2005-12-18 14:26:49.564092500 krb5kdc: Cannot find/read stored master key - while fetching master key K/M for realm ILPORT.INTERNAL
2005-12-18 14:26:49.564164500 krb5kdc: cannot initialize realm ILPORT.INTERNAL - see log file for details

IOW: it does list /etc/krb5.conf twice.

same log but with "env - KRB5_CONFIG=/etc/krb5.conf krb5kdc -n" run:

2005-12-18 14:27:43.615314500 conf_files
2005-12-18 14:27:43.615319500 conf_file:/etc/krb5.conf
2005-12-18 14:27:43.615321500 kdc
2005-12-18 14:27:43.615322500 krb5kdc
2005-12-18 14:27:43.615324500 FILE:/proc/self/fd/2
2005-12-18 14:27:43.615325500 FILE
2005-12-18 14:27:43.615326500 conf_files
2005-12-18 14:27:43.615327500 conf_file:/usr/app/krb5-1.4.3/var/krb5kdc/kdc.conf - can't read it
2005-12-18 14:27:43.615330500 conf_files
2005-12-18 14:27:43.615331500 conf_file:/etc/krb5.conf
2005-12-18 14:27:43.615333500 conf_files
2005-12-18 14:27:43.615334500 conf_file:/usr/app/krb5-1.4.3/var/krb5kdc/kdc.conf - can't read it
2005-12-18 14:27:43.615467500 krb5kdc: Cannot find/read stored master key - while fetching master key K/M for realm ILPORT.INTERNAL
2005-12-18 14:27:43.615470500 krb5kdc: cannot initialize realm ILPORT.INTERNAL - see log file for details
--
vda
Download double_log_bug.diff
text/x-diff 6.6KiB

Message body is not shown because sender requested not to inline it.

# Sun Dec 18 18:24:48 2005 raeburn (Ken Raeburn) - Correspondence added
Cc: rt@krbdev.mit.edu
From: Ken Raeburn <raeburn@MIT.EDU>
Subject: Re: [krbdev.mit.edu #3277] doubled kerberos logging to stderr
Date: Sun, 18 Dec 2005 18:24:34 -0500
To: Denis Vlasenko <vda@ilport.com.ua>
RT-Send-Cc:
Download (untitled) / with headers
text/plain 1.5KiB
On Dec 18, 2005, at 07:35, Denis Vlasenko via RT wrote:
Show quoted text
> 2005-12-18 14:26:49.560868500 conf_files
> 2005-12-18 14:26:49.561030500 conf_file:/etc/krb5.conf
> 2005-12-18 14:26:49.561846500 conf_file:/etc/krb5.conf
> 2005-12-18 14:26:49.562310500 kdc

Okay, that looks like the default profile path has /etc/krb5.conf
listed twice. Could you check in the generated include/krb5/osconf.h
and see what DEFAULT_PROFILE_PATH (and DEFAULT_SECURE_PROFILE_PATH)
is defined as? Normally it should be /etc/krb5.conf and $sysconfdir/
krb5.conf, where $sysconfdir is normally $prefix/etc, so unless
prefix is empty or you set sysconfdir, something funny is going on.
Perhaps the sed substitution done in include/krb5/Makefile didn't
work right, and generated a broken osconf.h?

(It looks like we *will* do the wrong thing if --sysconfdir=/ is
given at configure time. We should perhaps have the profile code
check whether the same file is included twice even via different
paths, and not duplicate the data -- though having the hard-link
behavior be different from copy-of-file behavior would be a little
odd. And all of that aside, I think it would make sense for the
logging code to ignore duplicates, but since duplicates could
probably confuse other bits of our code too, that's not a complete fix.)

Show quoted text
> 2005-12-18 14:27:43.615334500 conf_file:/usr/app/krb5-1.4.3/var/
> krb5kdc/kdc.conf - can't read it

This uses DEFAULT_KDC_PROFILE, also defined in osconf.h, but that
uses $localstatedir, normally $prefix/var. So it looks like that
part of the sed substitution worked...

Ken
# Mon Dec 19 09:57:34 2005 Denis Vlasenko <vda@ilport.com.ua> - Correspondence added
From: Denis Vlasenko <vda@ilport.com.ua>
To: Ken Raeburn <raeburn@mit.edu>
Subject: Re: [krbdev.mit.edu #3277] doubled kerberos logging to stderr
Date: Mon, 19 Dec 2005 16:56:52 +0200
Cc: rt@krbdev.mit.edu
RT-Send-Cc:
Download (untitled) / with headers
text/plain 1.8KiB
On Monday 19 December 2005 01:24, Ken Raeburn wrote:
Show quoted text
> On Dec 18, 2005, at 07:35, Denis Vlasenko via RT wrote:
> > 2005-12-18 14:26:49.560868500 conf_files
> > 2005-12-18 14:26:49.561030500 conf_file:/etc/krb5.conf
> > 2005-12-18 14:26:49.561846500 conf_file:/etc/krb5.conf
> > 2005-12-18 14:26:49.562310500 kdc
>
> Okay, that looks like the default profile path has /etc/krb5.conf
> listed twice. Could you check in the generated include/krb5/osconf.h
> and see what DEFAULT_PROFILE_PATH (and DEFAULT_SECURE_PROFILE_PATH)
> is defined as? Normally it should be /etc/krb5.conf and $sysconfdir/
> krb5.conf, where $sysconfdir is normally $prefix/etc, so unless
> prefix is empty or you set sysconfdir, something funny is going on.

Bingo.

#define DEFAULT_SECURE_PROFILE_PATH "/etc/krb5.conf:/etc/krb5.conf"

I did set configure --sysconfdir=/etc.

Show quoted text
> Perhaps the sed substitution done in include/krb5/Makefile didn't
> work right, and generated a broken osconf.h?
>
> (It looks like we *will* do the wrong thing if --sysconfdir=/ is
> given at configure time. We should perhaps have the profile code
> check whether the same file is included twice even via different
> paths, and not duplicate the data -- though having the hard-link
> behavior be different from copy-of-file behavior would be a little
> odd. And all of that aside, I think it would make sense for the
> logging code to ignore duplicates, but since duplicates could
> probably confuse other bits of our code too, that's not a complete fix.)
>
> > 2005-12-18 14:27:43.615334500 conf_file:/usr/app/krb5-1.4.3/var/
> > krb5kdc/kdc.conf - can't read it
>
> This uses DEFAULT_KDC_PROFILE, also defined in osconf.h, but that
> uses $localstatedir, normally $prefix/var. So it looks like that
> part of the sed substitution worked...
--
vda
# Fri Dec 01 12:36:44 2006 tlyu (Taylor Yu) - Subject changed from 'doubled kerberos logging to stderr' to 'configure --sysconfdir=/etc can make redundant entries in profile search paths'
# Fri Dec 01 12:36:45 2006 tlyu (Taylor Yu) - Status changed from 'new' to 'open'
# Fri Dec 01 12:36:45 2006 tlyu (Taylor Yu) - Given to tlyu (Taylor Yu)
# Fri Dec 01 12:36:46 2006 tlyu (Taylor Yu) - Component krb5-build added
# Fri Dec 01 12:36:46 2006 tlyu (Taylor Yu) - Version_reported 1.4.3 added
# Fri Dec 01 12:36:47 2006 tlyu (Taylor Yu) - Comments added
Download (untitled) / with headers
text/plain 42B
Update to identify the underlying problem.
# Mon Feb 25 15:52:30 2008 guest (Public Submitter) - Comments added
RT-Send-CC: nalin@redhat.com
Download (untitled) / with headers
text/plain 207B
Adding these two substitutions removes the duplicates for me in the
--sysconfdir=/etc case:
's+:/etc/krb5.conf:/etc/krb5.conf"+:/etc/krb5.conf"+'
's+"/etc/krb5.conf:/etc/krb5.conf"+"/etc/krb5.conf"+'
# Fri Oct 24 15:36:17 2008 tlyu (Taylor Yu) - FinalPriority changed from (no value) to '25'
# Fri Oct 24 15:36:17 2008 tlyu (Taylor Yu) - Priority changed from (no value) to '25'
# Wed Feb 26 13:50:37 2014 tlyu (Taylor Yu) - Target_Version 1.12.2 added
# Wed Feb 26 13:50:37 2014 tlyu (Taylor Yu) - Status changed from 'open' to 'review'
# Wed Feb 26 13:50:37 2014 tlyu (Taylor Yu) - Tags pullup added
# Wed Feb 26 13:50:37 2014 tlyu (Taylor Yu) - Correspondence added
From: tlyu@mit.edu
Subject: git commit
Download (untitled) / with headers
text/plain 749B

Avoid duplicate "/etc/krb5.conf" in profile path

If configure gets run with --sysconfdir=/etc, "/etc/krb5.conf" shows
up twice in the profile path, which causes its contents to be read
twice. This can cause some confusing and possibly problematic
behavior.

Add some logic to configure.in to avoid adding the duplicate entry for
"/etc/krb5.conf".

Reported independently by Denis Vlasenko and Fredrik Tolf.

https://github.com/krb5/krb5/commit/8df1965d1ccdbcb8d74a3e68ad35d7579db9ac44
Author: Tom Yu <tlyu@mit.edu>
Commit: 8df1965d1ccdbcb8d74a3e68ad35d7579db9ac44
Branch: master
src/configure.in | 9 +++++++++
src/include/Makefile.in | 4 +++-
src/include/osconf.hin | 4 ++--
3 files changed, 14 insertions(+), 3 deletions(-)
# Thu Jun 26 16:36:13 2014 tlyu (Taylor Yu) - Status changed from 'review' to 'resolved'
# Thu Jun 26 16:36:13 2014 tlyu (Taylor Yu) - Version_Fixed 1.12.2 added
# Thu Jun 26 16:36:13 2014 tlyu (Taylor Yu) - Correspondence added
From: tlyu@mit.edu
Subject: git commit
Download (untitled) / with headers
text/plain 820B

Avoid duplicate "/etc/krb5.conf" in profile path

If configure gets run with --sysconfdir=/etc, "/etc/krb5.conf" shows
up twice in the profile path, which causes its contents to be read
twice. This can cause some confusing and possibly problematic
behavior.

Add some logic to configure.in to avoid adding the duplicate entry for
"/etc/krb5.conf".

Reported independently by Denis Vlasenko and Fredrik Tolf.

(back ported from commit 8df1965d1ccdbcb8d74a3e68ad35d7579db9ac44)

https://github.com/krb5/krb5/commit/51ef4b50e46d21374319b7070ad63ba7bb672ee2
Author: Tom Yu <tlyu@mit.edu>
Commit: 51ef4b50e46d21374319b7070ad63ba7bb672ee2
Branch: krb5-1.12
src/configure.in | 9 +++++++++
src/include/Makefile.in | 4 +++-
src/include/osconf.hin | 4 ++--
3 files changed, 14 insertions(+), 3 deletions(-)
# Wed Dec 16 18:02:45 2015 tlyu (Taylor Yu) - CustomField pullup deleted