[
https://issues.apache.org/jira/browse/DIRMINA-1040?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15401558#comment-15401558
]
Silver Cheng commented on DIRMINA-1040:
---------------------------------------
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 log and tcpdump.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)
