[Kamailio-Users] reply_route is not called though a response is received
Aurelien Grimaud
gstelzz at yahoo.fr
Fri Dec 5 13:23:04 CET 2008
Daniel-Constantin Mierla a écrit :
> Hello,
>
> On 12/04/08 12:48, Aurelien Grimaud wrote:
>> Hi,
>> I am running a rather old version of openser, but since in a
>> production context, I cannot upgrade anytime I want to catch up with
>> newer releases.
>> I searched bugs and googled for my problem without any result.
>>
>> There it is.
>> I have a module with functions beginning with mn_
>> mn_received handle any incoming request and prints it out.
>> my module has a callback on response which prints out responses.
>>
>> My configuration file is something like
>>
>> // handle register
>>
>> mn_received() ;
>>
>> record_route() ;
>> if ( method=="INVITE")
>> {
>> t_on_failure(ROUTE_INVITE) ;
>> t_on_reply(ROUTE_INVITE) ;
>> }
>>
>> Then the request is t_relayed to destination.
>>
>> The onreply_route[ROUTE_INVITE] prints some output, and fix_contact
>> on 200, ... whatever.
>>
>> Then this happens :
>> - An INVITE is received from A (I see it with mn_received)
>> - INVITE is relayed to destination B
>> - B replies 180, I see the response on my module output and I see my
>> onreply_route[INVITE] statements.
>> - B replies 200, I see the response on my module output, but, I *do
>> not* see my reply_route statements.
>>
> one reason can be that TM does not match the reply to any transaction.
> Can you paste here the INVITE and the reply with problems? Will help
> to troubleshoot even there is another reason.
>
Ok, Here is my log.
Thank you for your time !
* Logs with RECEIVED are the one from mn_received() method
* Logs with REPLY are the one from module response callback.
* in brackets : callid, From -> To and ip source -> ip dest]
* Then headers, printed from openser sip_msg struct
T000 12/02/2008 15:07:19.756 bin#ser#05138#-1 = (sermonicom.cc:317) [3084977856]
MONICOM RECEIVED .
[Call-ID=001B2105E7ACD49F08589FB6EE44 at 10.170.72.38]
[From=<sip:FROM at 10.170.72.38>;tag=05p50qBVv20004jR0501u00cVFk0YrBzR -> To=<sip:TO at ccc>]
[10.170.72.38/5060 -> 10.170.74.21/5060]
[234895 REQUEST INVITE sip:TO at ccc SIP/2.0]
Via=SIP/2.0/UDP 10.170.72.38:5060;branch=z9hG4bK001B2105E7ACD49F085841888DF3
From=<sip:FROM at 10.170.72.38>;tag=05p50qBVv20004jR0501u00cVFk0YrBzR
To=<sip:TO at ccc>
Call-ID=001B2105E7ACD49F08589FB6EE44 at 10.170.72.38
CSeq=31558 INVITE
Contact=<sip:10.170.72.38:5060>
Allow-Events=refer
Max-Forwards=69
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, INFO, REFER, NOTIFY, SUBSCRIBE, UPDATE
Content-Type: application/sdp
Supported: 100rel, timer, replaces
User-Agent: TELES.MGC
Content-Length: 291
v=0
o=- 1183407772 0 IN IP4 10.170.72.109
s=session
c=IN IP4 10.170.72.109
t=0 0
m=audio 14720 RTP/AVP 8 0 97 2 99 96
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:97 G726-16/8000
a=rtpmap:2 G726-32/8000
a=rtpmap:99 G726-40/8000
a=rtpmap:96 telephone-event/8000
a=sendrecv
..
Serial forking
T000 12/02/2008 15:07:19.757 bin#ser#05138#-1 = (sermonicom.cc:293) [3084977856]
[Call-ID=001B2105E7ACD49F08589FB6EE44 at 10.170.72.38]
[From=<sip:FROM at 10.170.72.38>;tag=05p50qBVv20004jR0501u00cVFk0YrBzR -> To=<sip:TO at ccc>]
[10.170.72.38/5060 -> 10.170.74.21/5060]
[234895 REQUEST INVITE sip:TO at ccc SIP/2.0] -- .[openser.cfg.m4:963] route_serial_forking : Sending 'RUri=sip:TO at ccc ' to first contact 'DUri=sip:TO at 10.170.74.24:20555 '.
Incoming response 180 Ringing
T000 12/02/2008 15:07:19.758 bin#ser#05136#-1 = (sermonicom.cc:323) [3084977856]
MONICOM RESPONSE .[ -> ]
[10.170.74.24/20555 -> 10.170.74.21/5060]
[236348 REPLY 180 Ringing SIP/2.0]
Record-Route=<sip:10.170.74.21;lr=on;ftag=05p50qBVv20004jR0501u00cVFk0YrBzR>
Via=SIP/2.0/UDP 10.170.74.21;branch=z9hG4bK824a.36ce84a7.0;received=10.170.74.21, SIP/2.0/UDP 10.170.72.38:5060;branch=z9hG4bK001B2105E7ACD49F085841888DF3
To: <sip:TO at ccc>;tag=118d620a
From: <sip:FROM at 10.170.72.38>;tag=05p50qBVv20004jR0501u00cVFk0YrBzR
Call-ID: 001B2105E7ACD49F08589FB6EE44 at 10.170.72.38
Contact: <sip:ccc at 10.170.74.24:20555>
CSeq: 31558 INVITE
Content-Length: 0
.... is handled in onreply_route. I see it there
T000 12/02/2008 15:07:19.758 bin#ser#05136#-1 = (sermonicom.cc:293) [3084977856] .
[Call-ID=001B2105E7ACD49F08589FB6EE44 at 10.170.72.38]
[From=<sip:FROM at 10.170.72.38>;tag=05p50qBVv20004jR0501u00cVFk0YrBzR -> To=<sip:TO at ccc>;tag=118d620a]
[10.170.74.24/20555 -> 10.170.74.21/5060]
[236348 REPLY 180 Ringing SIP/2.0] -- .[openser.cfg.m4:677] reply for INVITE.
Incoming response 200 ok
T000 12/02/2008 15:07:19.760 bin#ser#05122#-1 = (sermonicom.cc:323) [3084977856] MONICOM RESPONSE .[ -> ]
[10.170.74.24/20555 -> 10.170.74.21/5060]
[235990 REPLY 200 OK SIP/2.0]
Record-Route=<sip:10.170.74.21;lr=on;ftag=05p50qBVv20004jR0501u00cVFk0YrBzR>
Via=SIP/2.0/UDP 10.170.74.21;branch=z9hG4bK824a.36ce84a7.0;received=10.170.74.21, SIP/2.0/UDP 10.170.72.38:5060;branch=z9hG4bK001B2105E7ACD49F085841888DF3
To: <sip:TO at ccc>;tag=118d620a
From: <sip:FROM at 10.170.72.38>;tag=05p50qBVv20004jR0501u00cVFk0YrBzR
Call-ID: 001B2105E7ACD49F08589FB6EE44 at 10.170.72.38
Contact: <sip:ccc at 10.170.74.24:20555>
CSeq: 31558 INVITE
Content-Length: 224
Content-Type: application/sdp
v=0
o=- 2127131933 2127131933 IN IP4 10.170.74.24
s=Session SDP
c=IN IP4 10.170.74.24
t=0 0
m=audio 40608 RTP/AVP 8 0 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
**
Log from oneply_route are not printed here for 200 ok.
But there is an incoming ACK so the initial caller received it.
Openser relayed it statelessely ?
**
T000 12/02/2008 15:07:19.762 bin#ser#05125#-1 = (sermonicom.cc:317) [3084977856]
MONICOM RECEIVED .
[Call-ID=001B2105E7ACD49F08589FB6EE44 at 10.170.72.38]
[From=<sip:FROM at 10.170.72.38>;tag=05p50qBVv20004jR0501u00cVFk0YrBzR -> To=<sip:TO at ccc>;tag=118d620a]
[10.170.72.38/5060 -> 10.170.74.21/5060]
[235385 REQUEST ACK sip:ccc at 10.170.74.24:20555 SIP/2.0]
Via=SIP/2.0/UDP 10.170.72.38:5060;branch=z9hG4bK001B2105E7ACD49F0859FF56AAB0
Route=<sip:10.170.74.21;lr=on;ftag=05p50qBVv20004jR0501u00cVFk0YrBzR>
From=<sip:FROM at 10.170.72.38>;tag=05p50qBVv20004jR0501u00cVFk0YrBzR
To=<sip:TO at ccc>;tag=118d620a
Call-ID=001B2105E7ACD49F08589FB6EE44 at 10.170.72.38
CSeq=31558 ACK
Contact=<sip:FROM at 10.170.72.38:5060>
Max-Forwards=69
Content-Length: 0
ACK is handled ok
T000 12/02/2008 15:07:19.762 bin#ser#05125#-1 = (sermonicom.cc:293) [3084977856]
[Call-ID=001B2105E7ACD49F08589FB6EE44 at 10.170.72.38]
[From=<sip:FROM at 10.170.72.38>;tag=05p50qBVv20004jR0501u00cVFk0YrBzR -> To=<sip:TO at ccc>;tag=118d620a]
[10.170.72.38/5060 -> 10.170.74.21/5060]
[235385 REQUEST ACK sip:ccc at 10.170.74.24:20555 SIP/2.0] -- .[openser.cfg.m4:637] Processing ok : t_relay DUri= RUri=sip:ccc at 10.170.74.24:20555 .
All goes ok, the conversation ends 30 seconds later
T000 12/02/2008 15:07:49.191 bin#ser#05131#-1 = (sermonicom.cc:317) [3084977856]
MONICOM RECEIVED
[Call-ID=001B2105E7ACD49F08589FB6EE44 at 10.170.72.38]
[From=<sip:FROM at 10.170.72.38>;tag=05p50qBVv20004jR0501u00cVFk0YrBzR -> To=<sip:TO at ccc>;tag=118d620a]
[10.170.72.38/5060 -> 10.170.74.21/5060]
[235413 REQUEST BYE sip:ccc at 10.170.74.24:20555 SIP/2.0]
Via=SIP/2.0/UDP 10.170.72.38:5060;branch=z9hG4bK001B2105E7ACD49F13D830F0C46B
Route=<sip:10.170.74.21;lr=on;ftag=05p50qBVv20004jR0501u00cVFk0YrBzR>
From=<sip:FROM at 10.170.72.38>;tag=05p50qBVv20004jR0501u00cVFk0YrBzR
To=<sip:TO at ccc>;tag=118d620a
Call-ID=001B2105E7ACD49F08589FB6EE44 at 10.170.72.38
CSeq=31559 BYE
Contact=<sip:FROM at 10.170.72.38:5060>
Max-Forwards=69
Content-Length: 0
BYE is processed ok
T000 12/02/2008 15:07:49.192 bin#ser#05131#-1 = (sermonicom.cc:293) [3084977856] .
[Call-ID=001B2105E7ACD49F08589FB6EE44 at 10.170.72.38]
[From=<sip:FROM at 10.170.72.38>;tag=05p50qBVv20004jR0501u00cVFk0YrBzR -> To=<sip:TO at ccc>;tag=118d620a]
[10.170.72.38/5060 -> 10.170.74.21/5060]
[235413 REQUEST BYE sip:ccc at 10.170.74.24:20555 SIP/2.0] -- .[openser.cfg.m4:637] Processing ok : t_relay DUri= RUri=sip:ccc at 10.170.74.24:20555
And we got the 200 ok
T000 12/02/2008 15:07:49.193 bin#ser#05122#-1 = (sermonicom.cc:323) [3084977856] MONICOM RESPONSE .[ -> ]
[10.170.74.24/20555 -> 10.170.74.21/5060]
[236083 REPLY 200 OK SIP/2.0]
Record-Route=<sip:10.170.74.21;lr=on;ftag=05p50qBVv20004jR0501u00cVFk0YrBzR>
Via=SIP/2.0/UDP 10.170.74.21;branch=z9hG4bK724a.ea42f1f3.0;received=10.170.74.21, SIP/2.0/UDP 10.170.72.38:5060;branch=z9hG4bK001B2105E7ACD49F13D830F0C46B
To: <sip:TO at ccc>;tag=118d620a
From: <sip:FROM at 10.170.72.38>;tag=05p50qBVv20004jR0501u00cVFk0YrBzR
Call-ID: 001B2105E7ACD49F08589FB6EE44 at 10.170.72.38
Contact: <sip:ccc at 10.170.74.24:20555>
CSeq: 31559 BYE
Content-Length: 0
Which is retransmitted ???? ...
T000 12/02/2008 15:07:49.677 bin#ser#05136#-1 = (sermonicom.cc:323) [3084977856] MONICOM RESPONSE .[ -> ]
[10.170.74.24/20555 -> 10.170.74.21/5060]
[236430 REPLY 200 OK SIP/2.0]
Record-Route=<sip:10.170.74.21;lr=on;ftag=05p50qBVv20004jR0501u00cVFk0YrBzR>
Via=SIP/2.0/UDP 10.170.74.21;branch=z9hG4bK724a.ea42f1f3.0;received=10.170.74.21, SIP/2.0/UDP 10.170.72.38:5060;branch=z9hG4bK001B2105E7ACD49F13D830F0C46B
To: <sip:TO at ccc>;tag=118d620a
From: <sip:FROM at 10.170.72.38>;tag=05p50qBVv20004jR0501u00cVFk0YrBzR
Call-ID: 001B2105E7ACD49F08589FB6EE44 at 10.170.72.38
Contact: <sip:ccc at 10.170.74.24:20555>
CSeq: 31559 BYE
Content-Length: 0
Then, 1'30 after BYE, which is 2' after initial INVITE : the onfailure route for serial forking triggers and send INVITE to next contact
T000 12/02/2008 15:09:19.143 bin#ser#05142#-1 = (sermonicom.cc:293) [3084977856]
[Call-ID=001B2105E7ACD49F08589FB6EE44 at 10.170.72.38]
[From=<sip:FROM at 10.170.72.38>;tag=05p50qBVv20004jR0501u00cVFk0YrBzR -> To=<sip:TO at ccc>]
[10.170.72.38/5060 -> 10.170.74.21/5060]
[234894 REQUEST INVITE sip:TO at ccc SIP/2.0] -- .[openser.cfg.m4:987] serial fork on failure : Sending 'RUri= ' to next contact 'DUri=sip:TO at 10.170.74.24:20540 '.
Openser sent a cancel to initial contact
Which is no more referenced because of the previous BYE so it leads to 481
T000 12/02/2008 15:09:19.144 bin#ser#05124#-1 = (sermonicom.cc:323) [3084977856]
MONICOM RESPONSE
[Call-ID=001B2105E7ACD49F08589FB6EE44 at 10.170.72.38]
[From=<sip:FROM at 10.170.72.38>;tag=05p50qBVv20004jR0501u00cVFk0YrBzR -> To=<sip:TO at ccc>]
[10.170.74.24/20555 -> 10.170.74.21/5060]
[235741 REPLY 481 Call leg/Transaction does not exist SIP/2.0] Via=SIP/2.0/UDP 10.170.74.21;branch=z9hG4bK824a.36ce84a7.0;received=10.170.74.21
To=<sip:TO at ccc>
From=<sip:FROM at 10.170.72.38>;tag=05p50qBVv20004jR0501u00cVFk0YrBzR
Call-ID=001B2105E7ACD49F08589FB6EE44 at 10.170.72.38
Contact=<sip:ccc at 10.170.74.24:20555>
CSeq=31558 CANCEL
But Second Invite is ok and is processed ok
180 Ringing
T000 12/02/2008 15:09:19.144 bin#ser#05125#-1 = (sermonicom.cc:323) [3084977856]
MONICOM RESPONSE .[ -> ]
[10.170.74.24/20540 -> 10.170.74.21/5060]
[235729 REPLY 180 Ringing SIP/2.0]
Record-Route=<sip:10.170.74.21;lr=on;ftag=05p50qBVv20004jR0501u00cVFk0YrBzR>
Via=SIP/2.0/UDP 10.170.74.21;branch=z9hG4bK824a.36ce84a7.1;received=10.170.74.21, SIP/2.0/UDP 10.170.72.38:5060;branch=z9hG4bK001B2105E7ACD49F085841888DF3
To: <sip:TO at ccc>;tag=1e27ac08
From: <sip:FROM at 10.170.72.38>;tag=05p50qBVv20004jR0501u00cVFk0YrBzR
Call-ID: 001B2105E7ACD49F08589FB6EE44 at 10.170.72.38
Contact: <sip:ccc at 10.170.74.24:20540>
CSeq: 31558 INVITE
Content-Length: 0
T000 12/02/2008 15:09:19.144 bin#ser#05125#-1 = (sermonicom.cc:293) [3084977856] .
[Call-ID=001B2105E7ACD49F08589FB6EE44 at 10.170.72.38]
[From=<sip:FROM at 10.170.72.38>;tag=05p50qBVv20004jR0501u00cVFk0YrBzR -> To=<sip:TO at ccc>;tag=1e27ac08]
[10.170.74.24/20540 -> 10.170.74.21/5060]
[235729 REPLY 180 Ringing SIP/2.0] -- .[openser.cfg.m4:677] reply for INVITE.
200 OK
T000 12/02/2008 15:09:19.153 bin#ser#05134#-1 = (sermonicom.cc:323) [3084977856]
MONICOM RESPONSE .[ -> ]
[10.170.74.24/20540 -> 10.170.74.21/5060]
[237162 REPLY 200 OK SIP/2.0]
Record-Route=<sip:10.170.74.21;lr=on;ftag=05p50qBVv20004jR0501u00cVFk0YrBzR>
Via=SIP/2.0/UDP 10.170.74.21;branch=z9hG4bK824a.36ce84a7.1;received=10.170.74.21, SIP/2.0/UDP 10.170.72.38:5060;branch=z9hG4bK001B2105E7ACD49F085841888DF3
To: <sip:TO at ccc>;tag=1e27ac08
From: <sip:FROM at 10.170.72.38>;tag=05p50qBVv20004jR0501u00cVFk0YrBzR
Call-ID: 001B2105E7ACD49F08589FB6EE44 at 10.170.72.38
Contact: <sip:ccc at 10.170.74.24:20540>
CSeq: 31558 INVITE
Content-Length: 222
Content-Type: application/sdp
v=0
o=- 621324986 621324986 IN IP4 10.170.74.24
s=Session SDP
c=IN IP4 10.170.74.24
t=0 0
m=audio 40136 RTP/AVP 8 0 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
Which is handled in onreply_route
T000 12/02/2008 15:09:19.153 bin#ser#05134#-1 = (sermonicom.cc:293) [3084977856] .
[Call-ID=001B2105E7ACD49F08589FB6EE44 at 10.170.72.38]
[From=<sip:FROM at 10.170.72.38>;tag=05p50qBVv20004jR0501u00cVFk0YrBzR -> To=<sip:TO at ccc>;tag=1e27ac08]
[10.170.74.24/20540 -> 10.170.74.21/5060] [237162 REPLY 200 OK SIP/2.0] -- .[openser.cfg.m4:677] reply for INVITE.
But retransmitted (not aced by openser ? or ACK has been lost)
T000 12/02/2008 15:09:19.655 bin#ser#05136#-1 = (sermonicom.cc:323) [3084977856] MONICOM RESPONSE .[ -> ]
[10.170.74.24/20540 -> 10.170.74.21/5060]
[236665 REPLY 200 OK SIP/2.0]
Record-Route=<sip:10.170.74.21;lr=on;ftag=05p50qBVv20004jR0501u00cVFk0YrBzR>
Via=SIP/2.0/UDP 10.170.74.21;branch=z9hG4bK824a.36ce84a7.1;received=10.170.74.21, SIP/2.0/UDP 10.170.72.38:5060;branch=z9hG4bK001B2105E7ACD49F085841888DF3
To: <sip:TO at ccc>;tag=1e27ac08
From: <sip:FROM at 10.170.72.38>;tag=05p50qBVv20004jR0501u00cVFk0YrBzR
Call-ID: 001B2105E7ACD49F08589FB6EE44 at 10.170.72.38
Contact: <sip:ccc at 10.170.74.24:20540>
CSeq: 31558 INVITE
Content-Length: 222
Content-Type: application/sdp
v=0
o=- 621324986 621324986 IN IP4 10.170.74.24
s=Session SDP
c=IN IP4 10.170.74.24
t=0 0
m=audio 40136 RTP/AVP 8 0 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
And retransmitted ...
T000 12/02/2008 15:09:20.655 bin#ser#05125#-1 = (sermonicom.cc:323) [3084977856] MONICOM RESPONSE .[ -> ]
[10.170.74.24/20540 -> 10.170.74.21/5060]
[235785 REPLY 200 OK SIP/2.0]
Record-Route=<sip:10.170.74.21;lr=on;ftag=05p50qBVv20004jR0501u00cVFk0YrBzR>
Via=SIP/2.0/UDP 10.170.74.21;branch=z9hG4bK824a.36ce84a7.1;received=10.170.74.21, SIP/2.0/UDP 10.170.72.38:5060;branch=z9hG4bK001B2105E7ACD49F085841888DF3
To: <sip:TO at ccc>;tag=1e27ac08
From: <sip:FROM at 10.170.72.38>;tag=05p50qBVv20004jR0501u00cVFk0YrBzR
Call-ID: 001B2105E7ACD49F08589FB6EE44 at 10.170.72.38
Contact: <sip:ccc at 10.170.74.24:20540>
CSeq: 31558 INVITE
Content-Length: 222
Content-Type: application/sdp
v=0
o=- 621324986 621324986 IN IP4 10.170.74.24
s=Session SDP
c=IN IP4 10.170.74.24
t=0 0
m=audio 40136 RTP/AVP 8 0 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
And handled ok
T000 12/02/2008 15:09:20.655 bin#ser#05125#-1 = (sermonicom.cc:293) [3084977856] .[Call-ID=001B2105E7ACD49F08589FB6EE44 at 10.170.72.38] [From=<sip:FROM at 10.170.72.38>;tag=05p50qBVv20004jR0501u00cVFk0YrBzR -> To=<sip:TO at ccc>;tag=1e27ac08] [10.170.74.24/20540 -> 10.170.74.21/5060] [235785 REPLY 200 OK SIP/2.0] -- .[openser.cfg.m4:677] reply for INVITE.
But still retransmitted
T000 12/02/2008 15:09:22.655 bin#ser#05124#-1 = (sermonicom.cc:323) [3084977856] MONICOM RESPONSE .[ -> ]
[10.170.74.24/20540 -> 10.170.74.21/5060]
[235788 REPLY 200 OK SIP/2.0]
Record-Route=<sip:10.170.74.21;lr=on;ftag=05p50qBVv20004jR0501u00cVFk0YrBzR>
Via=SIP/2.0/UDP 10.170.74.21;branch=z9hG4bK824a.36ce84a7.1;received=10.170.74.21, SIP/2.0/UDP 10.170.72.38:5060;branch=z9hG4bK001B2105E7ACD49F085841888DF3
To: <sip:TO at ccc>;tag=1e27ac08
From: <sip:FROM at 10.170.72.38>;tag=05p50qBVv20004jR0501u00cVFk0YrBzR
Call-ID: 001B2105E7ACD49F08589FB6EE44 at 10.170.72.38
Contact: <sip:ccc at 10.170.74.24:20540>
CSeq: 31558 INVITE
Content-Length: 222
Content-Type: application/sdp
v=0
o=- 621324986 621324986 IN IP4 10.170.74.24
s=Session SDP
c=IN IP4 10.170.74.24
t=0 0
m=audio 40136 RTP/AVP 8 0 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
..
And again handled in onreply_route
T000 12/02/2008 15:09:22.655 bin#ser#05124#-1 = (sermonicom.cc:293) [3084977856] .
[Call-ID=001B2105E7ACD49F08589FB6EE44 at 10.170.72.38]
[From=<sip:FROM at 10.170.72.38>;tag=05p50qBVv20004jR0501u00cVFk0YrBzR -> To=<sip:TO at ccc>;tag=1e27ac08]
[10.170.74.24/20540 -> 10.170.74.21/5060]
[235788 REPLY 200 OK SIP/2.0] -- .[openser.cfg.m4:677] reply for INVITE.
But retransmitted
T000 12/02/2008 15:09:26.655 bin#ser#05134#-1 = (sermonicom.cc:323) [3084977856] MONICOM RESPONSE .[ -> ]
[10.170.74.24/20540 -> 10.170.74.21/5060]
[237198 REPLY 200 OK SIP/2.0]
Record-Route=<sip:10.170.74.21;lr=on;ftag=05p50qBVv20004jR0501u00cVFk0YrBzR>
Via=SIP/2.0/UDP 10.170.74.21;branch=z9hG4bK824a.36ce84a7.1;received=10.170.74.21, SIP/2.0/UDP 10.170.72.38:5060;branch=z9hG4bK001B2105E7ACD49F085841888DF3
To: <sip:TO at ccc>;tag=1e27ac08
From: <sip:FROM at 10.170.72.38>;tag=05p50qBVv20004jR0501u00cVFk0YrBzR
Call-ID: 001B2105E7ACD49F08589FB6EE44 at 10.170.72.38
Contact: <sip:ccc at 10.170.74.24:20540>
CSeq: 31558 INVITE
Content-Length: 222
Content-Type: application/sdp
v=0
o=- 621324986 621324986 IN IP4 10.170.74.24
s=Session SDP
c=IN IP4 10.170.74.24
t=0 0
m=audio 40136 RTP/AVP 8 0 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
Reply_route is not called there
Retransmitted
T000 12/02/2008 15:09:30.654 bin#ser#05124#-1 = (sermonicom.cc:323) [3084977856] MONICOM RESPONSE .[ -> ]
[10.170.74.24/20540 -> 10.170.74.21/5060]
[235800 REPLY 200 OK SIP/2.0]
Record-Route=<sip:10.170.74.21;lr=on;ftag=05p50qBVv20004jR0501u00cVFk0YrBzR>
Via=SIP/2.0/UDP 10.170.74.21;branch=z9hG4bK824a.36ce84a7.1;received=10.170.74.21, SIP/2.0/UDP 10.170.72.38:5060;branch=z9hG4bK001B2105E7ACD49F085841888DF3
To: <sip:TO at ccc>;tag=1e27ac08
From: <sip:FROM at 10.170.72.38>;tag=05p50qBVv20004jR0501u00cVFk0YrBzR
Call-ID: 001B2105E7ACD49F08589FB6EE44 at 10.170.72.38
Contact: <sip:ccc at 10.170.74.24:20540>
CSeq: 31558 INVITE
Content-Length: 222
Content-Type: application/sdp
v=0
o=- 621324986 621324986 IN IP4 10.170.74.24
s=Session SDP
c=IN IP4 10.170.74.24
t=0 0
m=audio 40136 RTP/AVP 8 0 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
No reply route
Retransmitted
T000 12/02/2008 15:09:34.655 bin#ser#05134#-1 = (sermonicom.cc:323) [3084977856] MONICOM RESPONSE .[ -> ]
[10.170.74.24/20540 -> 10.170.74.21/5060]
[237215 REPLY 200 OK SIP/2.0]
Record-Route=<sip:10.170.74.21;lr=on;ftag=05p50qBVv20004jR0501u00cVFk0YrBzR>
Via=SIP/2.0/UDP 10.170.74.21;branch=z9hG4bK824a.36ce84a7.1;received=10.170.74.21, SIP/2.0/UDP 10.170.72.38:5060;branch=z9hG4bK001B2105E7ACD49F085841888DF3
To: <sip:TO at ccc>;tag=1e27ac08
From: <sip:FROM at 10.170.72.38>;tag=05p50qBVv20004jR0501u00cVFk0YrBzR
Call-ID: 001B2105E7ACD49F08589FB6EE44 at 10.170.72.38
Contact: <sip:ccc at 10.170.74.24:20540>
CSeq: 31558 INVITE
Content-Length: 222
Content-Type: application/sdp
v=0
o=- 621324986 621324986 IN IP4 10.170.74.24
s=Session SDP
c=IN IP4 10.170.74.24
t=0 0
m=audio 40136 RTP/AVP 8 0 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
..
And again
T000 12/02/2008 15:09:38.655 bin#ser#05122#-1 = (sermonicom.cc:323) [3084977856] MONICOM RESPONSE .[ -> ]
[10.170.74.24/20540 -> 10.170.74.21/5060]
[236425 REPLY 200 OK SIP/2.0]
Record-Route=<sip:10.170.74.21;lr=on;ftag=05p50qBVv20004jR0501u00cVFk0YrBzR>
Via=SIP/2.0/UDP 10.170.74.21;branch=z9hG4bK824a.36ce84a7.1;received=10.170.74.21, SIP/2.0/UDP 10.170.72.38:5060;branch=z9hG4bK001B2105E7ACD49F085841888DF3
To: <sip:TO at ccc>;tag=1e27ac08
From: <sip:FROM at 10.170.72.38>;tag=05p50qBVv20004jR0501u00cVFk0YrBzR
Call-ID: 001B2105E7ACD49F08589FB6EE44 at 10.170.72.38
Contact: <sip:ccc at 10.170.74.24:20540>
CSeq: 31558 INVITE
Content-Length: 222
Content-Type: application/sdp
v=0
o=- 621324986 621324986 IN IP4 10.170.74.24
s=Session SDP
c=IN IP4 10.170.74.24
t=0 0
m=audio 40136 RTP/AVP 8 0 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
..
And again
T000 12/02/2008 15:09:42.655 bin#ser#05136#-1 = (sermonicom.cc:323) [3084977856] MONICOM RESPONSE .[ -> ]
[10.170.74.24/20540 -> 10.170.74.21/5060]
[236733 REPLY 200 OK SIP/2.0]
Record-Route=<sip:10.170.74.21;lr=on;ftag=05p50qBVv20004jR0501u00cVFk0YrBzR>
Via=SIP/2.0/UDP 10.170.74.21;branch=z9hG4bK824a.36ce84a7.1;received=10.170.74.21, SIP/2.0/UDP 10.170.72.38:5060;branch=z9hG4bK001B2105E7ACD49F085841888DF3
To: <sip:TO at ccc>;tag=1e27ac08
From: <sip:FROM at 10.170.72.38>;tag=05p50qBVv20004jR0501u00cVFk0YrBzR
Call-ID: 001B2105E7ACD49F08589FB6EE44 at 10.170.72.38
Contact: <sip:ccc at 10.170.74.24:20540>
CSeq: 31558 INVITE
Content-Length: 222
Content-Type: application/sdp
v=0
o=- 621324986 621324986 IN IP4 10.170.74.24
s=Session SDP
c=IN IP4 10.170.74.24
t=0 0
m=audio 40136 RTP/AVP 8 0 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
..
And again
T000 12/02/2008 15:09:46.656 bin#ser#05131#-1 = (sermonicom.cc:323) [3084977856] MONICOM RESPONSE .[ -> ]
[10.170.74.24/20540 -> 10.170.74.21/5060]
[235778 REPLY 200 OK SIP/2.0]
Record-Route=<sip:10.170.74.21;lr=on;ftag=05p50qBVv20004jR0501u00cVFk0YrBzR>
Via=SIP/2.0/UDP 10.170.74.21;branch=z9hG4bK824a.36ce84a7.1;received=10.170.74.21, SIP/2.0/UDP 10.170.72.38:5060;branch=z9hG4bK001B2105E7ACD49F085841888DF3
To: <sip:TO at ccc>;tag=1e27ac08
From: <sip:FROM at 10.170.72.38>;tag=05p50qBVv20004jR0501u00cVFk0YrBzR
Call-ID: 001B2105E7ACD49F08589FB6EE44 at 10.170.72.38
Contact: <sip:ccc at 10.170.74.24:20540>
CSeq: 31558 INVITE
Content-Length: 222
Content-Type: application/sdp
v=0
o=- 621324986 621324986 IN IP4 10.170.74.24
s=Session SDP
c=IN IP4 10.170.74.24
t=0 0
m=audio 40136 RTP/AVP 8 0 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
..
And again
T000 12/02/2008 15:09:50.655 bin#ser#05122#-1 = (sermonicom.cc:323) [3084977856] MONICOM RESPONSE .[ -> ]
[10.170.74.24/20540 -> 10.170.74.21/5060]
[236492 REPLY 200 OK SIP/2.0]
Record-Route=<sip:10.170.74.21;lr=on;ftag=05p50qBVv20004jR0501u00cVFk0YrBzR>
Via=SIP/2.0/UDP 10.170.74.21;branch=z9hG4bK824a.36ce84a7.1;received=10.170.74.21, SIP/2.0/UDP 10.170.72.38:5060;branch=z9hG4bK001B2105E7ACD49F085841888DF3
To: <sip:TO at ccc>;tag=1e27ac08
From: <sip:FROM at 10.170.72.38>;tag=05p50qBVv20004jR0501u00cVFk0YrBzR
Call-ID: 001B2105E7ACD49F08589FB6EE44 at 10.170.72.38
Contact: <sip:ccc at 10.170.74.24:20540>
CSeq: 31558 INVITE
Content-Length: 222
Content-Type: application/sdp
v=0
o=- 621324986 621324986 IN IP4 10.170.74.24
s=Session SDP
c=IN IP4 10.170.74.24
t=0 0
m=audio 40136 RTP/AVP 8 0 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
..
> Cheers,
> Daniel
>
>> - A sends ACK for INVITE
>> - ACK is relayed to B
>>
>> 2 minutes later (fr_inv_timer), the failure_route[INVITE] is triggered !
>> Since I use failure routes to manage serial forking, this means
>> openser forward the initial INVITE to the other destination, though
>> first call was established !
>> Moreover, first call, which seems ok is CANCELED by the openser (I
>> can see a 200 answer to a cancel from B)
>>
>> Openser did not disarm the fr_inv_timer on "200" answer to INVITE ?
>> Openser did not triggered my onreply_route...
>>
>> Has someone already experienced this ?
>> Has someone a clue where it may come from ?
>>
>> - Sometimes it works ok
>> - Sometimes, 180 is not "seen" and 200 is ok
>> - Sometimes 180 is seen but not 200
>> - Sometimes neither 180, nor 200 are seen
>> - Headers in 180 and 200 are the same except for content
>> - I'm running openser-1.2.0 (ouch !)
>>
>> I'm stuck !
>>
>> Could this be related to
>>
>> 2008-05-15 10:59 Bogdan-Andrei Iancu, <bogdan at voice-system dot ro>
>>
>> * [r4191] modules/tm/t_reply.c:
>> backport from trunk (rev #4190):
>> - fixed race condition that may lead to deadlock on the
>> transaction
>> lock. As the reply route (t_on_reply()) stored in transaction
>> may be
>> changed in reply route br the current process or any other
>> process, to
>> avoid race conditions, it is better to make a local copy of the
>> reply
>> route number to be sure it will not be changed.
>> The deadlock can appear as the reply route number is used in
>> several
>> conditions to determine id locking is required. But as this
>> value may
>> be changed (by current or other process), it may lead to multiple
>> lockings with no unlock -> deadlock.
>> NOTE: this might happen only if onreply_avp_mode is turned on.
>>
>>
>>
>> Aurelien
>>
>>
>> _______________________________________________
>> Users mailing list
>> Users at lists.kamailio.org
>> http://lists.kamailio.org/cgi-bin/mailman/listinfo/users
>>
>>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.kamailio.org/pipermail/users/attachments/20081205/3173431e/attachment.htm
More information about the Users
mailing list