You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@directory.apache.org by "Sangjin Lee (JIRA)" <ji...@apache.org> on 2015/06/09 19:27:01 UTC
[jira] [Commented] (DIRSERVER-2071) MinaKerberosDecoder fails with
NullPointerException if the kerberos message is split in multiple packets
[ https://issues.apache.org/jira/browse/DIRSERVER-2071?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14579275#comment-14579275 ]
Sangjin Lee commented on DIRSERVER-2071:
----------------------------------------
I applied the diff onto 2.0.0-M15 and tested the same scenario. It is still failing but for a different reason. It appears that the decoding times out. The following is the debug log (you can compare against the one in the description):
{noformat}
2015-06-09 16:56:02,602 DEBUG Asn1Decoder - >>>==========================================
2015-06-09 16:56:02,602 DEBUG Asn1Decoder - --> Decoding a PDU
2015-06-09 16:56:02,602 DEBUG Asn1Decoder - >>>------------------------------------------
2015-06-09 16:56:02,602 DEBUG Asn1Decoder - --- State = TAG_STATE_START ---
2015-06-09 16:56:02,602 DEBUG Asn1Decoder - current byte : 0x6C
2015-06-09 16:56:02,602 DEBUG Asn1Decoder - Tag 0x6C has been decoded
2015-06-09 16:56:02,602 DEBUG Asn1Decoder - --- State = LENGTH_STATE_START ---
2015-06-09 16:56:02,602 DEBUG Asn1Decoder - current byte : 0x82
2015-06-09 16:56:02,602 DEBUG Asn1Decoder - --- State = LENGTH_STATE_PENDING ---
2015-06-09 16:56:02,602 DEBUG Asn1Decoder - current byte : 0x02
2015-06-09 16:56:02,602 DEBUG Asn1Decoder - current byte : 0x02
2015-06-09 16:56:02,602 DEBUG Asn1Decoder - current byte : 0x41
2015-06-09 16:56:02,602 DEBUG Asn1Decoder - --- State = LENGTH_STATE_END ---
2015-06-09 16:56:02,602 DEBUG Asn1Decoder - current byte : 0x30
2015-06-09 16:56:02,602 DEBUG Asn1Decoder - Parent length : TLV expected length stack : - null
2015-06-09 16:56:02,602 DEBUG Asn1Decoder - Root TLV[577]
2015-06-09 16:56:02,602 DEBUG Asn1Decoder - Length 577 has been decoded
2015-06-09 16:56:02,602 DEBUG Asn1Decoder - --- State = VALUE_STATE_START ---
2015-06-09 16:56:02,602 DEBUG Asn1Decoder - current byte : 0x30
2015-06-09 16:56:02,602 DEBUG Asn1Decoder - <<<------------------------------------------
2015-06-09 16:56:02,602 DEBUG Asn1Decoder - <-- End decoding : TLV[ 0x6C, 577, DATA[... ]]
2015-06-09 16:56:02,602 DEBUG Asn1Decoder - <<<==========================================
2015-06-09 16:56:02,808 DEBUG Asn1Decoder - >>>==========================================
2015-06-09 16:56:02,808 DEBUG Asn1Decoder - --> Decoding a PDU
2015-06-09 16:56:02,808 DEBUG Asn1Decoder - >>>------------------------------------------
2015-06-09 16:56:02,808 DEBUG Asn1Decoder - --- State = TAG_STATE_START ---
2015-06-09 16:56:02,808 DEBUG Asn1Decoder - current byte : 0x01
2015-06-09 16:56:02,808 DEBUG Asn1Decoder - Tag 0x01 has been decoded
2015-06-09 16:56:02,808 DEBUG Asn1Decoder - --- State = LENGTH_STATE_START ---
2015-06-09 16:56:02,808 DEBUG Asn1Decoder - current byte : 0x10
2015-06-09 16:56:02,808 DEBUG Asn1Decoder - --- State = LENGTH_STATE_END ---
2015-06-09 16:56:02,808 DEBUG Asn1Decoder - current byte : 0x02
2015-06-09 16:56:02,808 DEBUG Asn1Decoder - Parent length : TLV expected length stack : - null
2015-06-09 16:56:02,808 DEBUG Asn1Decoder - Root TLV[16]
2015-06-09 16:56:02,808 DEBUG Asn1Decoder - Length 16 has been decoded
2015-06-09 16:56:02,808 DEBUG Asn1Decoder - --- State = VALUE_STATE_START ---
2015-06-09 16:56:02,808 DEBUG Asn1Decoder - current byte : 0x02
2015-06-09 16:56:02,808 DEBUG Asn1Decoder - <<<------------------------------------------
2015-06-09 16:56:02,808 DEBUG Asn1Decoder - <-- End decoding : TLV[ 0x01, 16, DATA[0x02 0x01 0x17 0x02 0x01 0x01 0x02 0x01 0x03 0x00 0x00 0x00 0x00 0x00 0x00 0x00 ]]
2015-06-09 16:56:02,808 DEBUG Asn1Decoder - <<<==========================================
SocketTimeOutException with attempt: 1
2015-06-09 16:56:32,615 DEBUG KerberosProtocolHandler - /127.0.0.1:59209 CLOSED
2015-06-09 16:56:32,615 DEBUG KERBEROS_LOG - /127.0.0.1:59209 CLOSED
{noformat}
It does it 3 times before the call eventually times out.
> MinaKerberosDecoder fails with NullPointerException if the kerberos message is split in multiple packets
> --------------------------------------------------------------------------------------------------------
>
> Key: DIRSERVER-2071
> URL: https://issues.apache.org/jira/browse/DIRSERVER-2071
> Project: Directory ApacheDS
> Issue Type: Bug
> Components: asn1
> Affects Versions: 2.0.0-M15
> Reporter: Sangjin Lee
> Assignee: Kiran Ayyagari
> Fix For: 2.0.0-M21
>
>
> On some machines (but not all), kerberos authentication to Apache DS is consistently failing with a NullPointerException:
> {noformat}
> 2015-06-08 20:35:57,189 ERROR KerberosProtocolHandler - /127.0.0.1:54477 EXCEPTION
> org.apache.mina.filter.codec.ProtocolDecoderException: java.lang.NullPointerException: message (Hexdump: ...)
> at org.apache.mina.filter.codec.ProtocolCodecFilter.messageReceived(ProtocolCodecFilter.java:234)
> at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:434)
> at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoFilterChain.java:48)
> at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:802)
> at org.apache.mina.core.filterchain.IoFilterAdapter.messageReceived(IoFilterAdapter.java:120)
> at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:434)
> at org.apache.mina.core.filterchain.DefaultIoFilterChain.fireMessageReceived(DefaultIoFilterChain.java:426)
> at org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:604)
> at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:564)
> at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:553)
> at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$400(AbstractPollingIoProcessor.java:57)
> at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:892)
> at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:65)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:745)
> Caused by: java.lang.NullPointerException: message
> at org.apache.mina.filter.codec.AbstractProtocolDecoderOutput.write(AbstractProtocolDecoderOutput.java:44)
> at org.apache.directory.server.kerberos.protocol.codec.MinaKerberosDecoder.decode(MinaKerberosDecoder.java:65)
> at org.apache.mina.filter.codec.ProtocolCodecFilter.messageReceived(ProtocolCodecFilter.java:224)
> ... 15 more
> {noformat}
> I traced it down to a silent failure of Asn1Decoder. Basically the ASN.1 decoder thinks the byte buffer it is passed does not have the promised size payload, and aborts parsing:
> {noformat}
> 2015-06-08 20:35:57,187 DEBUG Asn1Decoder - >>>==========================================
> 2015-06-08 20:35:57,187 DEBUG Asn1Decoder - --> Decoding a PDU
> 2015-06-08 20:35:57,187 DEBUG Asn1Decoder - >>>------------------------------------------
> 2015-06-08 20:35:57,187 DEBUG Asn1Decoder - --- State = TAG_STATE_START ---
> 2015-06-08 20:35:57,187 DEBUG Asn1Decoder - current byte : 0x6C
> 2015-06-08 20:35:57,187 DEBUG Asn1Decoder - Tag 0x6C has been decoded
> 2015-06-08 20:35:57,187 DEBUG Asn1Decoder - --- State = LENGTH_STATE_START ---
> 2015-06-08 20:35:57,187 DEBUG Asn1Decoder - current byte : 0x82
> 2015-06-08 20:35:57,187 DEBUG Asn1Decoder - --- State = LENGTH_STATE_PENDING ---
> 2015-06-08 20:35:57,187 DEBUG Asn1Decoder - current byte : 0x02
> 2015-06-08 20:35:57,187 DEBUG Asn1Decoder - current byte : 0x02
> 2015-06-08 20:35:57,187 DEBUG Asn1Decoder - current byte : 0x41
> 2015-06-08 20:35:57,187 DEBUG Asn1Decoder - --- State = LENGTH_STATE_END ---
> 2015-06-08 20:35:57,187 DEBUG Asn1Decoder - current byte : 0x30
> 2015-06-08 20:35:57,187 DEBUG Asn1Decoder - Parent length : TLV expected length stack : - null
> 2015-06-08 20:35:57,187 DEBUG Asn1Decoder - Root TLV[577]
> 2015-06-08 20:35:57,187 DEBUG Asn1Decoder - Length 577 has been decoded
> 2015-06-08 20:35:57,187 DEBUG Asn1Decoder - --- State = VALUE_STATE_START ---
> 2015-06-08 20:35:57,187 DEBUG Asn1Decoder - current byte : 0x30
> 2015-06-08 20:35:57,187 DEBUG Asn1Decoder - <<<------------------------------------------
> 2015-06-08 20:35:57,187 DEBUG Asn1Decoder - <-- End decoding : TLV[ 0x6C, 577, DATA[... ]]
> {noformat}
> Here's an interesting thing however. The reason the buffer has fewer bytes than the length value indicates is that the TCP message is split into 2 packets due to a small TCP window size on this problematic machine. For the kerberos message of size 585 bytes, the first 570 bytes are sent in the first packet, and the remaining 15 bytes in another packet. The Asn1Decoder thinks that it is missing the last 15 bytes and aborts decoding it. The following is the gist of the tcpdump capture of this TCP conversation:
> {noformat}
> 13:35:57.186758 IP localhost.54477 > localhost.40829: Flags [S], seq 1599306555, win 32792, options [mss 16396,sackOK,TS val 318374489 ecr 0,nop,wscale 8], length 0
> 13:35:57.186771 IP localhost.40829 > localhost.54477: Flags [S.], seq 7524064, ack 1599306556, win 1140, options [mss 16396,sackOK,TS val 318374489 ecr 318374489,nop,wscale 0], length 0
> 13:35:57.186781 IP localhost.54477 > localhost.40829: Flags [.], ack 1, win 129, options [nop,nop,TS val 318374489 ecr 318374489], length 0
> 13:35:57.186903 IP localhost.54477 > localhost.40829: Flags [.], seq 1:571, ack 1, win 129, options [nop,nop,TS val 318374490 ecr 318374489], length 570
> 13:35:57.186909 IP localhost.40829 > localhost.54477: Flags [.], ack 571, win 570, options [nop,nop,TS val 318374490 ecr 318374490], length 0
> 13:35:57.186914 IP localhost.54477 > localhost.40829: Flags [P.], seq 571:586, ack 1, win 129, options [nop,nop,TS val 318374490 ecr 318374489], length 15
> 13:35:57.187519 IP localhost.40829 > localhost.54477: Flags [.], ack 571, win 1140, options [nop,nop,TS val 318374490 ecr 318374490], length 0
> 13:35:57.190641 IP localhost.40829 > localhost.54477: Flags [F.], seq 1, ack 571, win 1140, options [nop,nop,TS val 318374493 ecr 318374490], length 0
> 13:35:57.190687 IP localhost.54477 > localhost.40829: Flags [F.], seq 586, ack 2, win 129, options [nop,nop,TS val 318374493 ecr 318374493], length 0
> 13:35:57.190701 IP localhost.40829 > localhost.54477: Flags [R], seq 7524066, win 0, length 0
> {noformat}
> Having small TCP window sizes aside, this strikes me as a code issue. The server should be able to handle the kerberos message even if it is split into multiple packets.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)