Thanks Kiran! Let me try your patch and see if it works. I'm at a conference so it might be delayed a bit. I'll update the ticket.
Regards, Sangjin On Tue, Jun 9, 2015 at 1:20 AM, Kiran Ayyagari <[email protected]> wrote: > > > On Tue, Jun 9, 2015 at 12:28 PM, Sangjin Lee <[email protected]> wrote: > >> Thanks folks. I filed DIRSERVER-2071: >> https://issues.apache.org/jira/browse/DIRSERVER-2071 >> > thanks for the bug report, I have committed the fix in trunk, would it be > possible for you to give a try? > >> >> Sangjin >> >> On Mon, Jun 8, 2015 at 8:16 PM, Kiran Ayyagari <[email protected]> >> wrote: >> >>> Hi Sangjin, >>> >>> On Tue, Jun 9, 2015 at 6:45 AM, Sangjin Lee <[email protected]> wrote: >>> >>>> Hi, >>>> >>>> This might be a known issue, but I was not able to find discussions on >>>> this anywhere... >>>> >>>> I stumbled on an interesting issue with kerberos authentication failure >>>> with an Apache DS server while debugging a hadoop unit test failure. FYI, >>>> hadoop is using Apache DS 1.0.0-M20 with Mina 2.0.0-M15. This problem is >>>> happening on some machines but not on others. >>>> >>>> Basically, a kerberos message to the Apache DS server is failing with >>>> the following exception: >>>> 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 >>>> >>>> >>>> I traced it down to a rather 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: >>>> 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[... ]] >>>> >>>> >>>> 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. >>>> >>>> Having small TCP window sizes aside, this strikes me as a code issue. >>>> Shouldn't the server be able to handle the kerberos message even if it is >>>> split into multiple packets? Is this a known issue with a >>>> workaround/solution? >>>> >>>> I looked at MinaKerberosDecoder, and see it extend >>>> ProtocolDecoderAdapter. But shouldn't it extend CumulativeProtocolDecoder >>>> to be able to handle situations like this? >>>> >>> the current ASN.1 decoder is supposed to handle this case, can you file >>> a bug, I will take a look >>> >>>> >>>> Thanks in advance, >>>> Sangjin >>>> >>> >>> >>> >>> -- >>> Kiran Ayyagari >>> http://keydap.com >>> >> >> > > > -- > Kiran Ayyagari > http://keydap.com >
