Hi Kai,
Thanks for the response. I prepared a minimal config that reproduces my
problem.
You can fetch the branch/commit from:
https://github.com/vtslab/directory-kerby/commits/MitIssue
This is relative to RC2, but I also tried this on trunk for my actual
project.
This config produces the debug and error messages below.
1. For the terminal with the bash + python script
$ klist
Ticket cache: FILE:kerby-kerb/kerb-kdc-test/target/tmp/test-tkt.cc
Default principal: [email protected]
Valid starting Expires Service principal
29-04-17 21:07:39 30-04-17 05:07:39 krbtgt/[email protected]
renew until 29-04-17 21:07:39
$ .
kerby-kerb/kerb-kdc-test/src/test/java/org/apache/kerby/kerberos/kerb/server/MitIssueTest.sh
[15538] 1493491231.917606: Retrieving [email protected] from
FILE:/etc/krb5/user/1000/client.keytab (vno 0, enctype 0) with result:
2/Key table file '/etc/krb5/user/1000/client.keytab' not found
[15538] 1493491231.917827: Retrieving [email protected] from
FILE:/etc/krb5/user/1000/client.keytab (vno 0, enctype 0) with result:
2/Key table file '/etc/krb5/user/1000/client.keytab' not found
kerberos.authGSSClientInit successful
[15538] 1493491231.918185: Getting credentials [email protected] ->
test-service/localhost@ using ccache
FILE:kerby-kerb/kerb-kdc-test/target/tmp/test-tkt.cc
[15538] 1493491231.918210: Retrieving [email protected] ->
test-service/localhost@ from
FILE:kerby-kerb/kerb-kdc-test/target/tmp/test-tkt.cc with result:
-1765328243/Matching credential not found (filename:
kerby-kerb/kerb-kdc-test/target/tmp/test-tkt.cc)
[15538] 1493491231.918226: Retrying [email protected] ->
test-service/[email protected] with result: -1765328243/Matching
credential not found (filename:
kerby-kerb/kerb-kdc-test/target/tmp/test-tkt.cc)
[15538] 1493491231.918229: Server has referral realm; starting with
test-service/[email protected]
[15538] 1493491231.918278: Retrieving [email protected] ->
krbtgt/[email protected] from
FILE:kerby-kerb/kerb-kdc-test/target/tmp/test-tkt.cc with result: 0/Success
[15538] 1493491231.918281: Starting with TGT for client realm:
[email protected] -> krbtgt/[email protected]
[15538] 1493491231.918301: Requesting tickets for
test-service/[email protected], referrals on
[15538] 1493491231.918326: Generated subkey for TGS request: aes128-cts/FA30
[15538] 1493491231.918359: etypes requested in TGS request: aes256-cts,
aes128-cts, aes256-sha2, aes128-sha2, des3-cbc-sha1, rc4-hmac,
camellia128-cts, camellia256-cts
[15538] 1493491231.918484: Encoding request body and padata into FAST
request
[15538] 1493491231.918541: Sending request (836 bytes) to TEST.COM
[15538] 1493491231.918597: Resolving hostname localhost
[15538] 1493491231.918703: Initiating TCP connection to stream
127.0.0.1:44292
[15538] 1493491231.918777: Sending TCP request to stream 127.0.0.1:44292
[15538] 1493491231.922803: TCP error receiving from stream
127.0.0.1:44292: 104/Connection reset by peer
[15538] 1493491231.922812: Terminating TCP connection to stream
127.0.0.1:44292
[15538] 1493491231.922858: Sending initial UDP request to dgram
127.0.0.1:44292
('First kerberos.authGSSClientStep not successful',
GSSError(('Unspecified GSS failure. Minor code may provide more
information', 851968), ("Cannot contact any KDC for realm 'TEST.COM'",
-1765328228)))
2. For the terminal that runs mvn clean test -Dtest=MitIssueTest
Running org.apache.kerby.kerberos.kerb.server.MitIssueTest
2017-04-29 21:07:39,182 DEBUG [main] backend.AbstractIdentityBackend:
initialize called
2017-04-29 21:07:39,195 DEBUG [main] backend.AbstractIdentityBackend:
getIdentity called, principalName = krbtgt/[email protected]
2017-04-29 21:07:39,195 DEBUG [main] backend.AbstractIdentityBackend:
getIdentity failed, principalName = krbtgt/[email protected]
2017-04-29 21:07:39,212 DEBUG [main] backend.AbstractIdentityBackend:
addIdentity successful, principalName = krbtgt/[email protected]
2017-04-29 21:07:39,212 DEBUG [main] backend.AbstractIdentityBackend:
getIdentity called, principalName = kadmin/[email protected]
2017-04-29 21:07:39,212 DEBUG [main] backend.AbstractIdentityBackend:
getIdentity failed, principalName = kadmin/[email protected]
2017-04-29 21:07:39,213 DEBUG [main] backend.AbstractIdentityBackend:
addIdentity successful, principalName = kadmin/[email protected]
2017-04-29 21:07:39,216 DEBUG [main] backend.AbstractIdentityBackend:
start called
2017-04-29 21:07:39,232 DEBUG [main] backend.AbstractIdentityBackend:
addIdentity successful, principalName = test-service/[email protected]
2017-04-29 21:07:39,425 DEBUG [main] backend.AbstractIdentityBackend:
addIdentity successful, principalName = [email protected]
2017-04-29 21:07:39,465 DEBUG [pool-1-thread-1]
backend.AbstractIdentityBackend: getIdentity called, principalName =
krbtgt/[email protected]
2017-04-29 21:07:39,465 DEBUG [pool-1-thread-1]
backend.AbstractIdentityBackend: getIdentity successful, principalName =
krbtgt/[email protected]
2017-04-29 21:07:39,465 INFO [pool-1-thread-1] request.KdcRequest:
Client entry is empty.
2017-04-29 21:07:39,465 DEBUG [pool-1-thread-1]
backend.AbstractIdentityBackend: getIdentity called, principalName =
[email protected]
2017-04-29 21:07:39,465 DEBUG [pool-1-thread-1]
backend.AbstractIdentityBackend: getIdentity successful, principalName =
[email protected]
2017-04-29 21:07:39,465 DEBUG [pool-1-thread-1]
backend.AbstractIdentityBackend: getIdentity called, principalName =
krbtgt/[email protected]
2017-04-29 21:07:39,465 DEBUG [pool-1-thread-1]
backend.AbstractIdentityBackend: getIdentity successful, principalName =
krbtgt/[email protected]
2017-04-29 21:07:39,476 DEBUG [pool-1-thread-1] impl.DefaultKdcHandler:
Transport or decoding error occurred, disconnecting abnormally
java.io.EOFException
at java.io.DataInputStream.readInt(DataInputStream.java:392)
at
org.apache.kerby.kerberos.kerb.transport.KrbTcpTransport.receiveMessage(KrbTcpTransport.java:54)
at
org.apache.kerby.kerberos.kerb.server.impl.DefaultKdcHandler.run(DefaultKdcHandler.java:46)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:748)
2017-04-29 21:07:39,477 INFO [main] client.KrbClientBase: Storing the
tgt to the credential cache file.
2017-04-29 21:07:39,491 DEBUG [main] backend.AbstractIdentityBackend:
getIdentity called, principalName = test-service/[email protected]
2017-04-29 21:07:39,491 DEBUG [main] backend.AbstractIdentityBackend:
getIdentity successful, principalName = test-service/[email protected]
2017-04-29 21:07:39,498 DEBUG [pool-1-thread-1]
backend.AbstractIdentityBackend: getIdentity called, principalName =
krbtgt/[email protected]
2017-04-29 21:07:39,498 DEBUG [pool-1-thread-1]
backend.AbstractIdentityBackend: getIdentity successful, principalName =
krbtgt/[email protected]
2017-04-29 21:07:39,498 INFO [pool-1-thread-1] request.KdcRequest:
Client entry is empty.
2017-04-29 21:07:39,499 DEBUG [pool-1-thread-1]
backend.AbstractIdentityBackend: getIdentity called, principalName =
test-service/[email protected]
2017-04-29 21:07:39,499 DEBUG [pool-1-thread-1]
backend.AbstractIdentityBackend: getIdentity successful, principalName =
test-service/[email protected]
2017-04-29 21:07:39,499 DEBUG [pool-1-thread-1]
backend.AbstractIdentityBackend: getIdentity called, principalName =
krbtgt/[email protected]
2017-04-29 21:07:39,499 DEBUG [pool-1-thread-1]
backend.AbstractIdentityBackend: getIdentity successful, principalName =
krbtgt/[email protected]
2017-04-29 21:07:39,499 INFO [pool-1-thread-1] request.KdcRequest: The
preauth data is empty.
2017-04-29 21:07:39,501 INFO [pool-1-thread-1] server.KdcHandler: KRB
error occurred while processing request:Additional pre-authentication
required
2017-04-29 21:07:39,502 DEBUG [pool-1-thread-1] impl.DefaultKdcHandler:
Transport or decoding error occurred, disconnecting abnormally
java.io.EOFException
at java.io.DataInputStream.readInt(DataInputStream.java:392)
at
org.apache.kerby.kerberos.kerb.transport.KrbTcpTransport.receiveMessage(KrbTcpTransport.java:54)
at
org.apache.kerby.kerberos.kerb.server.impl.DefaultKdcHandler.run(DefaultKdcHandler.java:46)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:748)
2017-04-29 21:07:39,505 DEBUG [pool-1-thread-1]
backend.AbstractIdentityBackend: getIdentity called, principalName =
krbtgt/[email protected]
2017-04-29 21:07:39,505 DEBUG [pool-1-thread-1]
backend.AbstractIdentityBackend: getIdentity successful, principalName =
krbtgt/[email protected]
2017-04-29 21:07:39,505 INFO [pool-1-thread-1] request.KdcRequest:
Client entry is empty.
2017-04-29 21:07:39,506 DEBUG [pool-1-thread-1]
backend.AbstractIdentityBackend: getIdentity called, principalName =
test-service/[email protected]
2017-04-29 21:07:39,506 DEBUG [pool-1-thread-1]
backend.AbstractIdentityBackend: getIdentity successful, principalName =
test-service/[email protected]
2017-04-29 21:07:39,506 DEBUG [pool-1-thread-1]
backend.AbstractIdentityBackend: getIdentity called, principalName =
krbtgt/[email protected]
2017-04-29 21:07:39,506 DEBUG [pool-1-thread-1]
backend.AbstractIdentityBackend: getIdentity successful, principalName =
krbtgt/[email protected]
2017-04-29 21:07:39,510 DEBUG [pool-1-thread-1] impl.DefaultKdcHandler:
Transport or decoding error occurred, disconnecting abnormally
java.io.EOFException
at java.io.DataInputStream.readInt(DataInputStream.java:392)
at
org.apache.kerby.kerberos.kerb.transport.KrbTcpTransport.receiveMessage(KrbTcpTransport.java:54)
at
org.apache.kerby.kerberos.kerb.server.impl.DefaultKdcHandler.run(DefaultKdcHandler.java:46)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:748)
2017-04-29 21:07:55,602 DEBUG [pool-1-thread-1]
backend.AbstractIdentityBackend: getIdentity called, principalName =
krbtgt/[email protected]
2017-04-29 21:07:55,602 DEBUG [pool-1-thread-1]
backend.AbstractIdentityBackend: getIdentity successful, principalName =
krbtgt/[email protected]
2017-04-29 21:07:55,602 INFO [pool-1-thread-1] request.KdcRequest:
Found fast padata and start to process it.
2017-04-29 21:07:55,603 ERROR [pool-1-thread-1] impl.DefaultKdcHandler:
Error occured while processing request:
org.apache.kerby.kerberos.kerb.KrbException: Decoding failed
at org.apache.kerby.kerberos.kerb.KrbCodec.decode(KrbCodec.java:85)
at org.apache.kerby.kerberos.kerb.KrbCodec.decode(KrbCodec.java:70)
at
org.apache.kerby.kerberos.kerb.server.request.KdcRequest.kdcFindFast(KdcRequest.java:208)
at
org.apache.kerby.kerberos.kerb.server.request.KdcRequest.process(KdcRequest.java:168)
at
org.apache.kerby.kerberos.kerb.server.KdcHandler.handleMessage(KdcHandler.java:115)
at
org.apache.kerby.kerberos.kerb.server.impl.DefaultKdcHandler.handleMessage(DefaultKdcHandler.java:67)
at
org.apache.kerby.kerberos.kerb.server.impl.DefaultKdcHandler.run(DefaultKdcHandler.java:52)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:748)
Caused by: java.io.IOException: Unexpected item context [0] [tag=0xA0,
off=0, len=3+207], expecting 0x30
at
org.apache.kerby.asn1.type.Asn1Encodeable.decode(Asn1Encodeable.java:210)
at
org.apache.kerby.asn1.type.Asn1Encodeable.decode(Asn1Encodeable.java:197)
at org.apache.kerby.kerberos.kerb.KrbCodec.decode(KrbCodec.java:83)
... 9 more
2017-04-29 21:07:55,604 DEBUG [pool-1-thread-1] impl.DefaultKdcHandler:
Transport or decoding error occurred, disconnecting abnormally
java.net.SocketException: Socket closed
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
at java.net.SocketInputStream.read(SocketInputStream.java:171)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at java.net.SocketInputStream.read(SocketInputStream.java:224)
at java.io.DataInputStream.readInt(DataInputStream.java:387)
at
org.apache.kerby.kerberos.kerb.transport.KrbTcpTransport.receiveMessage(KrbTcpTransport.java:54)
at
org.apache.kerby.kerberos.kerb.server.impl.DefaultKdcHandler.run(DefaultKdcHandler.java:46)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:748)
In a FreeIPA environment these python lines "just" work.
Any suggestions are welcome!
Marc
