directory-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Sangjin Lee <sj...@apache.org>
Subject strange kerberos issue with apacheds
Date Mon, 08 Jun 2015 22:45:34 GMT
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?

Thanks in advance,
Sangjin

Mime
View raw message