[OpenSIPS-Users] OpenSIPS not processing responses?

Thu Nov 14 18:40:47 CET 2013

Seems opensips is acting as transport bridge between udp and tcp, so, 
do the SIP replies actually arrive at same interface (transport + ip + 
port) from where the request was sent, and opensips is listening to that 
interface? Can you share SIP trace with us?

Also, are you using any custom application, e.g. perl / lua script etc. 
in opensips dial plan, that might be blocking the opensips thread that 
is managing this transaction. As far as i remember opensips 1.8.x does 
not have async processing, therefore, if any script or module command 
that consumes time e.g. custom sql query, external script or shell 
command etc. would block opensips and any responses received during that 
time are likely to be ignored.

Thank you.

On 2013-11-14 16:05, Gavin Murphy wrote:
> 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

-- 
Mit freundlichen Grüßen
Muhammad Shahzad
-----------------------------------
CISCO Rich Media Communication Specialist (CRMCS)
CISCO Certified Network Associate (CCNA)
Cell: +49 176 99 83 10 85
MSN: shari_786pk at hotmail.com
Email: shaheryarkh at googlemail.com