Unexpected exception while processing request ACK

[Vadim]

I see the exception below and I am not sure why.

SCENARIO: I receive an INVITE from a media server. I send OK, and
media server receives it. Media server sends me an ACK, after
receiving the OK. Instead of seeing it in doAck() in sipservlet, I
get the exception below.

Any ideas? I took the SipServlet out of the path of the call flow and
UAC (SJ Phone as well as X-Lite) both register ACKs properly.


12:27:45,015 INFO [SipApplicationDispatcherImpl] Got a request event
ACK sip:10.15.178.47:5080;fina
l_response=true;transport=udp;appname=com.test.sip.servlet.ClickToCallSipServlet
SIP/2.0
From: <sip:
7038731123@10.15.181.84:5060;crID=010000089684;type=outbound>;tag=nu-
d7f-fb0e
To: <sip:917032...@10.15.178.103:5060>;tag=71834971_f955b5d0
Call-ID: 5e4f77de2455fe36...@0.0.0.0
CSeq: 1 ACK
Route: <sip:10.15.178.47:5080;transport=udp>
Via: SIP/2.0/UDP 10.15.181.84:5060;branch=z9Hg4Bkc75486e9-
b818-11de-9316-f38726c94010
Content-Length: 0


12:27:45,015 INFO [SipApplicationDispatcherImpl] ServerTx ref
gov.nist.javax.sip.stack.SIPServerTra
nsaction@9ae01f0a
12:27:45,015 INFO [SipApplicationDispatcherImpl] Dialog ref
gov.nist.javax.sip.stack.SIPDialog@e301
d6
12:27:45,015 INFO [SipApplicationDispatcherImpl] Routing State
SUBSEQUENT
12:27:45,015 INFO [SubsequentRequestDispatcher] Routing of Subsequent
Request ACK sip:10.15.178.47:
5080;final_response=true;transport=udp;appname=com.test.sip.servlet.ClickToCallSipServlet
SIP/2.0
From: <sip:
7038731123@10.15.181.84:5060;crID=010000089684;type=outbound>;tag=nu-
d7f-fb0e
To: <sip:917032...@10.15.178.103:5060>;tag=71834971_f955b5d0
Call-ID: 5e4f77de2455fe36...@0.0.0.0
CSeq: 1 ACK
Via: SIP/2.0/UDP 10.15.181.84:5060;branch=z9Hg4Bkc75486e9-
b818-11de-9316-f38726c94010
Content-Length: 0


12:27:45,031 ERROR [SipApplicationDispatcherImpl] Unexpected exception
while processing request ACK
sip:
10.15.178.47:5080;final_response=true;transport=udp;appname=com.test.sip.servlet.ClickToCallSipS
ervlet SIP/2.0
From: <sip:
7038731123@10.15.181.84:5060;crID=010000089684;type=outbound>;tag=nu-
d7f-fb0e
To: <sip:917032...@10.15.178.103:5060>;tag=71834971_f955b5d0
Call-ID: 5e4f77de2455fe36...@0.0.0.0
CSeq: 1 ACK
Via: SIP/2.0/UDP 10.15.181.84:5060;branch=z9Hg4Bkc75486e9-
b818-11de-9316-f38726c94010
Content-Length: 0


org.mobicents.servlet.sip.core.dispatchers.DispatcherException: cannot
find the application to handl
e this subsequent request in this popped routed header <sip:
10.15.178.47:5080;transport=udp>
at
org.mobicents.servlet.sip.core.dispatchers.SubsequentRequestDispatcher.dispatchMessage
(Su
bsequentRequestDispatcher.java:113)
at
org.mobicents.servlet.sip.core.SipApplicationDispatcherImpl.processRequest
(SipApplication
DispatcherImpl.java:565)
at gov.nist.javax.sip.EventScanner.deliverEvent
(EventScanner.java:223)
at gov.nist.javax.sip.SipProviderImpl.handleEvent
(SipProviderImpl.java:158)
at gov.nist.javax.sip.DialogFilter.processRequest
(DialogFilter.java:917)
at gov.nist.javax.sip.stack.SIPServerTransaction.processRequest
(SIPServerTransaction.java:84
3)
at gov.nist.javax.sip.stack.UDPMessageChannel.processMessage
(UDPMessageChannel.java:454)
at
gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket
(UDPMessageChannel.ja
va:413)
at gov.nist.javax.sip.stack.UDPMessageChannel.run
(UDPMessageChannel.java:257)
at java.lang.Thread.run(Thread.java:619)
12:27:45,109 INFO [Mobicents-SIP-Servlets] <message
from="10.15.181.84:5060"
to="0.0.0.0:5080"
time="1255451265109"
isSender="false"
transactionId="z9hg4bk54e8ad38494d7a6b5a4d04cf6eb77e20"
callId="5e4f77de2455fe36...@0.0.0.0"
firstLine="SIP/2.0 200 Ok"
>
<![CDATA[SIP/2.0 200 Ok
Via: SIP/2.0/UDP
0.0.0.0:5080;branch=z9hG4bK54e8ad38494d7a6b5a4d04cf6eb77e20;received=10.15.178.47
From: <sip:917032...@10.15.178.103:5060>;tag=71834971_f955b5d0
To: <sip:
7038731123@10.15.181.84:5060;type=outbound;crID=010000089684>;tag=nu-
d7f-fb0e
Call-ID: 5e4f77de2455fe36...@0.0.0.0
CSeq: 2 INVITE
Content-Type: application/sdp
Contact: <sip:n...@10.15.181.84:5060>;transport=udp
Content-Length: 191

v=0
o=- 1255452743 1255452743 IN IP4 10.15.181.84
s=SIP Call
t=0 0
m=audio 4480 RTP/AVP 0 101
c=IN IP4 0.0.0.0
a=rtpmap:0 pcmu/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
]]>
</message>

12:27:45,125 INFO [SipApplicationDispatcherImpl] Response SIP/2.0 200
Ok
Via: SIP/2.0/UDP
0.0.0.0:5080;branch=z9hG4bK54e8ad38494d7a6b5a4d04cf6eb77e20;received=10.15.178.47
From: <sip:917032...@10.15.178.103:5060>;tag=71834971_f955b5d0
To: <sip:
7038731123@10.15.181.84:5060;type=outbound;crID=010000089684>;tag=nu-
d7f-fb0e
Call-ID: 5e4f77de2455fe36...@0.0.0.0
CSeq: 2 INVITE
Content-Type: application/sdp
Contact: <sip:n...@10.15.181.84:5060>;transport=udp
Content-Length: 191

v=0
o=- 1255452743 1255452743 IN IP4 10.15.181.84
s=SIP Call
t=0 0
m=audio 4480 RTP/AVP 0 101
c=IN IP4 0.0.0.0
a=rtpmap:0 pcmu/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15

12:27:45,140 INFO [ResponseDispatcher] viaHeader = Via: SIP/2.0/UDP
0.0.0.0:5080;branch=z9hG4bK54e8
ad38494d7a6b5a4d04cf6eb77e20;received=10.15.178.47

12:27:45,140 INFO [SipApplicationDispatcherImpl] transaction
gov.nist.javax.sip.stack.SIPClientTran
saction@f0bf5ded terminated => INVITE sip:10.15.178.103:5060 SIP/2.0
CSeq: 2 INVITE
Call-ID: 5e4f77de2455fe36...@0.0.0.0
From: <sip:
7038731123@10.15.181.84:5060;crID=010000089684;type=outbound>;tag=02573483_f955b5d0
To: <sip:917032...@10.15.178.103:5060>;tag=13207978271088691719
Max-Forwards: 70
Contact: <sip:0.0.0.0:5080;transport=udp>
Content-Type: application/sdp
Via: SIP/2.0/UDP
10.15.178.47:5080;branch=z9hG4bKa27f394ac3ca703103e42c7bdae0b54a;appname=com.test.s
ip.servlet.ClickToCallSipServlet
Content-Length: 191

v=0
o=- 1255452743 1255452743 IN IP4 10.15.181.84
s=SIP Call
c=IN IP4 0.0.0.0
t=0 0
m=audio 4480 RTP/AVP 0 101
a=rtpmap:0 pcmu/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15

[Jean Deruelle]

Which version are you using ?

Could you provide the full log files located at JBOSS_HOME/server/default/log and attach it to this email ?

Thanks in advance

Jean

[Vadim]

I am using Mobicents 1.2.0, and the log files have been uploaded to
http://groups.google.com/group/mobicents-public/web/ack_req_exception_log.zip

Also, I have a WireShark PCAP if you need it.

Thank You for your help,
Vadim

On Oct 13, 3:03 pm, Jean Deruelle <jean.derue...@gmail.com> wrote:
> Which version are you using ?
> Could you provide the full log files located at
> JBOSS_HOME/server/default/log and attach it to this email ?
>
> Thanks in advance
> Jean
>
>
>
> On Tue, Oct 13, 2009 at 7:01 PM, Vadim <vadim.snitkov...@gmail.com> wrote:
>
> > I see the exception below and I am not sure why.
>
> > SCENARIO: I receive an INVITE from a media server.  I send OK, and
> > media server receives it.  Media server sends me an ACK, after
> > receiving the OK.  Instead of seeing it in doAck() in sipservlet, I
> > get the exception below.
>
> > Any ideas? I took the SipServlet out of the path of the call flow and
> > UAC (SJ Phone as well as X-Lite) both register ACKs properly.
>
> > 12:27:45,015 INFO  [SipApplicationDispatcherImpl] Got a request event
> > ACK sip:10.15.178.47:5080;fina
>

> > l_response=true;transport=udp;appname=com.test.sip.servlet.ClickToCallSipSe rvlet
> > SIP/2.0
> > From: <sip:

> > 7038731...@10.15.181.84:5060;crID=010000089684;type=outbound>;tag=nu-
> > d7f-fb0e
> > To: <sip:917032878...@10.15.178.103:5060>;tag=71834971_f955b5d0
> > Call-ID: 5e4f77de2455fe36aad67ab2aff9d...@0.0.0.0

> > CSeq: 1 ACK
> > Route: <sip:10.15.178.47:5080;transport=udp>
> > Via: SIP/2.0/UDP 10.15.181.84:5060;branch=z9Hg4Bkc75486e9-
> > b818-11de-9316-f38726c94010
> > Content-Length: 0
>
> > 12:27:45,015 INFO  [SipApplicationDispatcherImpl] ServerTx ref
> > gov.nist.javax.sip.stack.SIPServerTra
> > nsaction@9ae01f0a
> > 12:27:45,015 INFO  [SipApplicationDispatcherImpl] Dialog ref
> > gov.nist.javax.sip.stack.SIPDialog@e301
> > d6
> > 12:27:45,015 INFO  [SipApplicationDispatcherImpl] Routing State
> > SUBSEQUENT
> > 12:27:45,015 INFO  [SubsequentRequestDispatcher] Routing of Subsequent
> > Request ACK sip:10.15.178.47:
>

> > 5080;final_response=true;transport=udp;appname=com.test.sip.servlet.ClickTo CallSipServlet
> > SIP/2.0
> > From: <sip:

> > 7038731...@10.15.181.84:5060;crID=010000089684;type=outbound>;tag=nu-
> > d7f-fb0e
> > To: <sip:917032878...@10.15.178.103:5060>;tag=71834971_f955b5d0
> > Call-ID: 5e4f77de2455fe36aad67ab2aff9d...@0.0.0.0

> > CSeq: 1 ACK
> > Via: SIP/2.0/UDP 10.15.181.84:5060;branch=z9Hg4Bkc75486e9-
> > b818-11de-9316-f38726c94010
> > Content-Length: 0
>
> > 12:27:45,031 ERROR [SipApplicationDispatcherImpl] Unexpected exception
> > while processing request ACK
> > sip:
> > 10.15.178.47:5080
> > ;final_response=true;transport=udp;appname=com.test.sip.servlet.ClickToCall SipS
> > ervlet SIP/2.0
> > From: <sip:

> > 7038731...@10.15.181.84:5060;crID=010000089684;type=outbound>;tag=nu-
> > d7f-fb0e
> > To: <sip:917032878...@10.15.178.103:5060>;tag=71834971_f955b5d0
> > Call-ID: 5e4f77de2455fe36aad67ab2aff9d...@0.0.0.0

> > callId="5e4f77de2455fe36aad67ab2aff9d...@0.0.0.0"

> > firstLine="SIP/2.0 200 Ok"
>
> > <![CDATA[SIP/2.0 200 Ok
> > Via: SIP/2.0/UDP
> > 0.0.0.0:5080
> > ;branch=z9hG4bK54e8ad38494d7a6b5a4d04cf6eb77e20;received=10.15.178.47

> > From: <sip:917032878...@10.15.178.103:5060>;tag=71834971_f955b5d0
> > To: <sip:
> > 7038731...@10.15.181.84:5060;type=outbound;crID=010000089684>;tag=nu-
> > d7f-fb0e
> > Call-ID: 5e4f77de2455fe36aad67ab2aff9d...@0.0.0.0

> > CSeq: 2 INVITE
> > Content-Type: application/sdp
> > Contact: <sip:n...@10.15.181.84:5060>;transport=udp
> > Content-Length: 191
>
> > v=0
> > o=- 1255452743 1255452743 IN IP4 10.15.181.84
> > s=SIP Call
> > t=0 0
> > m=audio 4480 RTP/AVP 0 101
> > c=IN IP4 0.0.0.0
> > a=rtpmap:0 pcmu/8000
> > a=rtpmap:101 telephone-event/8000
> > a=fmtp:101 0-15
> > ]]>
> > </message>
>
> > 12:27:45,125 INFO  [SipApplicationDispatcherImpl] Response SIP/2.0 200
> > Ok
> > Via: SIP/2.0/UDP
> > 0.0.0.0:5080
> > ;branch=z9hG4bK54e8ad38494d7a6b5a4d04cf6eb77e20;received=10.15.178.47

> > From: <sip:917032878...@10.15.178.103:5060>;tag=71834971_f955b5d0
> > To: <sip:
> > 7038731...@10.15.181.84:5060;type=outbound;crID=010000089684>;tag=nu-
> > d7f-fb0e
> > Call-ID: 5e4f77de2455fe36aad67ab2aff9d...@0.0.0.0

> > CSeq: 2 INVITE
> > Content-Type: application/sdp
> > Contact: <sip:n...@10.15.181.84:5060>;transport=udp
> > Content-Length: 191
>
> > v=0
> > o=- 1255452743 1255452743 IN IP4 10.15.181.84
> > s=SIP Call
> > t=0 0
> > m=audio 4480 RTP/AVP 0 101
> > c=IN IP4 0.0.0.0
> > a=rtpmap:0 pcmu/8000
> > a=rtpmap:101 telephone-event/8000
> > a=fmtp:101 0-15
>
> > 12:27:45,140 INFO  [ResponseDispatcher] viaHeader = Via: SIP/2.0/UDP
> > 0.0.0.0:5080;branch=z9hG4bK54e8
> > ad38494d7a6b5a4d04cf6eb77e20;received=10.15.178.47
>
> > 12:27:45,140 INFO  [SipApplicationDispatcherImpl] transaction
> > gov.nist.javax.sip.stack.SIPClientTran
> > saction@f0bf5ded terminated => INVITE sip:10.15.178.103:5060 SIP/2.0
> > CSeq: 2 INVITE

> > Call-ID: 5e4f77de2455fe36aad67ab2aff9d...@0.0.0.0
> > From: <sip:
> > 7038731...@10.15.181.84:5060
> > ;crID=010000089684;type=outbound>;tag=02573483_f955b5d0
> > To: <sip:917032878...@10.15.178.103:5060>;tag=13207978271088691719

[Vadim]

attaching in a minute

On Oct 13, 3:03 pm, Jean Deruelle <jean.derue...@gmail.com> wrote:

> Which version are you using ?
> Could you provide the full log files located at
> JBOSS_HOME/server/default/log and attach it to this email ?
>
> Thanks in advance
> Jean
>
>
>
> On Tue, Oct 13, 2009 at 7:01 PM, Vadim <vadim.snitkov...@gmail.com> wrote:
>
> > I see the exception below and I am not sure why.
>
> > SCENARIO: I receive an INVITE from a media server.  I send OK, and
> > media server receives it.  Media server sends me an ACK, after
> > receiving the OK.  Instead of seeing it in doAck() in sipservlet, I
> > get the exception below.
>
> > Any ideas? I took the SipServlet out of the path of the call flow and
> > UAC (SJ Phone as well as X-Lite) both register ACKs properly.
>
> > 12:27:45,015 INFO  [SipApplicationDispatcherImpl] Got a request event
> > ACK sip:10.15.178.47:5080;fina
>

> > l_response=true;transport=udp;appname=com.test.sip.servlet.ClickToCallSipSe rvlet
> > SIP/2.0
> > From: <sip:

> > 7038731...@10.15.181.84:5060;crID=010000089684;type=outbound>;tag=nu-
> > d7f-fb0e

> > To: <sip:917032878...@10.15.178.103:5060>;tag=71834971_f955b5d0
> > Call-ID: 5e4f77de2455fe36aad67ab2aff9d...@0.0.0.0

> > CSeq: 1 ACK
> > Route: <sip:10.15.178.47:5080;transport=udp>
> > Via: SIP/2.0/UDP 10.15.181.84:5060;branch=z9Hg4Bkc75486e9-
> > b818-11de-9316-f38726c94010
> > Content-Length: 0
>
> > 12:27:45,015 INFO  [SipApplicationDispatcherImpl] ServerTx ref
> > gov.nist.javax.sip.stack.SIPServerTra
> > nsaction@9ae01f0a
> > 12:27:45,015 INFO  [SipApplicationDispatcherImpl] Dialog ref
> > gov.nist.javax.sip.stack.SIPDialog@e301
> > d6
> > 12:27:45,015 INFO  [SipApplicationDispatcherImpl] Routing State
> > SUBSEQUENT
> > 12:27:45,015 INFO  [SubsequentRequestDispatcher] Routing of Subsequent
> > Request ACK sip:10.15.178.47:
>

> > 5080;final_response=true;transport=udp;appname=com.test.sip.servlet.ClickTo CallSipServlet
> > SIP/2.0
> > From: <sip:

> > 7038731...@10.15.181.84:5060;crID=010000089684;type=outbound>;tag=nu-
> > d7f-fb0e

> > To: <sip:917032878...@10.15.178.103:5060>;tag=71834971_f955b5d0
> > Call-ID: 5e4f77de2455fe36aad67ab2aff9d...@0.0.0.0

> > CSeq: 1 ACK
> > Via: SIP/2.0/UDP 10.15.181.84:5060;branch=z9Hg4Bkc75486e9-
> > b818-11de-9316-f38726c94010
> > Content-Length: 0
>
> > 12:27:45,031 ERROR [SipApplicationDispatcherImpl] Unexpected exception
> > while processing request ACK
> > sip:
> > 10.15.178.47:5080

> > ;final_response=true;transport=udp;appname=com.test.sip.servlet.ClickToCall SipS
> > ervlet SIP/2.0
> > From: <sip:

> > 7038731...@10.15.181.84:5060;crID=010000089684;type=outbound>;tag=nu-
> > d7f-fb0e

> > To: <sip:917032878...@10.15.178.103:5060>;tag=71834971_f955b5d0
> > Call-ID: 5e4f77de2455fe36aad67ab2aff9d...@0.0.0.0

> > callId="5e4f77de2455fe36aad67ab2aff9d...@0.0.0.0"

> > firstLine="SIP/2.0 200 Ok"
>
> > <![CDATA[SIP/2.0 200 Ok
> > Via: SIP/2.0/UDP
> > 0.0.0.0:5080
> > ;branch=z9hG4bK54e8ad38494d7a6b5a4d04cf6eb77e20;received=10.15.178.47

> > From: <sip:917032878...@10.15.178.103:5060>;tag=71834971_f955b5d0
> > To: <sip:

> > 7038731...@10.15.181.84:5060;type=outbound;crID=010000089684>;tag=nu-
> > d7f-fb0e
> > Call-ID: 5e4f77de2455fe36aad67ab2aff9d...@0.0.0.0

> > CSeq: 2 INVITE
> > Content-Type: application/sdp
> > Contact: <sip:n...@10.15.181.84:5060>;transport=udp
> > Content-Length: 191
>
> > v=0
> > o=- 1255452743 1255452743 IN IP4 10.15.181.84
> > s=SIP Call
> > t=0 0
> > m=audio 4480 RTP/AVP 0 101
> > c=IN IP4 0.0.0.0
> > a=rtpmap:0 pcmu/8000
> > a=rtpmap:101 telephone-event/8000
> > a=fmtp:101 0-15
> > ]]>
> > </message>
>
> > 12:27:45,125 INFO  [SipApplicationDispatcherImpl] Response SIP/2.0 200
> > Ok
> > Via: SIP/2.0/UDP
> > 0.0.0.0:5080
> > ;branch=z9hG4bK54e8ad38494d7a6b5a4d04cf6eb77e20;received=10.15.178.47

> > From: <sip:917032878...@10.15.178.103:5060>;tag=71834971_f955b5d0
> > To: <sip:

> > 7038731...@10.15.181.84:5060;type=outbound;crID=010000089684>;tag=nu-
> > d7f-fb0e
> > Call-ID: 5e4f77de2455fe36aad67ab2aff9d...@0.0.0.0

> > CSeq: 2 INVITE
> > Content-Type: application/sdp
> > Contact: <sip:n...@10.15.181.84:5060>;transport=udp
> > Content-Length: 191
>
> > v=0
> > o=- 1255452743 1255452743 IN IP4 10.15.181.84
> > s=SIP Call
> > t=0 0
> > m=audio 4480 RTP/AVP 0 101
> > c=IN IP4 0.0.0.0
> > a=rtpmap:0 pcmu/8000
> > a=rtpmap:101 telephone-event/8000
> > a=fmtp:101 0-15
>
> > 12:27:45,140 INFO  [ResponseDispatcher] viaHeader = Via: SIP/2.0/UDP
> > 0.0.0.0:5080;branch=z9hG4bK54e8
> > ad38494d7a6b5a4d04cf6eb77e20;received=10.15.178.47
>
> > 12:27:45,140 INFO  [SipApplicationDispatcherImpl] transaction
> > gov.nist.javax.sip.stack.SIPClientTran
> > saction@f0bf5ded terminated => INVITE sip:10.15.178.103:5060 SIP/2.0
> > CSeq: 2 INVITE

> > Call-ID: 5e4f77de2455fe36aad67ab2aff9d...@0.0.0.0
> > From: <sip:
> > 7038731...@10.15.181.84:5060
> > ;crID=010000089684;type=outbound>;tag=02573483_f955b5d0
> > To: <sip:917032878...@10.15.178.103:5060>;tag=13207978271088691719

[Vadim]

I have just tested the same code with Mobicents 1.2.1, and have
reproduced the same issue. The error is slightly different, but the
exception is the unexpected exception while processing ack.

In case you need more details, I am doing the following (a sort of
click to call application):

1. send 2 invites to a UAC1 and a MediaServer.
2. get OKs from both and send on ACKs with corresponding SDPs.
3. At some point MediaServer will need to put UAC1 on hold, this is
where MediaServer send me the INVITE with hold SDP
4. in doInvite(), I receive this invite and create new one (from the
session.createRequest()) for the UAC1 with hold SDP from MediaServer,
at the same time I send TRYING to MediaServer, and save OK in the
session to send to MediaServer as soon as I receive OK from UAC1.
5. I get OK from UAC1, which I receive in doSuccessResponse(), and I
retrieve OK from step 4 from session, set SDP on that OK from UAC1 and
send it on to the MediaServer. Here I also create an ACK for UAC1 and
store it in corresponding session, for use after I receive the ACK
from MediaServer.
6. At this point, all I need is ACK from MediaServer to the OK that I
just sent in. And, as soon as I send that ACK to the UAC1 the
interaction will be complete. So, in doAck() we wait for the ACK from
MediaServer, instead we get the message from the SipServletContainer
on our console:

Note: I examined the sip packets in WireShark and I do see that the
ACK contains
"transport=udp;appname=com.test.sip.servlet.ClickToCallSipServlet" not
sure if that helps.

12:27:45,031 ERROR [SipApplicationDispatcherImpl] Unexpected exception
while processing request ACK
sip:
10.15.178.47:5080;final_response=true;transport=udp;appname=com.test.sip.servlet.ClickToCallSipServlet
SIP/2.0
From: <sip:
7038731...@10.15.181.84:5060;crID=010000089684;type=outbound>;tag=nu-
d7f-fb0e
To: <sip:917032878...@10.15.178.103:5060>;tag=71834971_f955b5d0
Call-ID: 5e4f77de2455fe36aad67ab2aff9d...@0.0.0.0
CSeq: 1 ACK
Via: SIP/2.0/UDP 10.15.181.84:5060;branch=z9Hg4Bkc75486e9-
b818-11de-9316-f38726c94010
Content-Length: 0
org.mobicents.servlet.sip.core.dispatchers.DispatcherException: cannot

find the application to handle this subsequent request in this popped

[Vladimir Ralev]

This problem sounds a bit like strict routing vs loose routing
http://www.iptel.org/sip/intro/scenarios/rr/strict_vs_loose

By looking at the code we expect loose routing and we don't actually
check for info in the request URI. This could be a bug on our side. I
will look a bit deeper. In the mean time you could try to see if you
devices have any settings about strict/loose routing.

[Jean Deruelle]

Vadim,

 

We don't support strict routing indeed. Can you confirm that you have a strict routing element somewhere in your use case ?

Providing the Wireshark would prove useful as well

Can you create an Issue (preferrably in CSP if you have a JBCP subscription or in the GCode issue tracker otherwise) about that against the latest version (1.2.1) ?

Thanks in advance

Best regards

Jean

[Vadim]

I switched to Mobicents 1.2.1, and I have a slightly different
exception that is still related to ACK. That is doAck() is never
triggered.

Also, the OK that I sent back to the MediaServer in step 5 above, has
LR (Loose Routing) in it, so there is no reason for strict routing as
far as I can see. Actually, in the new PCAP there is no route anymore
in the Mobicents 1.2.1, plus I create the ok using
sipRequest.createResponse(SipServletResponse.SC_OK);

Since I switched to Mobicents 1.2.1, I am uploading the log and
WireShark PCAP for your review. Please see ACK packet number 1467,
timestamp 12:50:54.869638, it looks find on PCAP, but the servlet
container throws exception before it even gets to my sip servlet.

http://groups.google.com/group/mobicents-public/web/ack_req_exception_log2.zip

Vadim

[Jean Deruelle]

It's a bug on our side.

For SipSession, the id is of the form fromURI,fromTag,ToURI,ToTag(if present),CallId,appsessionid,appname

The sip session that cannot be found on the ACK tries to be found with this key :

(sip:917032...@10.15.178.103:5060,76620883_f955b5d0_10181084267443024,sip:7038731123@10.15.181.84:5060;type=outbound;crID=010000089708,6dbd01fd5366b95f...@0.0.0.0,10181084267443024,com.mstr.sip.servlet.ClickToCallSipServlet)

And the session key on the INVITE was :

(sip:917032...@10.15.178.103:5060,76620883_f955b5d0_10181084267443024,sip:7038731123@10.15.181.84:5060;crID=010000089708;type=outbound,6dbd01fd5366b95f...@0.0.0.0,10181084267443024,com.mstr.sip.servlet.ClickToCallSipServlet)

So the problem is with the URI params, since they switched between ACK and INVITE we cannot find the session on the ACK,

type=outbound param is first in the ACK instead of being second as in the INVITE, we cannot found the sip session.

A fix would be to not take the URI params into account for session key. (I actually thought it was not the case already)

Even better would be not use the from address and to address but just the tags as in RFC3261 for identifying a dialog but we have to check if that's possible

In any case, please file a bug. 

In the meantime, if you have control on the ACK creation you can try to have the parameters for the From Header URI in the same position as in the INVITE, this will correct the problem.

Thanks for the report,

Jean

[Jean Deruelle]

http://code.google.com/p/mobicents/issues/detail?id=1021

[Jean Deruelle]

I fixed it in trunk.

The CI job for producing the binary snapshot is a bit broken right now will update as soon as our hudson is back on track for you to test a binary containing the fix.

Jean

[Vadim]

We have just found another issue that I think is related. Does the fix
above address this one as well? It looks very very similar.

The BYE comes to the Mobicent Sip Servlet container, but then,
mobicents cannot find the corresponding session. Is this related?


12:08:03,116 INFO [Jain-Sip-Stack] <message
from="10.20.2.127"
to="10.20.2.45:5080"
time="1256918883115"
isSender="false"
transactionId="z9hg4bk6c1e246fcb1f16fe3a32f4fb9"
callId="c32338cce671a79c...@10.20.2.45"
firstLine="BYE sip:10.20.2.45:5080 SIP/2.0"
>
<![CDATA[BYE sip:10.20.2.45:5080 SIP/2.0^M
From: <sip:
8888137473@10.20.2.127:5060;crID=100107063341;type=outbound>;tag=ds-3af-5977^M
To: <sip:
19045...@10.20.2.127:5060>;tag=50464158_f955b5d0_3585987475461983^M
Contact: <sip:10.20.2.210:5062;transport=udp>^M
Call-ID: c32338cce671a79c...@10.20.2.45^M
CSeq: 1 BYE^M
Via: SIP/2.0/UDP 10.20.2.127;branch=z9hG4bK6c1e246fcb1f16fe3a32f4fb9^M
Via: SIP/2.0/UDP 10.20.2.210:5062^M
Max-Forwards: 70^M
Record-Route: <sip:10.20.2.127;lr>^M
Content-Length: 0^M
^M
]]>
</message>

12:08:03,118 ERROR [SipApplicationDispatcherImpl] Unexpected exception
while processing request BYE sip:10.20.2.45:5080 SIP/2.0^M
From: <sip:
8888137473@10.20.2.127:5060;crID=100107063341;type=outbound>;tag=ds-3af-5977^M
To: <sip:
19045...@10.20.2.127:5060>;tag=50464158_f955b5d0_3585987475461983^M
Contact: <sip:10.20.2.210:5062;transport=udp>^M
Call-ID: c32338cce671a79c...@10.20.2.45^M
CSeq: 1 BYE^M
Via: SIP/2.0/UDP 10.20.2.127;branch=z9hG4bK6c1e246fcb1f16fe3a32f4fb9^M
Via: SIP/2.0/UDP 10.20.2.210:5062^M
Max-Forwards: 70^M
Record-Route: <sip:10.20.2.127;lr>^M
Content-Length: 0^M
^M

org.mobicents.servlet.sip.core.dispatchers.DispatcherException: Cannot
find the corresponding sip application session to this subsequent
request BYE sip:10.20.2.45:5080 SIP/2.0^M
From: <sip:
8888137473@10.20.2.127:5060;crID=100107063341;type=outbound>;tag=ds-3af-5977^M
To: <sip:
19045...@10.20.2.127:5060>;tag=50464158_f955b5d0_3585987475461983^M
Contact: <sip:10.20.2.210:5062;transport=udp>^M
Call-ID: c32338cce671a79c...@10.20.2.45^M
CSeq: 1 BYE^M
Via: SIP/2.0/UDP 10.20.2.127;branch=z9hG4bK6c1e246fcb1f16fe3a32f4fb9^M
Via: SIP/2.0/UDP 10.20.2.210:5062^M
Max-Forwards: 70^M
Record-Route: <sip:10.20.2.127;lr>^M
Content-Length: 0^M
^M

with the following popped route header null
at
org.mobicents.servlet.sip.core.dispatchers.SubsequentRequestDispatcher.dispatchMessage
(SubsequentRequestDispatcher.java:174)
at
org.mobicents.servlet.sip.core.SipApplicationDispatcherImpl.processRequest
(SipApplicationDispatcherImpl.java:568)

at gov.nist.javax.sip.EventScanner.deliverEvent
(EventScanner.java:223)
at gov.nist.javax.sip.SipProviderImpl.handleEvent

(SipProviderImpl.java:184)
at gov.nist.javax.sip.DialogFilter.processRequest
(DialogFilter.java:944)
at gov.nist.javax.sip.stack.SIPServerTransaction.processRequest
(SIPServerTransaction.java:809)
at gov.nist.javax.sip.stack.UDPMessageChannel.processMessage
(UDPMessageChannel.java:455)
at
gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket
(UDPMessageChannel.java:414)
at gov.nist.javax.sip.stack.UDPMessageChannel.run
(UDPMessageChannel.java:258)
at java.lang.Thread.run(Thread.java:619)
12:08:03,119 INFO [Jain-Sip-Stack] <message
from="10.20.2.45:5080"
to="10.20.2.127:5060"
time="1256918883119"
isSender="true"
transactionId="z9hg4bk6c1e246fcb1f16fe3a32f4fb9"
callId="c32338cce671a79c...@10.20.2.45"
firstLine="SIP/2.0 500 Server Internal Error"
>
<![CDATA[SIP/2.0 500 Server Internal Error^M
From: <sip:
8888137473@10.20.2.127:5060;crID=100107063341;type=outbound>;tag=ds-3af-5977^M
To: <sip:
19045...@10.20.2.127:5060>;tag=50464158_f955b5d0_3585987475461983^M
Call-ID: c32338cce671a79c...@10.20.2.45^M
CSeq: 1 BYE^M
Via: SIP/2.0/UDP 10.20.2.127;branch=z9hG4bK6c1e246fcb1f16fe3a32f4fb9^M
Via: SIP/2.0/UDP 10.20.2.210:5062^M
Content-Length: 0^M
^M
]]>
</message>

On Oct 26, 1:31 pm, Jean Deruelle <jean.derue...@gmail.com> wrote:
> I fixed it in trunk.
> The CI job for producing the binary snapshot is a bit broken right now will
> update as soon as our hudson is back on track for you to test a binary
> containing the fix.
>
> Jean
>

> On Mon, Oct 26, 2009 at 6:10 PM, Jean Deruelle <jean.derue...@gmail.com>wrote:
>
>
>
> >http://code.google.com/p/mobicents/issues/detail?id=1021
>

> > On Wed, Oct 14, 2009 at 8:20 PM, Jean Deruelle <jean.derue...@gmail.com>wrote:
>
> >> It's a bug on our side.
> >> For SipSession, the id is of the form fromURI,fromTag,ToURI,ToTag(if
> >> present),CallId,appsessionid,appname
>
> >> The sip session that cannot be found on the ACK tries to be found with
> >> this key :

> >> (sip:917032878...@10.15.178.103:5060
> >> ,76620883_f955b5d0_10181084267443024,sip:7038731...@10.15.181.84:5060
> >> ;type=outbound;crID=010000089708,6dbd01fd5366b95fb9a0d32a30ad0...@0.0.0.0
> >> ,10181084267443024,com.mstr.sip.servlet.ClickToCallSipServlet)

>
> >> And the session key on the INVITE was :

> >> (sip:917032878...@10.15.178.103:5060
> >> ,76620883_f955b5d0_10181084267443024,sip:7038731...@10.15.181.84:5060
> >> ;crID=010000089708;type=outbound,6dbd01fd5366b95fb9a0d32a30ad0...@0.0.0.0
> >> ,10181084267443024,com.mstr.sip.servlet.ClickToCallSipServlet)

>
> >> So the problem is with the URI params, since they switched between ACK and
> >> INVITE we cannot find the session on the ACK,
> >> type=outbound param is first in the ACK instead of being second as in the
> >> INVITE, we cannot found the sip session.
>
> >> A fix would be to not take the URI params into account for session key. (I
> >> actually thought it was not the case already)
>
> >> Even better would be not use the from address and to address but just the
> >> tags as in RFC3261 for identifying a dialog but we have to check if that's
> >> possible
>
> >> In any case, please file a bug.
> >> In the meantime, if you have control on the ACK creation you can try to
> >> have the parameters for the From Header URI in the same position as in the
> >> INVITE, this will correct the problem.
>
> >> Thanks for the report,
> >> Jean
>

> >> On Wed, Oct 14, 2009 at 7:03 PM, Vadim <vadim.snitkov...@gmail.com>wrote:
>
> >>> I switched to Mobicents 1.2.1, and I have a slightly different
> >>> exception that is still related to ACK. That is doAck() is never
> >>> triggered.
>
> >>> Also, the OK that I sent back to the MediaServer in step 5 above, has
> >>> LR (Loose Routing) in it, so there is no reason for strict routing as
> >>> far as I can see.  Actually, in the new PCAP there is no route anymore
> >>> in the Mobicents 1.2.1, plus I create the ok using
> >>> sipRequest.createResponse(SipServletResponse.SC_OK);
>
> >>> Since I switched to Mobicents 1.2.1, I am uploading the log and
> >>> WireShark PCAP for your review.  Please see ACK packet number 1467,
> >>> timestamp 12:50:54.869638, it looks find on PCAP, but the servlet
> >>> container throws exception before it even gets to my sip servlet.
>

> >>>http://groups.google.com/group/mobicents-public/web/ack_req_exception...
>
> >>> Vadim

[Jean Deruelle]

Hi Vadim,

I would need the complete log file to be able to diagnose it.

The snapshot hudson job are back on track so you can test the binary containing all the fixes here :

http://hudson.jboss.org/hudson/job/MobicentsSipServletsRelease/ 

(starting from build 586)

If you could try it out, test and revert back to us that would be awesome

Thanks in advance

Jean

[Vadim]

I used the binary from: http://hudson.jboss.org/hudson/job/MobicentsSipServletsRelease/586/

I get ACKs now - great job on fixing that.

However, there is still an issue with a BYE. Logs are uploaded here:
http://groups.google.com/group/mobicents-public/web/errors_on_BYE_11_3_2009.zip

Thank You,
Vadim

PS I can start a new topic if it would help. Please, let me know.

On Nov 2, 8:45 am, Jean Deruelle <jean.derue...@gmail.com> wrote:
> Hi Vadim,
>
> I would need the complete log file to be able to diagnose it.
> The snapshot hudson job are back on track so you can test the binary
> containing all the fixes here :http://hudson.jboss.org/hudson/job/MobicentsSipServletsRelease/
> (starting from build 586)
> If you could try it out, test and revert back to us that would be awesome
>
> Thanks in advance
> Jean
>
>
>
> On Sat, Oct 31, 2009 at 5:43 AM, Vadim <vadim.snitkov...@gmail.com> wrote:
>
> > We have just found another issue that I think is related. Does the fix
> > above address this one as well?  It looks very very similar.
>
> > The BYE comes to the Mobicent Sip Servlet container, but then,
> > mobicents cannot find the corresponding session.  Is this related?
>
> > 12:08:03,116 INFO  [Jain-Sip-Stack] <message
> > from="10.20.2.127"
> > to="10.20.2.45:5080"
> > time="1256918883115"
> > isSender="false"
> > transactionId="z9hg4bk6c1e246fcb1f16fe3a32f4fb9"

> > callId="c32338cce671a79c991f5cea0c5f1...@10.20.2.45"

> > firstLine="BYE sip:10.20.2.45:5080 SIP/2.0"
>
> > <![CDATA[BYE sip:10.20.2.45:5080 SIP/2.0^M
> > From: <sip:

> > 8888137...@10.20.2.127:5060

> > ;crID=100107063341;type=outbound>;tag=ds-3af-5977^M
> > To: <sip:

> > 19045202...@10.20.2.127:5060>;tag=50464158_f955b5d0_3585987475461983^M

> > Contact: <sip:10.20.2.210:5062;transport=udp>^M

> > Call-ID: c32338cce671a79c991f5cea0c5f1...@10.20.2.45^M

> > CSeq: 1 BYE^M
> > Via: SIP/2.0/UDP 10.20.2.127;branch=z9hG4bK6c1e246fcb1f16fe3a32f4fb9^M
> > Via: SIP/2.0/UDP 10.20.2.210:5062^M
> > Max-Forwards: 70^M
> > Record-Route: <sip:10.20.2.127;lr>^M
> > Content-Length: 0^M
> > ^M
> > ]]>
> > </message>
>
> > 12:08:03,118 ERROR [SipApplicationDispatcherImpl] Unexpected exception
> > while processing request BYE sip:10.20.2.45:5080 SIP/2.0^M
> > From: <sip:

> > 8888137...@10.20.2.127:5060

> > ;crID=100107063341;type=outbound>;tag=ds-3af-5977^M
> > To: <sip:

> > 19045202...@10.20.2.127:5060>;tag=50464158_f955b5d0_3585987475461983^M

> > Contact: <sip:10.20.2.210:5062;transport=udp>^M

> > Call-ID: c32338cce671a79c991f5cea0c5f1...@10.20.2.45^M

> > CSeq: 1 BYE^M
> > Via: SIP/2.0/UDP 10.20.2.127;branch=z9hG4bK6c1e246fcb1f16fe3a32f4fb9^M
> > Via: SIP/2.0/UDP 10.20.2.210:5062^M
> > Max-Forwards: 70^M
> > Record-Route: <sip:10.20.2.127;lr>^M
> > Content-Length: 0^M
> > ^M
>
> > org.mobicents.servlet.sip.core.dispatchers.DispatcherException: Cannot
> > find the corresponding sip application session to this subsequent
> > request BYE sip:10.20.2.45:5080 SIP/2.0^M
> > From: <sip:

> > 8888137...@10.20.2.127:5060

> > ;crID=100107063341;type=outbound>;tag=ds-3af-5977^M
> > To: <sip:

> > 19045202...@10.20.2.127:5060>;tag=50464158_f955b5d0_3585987475461983^M

> > Contact: <sip:10.20.2.210:5062;transport=udp>^M

> > Call-ID: c32338cce671a79c991f5cea0c5f1...@10.20.2.45^M

> > callId="c32338cce671a79c991f5cea0c5f1...@10.20.2.45"

> > firstLine="SIP/2.0 500 Server Internal Error"
>
> > <![CDATA[SIP/2.0 500 Server Internal Error^M
> > From: <sip:

> > 8888137...@10.20.2.127:5060

> > ;crID=100107063341;type=outbound>;tag=ds-3af-5977^M
> > To: <sip:

> > 19045202...@10.20.2.127:5060>;tag=50464158_f955b5d0_3585987475461983^M
> > Call-ID: c32338cce671a79c991f5cea0c5f1...@10.20.2.45^M

[Vadim]

Just wanted to update you with some findings. Upon closer examination
of the log files I noticed that I see errors on BYE for certain
sessions. A closer look showed some of those sessions being
invalidated first. It makes sense that those should not be found by
the container after they are invalidated. One change I made is in
sip.xml for session-timeout to be longer, 60 minutes, as I understand
that by default it's something like 3 minutes.

<session-config>
<session-timeout>60</session-timeout>
</session-config>

This explains some of the BYEs not being able to find session, though
the error message is very generic and is similar to another error
which you addressed a bug for.

I guess, my request for enhancement would be to throw an exception
with a better error message for sip sessions which there is a sip
message for, but which cannot be found. The popper route header
"null" seems to be pretty generic as a cause, while not being able to
find sip session was pretty descriptive ;)

Current message is: "ERROR [SipApplicationDispatcherImpl] Unexpected
exception
while processing request BYE sip:10.20.2.45:5080 SIP/2.0 ......

org.mobicents.servlet.sip.core.dispatchers.DispatcherException: Cannot
find the corresponding sip application session to this subsequent

request BYE sip:10.20.2.45:5080 .........

with the following popped route header null at
org.mobicents.servlet.sip.core.dispatchers.SubsequentRequestDispatcher.disp
atchMessage"

Best Regards,
Vadim

On Nov 3, 3:11 pm, Vadim <vadim.snitkov...@gmail.com> wrote:
> I used the binary from:http://hudson.jboss.org/hudson/job/MobicentsSipServletsRelease/586/
>
> I get ACKs now - great job on fixing that.
>

> However, there is still an issue with a BYE. Logs are uploaded here:http://groups.google.com/group/mobicents-public/web/errors_on_BYE_11_...

[Jean Deruelle]

I agree. Thx

I replaced the previous message by "Cannot find the corresponding sip application session to this subsequent request, it may already have been invalidated or timed out".

It should be available from the next binary snapshot.