directory-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Sangjin Lee (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (DIRSERVER-2071) MinaKerberosDecoder fails with NullPointerException if the kerberos message is split in multiple packets
Date Wed, 10 Jun 2015 05:21:00 GMT

    [ https://issues.apache.org/jira/browse/DIRSERVER-2071?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14580039#comment-14580039
] 

Sangjin Lee commented on DIRSERVER-2071:
----------------------------------------

I applied the latest diff on top of the previous one (still based on 2.0.0-M15), and it's
failing with a different exception. I'm reproducing the entire debug log here:

{noformat}
2015-06-10 05:10:34,626 DEBUG Asn1Decoder - >>>==========================================
2015-06-10 05:10:34,626 DEBUG Asn1Decoder - --> Decoding a PDU
2015-06-10 05:10:34,626 DEBUG Asn1Decoder - >>>------------------------------------------
2015-06-10 05:10:34,626 DEBUG Asn1Decoder - --- State = TAG_STATE_START ---
2015-06-10 05:10:34,626 DEBUG Asn1Decoder -   current byte : 0x6C
2015-06-10 05:10:34,626 DEBUG Asn1Decoder - Tag 0x6C has been decoded
2015-06-10 05:10:34,626 DEBUG Asn1Decoder - --- State = LENGTH_STATE_START ---
2015-06-10 05:10:34,626 DEBUG Asn1Decoder -   current byte : 0x82
2015-06-10 05:10:34,626 DEBUG Asn1Decoder - --- State = LENGTH_STATE_PENDING ---
2015-06-10 05:10:34,626 DEBUG Asn1Decoder -   current byte : 0x02
2015-06-10 05:10:34,626 DEBUG Asn1Decoder -   current byte : 0x02
2015-06-10 05:10:34,626 DEBUG Asn1Decoder -   current byte : 0x41
2015-06-10 05:10:34,626 DEBUG Asn1Decoder - --- State = LENGTH_STATE_END ---
2015-06-10 05:10:34,626 DEBUG Asn1Decoder -   current byte : 0x30
2015-06-10 05:10:34,626 DEBUG Asn1Decoder - Parent length : TLV expected length stack :  -
null
2015-06-10 05:10:34,626 DEBUG Asn1Decoder - Root TLV[577]
2015-06-10 05:10:34,626 DEBUG Asn1Decoder - Length 577 has been decoded
2015-06-10 05:10:34,626 DEBUG Asn1Decoder - --- State = VALUE_STATE_START ---
2015-06-10 05:10:34,626 DEBUG Asn1Decoder -   current byte : 0x30
2015-06-10 05:10:34,627 DEBUG Asn1Decoder - <<<------------------------------------------
2015-06-10 05:10:34,627 DEBUG Asn1Decoder - <-- End decoding : TLV[ 0x6C, 577, DATA[0x30
0x82 0x02 0x3D 0xA1 0x03 0x02 0x01 0x05 0xA2 0x03 0x02 0x01 0x0C 0xA3 0x82 0x01 0xC4 0x30
0x82 0x01 0xC0 0x30 0x82 0x01 0xBC 0xA1 0x03 0x02 0x01 0x01 0xA2 0x82 0x01 0xB3 0x04 0x82
0x01 0xAF 0x6E 0x82 0x01 0xAB 0x30 0x82 0x01 0xA7 0xA0 0x03 0x02 0x01 0x05 0xA1 0x03 0x02
0x01 0x0E 0xA2 0x07 0x03 0x05 0x00 0x00 0x00 0x00 0x00 0xA3 0x81 0xF6 0x61 0x81 0xF3 0x30
0x81 0xF0 0xA0 0x03 0x02 0x01 0x05 0xA1 0x0D 0x1B 0x0B 0x45 0x58 0x41 0x4D 0x50 0x4C 0x45
0x2E 0x43 0x4F 0x4D 0xA2 0x20 0x30 0x1E 0xA0 0x03 0x02 0x01 0x02 0xA1 0x17 0x30 0x15 0x1B
0x06 0x6B 0x72 0x62 0x74 0x67 0x74 0x1B 0x0B 0x45 0x58 0x41 0x4D 0x50 0x4C 0x45 0x2E 0x43
0x4F 0x4D 0xA3 0x81 0xB7 0x30 0x81 0xB4 0xA0 0x03 0x02 0x01 0x11 0xA2 0x81 0xAC 0x04 0x81
0xA9 0xC6 0x60 0xAE 0xCB 0xA0 0xB4 0x18 0xFF 0xFA 0x56 0xCA 0x0F 0xDA 0x31 0x13 0xB9 0x0D
0x35 0x14 0xFD 0x89 0xCA 0x55 0xCF 0xA7 0x57 0x30 0x43 0x00 0x80 0x6D 0x61 0xC9 0xAD 0x7D
0xCF 0x77 0x59 0x7B 0x7F 0x7C 0x93 0xEA 0x69 0x23 0x40 0x68 0x08 0x5B 0xBA 0xE7 0x15 0x97
0x23 0x79 0xAF 0x6C 0x94 0x63 0x7F 0x99 0xCD 0xCC 0xD3 0x07 0x06 0x0A 0x68 0x73 0x97 0xDF
0x30 0x01 0x83 0x24 0xA1 0xB2 0xFA 0x62 0x51 0x0A 0x45 0x42 0x2A 0xE3 0x14 0x29 0xBA 0x4F
0xF8 0x0B 0xC9 0xB5 0x75 0x5A 0x8B 0x4E 0x8E 0xBD 0x9F 0xEF 0xF4 0x79 0x11 0x14 0xDB 0x26
0x70 0x49 0xF8 0xE7 0x41 0xE1 0xFF 0x1F 0x5E 0xFF 0xC3 0x5B 0x4F 0x3D 0xD8 0xD3 0x29 0x8F
0xE6 0x98 0x23 0xE2 0x02 0xDD 0x57 0x47 0xB6 0x27 0x2F 0x2F 0x97 0x99 0x4F 0x58 0xD8 0xC9
0x33 0x4D 0x53 0x22 0x38 0x0A 0xBC 0x99 0xF6 0xBD 0x38 0xCE 0x33 0x3E 0xD2 0xAB 0x95 0x75
0xA6 0x55 0x5A 0xBB 0x82 0x44 0x2C 0xE1 0xA4 0x81 0x98 0x30 0x81 0x95 0xA0 0x03 0x02 0x01
0x11 0xA2 0x81 0x8D 0x04 0x81 0x8A 0x12 0x21 0x82 0x31 0x7F 0x22 0x62 0x18 0x07 0xE9 0x0F
0x0B 0x79 0x10 0x42 0x81 0x0B 0xC7 0x6B 0x64 0x07 0xC6 0x2B 0x5B 0xE0 0xB9 0x08 0xCF 0x17
0xB2 0x2D 0x8E 0xE2 0xFC 0x04 0xC7 0x0E 0xDE 0x56 0x8E 0x0E 0xFB 0x71 0x21 0x59 0xCA 0xAC
0xE3 0x57 0x95 0xE8 0x01 0xCB 0xB7 0xFE 0x07 0x9F 0x23 0x65 0xB4 0xD7 0xC0 0xE4 0x03 0xB8
0xCA 0x8C 0x7C 0xA9 0x10 0xCB 0x2F 0xB5 0x77 0x41 0xA9 0x10 0x90 0x64 0x0A 0xDA 0xC3 0xEB
0xD2 0x66 0xA9 0xB2 0x38 0x5E 0x59 0x17 0x31 0x0B 0x1D 0x3F 0x43 0x3E 0x91 0xE3 0xD5 0xDD
0xD3 0x05 0x33 0x7E 0xAD 0x82 0xE4 0xE3 0xF3 0x70 0x67 0xB2 0x9F 0xBC 0xE7 0x86 0x0A 0xBC
0x3E 0xB3 0xF3 0xA7 0xEF 0xCD 0xE7 0xE9 0x7A 0xCF 0x6E 0x07 0x00 0x09 0x95 0x92 0x38 0x57
0xE0 0xA4 0x69 0x30 0x67 0xA0 0x07 0x03 0x05 0x00 0x00 0x00 0x00 0x00 0xA2 0x0D 0x1B 0x0B
0x45 0x58 0x41 0x4D 0x50 0x4C 0x45 0x2E 0x43 0x4F 0x4D 0xA3 0x1C 0x30 0x1A 0xA0 0x03 0x02
0x01 0x00 0xA1 0x13 0x30 0x11 0x1B 0x04 0x48 0x54 0x54 0x50 0x1B 0x09 0x6C 0x6F 0x63 0x61
0x6C 0x68 0x6F 0x73 0x74 0xA5 0x11 0x18 0x0F 0x31 0x39 0x37 0x30 0x30 0x31 0x30 0x31 0x30
0x30 0x30 0x30 0x30 0x30 0x5A 0xA7 0x06 0x02 0x04 0x02 0x82 0xF2 0x8A 0xA8 0x14 0x30 0x12
0x02 0x01 0x12 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
]]
2015-06-10 05:10:34,627 DEBUG Asn1Decoder - <<<==========================================
2015-06-10 05:10:34,832 DEBUG Asn1Decoder - >>>==========================================
2015-06-10 05:10:34,832 DEBUG Asn1Decoder - --> Decoding a PDU
2015-06-10 05:10:34,832 DEBUG Asn1Decoder - >>>------------------------------------------
2015-06-10 05:10:34,832 DEBUG Asn1Decoder - --- State = VALUE_STATE_PENDING ---
2015-06-10 05:10:34,832 DEBUG Asn1Decoder -   current byte : 0x02
2015-06-10 05:10:34,832 DEBUG Asn1Decoder - --- State = TLV_STATE_DONE ---
2015-06-10 05:10:34,832 DEBUG Asn1Decoder -   no more byte to decode in the stream
2015-06-10 05:10:34,832 DEBUG Asn1Decoder - TLV Tree : TLV0x6C(577)
2015-06-10 05:10:34,832 DEBUG AbstractGrammar - Transition from state <START_STATE>
to state <TGS_REQ_TAG_STATE>, tag <0x6C>, action : null
2015-06-10 05:10:34,832 DEBUG Asn1Decoder - >>>==========================================
2015-06-10 05:10:34,832 DEBUG Asn1Decoder - --> Decoding a PDU
2015-06-10 05:10:34,832 DEBUG Asn1Decoder - >>>------------------------------------------
2015-06-10 05:10:34,832 DEBUG Asn1Decoder - --- State = TAG_STATE_START ---
2015-06-10 05:10:34,832 DEBUG Asn1Decoder -   current byte : 0x02
2015-06-10 05:10:34,832 DEBUG Asn1Decoder - Tag 0x02 has been decoded
2015-06-10 05:10:34,832 DEBUG Asn1Decoder - --- State = LENGTH_STATE_START ---
2015-06-10 05:10:34,832 DEBUG Asn1Decoder -   current byte : 0x01
2015-06-10 05:10:34,832 DEBUG Asn1Decoder - --- State = LENGTH_STATE_END ---
2015-06-10 05:10:34,832 DEBUG Asn1Decoder -   current byte : 0x11
2015-06-10 05:10:34,832 DEBUG Asn1Decoder - Parent length : TLV expected length stack :  -
null
2015-06-10 05:10:34,832 DEBUG Asn1Decoder - Root TLV[1]
2015-06-10 05:10:34,832 DEBUG Asn1Decoder - Length 1 has been decoded
2015-06-10 05:10:34,832 DEBUG Asn1Decoder - --- State = VALUE_STATE_START ---
2015-06-10 05:10:34,832 DEBUG Asn1Decoder -   current byte : 0x11
2015-06-10 05:10:34,832 DEBUG Asn1Decoder - --- State = TLV_STATE_DONE ---
2015-06-10 05:10:34,832 DEBUG Asn1Decoder -   current byte : 0x02
2015-06-10 05:10:34,832 DEBUG Asn1Decoder - TLV Tree : TLV0x02(1)
2015-06-10 05:10:34,832 ERROR AbstractGrammar - ERR_00001_BAD_TRANSITION_FROM_STATE Bad transition
from state START_STATE, tag 0x02
2015-06-10 05:10:34,833 WARN  KERBEROS_LOG - Error while decoding kerberos message
org.apache.directory.api.asn1.DecoderException: ERR_00001_BAD_TRANSITION_FROM_STATE Bad transition
from state START_STATE, tag 0x02
        at org.apache.directory.api.asn1.ber.grammar.AbstractGrammar.executeAction(AbstractGrammar.java:125)
        at org.apache.directory.api.asn1.ber.Asn1Decoder.treatTLVDoneState(Asn1Decoder.java:599)
        at org.apache.directory.api.asn1.ber.Asn1Decoder.decode(Asn1Decoder.java:735)
        at org.apache.directory.shared.kerberos.codec.KerberosMessageGrammar$DecodeKerberosMessage.action(KerberosMessageGrammar.java:132)
        at org.apache.directory.shared.kerberos.codec.KerberosMessageGrammar$DecodeKerberosMessage.action(KerberosMessageGrammar.java:69)
        at org.apache.directory.api.asn1.ber.grammar.AbstractGrammar.executeAction(AbstractGrammar.java:136)
        at org.apache.directory.api.asn1.ber.Asn1Decoder.treatTLVDoneState(Asn1Decoder.java:599)
        at org.apache.directory.api.asn1.ber.Asn1Decoder.decode(Asn1Decoder.java:735)
        at org.apache.directory.server.kerberos.protocol.codec.MinaKerberosDecoder.doDecode(MinaKerberosDecoder.java:97)
        at org.apache.mina.filter.codec.CumulativeProtocolDecoder.decode(CumulativeProtocolDecoder.java:178)
        at org.apache.mina.filter.codec.ProtocolCodecFilter.messageReceived(ProtocolCodecFilter.java:224)
        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)
{noformat}

Would I need to test this on top of 2.0.0-M20? I suspect that's not an issue here. Let me
know if I need to try that.

> 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)

Mime
View raw message