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

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


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

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

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