<div dir="ltr">Hi,<div><br></div><div>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. </div><div><br></div><div>Can you help me figure out this issue?<br></div><div><br></div><div>Thanks,</div><div>Royee</div><div><br></div><div>Logs:</div><div><br></div><div><p class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-p1" style="color:rgb(33,33,33);font-size:13px"><span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">Feb<span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-Apple-converted-space">  </span>4 17:07:23 <a href="http://amz1vpsbc2.amz1.vocalocity.com/" style="outline:transparent solid 1px" target="_blank">sbc.company.com</a> /usr/sbin/opensips[29827]: </span><span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s4">WARNING</span><span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">: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: "" <<a href="http://sip:VH2677991@sip-190913.accounts.vocalocity.com:5060/" target="_blank">sip:<sip_id>@<account>.company.com:5060</a>>;tag=646749010#015#012To: "###" <<a href="http://sip:VH2677991@sip-190913.accounts.vocalocity.com:5060/" target="_blank">sip:#####@sip-#####.accounts.COMPANY.com:5060</a>>;tag=8b4547f60a700f827fe775c80b65be1b.efed#015#012Call-ID: <a href="http://0_2258842442@192.168.0.3/#015%23012CSeq" target="_blank">0_2258842442@<ip>#015#012CSeq</a>: 3575 REGISTER#015#012Contact: <<a href="http://sip:VH2677991@97.96.230.47:5060/" target="_blank">sip:######@<ip>:5060</a>>;expires=45;received="sip:<a href="http://52.7.62.159:5060/" target="_blank"><ip>:5060</a>"#015#012Server: Vonage#015#012Content-Length: 0#015#012#015#012</span></p><p class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-p1" style="color:rgb(33,33,33);font-size:13px"><span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">Feb<span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-Apple-converted-space">  </span>4 17:07:23 <a href="http://amz1vpsbc2.amz1.vocalocity.com/" target="_blank">sbc.amz1.company.com</a> /usr/sbin/opensips[29827]: </span><span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s4">WARNING</span><span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">:core:log_expiry: #1 is a module action : <font color="#ff0000">save - 8912725us</font> - line 914</span></p><p class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-p1" style="color:rgb(33,33,33);font-size:13px"><span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">Feb<span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-Apple-converted-space">  </span>4 17:07:23 <a href="http://amz1vpsbc2.amz1.vocalocity.com/" style="outline:transparent solid 1px" target="_blank">sbc.amz1.company.com</a> /usr/sbin/opensips[29827]: </span><span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s4">WARNING</span><span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">:core:log_expiry: #2 is a core action : 80 - 17us - line 1103</span></p><p class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-p1" style="color:rgb(33,33,33);font-size:13px"><span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">Feb<span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-Apple-converted-space">  </span>4 17:07:23 <a href="http://amz1vpsbc2.amz1.vocalocity.com/" style="outline:transparent solid 1px" target="_blank">sbc.amz1.company.com</a> /usr/sbin/opensips[29827]: </span><span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s4">WARNING</span><span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">:core:log_expiry: #3 is a core action : 72 - 5us - line 887</span></p><p class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-p1" style="color:rgb(33,33,33);font-size:13px"><span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">Feb<span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-Apple-converted-space">  </span>4 17:07:23 <a href="http://amz1vpsbc2.amz1.vocalocity.com/" style="outline:transparent solid 1px" target="_blank">sbc.amz1.company.com</a> /usr/sbin/opensips[29820]: </span><span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s4">WARNING</span><span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">:core:log_expiry: threshold exceeded : msg processing took too long - 5355695 us.Source : REGISTER sip:####<a href="http://sip-190913.accounts.vocalocity.com:5060/" target="_blank">.accounts.company.com:5060</a> SIP/2.0#015#012Via: SIP/2.0/UDP <ip>:5060;branch=z9hG4bK2715962793#015#012From: "###" <<a href="http://sip:VH2677991@sip-190913.accounts.vocalocity.com:5060/" target="_blank">sip:#####@sip-####.accounts.company.com:5060</a>>;tag=646749010#015#012To: "####" <<a href="http://sip:VH2677991@sip-190913.accounts.vocalocity.com:5060/" target="_blank">sip:####@sip-#####.accounts.company.com:5060</a>>#015#012Call-ID: <a href="http://0_2258842442@192.168.0.3/#015%23012CSeq" target="_blank">0_2258842442@######015#012CSeq</a>: 3575 REGISTER#015#012Contact: <<a href="http://sip:VH2677991@97.96.230.47:5060/" target="_blank">####@<ip>:5060</a>>#015#012Authorization: Digest username="####", realm="<a href="http://sip-190913.accounts.vocalocity.com/" target="_blank">####.accounts.company.com</a>", nonce="5a773de000000b19dc7d21205f1edfda504fac90296b04fb", uri="sip:<a href="http://sip-190913.accounts.vocalocity.com:5060/" target="_blank">sip-#######.accounts.company.com:5060</a>", 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</span></p><p class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-p1" style="color:rgb(33,33,33);font-size:13px"><br></p><p class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-p1" style="color:rgb(33,33,33);font-size:13px"><span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">Feb<span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-Apple-converted-space">  </span>4 17:07:23 </span><a href="http://amz1vpsbc2.amz1.vocalocity.com/" target="_blank" style="outline:transparent solid 1px">sbc.amz1.company.com</a> <span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1"> /usr/sbin/opensips[29827]: </span><span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s4">WARNING</span><span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">:core:log_expiry: #4 is a core action : 72 - 5us - line 1086</span></p><p class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-p1" style="color:rgb(33,33,33);font-size:13px"><span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">Feb<span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-Apple-converted-space">  </span>4 17:07:23 <a href="http://amz1vpsbc2.amz1.vocalocity.com/" target="_blank" style="outline:transparent solid 1px">sbc.amz1.company.com</a>  /usr/sbin/opensips[29820]: </span><span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s4">WARNING</span><span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">:core:log_expiry: #1 is a module action : <font color="#ff0000">t_relay - 5355333us</font> - line 465</span></p><p class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-p1" style="color:rgb(33,33,33);font-size:13px"><span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">Feb<span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-Apple-converted-space">  </span>4 17:07:23 <a href="http://amz1vpsbc2.amz1.vocalocity.com/" target="_blank" style="outline:transparent solid 1px">sbc.amz1.company.com</a>  /usr/sbin/opensips[29827]: </span><span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s4">WARNING</span><span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">:core:log_expiry: #5 is a module action : ds_is_in_list - 4us - line 943</span></p><p class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-p1" style="color:rgb(33,33,33);font-size:13px"><span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">Feb<span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-Apple-converted-space">  </span>4 17:07:23 <a href="http://amz1vpsbc2.amz1.vocalocity.com/" target="_blank" style="outline:transparent solid 1px">sbc.amz1.company.com</a>  /usr/sbin/opensips[29817]: </span><span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s4">WARNING</span><span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">:core:log_expiry: #1 is a module action : t_relay - 7375370us - line 465</span></p><p class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-p1" style="color:rgb(33,33,33);font-size:13px"><span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">Feb<span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-Apple-converted-space">  </span>4 17:07:23 <a href="http://amz1vpsbc2.amz1.vocalocity.com/" target="_blank" style="outline:transparent solid 1px">sbc.amz1.company.com</a>  /usr/sbin/opensips[29820]: </span><span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s4">WARNING</span><span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">:core:log_expiry: #2 is a core action : 78 - 105us - line 604</span></p><p class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-p1" style="color:rgb(33,33,33);font-size:13px"><span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">Feb<span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-Apple-converted-space">  </span>4 17:07:23 <a href="http://amz1vpsbc2.amz1.vocalocity.com/" target="_blank" style="outline:transparent solid 1px">sbc.amz1.company.com</a>  /usr/sbin/opensips[29817]: </span><span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s4">WARNING</span><span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">:core:log_expiry: #2 is a core action : 78 - 100us - line 604</span></p><p class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-p1" style="color:rgb(33,33,33);font-size:13px"><span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">Feb<span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-Apple-converted-space">  </span>4 17:07:23 <a href="http://amz1vpsbc2.amz1.vocalocity.com/" target="_blank" style="outline:transparent solid 1px">sbc.amz1.company.com</a>  /usr/sbin/opensips[29820]: </span><span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s4">WARNING</span><span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">:core:log_expiry: #3 is a core action : 78 - 99us - line 635</span></p><p class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-p1" style="color:rgb(33,33,33);font-size:13px"><span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">Feb<span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-Apple-converted-space">  </span>4 17:07:23 <a href="http://amz1vpsbc2.amz1.vocalocity.com/" target="_blank" style="outline:transparent solid 1px">sbc.amz1.company.com</a>  /usr/sbin/opensips[29817]: </span><span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s4">WARNING</span><span class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">:core:log_expiry: #3 is a core action : 78 - 98us - line 635</span></p></div></div>