[26925] in Athena Bugs
9.4.26 sun: Strange krb4 expiry problems
daemon@ATHENA.MIT.EDU (John Hawkinson)
Fri Aug 18 11:14:09 2006
Date: Fri, 18 Aug 2006 11:13:57 -0400 (EDT)
Message-Id: <200608181513.k7IFDvXe000383@multics.mit.edu>
To: bugs@mit.edu
From: John Hawkinson <jhawk@mit.edu>
X-Spam-Score: 1.217
X-Spam-Level: * (1.217)
X-Spam-Flag: NO
Errors-To: bugs-bounces@mit.edu
This one is even stranger [to me].
As you could perhaps tell from the last bug report, I've been
experimenting with renewable tickets.
I now find myself with a K4 TGT that seems to not work,
but that klist indicates is still valid:
Issued Expires Principal
08/17/06 16:26:03 08/18/06 14:41:22 krbtgt.ATHENA.MIT.EDU@ATHENA.MIT.EDU
[multics!jhawk:b] /var/tmp/x> discuss sipb-staff
Discuss version 1.6. Type '?' for a list of commands.
Warning: Kerberos ticket expired (krb_rd_req) while connecting to discuss@bloom-picayune.mit.edu
I'm not sure what went wrong here. Here's the full klist output:
[multics!jhawk:b] /var/tmp/x> klist
Ticket cache: FILE:/tmp/krb5cc_p631b
Default principal: jhawk@ATHENA.MIT.EDU
Valid starting Expires Service principal
08/17/06 17:26:22 08/18/06 14:41:22 krbtgt/ATHENA.MIT.EDU@ATHENA.MIT.EDU
renew until 08/22/06 23:26:17
08/17/06 17:26:22 08/18/06 14:41:22 afs/athena.mit.edu@ATHENA.MIT.EDU
renew until 08/22/06 23:26:17
08/17/06 17:26:22 08/18/06 14:41:22 afs/sipb.mit.edu@ATHENA.MIT.EDU
renew until 08/22/06 23:26:17
08/17/06 17:52:35 08/18/06 14:41:22 smtp/outgoing.mit.edu@ATHENA.MIT.EDU
renew until 08/22/06 23:26:17
08/17/06 21:36:25 08/18/06 14:41:22 ldap/ldap.mit.edu@ATHENA.MIT.EDU
renew until 08/22/06 23:26:17
08/18/06 02:37:56 08/18/06 14:41:22 krbtgt/WIN.MIT.EDU@ATHENA.MIT.EDU
renew until 08/22/06 23:26:17
08/18/06 02:37:56 08/18/06 12:37:56 ldap/m24dc1.win.mit.edu@WIN.MIT.EDU
renew until 08/22/06 23:26:17
Kerberos 4 ticket cache: /tmp/tkt_p631b
Principal: jhawk@ATHENA.MIT.EDU
Issued Expires Principal
08/17/06 16:26:03 08/18/06 14:41:22 krbtgt.ATHENA.MIT.EDU@ATHENA.MIT.EDU
08/18/06 02:38:53 08/18/06 05:03:53 zephyr.zephyr@ATHENA.MIT.EDU
08/18/06 02:43:59 08/18/06 05:03:59 moira.moira5@ATHENA.MIT.EDU
It seems particularly strange when I got zephyr and moira tickets earlier
this morning, they were set to expire at 05:03 -- less than 3 hours later --
yet the TGT was ostensibly not due to expire for another 12.
This v4 TGT was generated using krb524init. Specifically, I used:
kinit -5 -r7d -l21h15m $USER &&
sh -c "while krb524init; do aklog athena.mit.edu sipb.mit.edu;\
zctl load /dev/null 2>/dev/null; sleep 75600; kinit -R;\
done & echo Auto renewal process is pid "\$!
Looking to see when that last krb524init actually ran:
[multics!jhawk:b] /var/tmp/x> ptree 10429
10429 sh -c while krb524init; do aklog athena.mit.edu sipb.mit.edu; zctl load /dev/nu
16706 sleep 75600
[multics!jhawk:b] /var/tmp/x> ps -fp 10429
UID PID PPID C STIME TTY TIME CMD
jhawk 10429 1 0 Aug 15 pts/1 0:00 sh -c while krb524init; do aklog athena.mit.edu sipb.mit.edu; zctl load /dev/nu
[multics!jhawk:b] /var/tmp/x> ps -fp 16706
UID PID PPID C STIME TTY TIME CMD
jhawk 16706 10429 0 17:26:23 pts/1 0:00 sleep 75600
It appears that there is some extra-special clock problem. That is,
the krb4 TGT was issued at 16:26, but the 21-hour sleep was run at
17:26. It seems implausible that it took exactly an hour for aklog and
zctl to run. I don't know if this is a kernel bookkeeping error (!)
or a strange off-by-one error...
I've saved a copy of the ticket caches in question, if you'd like to
see them (the k4 one anytime, the k5 one anytime after 8/22). I'm not
sure how to try to reproduce this. This loop has been running since
August 15th, but it's possible that this is first time I've
tried to get a new k4 ticket more than 13 hours after a renewal.
My best hypothesis here is that the time inside the ticket does not
match the time displayed by klist.
--jhawk
p.s.: Anyone have a good trick to get the start time of a more-than-24-hour-old
process, short of mdb-and-friends?
Hmm, I guess this kind of works:
[multics!jhawk:b] /var/tmp/x> ps -fp 10429
UID PID PPID C STIME TTY TIME CMD
jhawk 10429 1 0 Aug 15 pts/1 0:00 sh -c while krb524init; do aklog athena.mit.edu sipb.mit.edu; zctl load /dev/nu
[multics!jhawk:b] /var/tmp/x> ps -fp 10429 -o etime;date
ELAPSED
2-11:45:20
Fri Aug 18 11:11:41 EDT 2006
Meaning 34 minutes before midnight on the 15th, i.e. 23:26.
etime In the POSIX locale, the elapsed time since
the process was started, in the form:
