[
https://issues.apache.org/jira/browse/DIRSERVER-2071?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14580887#comment-14580887
]
Sangjin Lee commented on DIRSERVER-2071:
----------------------------------------
OK, I applied the patch on top of M20, and tried it, and it's still failing.
The ASN.1 decoding is proceeding further, but it still fails with a NPE. The
following is the entire log for this request:
{noformat}
2015-06-10 17:49:54,816 DEBUG Asn1Decoder -
>>>==========================================
2015-06-10 17:49:54,817 DEBUG Asn1Decoder - --> Decoding a PDU
2015-06-10 17:49:54,817 DEBUG Asn1Decoder -
>>>------------------------------------------
2015-06-10 17:49:54,817 DEBUG Asn1Decoder - --- State = TAG_STATE_START ---
2015-06-10 17:49:54,817 DEBUG Asn1Decoder - current byte : 0x6C
2015-06-10 17:49:54,817 DEBUG Asn1Decoder - Tag 0x6C has been decoded
2015-06-10 17:49:54,817 DEBUG Asn1Decoder - --- State = LENGTH_STATE_START ---
2015-06-10 17:49:54,817 DEBUG Asn1Decoder - current byte : 0x82
2015-06-10 17:49:54,817 DEBUG Asn1Decoder - --- State = LENGTH_STATE_PENDING ---
2015-06-10 17:49:54,817 DEBUG Asn1Decoder - current byte : 0x02
2015-06-10 17:49:54,817 DEBUG Asn1Decoder - current byte : 0x02
2015-06-10 17:49:54,817 DEBUG Asn1Decoder - current byte : 0x40
2015-06-10 17:49:54,817 DEBUG Asn1Decoder - --- State = LENGTH_STATE_END ---
2015-06-10 17:49:54,817 DEBUG Asn1Decoder - current byte : 0x30
2015-06-10 17:49:54,817 DEBUG Asn1Decoder - Parent length : TLV expected length
stack : - null
2015-06-10 17:49:54,817 DEBUG Asn1Decoder - Root TLV[576]
2015-06-10 17:49:54,817 DEBUG Asn1Decoder - Length 576 has been decoded
2015-06-10 17:49:54,817 DEBUG Asn1Decoder - --- State = VALUE_STATE_START ---
2015-06-10 17:49:54,817 DEBUG Asn1Decoder - current byte : 0x30
2015-06-10 17:49:54,817 DEBUG Asn1Decoder -
<<<------------------------------------------
2015-06-10 17:49:54,817 DEBUG Asn1Decoder - <-- End decoding : TLV[ 0x6C, 576,
DATA[0x30 0x82 0x02 0x3C 0xA1 0x03 0x02 0x01 0x05 0xA2 0x03 0x02 0x01 0x0C 0xA3
0x82 0x01 0xC3 0x30 0x82 0x01 0xBF 0x30 0x82 0x01 0xBB 0xA1 0x03 0x02 0x01 0x01
0xA2 0x82 0x01 0xB2 0x04 0x82 0x01 0xAE 0x6E 0x82 0x01 0xAA 0x30 0x82 0x01 0xA6
0xA0 0x03 0x02 0x01 0x05 0xA1 0x03 0x02 0x01 0x0E 0xA2 0x07 0x03 0x05 0x00 0x00
0x00 0x00 0x00 0xA3 0x81 0xFF 0x61 0x81 0xFC 0x30 0x81 0xF9 0xA0 0x03 0x02 0x01
0x05 0xA1 0x0D 0x1B 0x0B 0x45 0x58 0x41 0x4D 0x50 0x4C 0x45 0x2E 0x43 0x4F 0x4D
0xA2 0x20 0x30 0x1E 0xA0 0x03 0x02 0x01 0x02 0xA1 0x17 0x30 0x15 0x1B 0x06 0x6B
0x72 0x62 0x74 0x67 0x74 0x1B 0x0B 0x45 0x58 0x41 0x4D 0x50 0x4C 0x45 0x2E 0x43
0x4F 0x4D 0xA3 0x81 0xC0 0x30 0x81 0xBD 0xA0 0x03 0x02 0x01 0x11 0xA2 0x81 0xB5
0x04 0x81 0xB2 0x1B 0x4F 0x25 0x0D 0x0B 0x98 0x63 0x1F 0x9B 0x68 0x45 0x03 0xCE
0x09 0x0E 0x3C 0x2D 0x37 0x0F 0xCD 0xCE 0xF4 0xDD 0xEE 0x82 0x0E 0xF0 0xBE 0xA7
0x04 0x07 0xA7 0x1C 0xB8 0x2F 0xB0 0xD8 0x65 0x7C 0xE9 0x2C 0x35 0x70 0x82 0x95
0x9D 0xB3 0x64 0x70 0x90 0x46 0x60 0xF8 0x44 0x83 0x45 0xBF 0x89 0xBC 0xCF 0x66
0x4E 0x2A 0xAF 0x6B 0x05 0x27 0xD3 0x1A 0xCC 0x5A 0x97 0x83 0x46 0x85 0xA4 0xF2
0xD9 0xD7 0x94 0x1C 0x14 0xF6 0xEB 0x17 0xF9 0xD8 0x64 0x2C 0x65 0xF7 0x20 0xA8
0x20 0x47 0xD1 0x50 0x51 0x28 0x9F 0xD1 0x14 0x0C 0x36 0x4E 0x85 0x4F 0xD5 0x43
0xED 0x24 0xD8 0x93 0x4A 0xBC 0xDE 0xD8 0xEE 0xA7 0xC9 0x44 0x0A 0x16 0x2D 0x13
0x5A 0x2D 0x3E 0xE9 0xAE 0xA8 0xDA 0xBF 0xC2 0x8E 0x03 0x19 0x86 0x7B 0xC5 0x9D
0x98 0x80 0xA2 0xC8 0x56 0xCF 0x4F 0x6F 0xDB 0xA2 0x0F 0xB0 0x78 0x50 0x86 0x4A
0x13 0x21 0x8E 0xA6 0x73 0x63 0x7F 0x86 0x89 0xFC 0x67 0x6E 0xC5 0xE9 0xEB 0x82
0x9A 0x88 0xD0 0xEB 0x8D 0xA4 0x81 0x8E 0x30 0x81 0x8B 0xA0 0x03 0x02 0x01 0x11
0xA2 0x81 0x83 0x04 0x81 0x80 0x90 0xF4 0x12 0xE5 0xA5 0x29 0x51 0x86 0xDD 0x0C
0xD8 0xE7 0x5C 0xA3 0x8B 0xE4 0x7A 0x62 0x72 0x86 0xC5 0x55 0x6C 0xAF 0x44 0xDE
0x7B 0x1C 0x27 0x34 0x95 0x91 0xDD 0x49 0x00 0x09 0x52 0x17 0xAF 0x02 0x42 0x5D
0x72 0xF2 0x99 0xC3 0xFA 0x1F 0x2E 0x27 0x2B 0x7C 0x4F 0x1F 0xC7 0x26 0x08 0xF3
0xE2 0x33 0x24 0x7F 0x5A 0xAA 0x29 0x3A 0xC4 0xB4 0x0B 0x4C 0xC1 0x36 0x85 0x58
0x24 0xBC 0xC3 0x9A 0x4B 0xD9 0xBE 0xBB 0xC6 0xA6 0x98 0x12 0xB9 0x7A 0x05 0x32
0x06 0x46 0xFE 0xA4 0xC2 0x1A 0xF0 0x24 0xA9 0x50 0xCC 0xD5 0x78 0x57 0xBA 0xFB
0x57 0x16 0x4E 0x17 0x8D 0xA7 0x2F 0x19 0xC9 0xCF 0x8A 0x70 0x5B 0x4D 0x7F 0x42
0xA0 0x1B 0x0D 0x39 0x2D 0x36 0xA4 0x69 0x30 0x67 0xA0 0x07 0x03 0x05 0x00 0x00
0x00 0x00 0x00 0xA2 0x0D 0x1B 0x0B 0x45 0x58 0x41 0x4D 0x50 0x4C 0x45 0x2E 0x43
0x4F 0x4D 0xA3 0x1C 0x30 0x1A 0xA0 0x03 0x02 0x01 0x00 0xA1 0x13 0x30 0x11 0x1B
0x04 0x48 0x54 0x54 0x50 0x1B 0x09 0x6C 0x6F 0x63 0x61 0x6C 0x68 0x6F 0x73 0x74
0xA5 0x11 0x18 0x0F 0x31 0x39 0x37 0x30 0x30 0x31 0x30 0x31 0x30 0x30 0x30 0x30
0x30 0x30 0x5A 0xA7 0x06 0x02 0x04 0x3C 0x13 0x04 0xD7 0xA8 0x14 0x30 0x12 0x02
0x01 0x12 0x02 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
0x00 ]]
2015-06-10 17:49:54,817 DEBUG Asn1Decoder -
<<<==========================================
2015-06-10 17:49:55,017 DEBUG Asn1Decoder -
>>>==========================================
2015-06-10 17:49:55,017 DEBUG Asn1Decoder - --> Decoding a PDU
2015-06-10 17:49:55,017 DEBUG Asn1Decoder -
>>>------------------------------------------
2015-06-10 17:49:55,017 DEBUG Asn1Decoder - --- State = VALUE_STATE_PENDING ---
2015-06-10 17:49:55,017 DEBUG Asn1Decoder - current byte : 0x01
2015-06-10 17:49:55,017 DEBUG Asn1Decoder - --- State = TLV_STATE_DONE ---
2015-06-10 17:49:55,017 DEBUG Asn1Decoder - no more byte to decode in the
stream
2015-06-10 17:49:55,017 DEBUG Asn1Decoder - TLV Tree : TLV0x6C(576)
2015-06-10 17:49:55,017 DEBUG AbstractGrammar - Transition from state
<START_STATE> to state <TGS_REQ_TAG_STATE>, tag <0x6C>, action : null
2015-06-10 17:49:55,019 DEBUG Asn1Decoder -
>>>==========================================
2015-06-10 17:49:55,019 DEBUG Asn1Decoder - --> Decoding a PDU
2015-06-10 17:49:55,019 DEBUG Asn1Decoder -
>>>------------------------------------------
2015-06-10 17:49:55,019 DEBUG Asn1Decoder - --- State = TAG_STATE_START ---
2015-06-10 17:49:55,019 DEBUG Asn1Decoder - current byte : 0x01
2015-06-10 17:49:55,019 DEBUG Asn1Decoder - Tag 0x01 has been decoded
2015-06-10 17:49:55,019 DEBUG Asn1Decoder - --- State = LENGTH_STATE_START ---
2015-06-10 17:49:55,019 DEBUG Asn1Decoder - current byte : 0x11
2015-06-10 17:49:55,019 DEBUG Asn1Decoder - --- State = LENGTH_STATE_END ---
2015-06-10 17:49:55,019 DEBUG Asn1Decoder - current byte : 0x02
2015-06-10 17:49:55,019 DEBUG Asn1Decoder - Parent length : TLV expected length
stack : - null
2015-06-10 17:49:55,019 DEBUG Asn1Decoder - Root TLV[17]
2015-06-10 17:49:55,019 DEBUG Asn1Decoder - Length 17 has been decoded
2015-06-10 17:49:55,019 DEBUG Asn1Decoder - --- State = VALUE_STATE_START ---
2015-06-10 17:49:55,020 DEBUG Asn1Decoder - current byte : 0x02
2015-06-10 17:49:55,020 DEBUG Asn1Decoder -
<<<------------------------------------------
2015-06-10 17:49:55,020 DEBUG Asn1Decoder - <-- End decoding : TLV[ 0x01, 17,
DATA[0x02 0x01 0x10 0x02 0x01 0x17 0x02 0x01 0x01 0x02 0x01 0x03 0x00 0x00 0x00
0x00 0x00 ]]
2015-06-10 17:49:55,020 DEBUG Asn1Decoder -
<<<==========================================
2015-06-10 17:49:55,020 DEBUG KerberosMessageGrammar - Decoded KerberosMessage
null
2015-06-10 17:49:55,020 DEBUG Asn1Decoder -
<<<------------------------------------------
2015-06-10 17:49:55,020 DEBUG Asn1Decoder - <-- Stop decoding : TLV[ 0x6C, 576,
DATA[0x30 0x82 0x02 0x3C 0xA1 0x03 0x02 0x01 0x05 0xA2 0x03 0x02 0x01 0x0C 0xA3
0x82 0x01 0xC3 0x30 0x82 0x01 0xBF 0x30 0x82 0x01 0xBB 0xA1 0x03 0x02 0x01 0x01
0xA2 0x82 0x01 0xB2 0x04 0x82 0x01 0xAE 0x6E 0x82 0x01 0xAA 0x30 0x82 0x01 0xA6
0xA0 0x03 0x02 0x01 0x05 0xA1 0x03 0x02 0x01 0x0E 0xA2 0x07 0x03 0x05 0x00 0x00
0x00 0x00 0x00 0xA3 0x81 0xFF 0x61 0x81 0xFC 0x30 0x81 0xF9 0xA0 0x03 0x02 0x01
0x05 0xA1 0x0D 0x1B 0x0B 0x45 0x58 0x41 0x4D 0x50 0x4C 0x45 0x2E 0x43 0x4F 0x4D
0xA2 0x20 0x30 0x1E 0xA0 0x03 0x02 0x01 0x02 0xA1 0x17 0x30 0x15 0x1B 0x06 0x6B
0x72 0x62 0x74 0x67 0x74 0x1B 0x0B 0x45 0x58 0x41 0x4D 0x50 0x4C 0x45 0x2E 0x43
0x4F 0x4D 0xA3 0x81 0xC0 0x30 0x81 0xBD 0xA0 0x03 0x02 0x01 0x11 0xA2 0x81 0xB5
0x04 0x81 0xB2 0x1B 0x4F 0x25 0x0D 0x0B 0x98 0x63 0x1F 0x9B 0x68 0x45 0x03 0xCE
0x09 0x0E 0x3C 0x2D 0x37 0x0F 0xCD 0xCE 0xF4 0xDD 0xEE 0x82 0x0E 0xF0 0xBE 0xA7
0x04 0x07 0xA7 0x1C 0xB8 0x2F 0xB0 0xD8 0x65 0x7C 0xE9 0x2C 0x35 0x70 0x82 0x95
0x9D 0xB3 0x64 0x70 0x90 0x46 0x60 0xF8 0x44 0x83 0x45 0xBF 0x89 0xBC 0xCF 0x66
0x4E 0x2A 0xAF 0x6B 0x05 0x27 0xD3 0x1A 0xCC 0x5A 0x97 0x83 0x46 0x85 0xA4 0xF2
0xD9 0xD7 0x94 0x1C 0x14 0xF6 0xEB 0x17 0xF9 0xD8 0x64 0x2C 0x65 0xF7 0x20 0xA8
0x20 0x47 0xD1 0x50 0x51 0x28 0x9F 0xD1 0x14 0x0C 0x36 0x4E 0x85 0x4F 0xD5 0x43
0xED 0x24 0xD8 0x93 0x4A 0xBC 0xDE 0xD8 0xEE 0xA7 0xC9 0x44 0x0A 0x16 0x2D 0x13
0x5A 0x2D 0x3E 0xE9 0xAE 0xA8 0xDA 0xBF 0xC2 0x8E 0x03 0x19 0x86 0x7B 0xC5 0x9D
0x98 0x80 0xA2 0xC8 0x56 0xCF 0x4F 0x6F 0xDB 0xA2 0x0F 0xB0 0x78 0x50 0x86 0x4A
0x13 0x21 0x8E 0xA6 0x73 0x63 0x7F 0x86 0x89 0xFC 0x67 0x6E 0xC5 0xE9 0xEB 0x82
0x9A 0x88 0xD0 0xEB 0x8D 0xA4 0x81 0x8E 0x30 0x81 0x8B 0xA0 0x03 0x02 0x01 0x11
0xA2 0x81 0x83 0x04 0x81 0x80 0x90 0xF4 0x12 0xE5 0xA5 0x29 0x51 0x86 0xDD 0x0C
0xD8 0xE7 0x5C 0xA3 0x8B 0xE4 0x7A 0x62 0x72 0x86 0xC5 0x55 0x6C 0xAF 0x44 0xDE
0x7B 0x1C 0x27 0x34 0x95 0x91 0xDD 0x49 0x00 0x09 0x52 0x17 0xAF 0x02 0x42 0x5D
0x72 0xF2 0x99 0xC3 0xFA 0x1F 0x2E 0x27 0x2B 0x7C 0x4F 0x1F 0xC7 0x26 0x08 0xF3
0xE2 0x33 0x24 0x7F 0x5A 0xAA 0x29 0x3A 0xC4 0xB4 0x0B 0x4C 0xC1 0x36 0x85 0x58
0x24 0xBC 0xC3 0x9A 0x4B 0xD9 0xBE 0xBB 0xC6 0xA6 0x98 0x12 0xB9 0x7A 0x05 0x32
0x06 0x46 0xFE 0xA4 0xC2 0x1A 0xF0 0x24 0xA9 0x50 0xCC 0xD5 0x78 0x57 0xBA 0xFB
0x57 0x16 0x4E 0x17 0x8D 0xA7 0x2F 0x19 0xC9 0xCF 0x8A 0x70 0x5B 0x4D 0x7F 0x42
0xA0 0x1B 0x0D 0x39 0x2D 0x36 0xA4 0x69 0x30 0x67 0xA0 0x07 0x03 0x05 0x00 0x00
0x00 0x00 0x00 0xA2 0x0D 0x1B 0x0B 0x45 0x58 0x41 0x4D 0x50 0x4C 0x45 0x2E 0x43
0x4F 0x4D 0xA3 0x1C 0x30 0x1A 0xA0 0x03 0x02 0x01 0x00 0xA1 0x13 0x30 0x11 0x1B
0x04 0x48 0x54 0x54 0x50 0x1B 0x09 0x6C 0x6F 0x63 0x61 0x6C 0x68 0x6F 0x73 0x74
0xA5 0x11 0x18 0x0F 0x31 0x39 0x37 0x30 0x30 0x31 0x30 0x31 0x30 0x30 0x30 0x30
0x30 0x30 0x5A 0xA7 0x06 0x02 0x04 0x3C 0x13 0x04 0xD7 0xA8 0x14 0x30 0x12 0x02
0x01 0x12 0x02 0x01 0x11 0x02 0x01 0x10 0x02 0x01 0x17 0x02 0x01 0x01 0x02 0x01
0x03 ]]
2015-06-10 17:49:55,020 DEBUG Asn1Decoder -
<<<==========================================
2015-06-10 17:49:55,020 DEBUG KERBEROS_LOG - Decoded KerberosMessage : null
2015-06-10 17:49:55,021 ERROR KerberosProtocolHandler - /127.0.0.1:37765
EXCEPTION
org.apache.mina.filter.codec.ProtocolDecoderException:
java.lang.NullPointerException: message (Hexdump: 01 11 02 01 10 02 01 17 02 01
01 02 01 03)
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.doDecode(MinaKerberosDecoder.java:107)
at
org.apache.mina.filter.codec.CumulativeProtocolDecoder.decode(CumulativeProtocolDecoder.java:178)
at
org.apache.mina.filter.codec.ProtocolCodecFilter.messageReceived(ProtocolCodecFilter.java:224)
... 15 more
{noformat}
It looks like Asn1Decoder didn't populate the message in the container.
> MinaKerberosDecoder fails with NullPointerException if the kerberos message
> is split in multiple packets
> --------------------------------------------------------------------------------------------------------
>
> Key: DIRSERVER-2071
> URL: https://issues.apache.org/jira/browse/DIRSERVER-2071
> Project: Directory ApacheDS
> Issue Type: Bug
> Components: asn1
> Affects Versions: 2.0.0-M15
> Reporter: Sangjin Lee
> Assignee: Kiran Ayyagari
> Fix For: 2.0.0-M21
>
>
> On some machines (but not all), kerberos authentication to Apache DS is
> consistently failing with a NullPointerException:
> {noformat}
> 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
> {noformat}
> I traced it down to a 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:
> {noformat}
> 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[... ]]
> {noformat}
> 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. The following is
> the gist of the tcpdump capture of this TCP conversation:
> {noformat}
> 13:35:57.186758 IP localhost.54477 > localhost.40829: Flags [S], seq
> 1599306555, win 32792, options [mss 16396,sackOK,TS val 318374489 ecr
> 0,nop,wscale 8], length 0
> 13:35:57.186771 IP localhost.40829 > localhost.54477: Flags [S.], seq
> 7524064, ack 1599306556, win 1140, options [mss 16396,sackOK,TS val 318374489
> ecr 318374489,nop,wscale 0], length 0
> 13:35:57.186781 IP localhost.54477 > localhost.40829: Flags [.], ack 1, win
> 129, options [nop,nop,TS val 318374489 ecr 318374489], length 0
> 13:35:57.186903 IP localhost.54477 > localhost.40829: Flags [.], seq 1:571,
> ack 1, win 129, options [nop,nop,TS val 318374490 ecr 318374489], length 570
> 13:35:57.186909 IP localhost.40829 > localhost.54477: Flags [.], ack 571, win
> 570, options [nop,nop,TS val 318374490 ecr 318374490], length 0
> 13:35:57.186914 IP localhost.54477 > localhost.40829: Flags [P.], seq
> 571:586, ack 1, win 129, options [nop,nop,TS val 318374490 ecr 318374489],
> length 15
> 13:35:57.187519 IP localhost.40829 > localhost.54477: Flags [.], ack 571, win
> 1140, options [nop,nop,TS val 318374490 ecr 318374490], length 0
> 13:35:57.190641 IP localhost.40829 > localhost.54477: Flags [F.], seq 1, ack
> 571, win 1140, options [nop,nop,TS val 318374493 ecr 318374490], length 0
> 13:35:57.190687 IP localhost.54477 > localhost.40829: Flags [F.], seq 586,
> ack 2, win 129, options [nop,nop,TS val 318374493 ecr 318374493], length 0
> 13:35:57.190701 IP localhost.40829 > localhost.54477: Flags [R], seq 7524066,
> win 0, length 0
> {noformat}
> Having small TCP window sizes aside, this strikes me as a code issue. The
> server should be able to handle the kerberos message even if it is split into
> multiple packets.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
