[OpenSIPS-Users] Registration Loss on opensips SBC

[Royee Tichauer]

Hi,

We are using opensips 2.1 as an SBC component and we see that we have loss
of registrations happening once in a while. When we captured SIP we saw
that some messages are being delayed by a couple of seconds. We enabled
'exec_execute_message=50000' and saw in the logs that opensips core methods
like 't_realy' and 'save' . I looked at SAR during this time and there are
no indications of CPU running high during this time.

Can you help me figure out this issue?

Thanks,
Royee

Logs:

Feb  4 17:07:23 sbc.company.com <http://amz1vpsbc2.amz1.vocalocity.com/>
 /usr/sbin/opensips[29827]: WARNING:core:log_expiry: threshold exceeded :
msg processing took too long - 8912776 us.Source : SIP/2.0 200
OK#015#012Via: SIP/2.0/UDP
<ip>5060;received=<ip>;rport=5060;branch=z9hG4bK7eec.23d21053.0#015#012Via:
SIP/2.0/UDP
<ip>:5060;rport=5060;received=<ip>;branch=z9hG4bK2715962793#015#012From: ""
<sip:<sip_id>@<account>.company.com:5060
<http://sip:VH2677991@sip-190913.accounts.vocalocity.com:5060/>>;tag=646749010#015#012To:
"###" <sip:#####@sip-#####.accounts.COMPANY.com:5060
<http://sip:VH2677991@sip-190913.accounts.vocalocity.com:5060/>
>;tag=8b4547f60a700f827fe775c80b65be1b.efed#015#012Call-ID:
0_2258842442@<ip>#015#012CSeq
<http://0_2258842442@192.168.0.3/#015%23012CSeq>: 3575
REGISTER#015#012Contact: <sip:######@<ip>:5060
<http://sip:VH2677991@97.96.230.47:5060/>>;expires=45;received="sip:
<ip>:5060 <http://52.7.62.159:5060/>"#015#012Server:
Vonage#015#012Content-Length: 0#015#012#015#012

Feb  4 17:07:23 sbc.amz1.company.com
<http://amz1vpsbc2.amz1.vocalocity.com/> /usr/sbin/opensips[29827]:
WARNING:core:log_expiry:
#1 is a module action : save - 8912725us - line 914

Feb  4 17:07:23 sbc.amz1.company.com
<http://amz1vpsbc2.amz1.vocalocity.com/> /usr/sbin/opensips[29827]:
WARNING:core:log_expiry:
#2 is a core action : 80 - 17us - line 1103

Feb  4 17:07:23 sbc.amz1.company.com
<http://amz1vpsbc2.amz1.vocalocity.com/> /usr/sbin/opensips[29827]:
WARNING:core:log_expiry:
#3 is a core action : 72 - 5us - line 887

Feb  4 17:07:23 sbc.amz1.company.com
<http://amz1vpsbc2.amz1.vocalocity.com/> /usr/sbin/opensips[29820]:
WARNING:core:log_expiry:
threshold exceeded : msg processing took too long - 5355695 us.Source :
REGISTER sip:####.accounts.company.com:5060
<http://sip-190913.accounts.vocalocity.com:5060/> SIP/2.0#015#012Via:
SIP/2.0/UDP <ip>:5060;branch=z9hG4bK2715962793#015#012From: "###" <
sip:#####@sip-####.accounts.company.com:5060
<http://sip:VH2677991@sip-190913.accounts.vocalocity.com:5060/>>;tag=646749010#015#012To:
"####" <sip:####@sip-#####.accounts.company.com:5060
<http://sip:VH2677991@sip-190913.accounts.vocalocity.com:5060/>
>#015#012Call-ID: 0_2258842442@######015#012CSeq
<http://0_2258842442@192.168.0.3/#015%23012CSeq>: 3575
REGISTER#015#012Contact: <####@<ip>:5060
<http://sip:VH2677991@97.96.230.47:5060/>>#015#012Authorization: Digest
username="####", realm="####.accounts.company.com
<http://sip-190913.accounts.vocalocity.com/>",
nonce="5a773de000000b19dc7d21205f1edfda504fac90296b04fb", uri="sip:
sip-#######.accounts.company.com:5060
<http://sip-190913.accounts.vocalocity.com:5060/>",
response="df8d6cbfd178a36913a1464920da3f06", algorithm=MD5#015#012Allow:
INVITE, INFO, PRACK, ACK, BYE, CANCEL, OPTIONS, NOTIFY, REGISTER,
SUBSCRIBE, REFER, PUBLISH, UPDATE, MESSAGE#015#012Max-Forwards:
69#015#012User-Agent: #########015#012Expires: 3600#015#012Allow-Events:
talk,hold,conference,refer,check-sync#015#012Content-Length:
0#015#012#015#012


Feb  4 17:07:23 sbc.amz1.company.com
<http://amz1vpsbc2.amz1.vocalocity.com/>  /usr/sbin/opensips[29827]:
WARNING:core:log_expiry:
#4 is a core action : 72 - 5us - line 1086

Feb  4 17:07:23 sbc.amz1.company.com
<http://amz1vpsbc2.amz1.vocalocity.com/>  /usr/sbin/opensips[29820]:
WARNING:core:log_expiry:
#1 is a module action : t_relay - 5355333us - line 465

Feb  4 17:07:23 sbc.amz1.company.com
<http://amz1vpsbc2.amz1.vocalocity.com/>  /usr/sbin/opensips[29827]:
WARNING:core:log_expiry:
#5 is a module action : ds_is_in_list - 4us - line 943

Feb  4 17:07:23 sbc.amz1.company.com
<http://amz1vpsbc2.amz1.vocalocity.com/>  /usr/sbin/opensips[29817]:
WARNING:core:log_expiry:
#1 is a module action : t_relay - 7375370us - line 465

Feb  4 17:07:23 sbc.amz1.company.com
<http://amz1vpsbc2.amz1.vocalocity.com/>  /usr/sbin/opensips[29820]:
WARNING:core:log_expiry:
#2 is a core action : 78 - 105us - line 604

Feb  4 17:07:23 sbc.amz1.company.com
<http://amz1vpsbc2.amz1.vocalocity.com/>  /usr/sbin/opensips[29817]:
WARNING:core:log_expiry:
#2 is a core action : 78 - 100us - line 604

Feb  4 17:07:23 sbc.amz1.company.com
<http://amz1vpsbc2.amz1.vocalocity.com/>  /usr/sbin/opensips[29820]:
WARNING:core:log_expiry:
#3 is a core action : 78 - 99us - line 635

Feb  4 17:07:23 sbc.amz1.company.com
<http://amz1vpsbc2.amz1.vocalocity.com/>  /usr/sbin/opensips[29817]:
WARNING:core:log_expiry:
#3 is a core action : 78 - 98us - line 635
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.opensips.org/pipermail/users/attachments/20180205/ad7da822/attachment-0001.html>