You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@directory.apache.org by Sangjin Lee <sj...@apache.org> on 2015/06/09 00:45:34 UTC
strange kerberos issue with apacheds
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
Re: strange kerberos issue with apacheds
Posted by Emmanuel Lécharny <el...@gmail.com>.
Le 09/06/15 04:18, Zheng, Kai a écrit :
> 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?
That should not be a pb at all. UDP or TCP.
The KerberosDecoder should be able to handle splitted TCP messages.
RE: strange kerberos issue with apacheds
Posted by "Zheng, Kai" <ka...@intel.com>.
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: sjlee0@gmail.com [mailto:sjlee0@gmail.com] On Behalf Of Sangjin Lee
Sent: Tuesday, June 09, 2015 9:18 AM
To: dev@directory.apache.org
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 <sj...@apache.org>> 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
Re: strange kerberos issue with apacheds
Posted by Sangjin Lee <sj...@apache.org>.
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 <sj...@apache.org> 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?
>
> Thanks in advance,
> Sangjin
>
Re: strange kerberos issue with apacheds
Posted by Sangjin Lee <sj...@apache.org>.
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 <ka...@apache.org> wrote:
>
>
> On Tue, Jun 9, 2015 at 12:28 PM, Sangjin Lee <sj...@apache.org> 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 <ka...@apache.org>
>> wrote:
>>
>>> Hi Sangjin,
>>>
>>> On Tue, Jun 9, 2015 at 6:45 AM, Sangjin Lee <sj...@apache.org> 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
>
Re: strange kerberos issue with apacheds
Posted by Kiran Ayyagari <ka...@apache.org>.
On Tue, Jun 9, 2015 at 12:28 PM, Sangjin Lee <sj...@apache.org> 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 <ka...@apache.org>
> wrote:
>
>> Hi Sangjin,
>>
>> On Tue, Jun 9, 2015 at 6:45 AM, Sangjin Lee <sj...@apache.org> 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
Re: strange kerberos issue with apacheds
Posted by Sangjin Lee <sj...@apache.org>.
Thanks folks. I filed DIRSERVER-2071:
https://issues.apache.org/jira/browse/DIRSERVER-2071
Sangjin
On Mon, Jun 8, 2015 at 8:16 PM, Kiran Ayyagari <ka...@apache.org> wrote:
> Hi Sangjin,
>
> On Tue, Jun 9, 2015 at 6:45 AM, Sangjin Lee <sj...@apache.org> 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
>
Re: strange kerberos issue with apacheds
Posted by Kiran Ayyagari <ka...@apache.org>.
Hi Sangjin,
On Tue, Jun 9, 2015 at 6:45 AM, Sangjin Lee <sj...@apache.org> 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