cannot find the application to handle this subsequent request PRACK

[Hui WANG]

Hi,

Here is a typical proxy where userA called userB. Before forwarding
the Initial INVITE request which contains "Supported: 100rel" to
userB, the proxy made a 183 response with "Require:100rel" in the
message header to trigger a Prack request from userA. Unfortunately
the coming prack invoked an
org.mobicents.servlet.sip.core.dispatchers.DispatcherException and I
got the the error as described in the title.

I'm using the newest MSS on ubuntu 9.10
The response and prack come as follows:

183 query capabilities for terminal or network
Call-ID: 1-6...@127.0.0.1
CSeq: 1 INVITE
From: <sip:al...@open-ims.test>;tag=1
To: <sip:sp...@msm.open-ims.test>;tag=1
Via: SIP/2.0/UDP 127.0.0.1:6060;branch=z9hG4bK8305.fef9b1e3.0
Via: SIP/2.0/UDP 127.0.0.1:4060;branch=z9hG4bK8305.d8990fb2.0
Via: SIP/2.0/UDP 127.0.0.1:5090;rport=5090;branch=z9hG4bK-6391-1-0
Contact: <sip:127.0.0.1:5080;transport=udp>
Route: <sip:m...@scscf.open-ims.test:6060;lr>
Route: <sip:m...@pcscf.open-ims.test:4060;lr>
Require: 100rel,100rel
Content-Type: application/sdp
RSeq: 226
Content-Length: 217

v=0
o=alice 3468086555 3468086555 IN IP4 127.0.0.1
s=A SIPp Stream
c=IN IP4 127.0.0.1
t=0 0
m=audio 23002 RTP/AVP 0 8 14
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:14 MPA/8000

19:01:16,047 ERROR [SipApplicationDispatcherImpl] Unexpected exception
while processing request PRACK sip:127.0.0.1:5080 SIP/2.0
From: <sip:al...@open-ims.test>;tag=1
To: <sip:sp...@msm.open-ims.test>;tag=1
Via: SIP/2.0/UDP 127.0.0.1:4060;branch=z9hG4bK5305.3fab3526.0
Via: SIP/2.0/UDP 127.0.0.1:5090;rport=5090;branch=z9hG4bK-6391-1-4
Call-ID: 1-6...@127.0.0.1
CSeq: 2 PRACK
Contact: <sip:al...@127.0.0.1:5090>
Max-Forwards: 16
RAck: 226 1 INVITE
Content-Type: application/sdp
P-Asserted-Identity: <sip:al...@open-ims.test>
Content-Length: 247

v=0
o=alice 3468086555 3468086555 IN IP4 127.0.0.1
s=A SIPp Stream
c=IN IP4 127.0.0.1
t=0 0
m=audio 23002 RTP/AVP 0 8 14
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:14 MPA/8000

Thanks in advance. Best wished for the new year !

Hui WANG

[Jean Deruelle]

Can u provide the full server.log file in DEBUG mode so that we can try to find what the problem is ?

a wireshark trace or tcpdump would be nice as well

Thanks

Jean

[Hui WANG]

Hi Jean,

Thanks for you reply.

What confuses me is that in the 183 response, the Record-Route header
is missing.
When switching to debug mode, i got a 404 error. So I'm attaching the
log from the running mode.

17:47:35,669 INFO [Mobicents-SIP-Servlets] <message
from="127.0.0.1:6060"
to="127.0.0.1:5080"
time="1262710055666"
isSender="false"
transactionId="z9hg4bk791b.77676ad.0"
callId="1-5...@127.0.0.1"
firstLine="INVITE sip:sp...@msm.open-ims.test SIP/2.0"
>
<![CDATA[INVITE sip:sp...@msm.open-ims.test SIP/2.0
Record-Route: <sip:m...@scscf.open-ims.test:6060;lr>
Record-Route: <sip:m...@pcscf.open-ims.test:4060;lr>
Route: <sip:127.0.0.1:5080;lr>
Route: <sip:isc...@scscf.open-ims.test:
6060;lr;s=2;h=0;d=0;a=7369703a616c696365406f70656e2d696d732e74657374>
Call-ID: 1-5...@127.0.0.1

CSeq: 1 INVITE
From: <sip:al...@open-ims.test>;tag=1
To: <sip:sp...@msm.open-ims.test>;tag=1

Via: SIP/2.0/UDP 127.0.0.1:6060;branch=z9hG4bK791b.77676ad.0
Via: SIP/2.0/UDP 127.0.0.1:4060;branch=z9hG4bK791b.a04a4263.0
Via: SIP/2.0/UDP 127.0.0.1:5090;rport=5090;branch=z9hG4bK-5320-1-0
Max-Forwards: 15
Contact: <sip:al...@127.0.0.1:5090>
Supported: 100rel

Content-Type: application/sdp
P-Asserted-Identity: <sip:al...@open-ims.test>

P-Charging-Vector: icid-value="P-CSCFabcd4b436d2700000017";icid-
generated-at=127.0.0.1;orig-ioi=open-ims.test
Content-Length: 191

v=0
o=alice 3468086555 3468086555 IN IP4 127.0.0.1
s=A SIPp Stream
c=IN IP4 127.0.0.1
t=0 0
m=audio 23002 RTP/AVP 0 8 14
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000

a=rtpmap:14 MPA/8000]]>
</message>

17:47:35,686 INFO [InitialRequestDispatcher] Dispatching the request
event to ModalityAdaptation
17:47:35,696 INFO [ModalityAdaptation] Got INVITE: INVITE
sip:sp...@msm.open-ims.test SIP/2.0
Record-Route: <sip:m...@scscf.open-ims.test:6060;lr>
Record-Route: <sip:m...@pcscf.open-ims.test:4060;lr>
Route: <sip:isc...@scscf.open-ims.test:
6060;lr;s=2;h=0;d=0;a=7369703a616c696365406f70656e2d696d732e74657374>
Call-ID: 1-5...@127.0.0.1

CSeq: 1 INVITE
From: <sip:al...@open-ims.test>;tag=1
To: <sip:sp...@msm.open-ims.test>;tag=1

Via: SIP/2.0/UDP 127.0.0.1:6060;branch=z9hG4bK791b.77676ad.0
Via: SIP/2.0/UDP 127.0.0.1:4060;branch=z9hG4bK791b.a04a4263.0
Via: SIP/2.0/UDP 127.0.0.1:5090;rport=5090;branch=z9hG4bK-5320-1-0
Max-Forwards: 15
Contact: <sip:al...@127.0.0.1:5090>
Supported: 100rel

Content-Type: application/sdp
P-Asserted-Identity: <sip:al...@open-ims.test>

P-Charging-Vector: icid-value="P-CSCFabcd4b436d2700000017";icid-
generated-at=127.0.0.1;orig-ioi=open-ims.test
Content-Length: 191

v=0
o=alice 3468086555 3468086555 IN IP4 127.0.0.1
s=A SIPp Stream
c=IN IP4 127.0.0.1
t=0 0
m=audio 23002 RTP/AVP 0 8 14
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:14 MPA/8000

17:47:35,696 INFO [ModalityAdaptation] The network capacity is
required.
17:47:35,700 INFO [Mobicents-SIP-Servlets] <message
from="127.0.0.1:5080"
to="127.0.0.1:6060"
time="1262710055700"
isSender="true"
transactionId="z9hg4bk791b.77676ad.0"
callId="1-5...@127.0.0.1"
firstLine="SIP/2.0 183 query capabilities for terminal or network"
>
<![CDATA[SIP/2.0 183 query capabilities for terminal or network
Call-ID: 1-5...@127.0.0.1

CSeq: 1 INVITE
From: <sip:al...@open-ims.test>;tag=1
To: <sip:sp...@msm.open-ims.test>;tag=1

Via: SIP/2.0/UDP 127.0.0.1:6060;branch=z9hG4bK791b.77676ad.0
Via: SIP/2.0/UDP 127.0.0.1:4060;branch=z9hG4bK791b.a04a4263.0
Via: SIP/2.0/UDP 127.0.0.1:5090;rport=5090;branch=z9hG4bK-5320-1-0

Contact: <sip:127.0.0.1:5080;transport=udp>
Route: <sip:m...@scscf.open-ims.test:6060;lr>
Route: <sip:m...@pcscf.open-ims.test:4060;lr>

Content-Type: application/sdp
Require: 100rel
RSeq: 88
Content-Length: 217

v=0
o=alice 3468086555 3468086555 IN IP4 127.0.0.1
s=A SIPp Stream
c=IN IP4 127.0.0.1
t=0 0
m=audio 23002 RTP/AVP 0 8 14
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:14 MPA/8000

q=6.6.5.3
a=sendonly:80]]>
</message>

17:47:35,700 INFO [ModalityAdaptation] Query sent
17:47:35,700 INFO [InitialRequestDispatcher] Request event dispatched
to ModalityAdaptation
17:47:35,702 INFO [Mobicents-SIP-Servlets] <message
from="127.0.0.1:4060"
to="127.0.0.1:5080"
time="1262710055702"
isSender="false"
transactionId="z9hg4bk491b.45d95c37.0"
callId="1-5...@127.0.0.1"
firstLine="PRACK sip:127.0.0.1:5080 SIP/2.0"
>
<![CDATA[PRACK sip:127.0.0.1:5080 SIP/2.0

From: <sip:al...@open-ims.test>;tag=1
To: <sip:sp...@msm.open-ims.test>;tag=1

Via: SIP/2.0/UDP 127.0.0.1:4060;branch=z9hG4bK491b.45d95c37.0
Via: SIP/2.0/UDP 127.0.0.1:5090;rport=5090;branch=z9hG4bK-5320-1-4
Call-ID: 1-5...@127.0.0.1

CSeq: 2 PRACK
Contact: <sip:al...@127.0.0.1:5090>
Max-Forwards: 16

RAck: 88 1 INVITE

Content-Type: application/sdp
P-Asserted-Identity: <sip:al...@open-ims.test>
Content-Length: 247

v=0
o=alice 3468086555 3468086555 IN IP4 127.0.0.1
s=A SIPp Stream
c=IN IP4 127.0.0.1
t=0 0
m=audio 23002 RTP/AVP 0 8 14
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:14 MPA/8000

q=6.6.5.3
a=recvonly:80
q=6.6.4.1
a=maxCapacity:100]]>
</message>

17:47:35,706 ERROR [SipApplicationDispatcherImpl] Unexpected exception

while processing request PRACK sip:127.0.0.1:5080 SIP/2.0
From: <sip:al...@open-ims.test>;tag=1
To: <sip:sp...@msm.open-ims.test>;tag=1

Via: SIP/2.0/UDP 127.0.0.1:4060;branch=z9hG4bK491b.45d95c37.0
Via: SIP/2.0/UDP 127.0.0.1:5090;rport=5090;branch=z9hG4bK-5320-1-4
Call-ID: 1-5...@127.0.0.1

CSeq: 2 PRACK
Contact: <sip:al...@127.0.0.1:5090>
Max-Forwards: 16

RAck: 88 1 INVITE

Content-Type: application/sdp
P-Asserted-Identity: <sip:al...@open-ims.test>
Content-Length: 247

v=0
o=alice 3468086555 3468086555 IN IP4 127.0.0.1
s=A SIPp Stream
c=IN IP4 127.0.0.1
t=0 0
m=audio 23002 RTP/AVP 0 8 14
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:14 MPA/8000

q=6.6.5.3
a=recvonly:80
q=6.6.4.1
a=maxCapacity:100
org.mobicents.servlet.sip.core.dispatchers.DispatcherException: cannot
find the application to handle this subsequent request PRACK sip:

127.0.0.1:5080 SIP/2.0
From: <sip:al...@open-ims.test>;tag=1
To: <sip:sp...@msm.open-ims.test>;tag=1

Via: SIP/2.0/UDP 127.0.0.1:4060;branch=z9hG4bK491b.45d95c37.0
Via: SIP/2.0/UDP 127.0.0.1:5090;rport=5090;branch=z9hG4bK-5320-1-4
Call-ID: 1-5...@127.0.0.1

CSeq: 2 PRACK
Contact: <sip:al...@127.0.0.1:5090>
Max-Forwards: 16

RAck: 88 1 INVITE

Content-Type: application/sdp
P-Asserted-Identity: <sip:al...@open-ims.test>
Content-Length: 247

v=0
o=alice 3468086555 3468086555 IN IP4 127.0.0.1
s=A SIPp Stream
c=IN IP4 127.0.0.1
t=0 0
m=audio 23002 RTP/AVP 0 8 14
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:14 MPA/8000

q=6.6.5.3
a=recvonly:80
q=6.6.4.1
a=maxCapacity:100
at
org.mobicents.servlet.sip.core.dispatchers.SubsequentRequestDispatcher.dispatchMessage
(SubsequentRequestDispatcher.java:147)
at
org.mobicents.servlet.sip.core.SipApplicationDispatcherImpl.processRequest
(SipApplicationDispatcherImpl.java:616)
at gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:
224)
at gov.nist.javax.sip.SipProviderImpl.handleEvent
(SipProviderImpl.java:192)
at gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:
1080)
at gov.nist.javax.sip.stack.SIPServerTransaction.processRequest
(SIPServerTransaction.java:810)
at gov.nist.javax.sip.stack.UDPMessageChannel.processMessage
(UDPMessageChannel.java:459)
at
gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket
(UDPMessageChannel.java:419)
at gov.nist.javax.sip.stack.UDPMessageChannel.run
(UDPMessageChannel.java:266)
at java.lang.Thread.run(Thread.java:619)
17:47:35,708 INFO [Mobicents-SIP-Servlets] <message
from="127.0.0.1:5080"
to="127.0.0.1:4060"
time="1262710055707"
isSender="true"
transactionId="z9hg4bk491b.45d95c37.0"
callId="1-5...@127.0.0.1"
firstLine="SIP/2.0 500 Server Internal Error"
>
<![CDATA[SIP/2.0 500 Server Internal Error

From: <sip:al...@open-ims.test>;tag=1
To: <sip:sp...@msm.open-ims.test>;tag=1

Via: SIP/2.0/UDP 127.0.0.1:4060;branch=z9hG4bK491b.45d95c37.0
Via: SIP/2.0/UDP 127.0.0.1:5090;rport=5090;branch=z9hG4bK-5320-1-4
Call-ID: 1-5...@127.0.0.1
CSeq: 2 PRACK
Content-Length: 0

]]>
</message>

17:47:37,614 INFO [SipApplicationDispatcherImpl] transaction
gov.nist.javax.sip.stack.SIPServerTransaction@64f6e43d terminated =>
CANCEL sip:sp...@msm.open-ims.test SIP/2.0
Max-Forwards: 10
Route: <sip:isc...@scscf.open-ims.test:
6060;lr;s=2;h=0;d=0;a=7369703a616c696365406f70656e2d696d732e74657374>
Via: SIP/2.0/UDP 127.0.0.1:6060;branch=z9hG4bK59e8.393428c3.0
Via: SIP/2.0/UDP 127.0.0.1:4060;branch=z9hG4bK59e8.f0da0c67.0
From: <sip:al...@open-ims.test>;tag=1
Call-ID: 1-5...@127.0.0.1
To: <sip:sp...@msm.open-ims.test>;tag=1
CSeq: 1 CANCEL
User-Agent: Sip EXpress router(2.1.0-dev1 OpenIMSCore (i386/linux))
Content-Length: 0

17:47:51,655 INFO [SipApplicationSessionImpl] Invalidating the
following sip application session (6253389249014:ModalityAdaptation)
17:47:51,656 INFO [SipSessionImpl] Invalidating the sip session
(1:1-5...@127.0.0.1:6253389249014:ModalityAdaptation)
17:47:51,657 INFO [SipApplicationSessionImpl] The following sip
application session (6253389249014:ModalityAdaptation) has been
invalidated
17:48:05,607 INFO [SipApplicationSessionImpl] Invalidating the
following sip application session (6267351034587:ModalityAdaptation)
17:48:05,610 INFO [SipSessionImpl] Invalidating the sip session
(1:1-5...@127.0.0.1:6267351034587:ModalityAdaptation)
17:48:05,610 INFO [SipApplicationSessionImpl] The following sip
application session (6267351034587:ModalityAdaptation) has been
invalidated
17:48:07,749 INFO [SipApplicationDispatcherImpl] transaction
gov.nist.javax.sip.stack.SIPServerTransaction@cb227203 terminated =>

PRACK sip:127.0.0.1:5080 SIP/2.0
From: <sip:al...@open-ims.test>;tag=1
To: <sip:sp...@msm.open-ims.test>;tag=1

Via: SIP/2.0/UDP 127.0.0.1:4060;branch=z9hG4bK491b.45d95c37.0
Via: SIP/2.0/UDP 127.0.0.1:5090;rport=5090;branch=z9hG4bK-5320-1-4
Call-ID: 1-5...@127.0.0.1

CSeq: 2 PRACK
Contact: <sip:al...@127.0.0.1:5090>
Max-Forwards: 16

RAck: 88 1 INVITE

Content-Type: application/sdp
P-Asserted-Identity: <sip:al...@open-ims.test>
Content-Length: 247

v=0
o=alice 3468086555 3468086555 IN IP4 127.0.0.1
s=A SIPp Stream
c=IN IP4 127.0.0.1
t=0 0
m=audio 23002 RTP/AVP 0 8 14
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:14 MPA/8000

q=6.6.5.3
a=recvonly:80
q=6.6.4.1
a=maxCapacity:100

Thanks again.

Hui WANG

On Jan 4, 11:48 am, Jean Deruelle <jean.derue...@gmail.com> wrote:
> Can u provide the full server.log file in DEBUG mode so that we can try to
> find what the problem is ?
> a wireshark trace or tcpdump would be nice as well
>
> Thanks
> Jean
>

[Jean Deruelle]

I cannot figure out what the problem is only with those logs.

Modify JBOSS_HOME/server/default/conf/jboss-log4j.xml to set the various threshold to DEBUG instead of INFO

Then please attach the corresponding server.log.

If you get a 404 error just by switching that is not good and we need to fix that as well

Thanks

Jean

[Hui WANG]

Thanks very much for your patience given for a beginner.

There are the server log in debug mode is too big, I can't upload it.
Can i send you by email.

On Jan 5, 6:19 pm, Jean Deruelle <jean.derue...@gmail.com> wrote:
> I cannot figure out what the problem is only with those logs.
>
> Modify JBOSS_HOME/server/default/conf/jboss-log4j.xml to set the various
> threshold to DEBUG instead of INFO
> Then please attach the corresponding server.log.
>
> If you get a 404 error just by switching that is not good and we need to fix
> that as well
>
> Thanks
> Jean
>

> On Tue, Jan 5, 2010 at 6:01 PM, Hui WANG <whuisonl...@gmail.com> wrote:
> > Hi Jean,
>
> > Thanks for you reply.
>
> > What confuses me is that in the 183 response, the Record-Route header
> > is missing.
> > When switching to debug mode, i got a 404 error. So I'm attaching the
> > log from the running mode.
>
> > 17:47:35,669 INFO  [Mobicents-SIP-Servlets] <message
> > from="127.0.0.1:6060"
> > to="127.0.0.1:5080"
> > time="1262710055666"
> > isSender="false"
> > transactionId="z9hg4bk791b.77676ad.0"
> > callId="1-5...@127.0.0.1"
> > firstLine="INVITE sip:sp...@msm.open-ims.test SIP/2.0"
>
> > <![CDATA[INVITE sip:sp...@msm.open-ims.test SIP/2.0
> > Record-Route: <sip:m...@scscf.open-ims.test:6060;lr>
> > Record-Route: <sip:m...@pcscf.open-ims.test:4060;lr>
> > Route: <sip:127.0.0.1:5080;lr>

> > Route: <sip:iscm...@scscf.open-ims.test:

> > Route: <sip:iscm...@scscf.open-ims.test:

> > Route: <sip:iscm...@scscf.open-ims.test:

> > 6060;lr;s=2;h=0;d=0;a=7369703a616c696365406f70656e2d696d732e74657374>
> > Via: SIP/2.0/UDP 127.0.0.1:6060;branch=z9hG4bK59e8.393428c3.0
> > Via: SIP/2.0/UDP 127.0.0.1:4060;branch=z9hG4bK59e8.f0da0c67.0
> > From: <sip:al...@open-ims.test>;tag=1
> > Call-ID: 1-5...@127.0.0.1
> > To: <sip:sp...@msm.open-ims.test>;tag=1
> > CSeq: 1 CANCEL
> > User-Agent: Sip EXpress router(2.1.0-dev1 OpenIMSCore (i386/linux))
> > Content-Length: 0
>
> > 17:47:51,655 INFO  [SipApplicationSessionImpl] Invalidating the
> > following sip application session (6253389249014:ModalityAdaptation)
> > 17:47:51,656 INFO  [SipSessionImpl] Invalidating the sip session
> > (1:1-5...@127.0.0.1:6253389249014:ModalityAdaptation)
> > 17:47:51,657 INFO  [SipApplicationSessionImpl] The following sip
>

> ...
>
> read more »

[Jean Deruelle]

I made some space on mobicents-public files section, or u can use rapdishare or dropbox to share it. Alternatively you can remove all the logging of the server startup if that is what is taking too much space. It's better not to send it to me directly so that the community can help out as well.

Thanks

Jean

[Hui WANG]

Hi Jean, sorry about the delay. Here are the debug log and wireshark
trace.

http://mobicents-public.googlegroups.com/web/prack_problem_wireshark_trace?gsc=rtLTwAsAAADGriy1wuqI6NZMoKUdL0nQ
http://mobicents-public.googlegroups.com/web/prack_problem_debug.txt?gsc=rtLTwAsAAADGriy1wuqI6NZMoKUdL0nQ

The current mss version is 1.0

Thanks very much for your help

Best regards

On Jan 6, 6:18 pm, Jean Deruelle <jean.derue...@gmail.com> wrote:
> I made some space on mobicents-public files section, or u can use rapdishare
> or dropbox to share it. Alternatively you can remove all the logging of the
> server startup if that is what is taking too much space. It's better not to
> send it to me directly so that the community can help out as well.
>
> Thanks
> Jean
>

> ...
>
> read more »

[Jean Deruelle]

Your INVITE has a To Tag which is incorrect for an initial request

Also please switch to the latest MSS version which is 1.1

[Hui WANG]

Thank you once again, Jean. You are life saving !

I'm wondering whether there are some tools we can use to program in
the server side.
I want to avoid this kind of mistakes concerned with the protocol.
Currently, I'm using SIPp to simulate the scenario.

On Jan 12, 9:16 am, Jean Deruelle <jean.derue...@gmail.com> wrote:
> Your INVITE has a To Tag which is incorrect for an initial request
> Also please switch to the latest MSS version which is 1.1
>

> On Mon, Jan 11, 2010 at 9:50 PM, Hui WANG <whuisonl...@gmail.com> wrote:
> > Hi Jean, sorry about the delay. Here are the debug log and wireshark
> > trace.
>

> >http://mobicents-public.googlegroups.com/web/prack_problem_wireshark_...
>
> >http://mobicents-public.googlegroups.com/web/prack_problem_debug.txt?...

> ...
>
> read more »

[Jean Deruelle]

We are using sipp as well for load testing.

If you just want to do some unit testing you can embed jain sip into junit or use testing framework that can do the job for you such as http://echarts.org/KitCAT/ from AT&T or http://www.cafesip.org/projects/sipunit/ from cafesip

Jean