search

MariusM95 / android-rcs-ims-stack

Automatically exported from code.google.com/p/android-rcs-ims-stack
0 stars 0 forks source link

ParseException when message is received in multiple packets #111

Open GoogleCodeExporter opened 9 years ago

GoogleCodeExporter commented 9 years ago 
What steps will reproduce the problem?
1. No known steps to reproduce it. It happens when one server message is 
received as multiple TCP packets and there are multiple PipelineMsgParser 
reading the same pipeline.

What is the expected output? What do you see instead?
Each message, even in multiple buffer, should only be processed by one 
PipelineMsgParser.
However, when there were multiple PipelineMsgParser,
One got the first part of the message and the other got the second part which 
caused the ParseException.
Other messages from server after would fail because the starting of the message 
could not be located correctly.

What version of the product are you using? On what operating system?
2.5.2 on Android 4.0.4

Please provide any additional information below.

Here are the log I got (organized for easier to read, not exactly in time 
order).
The first message buffer received starting as "INVITE..."
The second message buffer received starting with "ccept-types:*/*"

**** First part of the message received ****
05-20 01:17:18.029: I/Logger[RCS](2400): INFO [TCPMessageChannelThread]: 
LogWriter: ====> Thread Thread[TCPMessageChannelThread,5,main] read Chunk size 
1376 <====
05-20 01:17:18.029: I/Logger[RCS](2400): INFO [TCPMessageChannelThread]: 
LogWriter: ====> INVITE sip:+19253248967@10.161.142.46:5090 SIP/2.0
05-20 01:17:18.029: I/Logger[RCS](2400): To: 
<sip:+19253248967@server4.ourserver.com>
05-20 01:17:18.029: I/Logger[RCS](2400): From: 
<sip:0003556AC879000006060001@server4.ourserver.com>;tag=0003556AC87900000606000
1
05-20 01:17:18.029: I/Logger[RCS](2400): Via: SIP/2.0/TCP 
server4.ourserver.com:5060;branch=z9hG4bK10.161.142.46_5090_MMS-ACK_62915692_000
3556AC8940000BB00000101
05-20 01:17:18.029: I/Logger[RCS](2400): CSeq: 1 INVITE
05-20 01:17:18.029: I/Logger[RCS](2400): Max-Forwards: 70
05-20 01:17:18.029: I/Logger[RCS](2400): Request-Disposition: no-fork
05-20 01:17:18.029: I/Logger[RCS](2400): P-Asserted-Identity: 
<sip:conf@server4.ourserver.com>
05-20 01:17:18.029: I/Logger[RCS](2400): P-Charging-Vector: icid-value=XYZ123
05-20 01:17:18.029: I/Logger[RCS](2400): Call-ID: 0003556AC879000006060001
05-20 01:17:18.029: I/Logger[RCS](2400): User-Agent: IM-serv/OMA1.0
05-20 01:17:18.029: I/Logger[RCS](2400): Allow: 
REGISTER,INVITE,ACK,BYE,SUBSCRIBE,NOTIFY,REFER,OPTIONS,MESSAGE
05-20 01:17:18.029: I/Logger[RCS](2400): Contact: 
<sip:0003556AC879000006060001@server4.ourserver.com>;+g.oma.sip-im;isfocus
05-20 01:17:18.029: I/Logger[RCS](2400): Referred-By: 
<sip:+19253248941@server4.ourserver.com>
05-20 01:17:18.029: I/Logger[RCS](2400): Accept-Contact: *;+g.oma.sip-im
05-20 01:17:18.029: I/Logger[RCS](2400): Contribution-ID: 
03ac7f6cb14310b246be8a3c3ea03e78
05-20 01:17:18.029: I/Logger[RCS](2400): Subject: group subject: Aaaaaaa24
05-20 01:17:18.029: I/Logger[RCS](2400): Content-Length: 887
05-20 01:17:18.029: I/Logger[RCS](2400): Route: 
<sip:10.161.142.46:5090;transport=TCP>
05-20 01:17:18.029: I/Logger[RCS](2400): Content-Type: 
multipart/mixed;boundary="========0003556AC8940000BB00000101==BoUnDaRy=="
05-20 01:17:18.029: I/Logger[RCS](2400): 
05-20 01:17:18.029: I/Logger[RCS](2400): 
--========0003556AC8940000BB00000101==BoUnDaRy==
05-20 01:17:18.029: I/Logger[RCS](2400): Content-Type: application/sdp
05-20 01:17:18.029: I/Logger[RCS](2400): 
05-20 01:17:18.029: I/Logger[RCS](2400): v=0
05-20 01:17:18.029: I/Logger[RCS](2400): o=- 212235797838461184 
212235797838461184 IN IP4 server4.ourserver.com
05-20 01:17:18.029: I/Logger[RCS](2400): s=0003556AC879000006060001
05-20 01:17:18.029: I/Logger[RCS](2400): c=IN IP4 server4.ourserver.com
05-20 01:17:18.029: I/Logger[RCS](2400): t=0 0
05-20 01:17:18.029: I/Logger[RCS](2400): a=setup:passive
05-20 01:17:18.029: I/Logger[RCS](2400): m=message 5806 TCP/MSRP *
05-20 01:17:18.029: I/Logger[RCS](2400): 
a=path:msrp://server4.ourserver.com:5806/s/9253248967/0003556AC879000006060001;t
cp
05-20 01:17:18.029: I/Logger[RCS](2400): a=a

**** Second part of the message received ****
05-20 01:17:18.049: I/Logger[RCS](2400): INFO [TCPMessageChannelThread]: 
LogWriter: ====> Thread Thread[TCPMessageChannelThread,5,main] read Chunk size 
529 <====
05-20 01:17:18.049: I/Logger[RCS](2400): ccept-types:*/*
05-20 01:17:18.049: I/Logger[RCS](2400): a=accept-wrapped-types:*
05-20 01:17:18.049: I/Logger[RCS](2400): a=max-size:102400
05-20 01:17:18.049: I/Logger[RCS](2400): 
05-20 01:17:18.049: I/Logger[RCS](2400): 
--========0003556AC8940000BB00000101==BoUnDaRy==
05-20 01:17:18.049: I/Logger[RCS](2400): Content-Type: 
application/resource-lists+xml
05-20 01:17:18.049: I/Logger[RCS](2400): Content-Disposition: 
recipient-list-history;handling=optional
05-20 01:17:18.049: I/Logger[RCS](2400): 
05-20 01:17:18.049: I/Logger[RCS](2400): <?xml version="1.0" encoding="UTF-8"?>
05-20 01:17:18.049: I/Logger[RCS](2400): <resource-lists 
xmlns="urn:ietf:params:xml:ns:resource-lists">
05-20 01:17:18.049: I/Logger[RCS](2400): <list>
05-20 01:17:18.049: I/Logger[RCS](2400): <entry 
uri="sip:+19253248941@server4.ourserver.com"/>
05-20 01:17:18.049: I/Logger[RCS](2400): <entry 
uri="sip:+19253248967@server4.ourserver.com"/>
05-20 01:17:18.049: I/Logger[RCS](2400): </list>
05-20 01:17:18.049: I/Logger[RCS](2400): </resource-lists>
05-20 01:17:18.049: I/Logger[RCS](2400): 
05-20 01:17:18.049: I/Logger[RCS](2400): 
--========0003556AC8940000BB00000101==BoUnDaRy==--

**** PipelineThread-0 first read from the pipeline ****
05-20 01:17:18.039: W/Logger[RCS](2400): WARN [PipelineThread-0]: Read line1: 
INVITE sip:+19253248967@10.161.142.46:5090 SIP/2.0
05-20 01:17:18.039: W/Logger[RCS](2400): WARN [PipelineThread-0]: Read lineN: 
To: <sip:+19253248967@server4.ourserver.com>
05-20 01:17:18.039: W/Logger[RCS](2400): WARN [PipelineThread-0]: Read lineN: 
From: 
<sip:0003556AC879000006060001@server4.ourserver.com>;tag=0003556AC87900000606000
1
05-20 01:17:18.039: W/Logger[RCS](2400): WARN [PipelineThread-0]: Read lineN: 
Via: SIP/2.0/TCP 
server4.ourserver.com:5060;branch=z9hG4bK10.161.142.46_5090_MMS-ACK_62915692_000
3556AC8940000BB00000101
05-20 01:17:18.039: W/Logger[RCS](2400): WARN [PipelineThread-0]: Read lineN: 
CSeq: 1 INVITE
05-20 01:17:18.039: W/Logger[RCS](2400): WARN [PipelineThread-0]: Read lineN: 
Max-Forwards: 70
05-20 01:17:18.039: W/Logger[RCS](2400): WARN [PipelineThread-0]: Read lineN: 
Request-Disposition: no-fork
05-20 01:17:18.039: W/Logger[RCS](2400): WARN [PipelineThread-0]: Read lineN: 
P-Asserted-Identity: <sip:conf@server4.ourserver.com>
05-20 01:17:18.039: W/Logger[RCS](2400): WARN [PipelineThread-0]: Read lineN: 
P-Charging-Vector: icid-value=XYZ123
05-20 01:17:18.059: W/Logger[RCS](2400): WARN [PipelineThread-0]: Read lineN: 
Call-ID: 0003556AC879000006060001
05-20 01:17:18.069: W/Logger[RCS](2400): WARN [PipelineThread-0]: Read lineN: 
User-Agent: IM-serv/OMA1.0
05-20 01:17:18.069: W/Logger[RCS](2400): WARN [PipelineThread-0]: Read lineN: 
Allow: REGISTER,INVITE,ACK,BYE,SUBSCRIBE,NOTIFY,REFER,OPTIONS,MESSAGE
05-20 01:17:18.079: W/Logger[RCS](2400): WARN [PipelineThread-0]: Read lineN: 
Contact: 
<sip:0003556AC879000006060001@server4.ourserver.com>;+g.oma.sip-im;isfocus
05-20 01:17:18.079: W/Logger[RCS](2400): WARN [PipelineThread-0]: Read lineN: 
Referred-By: <sip:+19253248941@server4.ourserver.com>
05-20 01:17:18.079: W/Logger[RCS](2400): WARN [PipelineThread-0]: Read lineN: 
Accept-Contact: *;+g.oma.sip-im
05-20 01:17:18.079: W/Logger[RCS](2400): WARN [PipelineThread-0]: Read lineN: 
Contribution-ID: 03ac7f6cb14310b246be8a3c3ea03e78
05-20 01:17:18.089: W/Logger[RCS](2400): WARN [PipelineThread-0]: Read lineN: 
Subject: group subject: Aaaaaaa24
05-20 01:17:18.089: W/Logger[RCS](2400): WARN [PipelineThread-0]: Read lineN: 
Content-Length: 887
05-20 01:17:18.099: W/Logger[RCS](2400): WARN [PipelineThread-0]: Read lineN: 
Route: <sip:10.161.142.46:5090;transport=TCP>

**** PipelineThread-1 read from the pipeline CONCURRENTLY (check the timestamp 
wich overlaps with PipelineThread-0) ****
**** It picked up the 2nd part of the message which triggered the exception ****
05-20 01:17:18.049: W/Logger[RCS](2400): WARN [PipelineThread-1]: Read line1: 
ccept-types:*/*
05-20 01:17:18.049: W/Logger[RCS](2400): WARN [PipelineThread-1]: Read lineN: 
a=accept-wrapped-types:*
05-20 01:17:18.059: W/Logger[RCS](2400): WARN [PipelineThread-1]: Read lineN: 
a=max-size:102400
05-20 01:17:18.059: W/Logger[RCS](2400): WARN [PipelineThread-1]: Read lineN: 

05-20 01:17:18.099: E/Logger[RCS](2400): ERROR [PipelineThread-1]: LogWriter: 
java.text.ParseException: ccept-types:*/*
05-20 01:17:18.099: E/Logger[RCS](2400): Unexpected Token :  (at offset 15)
05-20 01:17:18.099: E/Logger[RCS](2400):   
gov2.nist.core.LexerCore.match(LexerCore.java:229)
05-20 01:17:18.099: E/Logger[RCS](2400):   
gov2.nist.javax2.sip.parser.Parser.sipVersion(Parser.java:59)
05-20 01:17:18.099: E/Logger[RCS](2400):   
gov2.nist.javax2.sip.parser.RequestLineParser.parse(RequestLineParser.java:65)
05-20 01:17:18.099: E/Logger[RCS](2400):   
gov2.nist.javax2.sip.parser.StringMsgParser.processFirstLine(StringMsgParser.jav
a:416)
05-20 01:17:18.099: E/Logger[RCS](2400):   
gov2.nist.javax2.sip.parser.StringMsgParser.parseLine(StringMsgParser.java:368)
05-20 01:17:18.099: E/Logger[RCS](2400):   
gov2.nist.javax2.sip.parser.StringMsgParser.parseSIPMessage(StringMsgParser.java
:288)
05-20 01:17:18.099: E/Logger[RCS](2400):   
gov2.nist.javax2.sip.parser.PipelinedMsgParser.run(PipelinedMsgParser.java:314)
05-20 01:17:18.099: E/Logger[RCS](2400):   java.lang.Thread.run(Thread.java:856)
05-20 01:17:18.099: W/Logger[RCS](2400): WARN [PipelineThread-0]: Read lineN: 
Content-Type: 
multipart/mixed;boundary="========0003556AC8940000BB00000101==BoUnDaRy=="
05-20 01:17:18.109: D/Logger[RCS](2400): DEBUG [PipelineThread-1]: LogWriter: 
Encountered Bad Message 
05-20 01:17:18.109: D/Logger[RCS](2400): Content-Length: 0
05-20 01:17:18.109: D/Logger[RCS](2400): 
05-20 01:17:18.109: D/Logger[RCS](2400): DEBUG [PipelineThread-1]: LogWriter: 
Could not formulate automatic 400 Bad Request
05-20 01:17:18.109: W/Logger[RCS](2400): WARN [PipelineThread-1]: Read line1: 
--========0003556AC8940000BB00000101==BoUnDaRy==
05-20 01:17:18.109: W/Logger[RCS](2400): WARN [PipelineThread-1]: Read lineN: 
Content-Type: application/resource-lists+xml
05-20 01:17:18.109: W/Logger[RCS](2400): WARN [PipelineThread-0]: Read lineN: 
05-20 01:17:18.109: W/Logger[RCS](2400): WARN [PipelineThread-1]: Read lineN: 
Content-Disposition: recipient-list-history;handling=optional
05-20 01:17:18.119: W/Logger[RCS](2400): WARN [PipelineThread-1]: Read lineN: 
05-20 01:17:18.129: I/Logger[RCS](2400): INFO [PipelineThread-0]: LogWriter: 
====> no more buffer, wait
05-20 01:17:18.129: E/Logger[RCS](2400): ERROR [PipelineThread-1]: LogWriter: 
java.text.ParseException: --========0003556AC8940000BB00000101==BoUnDaRy==
05-20 01:17:18.129: E/Logger[RCS](2400): :GenericURI, Bad URI format (at offset 
0) (at offset 48)
05-20 01:17:18.129: E/Logger[RCS](2400):   
gov2.nist.javax2.sip.parser.Parser.createParseException(Parser.java:46)
05-20 01:17:18.129: E/Logger[RCS](2400):   
gov2.nist.javax2.sip.parser.URLParser.uriReference(URLParser.java:361)
05-20 01:17:18.129: E/Logger[RCS](2400):   
gov2.nist.javax2.sip.parser.RequestLineParser.parse(RequestLineParser.java:61)
05-20 01:17:18.129: E/Logger[RCS](2400):   
gov2.nist.javax2.sip.parser.StringMsgParser.processFirstLine(StringMsgParser.jav
a:416)
05-20 01:17:18.129: E/Logger[RCS](2400):   
gov2.nist.javax2.sip.parser.StringMsgParser.parseLine(StringMsgParser.java:368)
05-20 01:17:18.129: E/Logger[RCS](2400):   
gov2.nist.javax2.sip.parser.StringMsgParser.parseSIPMessage(StringMsgParser.java
:288)
05-20 01:17:18.129: E/Logger[RCS](2400):   
gov2.nist.javax2.sip.parser.PipelinedMsgParser.run(PipelinedMsgParser.java:314)
05-20 01:17:18.129: E/Logger[RCS](2400):   java.lang.Thread.run(Thread.java:856)
05-20 01:17:18.129: D/Logger[RCS](2400): DEBUG [PipelineThread-1]: LogWriter: 
Encountered Bad Message 
05-20 01:17:18.129: D/Logger[RCS](2400): Content-Length: 0
05-20 01:17:18.129: D/Logger[RCS](2400): 
05-20 01:17:18.129: D/Logger[RCS](2400): DEBUG [PipelineThread-1]: LogWriter: 
Could not formulate automatic 400 Bad Request
05-20 01:17:18.139: W/Logger[RCS](2400): WARN [PipelineThread-1]: Read line1: 
<?xml version="1.0" encoding="UTF-8"?>
05-20 01:17:18.139: W/Logger[RCS](2400): WARN [PipelineThread-1]: Read lineN: 
<resource-lists xmlns="urn:ietf:params:xml:ns:resource-lists">
05-20 01:17:18.139: W/Logger[RCS](2400): WARN [PipelineThread-1]: Read lineN: 
<list>
05-20 01:17:18.139: W/Logger[RCS](2400): WARN [PipelineThread-1]: Read lineN: 
<entry uri="sip:+19253248941@server4.ourserver.com"/>
05-20 01:17:18.139: W/Logger[RCS](2400): WARN [PipelineThread-1]: Read lineN: 
<entry uri="sip:+19253248967@server4.ourserver.com"/>
05-20 01:17:18.149: W/Logger[RCS](2400): WARN [PipelineThread-1]: Read lineN: 
</list>
05-20 01:17:18.149: W/Logger[RCS](2400): WARN [PipelineThread-1]: Read lineN: 
</resource-lists>
05-20 01:17:18.149: W/Logger[RCS](2400): WARN [PipelineThread-1]: Read lineN: 
05-20 01:17:18.149: E/Logger[RCS](2400): ERROR [PipelineThread-1]: LogWriter: 
java.text.ParseException: <?xml version="1.0" encoding="UTF-8"?>
05-20 01:17:18.149: E/Logger[RCS](2400): :Invalid Method (at offset 0)
05-20 01:17:18.149: E/Logger[RCS](2400):   
gov2.nist.javax2.sip.parser.Parser.createParseException(Parser.java:46)
05-20 01:17:18.149: E/Logger[RCS](2400):   
gov2.nist.javax2.sip.parser.Parser.method(Parser.java:97)
05-20 01:17:18.149: E/Logger[RCS](2400):   
gov2.nist.javax2.sip.parser.RequestLineParser.parse(RequestLineParser.java:56)
05-20 01:17:18.149: E/Logger[RCS](2400):   
gov2.nist.javax2.sip.parser.StringMsgParser.processFirstLine(StringMsgParser.jav
a:416)
05-20 01:17:18.149: E/Logger[RCS](2400):   
gov2.nist.javax2.sip.parser.StringMsgParser.parseLine(StringMsgParser.java:368)
05-20 01:17:18.149: E/Logger[RCS](2400):   
gov2.nist.javax2.sip.parser.StringMsgParser.parseSIPMessage(StringMsgParser.java
:288)
05-20 01:17:18.149: E/Logger[RCS](2400):   
gov2.nist.javax2.sip.parser.PipelinedMsgParser.run(PipelinedMsgParser.java:314)
05-20 01:17:18.149: E/Logger[RCS](2400):   java.lang.Thread.run(Thread.java:856)
05-20 01:17:18.159: D/Logger[RCS](2400): DEBUG [PipelineThread-1]: LogWriter: 
Encountered Bad Message 
05-20 01:17:18.159: D/Logger[RCS](2400): Content-Length: 0
05-20 01:17:18.159: D/Logger[RCS](2400):

Original issue reported on code.google.com by mcd...@mcdull.us on 20 May 2013 at 6:37

GoogleCodeExporter commented 9 years ago 
I believe is due to multiple TCPMessageChannel objects each have its own 
PipelinedMsgParser but they are reading from the same socket.

You might not see this exception as the logging of the parser is disabled by 
default.  You will only notice REGISTER timeout because it will fail to locate 
the head of REGISTER response and eventually cause timeout.

Original comment by for...@mcdull.us on 24 May 2013 at 9:07

GoogleCodeExporter commented 9 years ago 
Here is what I found one situation this can happen.

The TCPMessageChannel objects are stored in a table and each one has a key.
One part of the key is the hostname or IP.
When it has to send a SIP message, it generates a key from the SIP message. If 
the message has a route header, it uses the route value to generate the key. 
Otherwise, it uses the request uri.

In my case, TCPMessageChannel is first created with route header and the key 
contains IP of the server.

When there is an error occurred, ImsServiceSession.terminateSession() is 
called. It sends a SIP BYE. However, the SIP BYE uses request-uri to generate 
they key which is a hostname. As a result, even though the hostname and IP are 
of the same server, it doesn't find a match from the MessageChannel table. A 
new TCPMessageChannel is created.

The existing TCPMessageChannel and new TCPMessageChannel are then reading from 
the same socket which will eventually cause the issue each channel read a part 
of a long SIP message.

Original comment by mcd...@mcdull.us on 10 Feb 2014 at 7:26

GoogleCodeExporter commented 9 years ago 
Try to take a look at the following issue from JSIP project:
https://java.net/jira/browse/JSIP-454

Original comment by joaoafon...@gmail.com on 5 Jun 2014 at 5:07