Pre-auth encrypted timestamp clock skew

Wed Aug 23 05:23:54 EDT 2017

Hi,

Long-time lurker, first-time writer...

We recently started testing pre-authentication for certain principals, and
I'm seeing an odd issue whereby kinit fails with "Clock skew too great
while getting initial credentials", despite all three KDCs and the client
systems' time being within one second of each other.

Output of a trace during kinit shows:

$ KRB5_TRACE=/dev/stderr kinit
[19033] 1503478211.842026: Getting initial credentials for
bnh1 at CC.COLUMBIA.EDU
[19033] 1503478211.842332: Sending request (194 bytes) to CC.COLUMBIA.EDU
[19033] 1503478211.848448: Sending initial UDP request to dgram
128.59.94.136:88
[19033] 1503478211.849318: Received answer from dgram 128.59.94.136:88
[19033] 1503478211.849408: Response was not from master KDC
[19033] 1503478211.849435: Received error from KDC: -1765328359/Additional
pre-authentication required
[19033] 1503478211.849476: Processing preauth types: 136, 19, 2, 133
[19033] 1503478211.849493: Selected etype info: etype aes256-cts, salt
"CC.COLUMBIA.EDUbnh1", params ""
[19033] 1503478211.849500: Received cookie: MIT
Password for bnh1 at CC.COLUMBIA.EDU:
[19033] 1503478218.212398: AS key obtained for encrypted timestamp:
aes256-cts/AD9B
[19033] 1503478218.212457: Encrypted timestamp (for 1503479452.212416):
plain 301AA011180F32303137303832333039313035325AA1050203033DC0, encrypted
D30E585A851DFEE714F524BF67C01C1CE1F0A91BEB466AD8EE9B692DF5D82C83B19803345A527321B08F2C482CF4039B58255CC17C21A79E
[19033] 1503478218.212507: Preauth module encrypted_timestamp (2) (flags=1)
returned: 0/Success
[19033] 1503478218.212517: Produced preauth for next request: 133, 2
[19033] 1503478218.212546: Sending request (289 bytes) to CC.COLUMBIA.EDU
[19033] 1503478218.213637: Sending initial UDP request to dgram
128.59.94.136:88
[19033] 1503478218.214539: Received answer from dgram 128.59.94.136:88
[19033] 1503478218.214619: Response was not from master KDC
[19033] 1503478218.214638: Received error from KDC: -1765328347/Clock skew
too great
[19033] 1503478218.214668: Retrying AS request with master KDC
[19033] 1503478218.214674: Getting initial credentials for
bnh1 at CC.COLUMBIA.EDU
[19033] 1503478218.214742: Sending request (194 bytes) to CC.COLUMBIA.EDU
(master)
[19033] 1503478218.214821: Sending initial UDP request to dgram
128.59.94.135:88
[19033] 1503478218.215573: Received answer from dgram 128.59.94.135:88
[19033] 1503478218.215592: Received error from KDC: -1765328359/Additional
pre-authentication required
[19033] 1503478218.215611: Processing preauth types: 136, 19, 2, 133
[19033] 1503478218.215619: Selected etype info: etype aes256-cts, salt
"CC.COLUMBIA.EDUbnh1", params ""
[19033] 1503478218.215623: Received cookie: MIT
[19033] 1503478218.223793: AS key obtained for encrypted timestamp:
aes256-cts/AD9B
[19033] 1503478218.223851: Encrypted timestamp (for 1503479452.223817):
plain 301AA011180F32303137303832333039313035325AA1050203036A49, encrypted
B7D40683552E9E5E4B041F5A01BBA3E73AF72A2C5ED6E4DDC285E5AC34906D75AB0A616C6020DC53A2791A941C34740430ED00E3A2F1345B
[19033] 1503478218.223876: Preauth module encrypted_timestamp (2) (flags=1)
returned: 0/Success
[19033] 1503478218.223881: Produced preauth for next request: 133, 2
[19033] 1503478218.223899: Sending request (289 bytes) to CC.COLUMBIA.EDU
(master)
[19033] 1503478218.224052: Sending initial UDP request to dgram
128.59.94.135:88
[19033] 1503478218.227476: Received answer from dgram 128.59.94.135:88
[19033] 1503478218.227509: Received error from KDC: -1765328347/Clock skew
too great
kinit: Clock skew too great while getting initial credentials

The part that seems interesting to me is that the pre-auth encrypted
timestamp appears to be off by way more than 5 minutes from the other
timestamps.  Note the line:

[19033] 1503478218.212457: Encrypted timestamp (for 1503479452.212416):
plain 301AA011180F32303137303832333039313035325AA1050203033DC0, encrypted
D30E585A851DFEE714F524BF67C01C1CE1F0A91BEB466AD8EE9B692DF5D82C83B19803345A527321B08F2C482CF4039B58255CC17C21A79E

$ perl -e 'print scalar localtime(1503479452.212416)' #encrypted timestamp
in parenthesis
Wed Aug 23 05:10:52 2017

$ perl -e 'print scalar localtime(1503478218.212457)' #kinit timestamp
Wed Aug 23 04:50:18 2017

On the KDC I see an error with matching timestamps:

Aug 23 04:50:18 kerbprodapp01 krb5kdc[11419](info): preauth
(encrypted_timestamp) verify failure: Clock skew too great
Aug 23 04:50:18 kerbprodapp01 krb5kdc[11419](info): AS_REQ (7 etypes {18 17
16 23 1 3 2}) 128.59.92.186: PREAUTH_FAILED: bnh1 at CC.COLUMBIA.EDU for
krbtgt/CC.COLUMBIA.EDU at CC.COLUMBIA.EDU, Clock skew too great

We're running a compiled (non-rpm) version of 1.11.6 on the KDCs.  Clients
and KDCs are RHEL6, sssd-krb5-1.11.6-30.el6_6.4.

Has anyone else ever experience something similar, or does anyone see
anything obvious happening here that I'm missing?  Is the pre-auth
timestamp difference even the source of the skew?  Or is that timestamp
meant to be different?

Advice would be much appreciated.

Thanks,
ben

-- 
Benjamin Hall
Lead Systems Engineer, CUIT
Columbia University
bnh1 at columbia.edu