[OpenSIPS-Users] OpenSIPS not processing responses?

[Gavin Murphy]

Hi all,

We're seeing a possible issue in OpenSIPS related to the timely 
processing of replies. For example, OpenSIPS receives a REGISTER and 
passes it on to our application server (which is the registrar). The 
registrar receives it within the same second and generates the response 
(a 401 initially) within 0.003 seconds. However OpenSIPS doesn't appear 
to receive that message, and half a second after the first REGISTER is 
sent, there is a retransmission after 0.5 second, which is again 
received by our registrar and a response is generated very quickly. But 
still the 401 doesn't get received and/or processed by OpenSIPS. The 
retransmission happens again a few times as per RFC 3261. Eventually, 
almost 30 seconds later OpenSIPS logs that the reply to the REGISTER has 
been received.

Based on the evidence it seems that there is no problem with OpenSIPS 
sending the request and it being received by our registrar. There also 
doesn't appear to be any issues with the retransmission by OpenSIPS at 
the right intervals, nor does the registrar appear to be introducing any 
delays. There is not much other traffic going on at the same time, but 
there are other REGISTERs that are getting the same result.

Here are some logs from OpenSIPS:
Initial relay to our registrar:
Nov  1 19:14:40 ip-10-72-7-129 rcs-opensips[13839]: RCS INFO: ROUTE[2] 
(Inbound and Outbound) - REGISTER REQUEST relayed. Exiting.
Nov  1 19:14:40 ip-10-72-7-129 rcs-opensips[13839]: DBG:tm:t_unref: 
UNREF_UNSAFE: [0x7f8f8b8d6518] after is 0
Nov  1 19:14:40 ip-10-72-7-129 rcs-opensips[13839]: 
DBG:core:destroy_avp_list: destroying list (nil)

Retransmissions:
Nov  1 19:14:40 ip-10-72-7-129 rcs-opensips[13836]: 
DBG:tm:retransmission_handler: retransmission_handler : request 
resending (t=0x7f8f8b8d6518, REGISTER  ... )
Nov  1 19:14:41 ip-10-72-7-129 rcs-opensips[13836]: 
DBG:tm:retransmission_handler: retransmission_handler : request 
resending (t=0x7f8f8b8d6518, REGISTER  ... )
Nov  1 19:14:43 ip-10-72-7-129 rcs-opensips[13836]: 
DBG:tm:retransmission_handler: retransmission_handler : request 
resending (t=0x7f8f8b8d6518, REGISTER  ... )
Nov  1 19:14:53 ip-10-72-7-129 rcs-opensips[13836]: 
DBG:tm:retransmission_handler: retransmission_handler : request 
resending (t=0x7f8f8b8d6518, REGISTER  ... )
Nov  1 19:15:04 ip-10-72-7-129 rcs-opensips[13836]: 
DBG:tm:retransmission_handler: retransmission_handler : request 
resending (t=0x7f8f8b8d6518, REGISTER  ... )

Reply "received" (IP,s TNs, and domains anonymized):
Nov  1 19:15:08 ip-10-72-7-129 rcs-opensips[13831]: 
DBG:tm:t_reply_matching: REF_UNSAFE:[0x7f8f8b8d6518] after is 1
Nov  1 19:15:08 ip-10-72-7-129 rcs-opensips[13831]: 
DBG:tm:t_reply_matching: reply matched (T=0x7f8f8b8d6518)!
Nov  1 19:15:08 ip-10-72-7-129 rcs-opensips[13831]: DBG:tm:t_check: 
end=0x7f8f8b8d6518
Nov  1 19:15:08 ip-10-72-7-129 rcs-opensips[13831]: 
DBG:tm:reply_received: org. status uas=0, uac[0]=0 local=0 is_invite=0)
Nov  1 19:15:08 ip-10-72-7-129 rcs-opensips[13831]: RCS INFO: PROCESSING 
ONREPLY ROUTE[2] (Reply for Inbound Request)
Nov  1 19:15:08 ip-10-72-7-129 rcs-opensips[13831]: RCS DEBUG: 
ONREPLY_ROUTE[1] (Reply for Inbound Request) - Dump Request Info.
Nov  1 19:15:08 ip-10-72-7-129 rcs-opensips[13831]: RCS DEBUG: 
============= DUMP REPLY =============
Nov  1 19:15:08 ip-10-72-7-129 rcs-opensips[13831]: RCS DEBUG: SIP 
message buffer:#012SIP/2.0 401 Unauthorized#015#012Via: SIP/2.0/UDP 
x.x.x.x:6000;branch=z9hG4bKf439.62091482.0;i=c04c3,SIP/2.0/TCP 
x.x.x.x:40042;branch=z9hG4bK1490773660;received=x.x.x.x;rport=40042#015#012Record-Route: 
<sip:x.x.x.x:6031;lr>#015#012Call-ID: 
6d76ce9e-ed19-9701-1e75-f070eacd3400#015#012From: 
<sip:+xxxxxxxxxxx at domain.net>;tag=330928025#015#012To: 
<sip:+xxxxxxxxxxx at domain.net>;tag=Jmuh3YOvEmCA#015#012CSeq: 221716357 
REGISTER#015#012Contact: <sip:x.x.x.x:6031>#015#012Require: 
gruu#015#012WWW-Authenticate: Digest 
realm="domain.net",nonce="5273fda02d788dccba9301c8e1f68f078f8e95e5",qop="auth",opaque="004533235332435434ffac663e",algorithm=MD5#015#012Content-Length: 
0#015#012P-Associated-URI: 
<sip:+xxxxxxxxxx at domain.net>#015#012P-Preferred-Identity: 
<sip:+xxxxxxxxxx at domain.net>#015#012P-Access-Network-Info: 
ADSL;utran-cell-id-3gpp=00000000#015#012Privacy: none#015#012#015#012

On the registrar the logs appear as follows:
[2013-Nov-01 19:14:40.185708] [14002] [6-inf] ===RECV==> REGISTER 
(6d76ce9e-ed19-9701-1e75-f070eacd3400:+xxxxxxxxxx => +xxxxxxxxxx)
[2013-Nov-01 19:14:40.188331] [14002] [6-inf] <==SENT=== 401 
Unauthorized (6d76ce9e-ed19-9701-1e75-f070eacd3400:+xxxxxxxxxx => 
+xxxxxxxxxx)
[2013-Nov-01 19:14:40.721011] [14002] [6-inf] ===RECV==> REGISTER 
(6d76ce9e-ed19-9701-1e75-f070eacd3400:+xxxxxxxxxx => +xxxxxxxxxx)
[2013-Nov-01 19:14:40.721162] [14002] [6-inf] <==SENT=== 401 
Unauthorized (6d76ce9e-ed19-9701-1e75-f070eacd3400:+xxxxxxxxxx => 
+xxxxxxxxxx)
[2013-Nov-01 19:14:41.723160] [14002] [6-inf] ===RECV==> REGISTER 
(6d76ce9e-ed19-9701-1e75-f070eacd3400:+xxxxxxxxxx => +xxxxxxxxxx)
[2013-Nov-01 19:14:41.723262] [14002] [6-inf] <==SENT=== 401 
Unauthorized (6d76ce9e-ed19-9701-1e75-f070eacd3400:+xxxxxxxxxx => 
+xxxxxxxxxx)

etc....

This "bogging down" seems to happen on a regular basis, and the only way 
we are able to resolve it at the moment is to restart OpenSIPS. Until it 
is restarted all of the registrations are essentially failing. I believe 
it is v1.8.2 that we are running.

Anyone have any thoughts as to what might be happening?

Thanks,

Gavin

-- 
Gavin Murphy
Vice President & CTO |www.newpace.ca  - Real Technology Solutions
(e)gavin.murphy at newpace.ca
(w) +1.902.406.8375 x 1002
(m) +1.902.401.9445
(f) +1.902.406.8377