Josh Clum
2014-04-17 15:21:42 UTC
Hi,
I'm setting up a test with the jsch client and an apache mina server to use
gss authentication. It looks like there is some protocal confusion with the
messages being sent. Are the versioning problems(kerberos, gssapi) that I
might incur when trying to use the jsch client to connect via userauthgss?
On the client side I'm getting:
java.net.SocketTimeoutException: Read timed out
On the server side this is my session start to finish:
11:08:08,876 DEBUG [KerberosProtocolHandler]
(KerberosProtocolHandler.java:91) /10.128.88.132:55448 CREATED: socket
11:08:08,877 DEBUG [KERBEROS_LOG] (KerberosProtocolHandler.java:96) /
10.128.88.132:55448 CREATED: socket
11:08:08,877 DEBUG [KerberosProtocolHandler]
(KerberosProtocolHandler.java:108) /10.128.88.132:55448 OPENED
11:08:08,877 DEBUG [KERBEROS_LOG] (KerberosProtocolHandler.java:113) /
10.128.88.132:55448 OPENED
11:08:08,877 DEBUG [ProtocolCodecFilter] (ProtocolCodecFilter.java:211)
Processing a MESSAGE_RECEIVED for session 6
11:08:54,898 DEBUG [Asn1Decoder] (Asn1Decoder.java:671)
11:08:54,899 DEBUG [Asn1Decoder] (Asn1Decoder.java:673)
TAG_STATE_START ---
11:08:54,901 DEBUG [Asn1Decoder] (Asn1Decoder.java:686) current byte :
0x32
11:08:54,901 DEBUG [Asn1Decoder] (Asn1Decoder.java:108) Tag 0x32 has been
decoded
11:08:54,901 DEBUG [Asn1Decoder] (Asn1Decoder.java:680) --- State =
LENGTH_STATE_START ---
11:08:54,902 DEBUG [Asn1Decoder] (Asn1Decoder.java:686) current byte :
0x2E
11:08:54,902 DEBUG [Asn1Decoder] (Asn1Decoder.java:680) --- State =
LENGTH_STATE_END ---
11:08:54,902 DEBUG [Asn1Decoder] (Asn1Decoder.java:686) current byte :
0x30
11:08:54,903 DEBUG [Asn1Decoder] (Asn1Decoder.java:360) Parent length : TLV
expected length stack : - null
11:08:54,903 DEBUG [Asn1Decoder] (Asn1Decoder.java:372) Root TLV[46]
11:08:54,903 DEBUG [Asn1Decoder] (Asn1Decoder.java:480) Length 46 has been
decoded
11:08:54,903 DEBUG [Asn1Decoder] (Asn1Decoder.java:680) --- State =
VALUE_STATE_START ---
11:08:54,904 DEBUG [Asn1Decoder] (Asn1Decoder.java:686) current byte :
0x30
11:08:54,904 DEBUG [Asn1Decoder] (Asn1Decoder.java:758)
<<<------------------------------------------
11:08:54,905 DEBUG [Asn1Decoder] (Asn1Decoder.java:775) <-- End decoding :
TLV[ 0x32, 46, DATA[0x30 0x2D 0x4A 0x53 0x43 0x48 0x2D 0x30 0x2E 0x31 0x2E
0x35 0x31 0x0A 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
0x00 0x00 0x00 0x00 0x00 ]]
11:08:54,905 DEBUG [Asn1Decoder] (Asn1Decoder.java:783)
<<<==========================================
11:10:23,724 ERROR [KerberosProtocolHandler]
(KerberosProtocolHandler.java:157) /10.128.88.132:55448 EXCEPTION
org.apache.mina.filter.codec.ProtocolDecoderException:
java.lang.IllegalArgumentException: message (Hexdump: 53 53 48 2D 32 2E 30
2D 4A 53 43 48 2D 30 2E 31 2E 35 31 0A)
at
org.apache.mina.filter.codec.ProtocolCodecFilter.messageReceived(ProtocolCodecFilter.java:242)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:417)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoFilterChain.java:47)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:765)
at
org.apache.mina.core.filterchain.IoFilterAdapter.messageReceived(IoFilterAdapter.java:109)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:417)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.fireMessageReceived(DefaultIoFilterChain.java:410)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:710)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:664)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:653)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.access$600(AbstractPollingIoProcessor.java:67)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1124)
at
org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
at java.lang.Thread.run(Thread.java:695)
Caused by: java.lang.IllegalArgumentException: message
at
org.apache.mina.filter.codec.AbstractProtocolDecoderOutput.write(AbstractProtocolDecoderOutput.java:43)
at
org.apache.directory.server.kerberos.protocol.codec.MinaKerberosDecoder.decode(MinaKerberosDecoder.java:65)
at
org.apache.mina.filter.codec.ProtocolCodecFilter.messageReceived(ProtocolCodecFilter.java:232)
... 15 more
11:10:23,726 ERROR [KERBEROS_LOG] (KerberosProtocolHandler.java:158) /
10.128.88.132:55448 EXCEPTION
org.apache.mina.filter.codec.ProtocolDecoderException:
java.lang.IllegalArgumentException: message (Hexdump: 53 53 48 2D 32 2E 30
2D 4A 53 43 48 2D 30 2E 31 2E 35 31 0A)
at
org.apache.mina.filter.codec.ProtocolCodecFilter.messageReceived(ProtocolCodecFilter.java:242)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:417)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoFilterChain.java:47)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:765)
at
org.apache.mina.core.filterchain.IoFilterAdapter.messageReceived(IoFilterAdapter.java:109)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:417)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.fireMessageReceived(DefaultIoFilterChain.java:410)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:710)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:664)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:653)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.access$600(AbstractPollingIoProcessor.java:67)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1124)
at
org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
at java.lang.Thread.run(Thread.java:695)
Caused by: java.lang.IllegalArgumentException: message
at
org.apache.mina.filter.codec.AbstractProtocolDecoderOutput.write(AbstractProtocolDecoderOutput.java:43)
at
org.apache.directory.server.kerberos.protocol.codec.MinaKerberosDecoder.decode(MinaKerberosDecoder.java:65)
at
org.apache.mina.filter.codec.ProtocolCodecFilter.messageReceived(ProtocolCodecFilter.java:232)
... 15 more
11:10:23,727 DEBUG [KerberosProtocolHandler]
(KerberosProtocolHandler.java:125) /10.128.88.132:55448 CLOSED
11:10:23,727 DEBUG [KERBEROS_LOG] (KerberosProtocolHandler.java:130) /
10.128.88.132:55448 CLOSED
Thanks,
Josh
I'm setting up a test with the jsch client and an apache mina server to use
gss authentication. It looks like there is some protocal confusion with the
messages being sent. Are the versioning problems(kerberos, gssapi) that I
might incur when trying to use the jsch client to connect via userauthgss?
On the client side I'm getting:
java.net.SocketTimeoutException: Read timed out
On the server side this is my session start to finish:
11:08:08,876 DEBUG [KerberosProtocolHandler]
(KerberosProtocolHandler.java:91) /10.128.88.132:55448 CREATED: socket
11:08:08,877 DEBUG [KERBEROS_LOG] (KerberosProtocolHandler.java:96) /
10.128.88.132:55448 CREATED: socket
11:08:08,877 DEBUG [KerberosProtocolHandler]
(KerberosProtocolHandler.java:108) /10.128.88.132:55448 OPENED
11:08:08,877 DEBUG [KERBEROS_LOG] (KerberosProtocolHandler.java:113) /
10.128.88.132:55448 OPENED
11:08:08,877 DEBUG [ProtocolCodecFilter] (ProtocolCodecFilter.java:211)
Processing a MESSAGE_RECEIVED for session 6
11:08:54,898 DEBUG [Asn1Decoder] (Asn1Decoder.java:671)
==========================================
11:08:54,899 DEBUG [Asn1Decoder] (Asn1Decoder.java:672) --> Decoding a PDU11:08:54,899 DEBUG [Asn1Decoder] (Asn1Decoder.java:673)
------------------------------------------
11:08:54,900 DEBUG [Asn1Decoder] (Asn1Decoder.java:680) --- State =TAG_STATE_START ---
11:08:54,901 DEBUG [Asn1Decoder] (Asn1Decoder.java:686) current byte :
0x32
11:08:54,901 DEBUG [Asn1Decoder] (Asn1Decoder.java:108) Tag 0x32 has been
decoded
11:08:54,901 DEBUG [Asn1Decoder] (Asn1Decoder.java:680) --- State =
LENGTH_STATE_START ---
11:08:54,902 DEBUG [Asn1Decoder] (Asn1Decoder.java:686) current byte :
0x2E
11:08:54,902 DEBUG [Asn1Decoder] (Asn1Decoder.java:680) --- State =
LENGTH_STATE_END ---
11:08:54,902 DEBUG [Asn1Decoder] (Asn1Decoder.java:686) current byte :
0x30
11:08:54,903 DEBUG [Asn1Decoder] (Asn1Decoder.java:360) Parent length : TLV
expected length stack : - null
11:08:54,903 DEBUG [Asn1Decoder] (Asn1Decoder.java:372) Root TLV[46]
11:08:54,903 DEBUG [Asn1Decoder] (Asn1Decoder.java:480) Length 46 has been
decoded
11:08:54,903 DEBUG [Asn1Decoder] (Asn1Decoder.java:680) --- State =
VALUE_STATE_START ---
11:08:54,904 DEBUG [Asn1Decoder] (Asn1Decoder.java:686) current byte :
0x30
11:08:54,904 DEBUG [Asn1Decoder] (Asn1Decoder.java:758)
<<<------------------------------------------
11:08:54,905 DEBUG [Asn1Decoder] (Asn1Decoder.java:775) <-- End decoding :
TLV[ 0x32, 46, DATA[0x30 0x2D 0x4A 0x53 0x43 0x48 0x2D 0x30 0x2E 0x31 0x2E
0x35 0x31 0x0A 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
0x00 0x00 0x00 0x00 0x00 ]]
11:08:54,905 DEBUG [Asn1Decoder] (Asn1Decoder.java:783)
<<<==========================================
11:10:23,724 ERROR [KerberosProtocolHandler]
(KerberosProtocolHandler.java:157) /10.128.88.132:55448 EXCEPTION
org.apache.mina.filter.codec.ProtocolDecoderException:
java.lang.IllegalArgumentException: message (Hexdump: 53 53 48 2D 32 2E 30
2D 4A 53 43 48 2D 30 2E 31 2E 35 31 0A)
at
org.apache.mina.filter.codec.ProtocolCodecFilter.messageReceived(ProtocolCodecFilter.java:242)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:417)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoFilterChain.java:47)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:765)
at
org.apache.mina.core.filterchain.IoFilterAdapter.messageReceived(IoFilterAdapter.java:109)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:417)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.fireMessageReceived(DefaultIoFilterChain.java:410)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:710)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:664)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:653)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.access$600(AbstractPollingIoProcessor.java:67)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1124)
at
org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
at java.lang.Thread.run(Thread.java:695)
Caused by: java.lang.IllegalArgumentException: message
at
org.apache.mina.filter.codec.AbstractProtocolDecoderOutput.write(AbstractProtocolDecoderOutput.java:43)
at
org.apache.directory.server.kerberos.protocol.codec.MinaKerberosDecoder.decode(MinaKerberosDecoder.java:65)
at
org.apache.mina.filter.codec.ProtocolCodecFilter.messageReceived(ProtocolCodecFilter.java:232)
... 15 more
11:10:23,726 ERROR [KERBEROS_LOG] (KerberosProtocolHandler.java:158) /
10.128.88.132:55448 EXCEPTION
org.apache.mina.filter.codec.ProtocolDecoderException:
java.lang.IllegalArgumentException: message (Hexdump: 53 53 48 2D 32 2E 30
2D 4A 53 43 48 2D 30 2E 31 2E 35 31 0A)
at
org.apache.mina.filter.codec.ProtocolCodecFilter.messageReceived(ProtocolCodecFilter.java:242)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:417)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoFilterChain.java:47)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:765)
at
org.apache.mina.core.filterchain.IoFilterAdapter.messageReceived(IoFilterAdapter.java:109)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:417)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.fireMessageReceived(DefaultIoFilterChain.java:410)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:710)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:664)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:653)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.access$600(AbstractPollingIoProcessor.java:67)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1124)
at
org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
at java.lang.Thread.run(Thread.java:695)
Caused by: java.lang.IllegalArgumentException: message
at
org.apache.mina.filter.codec.AbstractProtocolDecoderOutput.write(AbstractProtocolDecoderOutput.java:43)
at
org.apache.directory.server.kerberos.protocol.codec.MinaKerberosDecoder.decode(MinaKerberosDecoder.java:65)
at
org.apache.mina.filter.codec.ProtocolCodecFilter.messageReceived(ProtocolCodecFilter.java:232)
... 15 more
11:10:23,727 DEBUG [KerberosProtocolHandler]
(KerberosProtocolHandler.java:125) /10.128.88.132:55448 CLOSED
11:10:23,727 DEBUG [KERBEROS_LOG] (KerberosProtocolHandler.java:130) /
10.128.88.132:55448 CLOSED
Thanks,
Josh