[
https://issues.apache.org/jira/browse/DIRMINA-1040?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15405415#comment-15405415
]
Emmanuel Lecharny commented on DIRMINA-1040:
--------------------------------------------
Hi Silver,
from the logs you provided, line 28538 to 28541, the only thing I can tell is
that MINA is transmitting the buffer in two pieces : a first block of 16 bytes,
then the remaining 163 bytes :
{noformat}
...
2016-07-30 21:20:44,492 DEBUG (NioProcessor-2) ()
org.apache.mina.core.polling.AbstractPollingIoProcessor - ***2 Mina
AbstractPollingIoProcessor flushNow method msg: 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...];
2016-07-30 21:20:44,492 DEBUG (NioProcessor-2) ()
org.apache.mina.core.polling.AbstractPollingIoProcessor - ***3 Mina
AbstractPollingIoProcessor writeBuffer session's hasFragmentation: true ;
session: 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...];
2016-07-30 21:20:44,492 DEBUG (NioProcessor-2) ()
org.apache.mina.core.polling.AbstractPollingIoProcessor - ***3 Mina
AbstractPollingIoProcessor writeBuffer session's maxWrittenBytes: 98304 ;
buf: 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 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 33 30 32 31 31 30 34 38 32 33 32 30 37 32 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 33 30 32 31 32 30 20 64 6F 6E 65 20 64 61 74 65 3A 31 36 30 37 33 30
32 31 32 30 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 31 31 36 30 37 33 30 32 31 31 30 34
38 32 33 32 30 37 32 00;
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}
There is nothing wrong here : the {{flushNow}} method is called twice, trying
to write the buffer into the socket's buffer, and if this socket's buffer is
full, it will just write as much as possible (here, the first 16 bytes), then
schedule another write later on when the {{selectedKey}} is ready for write
(ie, there is some room in the socket's buffer, this is when the remaining 163
bytes are written).
The place where data are written is in the {{NioProcessor.write()}} method,
called by the {{AbstractPollingProcessor.writeBuffer()}} method. I would
suggest that you add some log here, printing the buffer and the
{{localWrittenBytes}} variable. If the buffer size and the
{{localWrittenBytes}} value are different, that means the message is
fragmented.
At this point, this is all I can tell, I don't have you r code, I can't
reproduce the problem, so there is not much I can do to help...
> 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)
