You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@mina.apache.org by "Silver Cheng (JIRA)" <ji...@apache.org> on 2016/08/01 06:14:20 UTC
[jira] [Comment Edited] (DIRMINA-1040) Mina 2.0.4 truncated the PDU
[ https://issues.apache.org/jira/browse/DIRMINA-1040?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15401558#comment-15401558 ]
Silver Cheng edited comment on DIRMINA-1040 at 8/1/16 6:13 AM:
---------------------------------------------------------------
Hi Emmanuel,
After upgraded to 2.0.13 version, we still have this PDU truncated issue(it occured at 2016-07-31, 04:20:44 UTC) in the send direction as before.
I added the debug traces of messages dump to below classes(please see the detail in attached doc file) :
1. IoHandler implementation: NorthSmppIoHandler.java method _sendDeliverSM()
2. AbstractIoSession.java method write()
3. AbstractPollingIoProcessor.java method flushNow() and writeBuffer()
4. NioProcessor.java method write()
5. DefaultIoFilterChain.java-> private class HeadFilter -->filterWrite()
6. AbstractIoBuffer.java toString()
from the debug traces(mina-debug-logging.log), and the tcpdump, it seemed Mina did the truncation indeed to below msg , no matter from the tcpdump or the mina debug logs, could you help to check? Your support is always highly apprecaited! thank you in advance!
===================this is the whole PDU of DeliverSM sent by IoHandler but got truncated in the end by Mina at ~2016-07-31, 04:20:44 UTC(below timestamp is 7 hour diff from UTC)==========:
2016-07-30 21:20:44,492 DEBUG (2017850780@WebForward 0.0.0.0:5001-2556) (121823e0cbff35a666c3) com.ipx.cpsmscapis.smpp.NorthSmppIoHandler - Sending DeliverSM: 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
===================this is the whole message received in Mina AbstractIoSession, same as the IoHandler=========
2016-07-30 21:20:44,492 DEBUG (2017850780@WebForward 0.0.0.0:5001-2556) (121823e0cbff35a666c3) org.apache.mina.core.session.AbstractIoSession - ***1 Enter Mina AbstractIoSession write method Object message: 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;
===================BUT we saw there are 25 bytes got truncated already in NioProcessor wirte method========
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: {};
2016-07-30 21:20:44,492 DEBUG (NioProcessor-2) () org.apache.mina.transport.socket.nio.NioProcessor - ***4.0 Enter Mina NioProcessor write method length: 189;buf: 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.core.polling.AbstractPollingIoProcessor - ***5.0 After NioProcessor write method, in Mina AbstractPollingIoProcessor writeBuffer session's localWrittenBytes: 164
=================we also upload the tcpdump here and you can checked that package #25806(filter by "tcp.srcport==10001 and tcp.dstport==59638"), package #25806is the truncated message here, we didn't see that missing 25 Bytes in other tcpdumps before or after this timestamp, either in mina debug logs=================
was (Author: silvercheng):
Hi Emmanuel,
After upgraded to 2.0.13 version, we still have this PDU truncated issue(it occured at 2016-07-31, 04:20:44 UTC) in the send direction as before.
I added the debug traces of messages dump to below classes(please see the detail in attached doc file) :
1. IoHandler implementation: NorthSmppIoHandler.java method _sendDeliverSM()
2. AbstractIoSession.java method write()
3. AbstractPollingIoProcessor.java method flushNow() and writeBuffer()
4. NioProcessor.java method write()
5. DefaultIoFilterChain.java-> private class HeadFilter -->filterWrite()
6. AbstractIoBuffer.java toString()
from the debug traces(mina-debug-logging.log), and the tcpdump, it seemed Mina did the truncation indeed to below msg , no matter from the tcpdump or the mina debug logs, could you help to check? Your support is always highly apprecaited! thank you in advance!
===================this is the whole PDU of DeliverSM sent by IoHandler but got truncated in the end by Mina at ~2016-07-31, 04:20:44 UTC(below timestamp is 7 hour diff from UTC)==========:
2016-07-30 21:20:44,492 DEBUG (2017850780@WebForward 0.0.0.0:5001-2556) (121823e0cbff35a666c3) com.ipx.cpsmscapis.smpp.NorthSmppIoHandler - Sending DeliverSM: 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
===================this is the whole message received in Mina AbstractIoSession, same as the IoHandler=========
2016-07-30 21:20:44,492 DEBUG (2017850780@WebForward 0.0.0.0:5001-2556) (121823e0cbff35a666c3) org.apache.mina.core.session.AbstractIoSession - ***1 Enter Mina AbstractIoSession write method Object message: 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;
===================BUT we saw there are 25 bytes got truncated already in NioProcessor wirte method========
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: {};
2016-07-30 21:20:44,492 DEBUG (NioProcessor-2) () org.apache.mina.transport.socket.nio.NioProcessor - ***4.0 Enter Mina NioProcessor write method length: 189;buf: 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.core.polling.AbstractPollingIoProcessor - ***5.0 After NioProcessor write method, in Mina AbstractPollingIoProcessor writeBuffer session's localWrittenBytes: 164
=================we also upload the tcpdump here and you can checked that package #436357(filter by "tcp.srcport==10001 and tcp.dstport==59638"), package #436357 is the truncated message here, we didn't see that missing 25 Bytes in other tcpdumps before or after this timestamp, either in mina debug logs=================
> 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
>
>
> 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)