Thanks Sangjin for the good report. I thought you’re right in the analysis.
I’m not familiar with the part but it looks like not easy to have a work around. Maybe we can force to use UDP transport thus bypass the problem? Regards, Kai From: [email protected] [mailto:[email protected]] On Behalf Of Sangjin Lee Sent: Tuesday, June 09, 2015 9:18 AM To: [email protected] Subject: Re: strange kerberos issue with apacheds Correction: hadoop is using Apache DS 2.0.0-M15 with Mina 2.0.0-M5. Sorry for the confusion. On Mon, Jun 8, 2015 at 3:45 PM, Sangjin Lee <[email protected]<mailto:[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<http://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? Thanks in advance, Sangjin
