====================
Scenraio:
====================
- A server is sending data to the MINA server which has implemented
"CumulativeProtocolDecoder"
- Server is sending x bytes
- While getting data first thread is getting data from position m instead of
position 0
- Second thread picks the data from 0 to m
- Either of the thread doesn't get the complete data and that's why protocol
decoding is failed
- Data is coming correctly to the socket as confirmed by "tcpdump logs"
- Something which is I am doing wrong or has to be taken care of? How do I
guarantee the only one thread picks up the data and in right order??
- Sorry for being little verbose, but thought it might help to give max info
in problem statement
====================
OS/Etc:
====================
Centos 6
Apache MINA 2.0.4
java version "1.6.0_17"
OpenJDK Runtime Environment (IcedTea6 1.7.5) (rhel-1.16.b17.el5-x86_64)
OpenJDK 64-Bit Server VM (build 14.0-b16, mixed mode)
====================
MINA LOGS:
====================
(2011-10-12
14:18:01,039)(pool-3-thread-45)(DEBUG)(IoFilterEvent.java)(fire)(69)--Firing
a MESSAGE_SENT event for session 35
(2011-10-12
14:18:01,039)(pool-3-thread-44)(DEBUG)(IoFilterEvent.java)(fire)(118)--Event
MESSAGE_RECEIVED has been fired for session 35
(2011-10-12
14:18:01,039)(pool-3-thread-45)(INFO)(LoggingFilter.java)(log)(141)--SENT:
HeapBuffer[pos=0 lim=0 cap=0: empty]
(2011-10-12
14:18:01,039)(pool-3-thread-45)(DEBUG)(IoFilterEvent.java)(fire)(118)--Event
MESSAGE_SENT has been fired for session 35
(2011-10-12
14:18:03,039)(pool-3-thread-45)(DEBUG)(IoFilterEvent.java)(fire)(69)--Firing
a SESSION_IDLE event for session 98
(2011-10-12
14:18:03,039)(pool-3-thread-45)(INFO)(LoggingFilter.java)(log)(159)--IDLE
(2011-10-12
14:18:03,039)(pool-3-thread-45)(DEBUG)(IoFilterEvent.java)(fire)(118)--Event
SESSION_IDLE has been fired for session 98
(2011-10-12
14:18:04,589)(pool-3-thread-45)(DEBUG)(IoFilterEvent.java)(fire)(69)--Firing
a MESSAGE_RECEIVED event for session 35
(2011-10-12
14:18:04,589)(pool-3-thread-44)(DEBUG)(IoFilterEvent.java)(fire)(69)--Firing
a MESSAGE_RECEIVED event for session 35
(2011-10-12
14:18:04,590)(pool-3-thread-44)(INFO)(LoggingFilter.java)(log)(141)--RECEIVE
D: HeapBuffer[pos=0 lim=86 cap=256: 10 09 00 00 10 10 00 00 10 11 00 00 10
12 00 00...]
(2011-10-12
14:18:04,590)(pool-3-thread-44)(DEBUG)(ProtocolCodecFilter.java)(messageRece
ived)(220)--Processing a MESSAGE_RECEIVED for session 35
(2011-10-12
14:18:04,590)(pool-3-thread-44)(ERROR)(NewCentralDecoder.java)(doDecode)(30)
--in.remaining()=86
(2011-10-12
14:18:04,589)(pool-3-thread-45)(INFO)(LoggingFilter.java)(log)(141)--RECEIVE
D: HeapBuffer[pos=0 lim=128 cap=128: 00 D4 60 07 92 80 88 00 CD 01 01 60 07
92 00 00...]
(2011-10-12
14:18:04,590)(pool-3-thread-44)(ERROR)(NewCentralDecoder.java)(doDecode)(31)
--markValue()=-1
(2011-10-12
14:18:04,590)(pool-3-thread-44)(ERROR)(NewCentralDecoder.java)(doDecode)(32)
--capacity()=256
(2011-10-12
14:18:04,590)(pool-3-thread-44)(DEBUG)(NewCentralDecoder.java)(doDecode)(36)
--At TOP Remaining=86
(2011-10-12
14:18:04,591)(pool-3-thread-44)(ERROR)(NewCentralDecoder.java)(doDecode)(60)
--in.remaining()=86
(2011-10-12
14:18:04,592)(pool-3-thread-44)(ERROR)(NewCentralDecoder.java)(doDecode)(61)
--markValue()=-1
(2011-10-12
14:18:04,592)(pool-3-thread-44)(ERROR)(NewCentralDecoder.java)(doDecode)(62)
--capacity()=256
(2011-10-12
14:18:04,590)(pool-3-thread-45)(DEBUG)(ProtocolCodecFilter.java)(messageRece
ived)(220)--Processing a MESSAGE_RECEIVED for session 35
(2011-10-12
14:18:04,592)(pool-3-thread-44)(TRACE)(NewCentralDecoder.java)(doDecode)(64)
--session.getCreationTime()=Wed Oct 12 12:22:12 IST 2011
(2011-10-12
14:18:04,592)(pool-3-thread-44)(TRACE)(NewCentralDecoder.java)(doDecode)(66)
--getId()=35
(2011-10-12
14:18:04,593)(pool-3-thread-44)(TRACE)(NewCentralDecoder.java)(doDecode)(70)
--getLastIoTime()=Wed Oct 12 14:18:04 IST 2011
(2011-10-12
14:18:04,593)(pool-3-thread-44)(TRACE)(NewCentralDecoder.java)(doDecode)(71)
--getLastReaderIdleTime()=Wed Oct 12 12:22:12 IST 2011
(2011-10-12
14:18:04,593)(pool-3-thread-44)(TRACE)(NewCentralDecoder.java)(doDecode)(72)
--getLastReadTime()=1318409284589
(2011-10-12
14:18:04,593)(pool-3-thread-44)(TRACE)(NewCentralDecoder.java)(doDecode)(73)
--getLastWriterIdleTime()=Wed Oct 12 12:22:12 IST 2011
(2011-10-12
14:18:04,593)(pool-3-thread-44)(TRACE)(NewCentralDecoder.java)(doDecode)(74)
--getLastWriteTime()=Wed Oct 12 14:18:01 IST 2011
(2011-10-12
14:18:04,593)(pool-3-thread-44)(TRACE)(NewCentralDecoder.java)(doDecode)(75)
--getLocalAddress()=/192.168.101.48:8279
(2011-10-12
14:18:04,594)(pool-3-thread-44)(TRACE)(NewCentralDecoder.java)(doDecode)(76)
--getRemoteAddress()=/121.242.8.166:8974
(2011-10-12
14:18:04,594)(pool-3-thread-44)(TRACE)(NewCentralDecoder.java)(doDecode)(80)
--getReadMessages()=8
(2011-10-12
14:18:04,594)(pool-3-thread-44)(TRACE)(NewCentralDecoder.java)(doDecode)(84)
--getWrittenBytes()=715
(2011-10-12
14:18:04,594)(pool-3-thread-44)(TRACE)(NewCentralDecoder.java)(doDecode)(86)
--getWrittenMessages()=8
(2011-10-12
14:18:04,594)(pool-3-thread-44)(TRACE)(NewCentralDecoder.java)(doDecode)(91)
--INSIDE HEADER 2 bytes
(2011-10-12
14:18:04,594)(pool-3-thread-44)(TRACE)(NewCentralDecoder.java)(doDecode)(97)
--remainingBytes <= 2048
(2011-10-12
14:18:04,595)(pool-3-thread-44)(ERROR)(NewCentralDecoder.java)(doDecode)(166
)--This is really a bad packet closing the connection, shall never happen
(2011-10-12
14:18:04,596)(pool-3-thread-44)(ERROR)(NewCentralDecoder.java)(doDecode)(182
)--Session closed, in buffer cleared
(2011-10-12
14:18:04,597)(pool-3-thread-45)(ERROR)(NewCentralDecoder.java)(doDecode)(30)
--in.remaining()=128
(2011-10-12
14:18:04,597)(pool-3-thread-45)(ERROR)(NewCentralDecoder.java)(doDecode)(31)
--markValue()=-1
(2011-10-12
14:18:04,597)(pool-3-thread-45)(ERROR)(NewCentralDecoder.java)(doDecode)(32)
--capacity()=128
(2011-10-12
14:18:04,597)(pool-3-thread-45)(DEBUG)(NewCentralDecoder.java)(doDecode)(36)
--At TOP Remaining=128
(2011-10-12
14:18:04,598)(pool-3-thread-45)(ERROR)(NewCentralDecoder.java)(doDecode)(60)
--in.remaining()=128
(2011-10-12
14:18:04,598)(pool-3-thread-45)(ERROR)(NewCentralDecoder.java)(doDecode)(61)
--markValue()=-1
(2011-10-12
14:18:04,598)(pool-3-thread-45)(ERROR)(NewCentralDecoder.java)(doDecode)(62)
--capacity()=128
(2011-10-12
14:18:04,598)(pool-3-thread-45)(TRACE)(NewCentralDecoder.java)(doDecode)(63)
--logging session info for all requests coming to decoder
(2011-10-12
14:18:04,597)(pool-3-thread-46)(DEBUG)(IoFilterEvent.java)(fire)(69)--Firing
a SESSION_CLOSED event for session 35
(2011-10-12
14:18:04,599)(pool-3-thread-45)(TRACE)(NewCentralDecoder.java)(doDecode)(64)
--session.getCreationTime()=Wed Oct 12 12:22:12 IST 2011
(2011-10-12
14:18:04,599)(pool-3-thread-45)(TRACE)(NewCentralDecoder.java)(doDecode)(66)
--getId()=35
(2011-10-12
14:18:04,599)(pool-3-thread-46)(INFO)(LoggingFilter.java)(log)(159)--CLOSED
(2011-10-12
14:18:04,599)(pool-3-thread-45)(TRACE)(NewCentralDecoder.java)(doDecode)(70)
--getLastIoTime()=Wed Oct 12 14:18:04 IST 2011
(2011-10-12
14:18:04,599)(pool-3-thread-46)(ERROR)(CentralMessageHandler.java)(sessionCl
osed)(80)--session closed
(2011-10-12
14:18:04,599)(pool-3-thread-45)(TRACE)(NewCentralDecoder.java)(doDecode)(71)
--getLastReaderIdleTime()=Wed Oct 12 12:22:12 IST 2011
(2011-10-12
14:18:04,600)(pool-3-thread-45)(TRACE)(NewCentralDecoder.java)(doDecode)(72)
--getLastReadTime()=1318409284589
(2011-10-12
14:18:04,600)(pool-3-thread-46)(DEBUG)(IoFilterEvent.java)(fire)(118)--Event
SESSION_CLOSED has been fired for session 35
(2011-10-12
14:18:04,600)(pool-3-thread-45)(TRACE)(NewCentralDecoder.java)(doDecode)(73)
--getLastWriterIdleTime()=Wed Oct 12 12:22:12 IST 2011
(2011-10-12
14:18:04,600)(pool-3-thread-45)(TRACE)(NewCentralDecoder.java)(doDecode)(74)
--getLastWriteTime()=Wed Oct 12 14:18:01 IST 2011
(2011-10-12
14:18:04,600)(pool-3-thread-45)(TRACE)(NewCentralDecoder.java)(doDecode)(75)
--getLocalAddress()=/192.168.101.48:8279
(2011-10-12
14:18:04,601)(pool-3-thread-45)(TRACE)(NewCentralDecoder.java)(doDecode)(76)
--getRemoteAddress()=null
(2011-10-12
14:18:04,601)(pool-3-thread-45)(TRACE)(NewCentralDecoder.java)(doDecode)(80)
--getReadMessages()=8
(2011-10-12
14:18:04,601)(pool-3-thread-45)(TRACE)(NewCentralDecoder.java)(doDecode)(84)
--getWrittenBytes()=715
(2011-10-12
14:18:04,601)(pool-3-thread-45)(TRACE)(NewCentralDecoder.java)(doDecode)(86)
--getWrittenMessages()=8
(2011-10-12
14:18:04,601)(pool-3-thread-45)(TRACE)(NewCentralDecoder.java)(doDecode)(91)
--INSIDE HEADER 2 bytes
(2011-10-12
14:18:04,601)(pool-3-thread-45)(TRACE)(NewCentralDecoder.java)(doDecode)(97)
--remainingBytes <= 2048
(2011-10-12
14:18:04,602)(pool-3-thread-45)(TRACE)(NewCentralDecoder.java)(doDecode)(108
)--
(2011-10-12
14:18:04,600)(pool-3-thread-44)(ERROR)(CentralMessageHandler.java)(exception
Caught)(29)--I GOT AN ERROR3 HERE....
(2011-10-12
14:18:04,604)(pool-3-thread-44)(ERROR)(CentralMessageHandler.java)(exception
Caught)(31)--Found a suspect txn, abrupt disconnection from terminal
(2011-10-12
14:18:04,604)(pool-3-thread-45)(TRACE)(NewCentralDecoder.java)(doDecode)(311
)--PartialData=null
(2011-10-12
14:18:04,605)(pool-3-thread-45)(ERROR)(NewCentralDecoder.java)(doDecode)(321
)--got the bytes but are not enough as per the len thats why reading the
data and adding it to prevBytes
(2011-10-12
14:18:04,605)(pool-3-thread-45)(DEBUG)(IoFilterEvent.java)(fire)(118)--Event
MESSAGE_RECEIVED has been fired for session 35
(2011-10-12
14:18:04,604)(pool-3-thread-44)(ERROR)(CentralMessageHandler.java)(exception
Caught)(34)--org.apache.mina.filter.codec.ProtocolDecoderException:
java.lang.Exception: Invalid data with invalid TPDU (Hexdump: 10 09 00 00 10
10 00 00 10 11 00 00 10 12 00 00 10 13 00 00 10 14 00 00 10 15 00 00 10 16
00 00 10 18 00 00 10 19 00 00 10 20 00 00 10 21 00 00 10 22 00 00 10 24 00
00 10 25 00 00 10 26 00 00 10 30 00 00 10 31 00 00 10 33 00 00 10 34 64 34
36 38 30 39 34 34 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
00)
(2011-10-12
14:18:04,607)(pool-3-thread-44)(DEBUG)(IoFilterEvent.java)(fire)(118)--Event
MESSAGE_RECEIVED has been fired for session 35
(2011-10-12
14:18:04,708)(pool-3-thread-44)(DEBUG)(IoFilterEvent.java)(fire)(69)--Firing
a SESSION_IDLE event for session 1
(2011-10-12
14:18:04,708)(pool-3-thread-44)(INFO)(LoggingFilter.java)(log)(159)--IDLE
(2011-10-12
14:18:04,708)(pool-3-thread-44)(DEBUG)(IoFilterEvent.java)(fire)(118)--Event
SESSION_IDLE has been fired for session 1
(2011-10-12
14:18:05,072)(pool-3-thread-44)(DEBUG)(IoFilterEvent.java)(fire)(69)--Firing
a SESSION_IDLE event for session 105
(2011-10-12
14:18:05,072)(pool-3-thread-44)(INFO)(LoggingFilter.java)(log)(159)--IDLE
(2011-10-12
14:18:05,072)(pool-3-thread-44)(DEBUG)(IoFilterEvent.java)(fire)(118)--Event
SESSION_IDLE has been fired for session 105
==========================================
TCPDUMP:
==========================================
0000 44 87 fc f5 a7 82 00 15 17 b0 71 aa 08 00 45 00 D....... ..q...E.
0010 00 fe 00 00 00 00 35 06 dc 89 79 f2 08 a6 c0 a8 ......5. ..y.....
0020 65 30 23 0e 20 57 d5 05 86 4d 75 ca 8c 1f 50 18 e0#. W.. .Mu...P.
0030 08 00 a9 73 00 00 00 d4 60 07 92 80 88 00 cd 01 ...s.... `.......
0040 01 60 07 92 00 00 00 c4 03 20 20 10 01 00 04 80 .`...... . .....
0050 60 29 96 01 20 12 10 11 12 15 12 07 92 31 30 31 `).. ... .....101
0060 30 31 31 00 00 00 00 99 00 10 04 31 32 33 34 04 011..... ...1234.
0070 31 32 33 34 00 20 6a 1e 26 b4 26 76 45 f4 c0 ec 1234. j. &.&vE...
0080 bf 04 72 ca ba 9c 81 89 fb 4e 00 14 08 37 30 34 ..r..... .N...704
0090 35 34 32 39 30 04 30 32 32 32 01 04 00 00 10 01 54290.02 22......
00a0 00 00 10 02 00 00 10 03 00 00 10 04 00 00 10 07 ........ ........
00b0 00 00 10 08 00 00 10 09 00 00 10 10 00 00 10 11 ........ ........
00c0 00 00 10 12 00 00 10 13 00 00 10 14 00 00 10 15 ........ ........
00d0 00 00 10 16 00 00 10 18 00 00 10 19 00 00 10 20 ........ .......
00e0 00 00 10 21 00 00 10 22 00 00 10 24 00 00 10 25 ...!..." ...$...%
00f0 00 00 10 26 00 00 10 30 00 00 10 31 00 00 10 33 ...&...0 ...1...3
0100 00 00 10 34 64 34 36 38 30 39 34 34 ...4d468 0944
====================
Code Snippet:
====================
DECODER
-------------------------------------------------------
public class NewCentralDecoder extends CumulativeProtocolDecoder {
private static final String DECODER_STATE_KEY =
NewCentralDecoder.class.getName() + ".STATE";
@Override
protected boolean doDecode(org.apache.mina.core.session.IoSession
session,
IoBuffer in, ProtocolDecoderOutput out) throws
Exception {
//get the number of bytes which are available to read
int remainingBytes = in.remaining();
logger.error("in.remaining()="+in.remaining());
logger.error("markValue()="+in.markValue());
logger.error("capacity()="+in.capacity());
LISTENER
-------------------------------------------------------
public static void main(String[] args) throws IOException,Exception {
IoBuffer.setUseDirectBuffer(false);
IoAcceptor acceptor = new NioSocketAcceptor();
acceptor.getFilterChain().addLast("threadPool", new
ExecutorFilter(Executors.newCachedThreadPool()));
acceptor.getFilterChain().addLast( "logger", new LoggingFilter()
);//setLogLevel(IoEventType, LogLevel)//(SESSION_CREATED,TRACE)
acceptor.getFilterChain().addLast( "logging", new LoggingFilter() );
acceptor.getFilterChain().addLast( "codec", new ProtocolCodecFilter(
new CentralCodecFactory(false)));
acceptor.getSessionConfig().setReadBufferSize( 2048 );
acceptor.getSessionConfig().setBothIdleTime(10);
try
{
SocketAddress arg1 = new
InetSocketAddress(Integer.parseInt(args[0])) ;
acceptor.setHandler(new CentralMessageHandler());
acceptor.bind( arg1);
}catch(Exception e)
{
logger.fatal(LoggerKeyWord.CRITICAL_ALERT + " CORE
Start Failed.");
System.exit(0);
}
