mina-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Emmanuel Lecharny (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (DIRMINA-1040) Mina 2.0.4 truncated the PDU
Date Wed, 03 Aug 2016 06:36:20 GMT

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

Mime
View raw message