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
