[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