mina-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Silver Cheng (JIRA)" <j...@apache.org>
Subject [jira] [Comment Edited] (DIRMINA-1040) Mina 2.0.4 truncated the PDU
Date Mon, 01 Aug 2016 06:14:20 GMT

    [ 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)

Mime
View raw message