[
https://issues.apache.org/jira/browse/DIRMINA-1040?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15405593#comment-15405593
]
Silver Cheng commented on DIRMINA-1040:
---------------------------------------
I attached a log which have one additional logging for the mina.
see below
in line 46978, the pos indicated 16, but I don't know why there are 9 bytes
"34 35 00 04 09 32 32 36 32" ahead of the PDU.
{noformat}
#46978: 2016-07-30 21:20:44,492 DEBUG (NioProcessor-2) ()
org.apache.mina.transport.socket.nio.NioProcessor - ***4.0 Enter Mina
NioProcessor write method buf.remaining: HeapBuffer[pos=16 lim=189 cap=189: 34
35 00 04 09 32 32 36 32 00 00 00 BD 00 00 00 05 00 00 00 00 00 01 18 11 00 01
01 31 38 31 36...]; msg: {};
{noformat}
while in line 46980 where we printed both getCurrentWriteMessage and
getCurrentWriteRequest in our app, found the postion is not the same, for
getCurrentWriteMessage, pos is 0; while for getCurrentWriteRequest, the pos is
25.
and in line 46989, localWrittenBytes is 164, which mean only 164 bytes got
written to channel, and we exactly lost the first 25 bytes in the tcpdump.
do you know if we have the thread safe for the buffer or writerequest?
{noformat}
#46980:2016-07-30 21:20:44,492 INFO (Timer-3) ()
com.ipx.cpsmscapis.smpp.NorthSmppAdapter - SmppSystemId=02980,
CompositeUserId=02980, SMPP Session: BindType=[Transceiver],
Transmitter=[Local:127.0.0.1:10001,Remote:127.0.0.1:59638](0x00000BFB: nio
socket, server, /127.0.0.1:59638 => /127.0.0.1:10001). Details -->
CreationTime=Sat Jul 30 10:53:40 PDT 2016, LastIoTime=Sat Jul 30 21:20:44 PDT
2016,
isClosing=false, isConnected=true, isBothIdle=false,
isReaderIdle=false, isReadSuspended=false, isWriterIdle=false,
isWriteSuspended=false,
LastReadTime=Sat Jul 30 21:20:44 PDT 2016, LastReaderIdleTime=Sat Jul
30 10:53:40 PDT 2016, ReaderIdleCount=0, ReadBytes=8964432,
ReadMessages=108521,
LastWriteTime=Sat Jul 30 21:20:44 PDT 2016, LastWriterIdleTime=Sat Jul
30 10:53:40 PDT 2016, WriterIdleCount=0, WrittenBytes=14204045,
WrittenMessages=108521,
CurrentWriteMessage=[null], CurrentWriteRequest=[null],
Receiver=[Local:127.0.0.1:10001,Remote:127.0.0.1:59638](0x00000BFB: nio socket,
server, /127.0.0.1:59638 => /127.0.0.1:10001). Details --> CreationTime=Sat Jul
30 10:53:40 PDT 2016, LastIoTime=Sat Jul 30 21:20:44 PDT 2016,
isClosing=false, isConnected=true, isBothIdle=false,
isReaderIdle=false, isReadSuspended=false, isWriterIdle=false,
isWriteSuspended=false,
LastReadTime=Sat Jul 30 21:20:44 PDT 2016, LastReaderIdleTime=Sat Jul
30 10:53:40 PDT 2016, ReaderIdleCount=0, ReadBytes=8964432,
ReadMessages=108521,
LastWriteTime=Sat Jul 30 21:20:44 PDT 2016, LastWriterIdleTime=Sat Jul
30 10:53:40 PDT 2016, WriterIdleCount=0, WrittenBytes=14204045,
WrittenMessages=108521,
CurrentWriteMessage=[HeapBuffer[pos=0 lim=189 cap=189: 00 00 00 BD 00
00 00 05 00 00 00 00 00 01 18 11 00 01 01 31 38 31 36 39 31 34 35 36 34 39 00
04...]], CurrentWriteRequest=[WriteRequest: HeapBuffer[pos=25 lim=189 cap=189:
34 35 36 34 39 00 04 09 32 32 36 32 32 00 04 00 00 00 00 00 00 00 00 6F 69 64
3A 31 31 36 30 37...]]
{noformat}
{noformat}
#46989: 2016-07-30 21:20:44,492 DEBUG (NioProcessor-2) ()
org.apache.mina.core.polling.AbstractPollingIoProcessor - ***5.0 After
NioProcessor write method, in Mina AbstractPollingIoProcessor writeBuffer
session's localWrittenBytes: 164
{noformat}
> Mina 2.0.4 truncated the PDU
> ----------------------------
>
> Key: DIRMINA-1040
> URL: https://issues.apache.org/jira/browse/DIRMINA-1040
> Project: MINA
> Issue Type: Bug
> Components: Filter
> Affects Versions: 2.0.4
> Environment: Mina 2.0.4 version
> pl-1@ECE8000-Z1 ~ # /usr/java/latest/bin/java -version
> java version "1.6.0_45"
> Java(TM) SE Runtime Environment (build 1.6.0_45-b06)
> Java HotSpot(TM) 64-Bit Server VM (build 20.45-b01, mixed mode)
> Reporter: Silver Cheng
> Labels: PDU, truncated
> Attachments: Mina-2.0.13-code delta.docx, mina log and tcpdump.zip,
> mina-debug-logging.zip, tcpdump-10001.zip
>
>
> Background:
> our app messaging-server is to handle the SMPP protocol messages, and we use
> Mina 2.0.4 for the lower TCP transport function.
> Problem:
> sometime, not often, I found that the PDU could be truncated by Mina from
> tcpdump. I added some debug loggers to mina codes, and found that indeed the
> PDU truncated is occuring at Mina.
> from below logs, you can see in #3, the buf which got from WriteRequest got
> truncated the first 16 bytes in Mina. could you know if it's a known issue
> in 2.0.4?
> Debug loggers & Logs:
> 1. IoHandler:
> WriteFuture future = iosession.write(deliverSm);
> 2016-07-14 01:52:19,865 DEBUG (62451235@WebForward 0.0.0.0:5001-21)
> (bbfa6690c88ab98aec4e) com.ipx.cpsmscapis.smpp.NorthSmppIoHandler - Sending
> DeliverSM: 00 00 00 be 00 00 00 05 00 00 00 00 00 00 03 02 00 01 01 31 32 30
> 32 34 36 30 38 39 33 33 00 04 09 37 36 32 32 36 35 00 04 00 00 00 00 00 00 00
> 00 6f 69 64 3a 32 31 36 30 37 31 34 30 31 30 30 31 32 34 32 32 38 35 38 20 73
> 75 62 3a 30 30 31 20 64 6c 76 72 64 3a 30 30 31 20 73 75 62 6d 69 74 20 64 61
> 74 65 3a 31 36 30 37 31 34 30 31 35 32 20 64 6f 6e 65 20 64 61 74 65 3a 31 36
> 30 37 31 34 30 31 35 32 20 73 74 61 74 3a 44 45 4c 49 56 52 44 20 65 72 72 3a
> 30 30 30 20 74 65 78 74 3a 04 27 00 01 02 00 1e 00 14 32 31 36 30 37 31 34 30
> 31 30 30 31 32 34 32 32 38 35 38 00
> 2. AbstractIoSession:
> public WriteFuture write(Object message, SocketAddress remoteAddress) {
> if (message == null) {
> throw new IllegalArgumentException("message");
> }
>
> //added by Silver
> if (DEBUG) {
> if
> (message.getClass().getName().equals("org.smpp.pdu.DeliverSM")) {
> LOGGER.debug( "***1 Enter Mina AbstractIoSession write
> method Object message: {};",message);
> }
> }
> 2016-07-14 01:52:19,866 DEBUG (62451235@WebForward 0.0.0.0:5001-21)
> (bbfa6690c88ab98aec4e) org.apache.mina.core.session.AbstractIoSession - ***1
> Enter Mina AbstractIoSession write method Object message: 00 00 00 be 00 00
> 00 05 00 00 00 00 00 00 03 02 00 01 01 31 32 30 32 34 36 30 38 39 33 33 00 04
> 09 37 36 32 32 36 35 00 04 00 00 00 00 00 00 00 00 6f 69 64 3a 32 31 36 30 37
> 31 34 30 31 30 30 31 32 34 32 32 38 35 38 20 73 75 62 3a 30 30 31 20 64 6c 76
> 72 64 3a 30 30 31 20 73 75 62 6d 69 74 20 64 61 74 65 3a 31 36 30 37 31 34 30
> 31 35 32 20 64 6f 6e 65 20 64 61 74 65 3a 31 36 30 37 31 34 30 31 35 32 20 73
> 74 61 74 3a 44 45 4c 49 56 52 44 20 65 72 72 3a 30 30 30 20 74 65 78 74 3a 04
> 27 00 01 02 00 1e 00 14 32 31 36 30 37 31 34 30 31 30 30 31 32 34 32 32 38 35
> 38 00;
> 3. AbstractPollingIoProcessor:
> private int writeBuffer(S session, WriteRequest req,
> boolean hasFragmentation, int maxLength, long currentTime)
> throws Exception {
> IoBuffer buf = (IoBuffer) req.getMessage();
>
> //add by silver
> if (DEBUG) {
> LOGGER.debug( "***3 Mina AbstractPollingIoProcessor writeBuffer
> session's hasFragmentation: {} ; session: {}; ",
> hasFragmentation,session.getCurrentWriteMessage());
> LOGGER.debug( "***3 Mina AbstractPollingIoProcessor writeBuffer
> session's maxWrittenBytes: {} ; buf: {};", maxLength,buf.getHexDump());
> }
> 2016-07-14 01:52:19,866 DEBUG (NioProcessor-3) ()
> org.apache.mina.core.polling.AbstractPollingIoProcessor - ***3 Mina
> AbstractPollingIoProcessor writeBuffer session's maxWrittenBytes: 98304 ;
> buf: 00 01 01 31 32 30 32 34 36 30 38 39 33 33 00 04 09 37 36 32 32 36 35 00
> 04 00 00 00 00 00 00 00 00 6F 69 64 3A 32 31 36 30 37 31 34 30 31 30 30 31 32
> 34 32 32 38 35 38 20 73 75 62 3A 30 30 31 20 64 6C 76 72 64 3A 30 30 31 20 73
> 75 62 6D 69 74 20 64 61 74 65 3A 31 36 30 37 31 34 30 31 35 32 20 64 6F 6E 65
> 20 64 61 74 65 3A 31 36 30 37 31 34 30 31 35 32 20 73 74 61 74 3A 44 45 4C 49
> 56 52 44 20 65 72 72 3A 30 30 30 20 74 65 78 74 3A 04 27 00 01 02 00 1E 00 14
> 32 31 36 30 37 31 34 30 31 30 30 31 32 34 32 32 38 35 38 00;
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
