[Kamailio-Users] reply_route is not called though a response is received

List overview All Threads
Download

newer

older

[Kamailio-Users] Port of kamailio...

Re: [Kamailio-Users] Failover from...

Aurelien Grimaud

4 Dec 2008 4 Dec '08

10:48 a.m.

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. - 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

Show replies by date

Daniel-Constantin Mierla

5 Dec 5 Dec

9:04 a.m.

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.

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@lists.kamailio.org http://lists.kamailio.org/cgi-bin/mailman/listinfo/users

-- Daniel-Constantin Mierla http://www.asipto.com

Aurelien Grimaud

12:23 p.m.

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@10.170.72.38] [From=sip:FROM@10.170.72.38;tag=05p50qBVv20004jR0501u00cVFk0YrBzR -> To=sip:TO@ccc] [10.170.72.38/5060 -> 10.170.74.21/5060] [234895 REQUEST INVITE sip:TO@ccc SIP/2.0] Via=SIP/2.0/UDP 10.170.72.38:5060;branch=z9hG4bK001B2105E7ACD49F085841888DF3 From=sip:FROM@10.170.72.38;tag=05p50qBVv20004jR0501u00cVFk0YrBzR To=sip:TO@ccc Call-ID=001B2105E7ACD49F08589FB6EE44@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@10.170.72.38] [From=sip:FROM@10.170.72.38;tag=05p50qBVv20004jR0501u00cVFk0YrBzR -> To=sip:TO@ccc] [10.170.72.38/5060 -> 10.170.74.21/5060] [234895 REQUEST INVITE sip:TO@ccc SIP/2.0] -- .[openser.cfg.m4:963] route_serial_forking : Sending 'RUri=sip:TO@ccc ' to first contact 'DUri=sip:TO@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@ccc;tag=118d620a From: sip:FROM@10.170.72.38;tag=05p50qBVv20004jR0501u00cVFk0YrBzR Call-ID: 001B2105E7ACD49F08589FB6EE44@10.170.72.38 Contact: sip:ccc@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@10.170.72.38] [From=sip:FROM@10.170.72.38;tag=05p50qBVv20004jR0501u00cVFk0YrBzR -> To=sip:TO@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@ccc;tag=118d620a From: sip:FROM@10.170.72.38;tag=05p50qBVv20004jR0501u00cVFk0YrBzR Call-ID: 001B2105E7ACD49F08589FB6EE44@10.170.72.38 Contact: sip:ccc@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@10.170.72.38] [From=sip:FROM@10.170.72.38;tag=05p50qBVv20004jR0501u00cVFk0YrBzR -> To=sip:TO@ccc;tag=118d620a] [10.170.72.38/5060 -> 10.170.74.21/5060] [235385 REQUEST ACK sip:ccc@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@10.170.72.38;tag=05p50qBVv20004jR0501u00cVFk0YrBzR To=sip:TO@ccc;tag=118d620a Call-ID=001B2105E7ACD49F08589FB6EE44@10.170.72.38 CSeq=31558 ACK Contact=sip:FROM@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@10.170.72.38] [From=sip:FROM@10.170.72.38;tag=05p50qBVv20004jR0501u00cVFk0YrBzR -> To=sip:TO@ccc;tag=118d620a] [10.170.72.38/5060 -> 10.170.74.21/5060] [235385 REQUEST ACK sip:ccc@10.170.74.24:20555 SIP/2.0] -- .[openser.cfg.m4:637] Processing ok : t_relay DUri= RUri=sip:ccc@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@10.170.72.38] [From=sip:FROM@10.170.72.38;tag=05p50qBVv20004jR0501u00cVFk0YrBzR -> To=sip:TO@ccc;tag=118d620a] [10.170.72.38/5060 -> 10.170.74.21/5060] [235413 REQUEST BYE sip:ccc@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@10.170.72.38;tag=05p50qBVv20004jR0501u00cVFk0YrBzR To=sip:TO@ccc;tag=118d620a Call-ID=001B2105E7ACD49F08589FB6EE44@10.170.72.38 CSeq=31559 BYE Contact=sip:FROM@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@10.170.72.38] [From=sip:FROM@10.170.72.38;tag=05p50qBVv20004jR0501u00cVFk0YrBzR -> To=sip:TO@ccc;tag=118d620a] [10.170.72.38/5060 -> 10.170.74.21/5060] [235413 REQUEST BYE sip:ccc@10.170.74.24:20555 SIP/2.0] -- .[openser.cfg.m4:637] Processing ok : t_relay DUri= RUri=sip:ccc@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@ccc;tag=118d620a From: sip:FROM@10.170.72.38;tag=05p50qBVv20004jR0501u00cVFk0YrBzR Call-ID: 001B2105E7ACD49F08589FB6EE44@10.170.72.38 Contact: sip:ccc@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@ccc;tag=118d620a From: sip:FROM@10.170.72.38;tag=05p50qBVv20004jR0501u00cVFk0YrBzR Call-ID: 001B2105E7ACD49F08589FB6EE44@10.170.72.38 Contact: sip:ccc@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@10.170.72.38] [From=sip:FROM@10.170.72.38;tag=05p50qBVv20004jR0501u00cVFk0YrBzR -> To=sip:TO@ccc] [10.170.72.38/5060 -> 10.170.74.21/5060] [234894 REQUEST INVITE sip:TO@ccc SIP/2.0] -- .[openser.cfg.m4:987] serial fork on failure : Sending 'RUri= ' to next contact 'DUri=sip:TO@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@10.170.72.38] [From=sip:FROM@10.170.72.38;tag=05p50qBVv20004jR0501u00cVFk0YrBzR -> To=sip:TO@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@ccc From=sip:FROM@10.170.72.38;tag=05p50qBVv20004jR0501u00cVFk0YrBzR Call-ID=001B2105E7ACD49F08589FB6EE44@10.170.72.38 Contact=sip:ccc@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@ccc;tag=1e27ac08 From: sip:FROM@10.170.72.38;tag=05p50qBVv20004jR0501u00cVFk0YrBzR Call-ID: 001B2105E7ACD49F08589FB6EE44@10.170.72.38 Contact: sip:ccc@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@10.170.72.38] [From=sip:FROM@10.170.72.38;tag=05p50qBVv20004jR0501u00cVFk0YrBzR -> To=sip:TO@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@ccc;tag=1e27ac08 From: sip:FROM@10.170.72.38;tag=05p50qBVv20004jR0501u00cVFk0YrBzR Call-ID: 001B2105E7ACD49F08589FB6EE44@10.170.72.38 Contact: sip:ccc@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@10.170.72.38] [From=sip:FROM@10.170.72.38;tag=05p50qBVv20004jR0501u00cVFk0YrBzR -> To=sip:TO@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@ccc;tag=1e27ac08 From: sip:FROM@10.170.72.38;tag=05p50qBVv20004jR0501u00cVFk0YrBzR Call-ID: 001B2105E7ACD49F08589FB6EE44@10.170.72.38 Contact: sip:ccc@10.170.74.24:20540 CSeq: 31558 INVITE Content-Length: 222 Content-Type: application/sdp

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@ccc;tag=1e27ac08 From: sip:FROM@10.170.72.38;tag=05p50qBVv20004jR0501u00cVFk0YrBzR Call-ID: 001B2105E7ACD49F08589FB6EE44@10.170.72.38 Contact: sip:ccc@10.170.74.24:20540 CSeq: 31558 INVITE Content-Length: 222 Content-Type: application/sdp

And handled ok

T000 12/02/2008 15:09:20.655 bin#ser#05125#-1 = (sermonicom.cc:293) [3084977856] .[Call-ID=001B2105E7ACD49F08589FB6EE44@10.170.72.38] [From=sip:FROM@10.170.72.38;tag=05p50qBVv20004jR0501u00cVFk0YrBzR -> To=sip:TO@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@ccc;tag=1e27ac08 From: sip:FROM@10.170.72.38;tag=05p50qBVv20004jR0501u00cVFk0YrBzR Call-ID: 001B2105E7ACD49F08589FB6EE44@10.170.72.38 Contact: sip:ccc@10.170.74.24:20540 CSeq: 31558 INVITE Content-Length: 222 Content-Type: application/sdp

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@10.170.72.38] [From=sip:FROM@10.170.72.38;tag=05p50qBVv20004jR0501u00cVFk0YrBzR -> To=sip:TO@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@ccc;tag=1e27ac08 From: sip:FROM@10.170.72.38;tag=05p50qBVv20004jR0501u00cVFk0YrBzR Call-ID: 001B2105E7ACD49F08589FB6EE44@10.170.72.38 Contact: sip:ccc@10.170.74.24:20540 CSeq: 31558 INVITE Content-Length: 222 Content-Type: application/sdp

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@ccc;tag=1e27ac08 From: sip:FROM@10.170.72.38;tag=05p50qBVv20004jR0501u00cVFk0YrBzR Call-ID: 001B2105E7ACD49F08589FB6EE44@10.170.72.38 Contact: sip:ccc@10.170.74.24:20540 CSeq: 31558 INVITE Content-Length: 222 Content-Type: application/sdp

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@ccc;tag=1e27ac08 From: sip:FROM@10.170.72.38;tag=05p50qBVv20004jR0501u00cVFk0YrBzR Call-ID: 001B2105E7ACD49F08589FB6EE44@10.170.72.38 Contact: sip:ccc@10.170.74.24:20540 CSeq: 31558 INVITE Content-Length: 222 Content-Type: application/sdp

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@ccc;tag=1e27ac08 From: sip:FROM@10.170.72.38;tag=05p50qBVv20004jR0501u00cVFk0YrBzR Call-ID: 001B2105E7ACD49F08589FB6EE44@10.170.72.38 Contact: sip:ccc@10.170.74.24:20540 CSeq: 31558 INVITE Content-Length: 222 Content-Type: application/sdp

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@ccc;tag=1e27ac08 From: sip:FROM@10.170.72.38;tag=05p50qBVv20004jR0501u00cVFk0YrBzR Call-ID: 001B2105E7ACD49F08589FB6EE44@10.170.72.38 Contact: sip:ccc@10.170.74.24:20540 CSeq: 31558 INVITE Content-Length: 222 Content-Type: application/sdp

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@ccc;tag=1e27ac08 From: sip:FROM@10.170.72.38;tag=05p50qBVv20004jR0501u00cVFk0YrBzR Call-ID: 001B2105E7ACD49F08589FB6EE44@10.170.72.38 Contact: sip:ccc@10.170.74.24:20540 CSeq: 31558 INVITE Content-Length: 222 Content-Type: application/sdp

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@ccc;tag=1e27ac08 From: sip:FROM@10.170.72.38;tag=05p50qBVv20004jR0501u00cVFk0YrBzR Call-ID: 001B2105E7ACD49F08589FB6EE44@10.170.72.38 Contact: sip:ccc@10.170.74.24:20540 CSeq: 31558 INVITE Content-Length: 222 Content-Type: application/sdp

...

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@lists.kamailio.org http://lists.kamailio.org/cgi-bin/mailman/listinfo/users

5927

Age (days ago)

5928

Last active (days ago)

sr-users@lists.kamailio.org

2 comments

2 participants

tags (0)

participants (2)

Aurelien Grimaud
Daniel-Constantin Mierla