<div dir="ltr">Wow those thresholds give you a good amount of info. I'll have to see how I can make my MySQL service quicker.<div><br></div><div><div>Apr 29 15:31:37 SIPProxy02 /usr/local/sbin/opensips[3104]: WARNING:db_mysql:log_expiry: threshold exceeded : mysql query took too long - 512355 us.Source : insert into location (username,contact,expires,q,ca</div>
<div>llid,cseq,flags,cflags,user_agent,received,path,socket,methods,last_modified,sip_instance,domain ) values ('9*12*1$%$%','sip:9*12*1$%$%@172.*.*.33:57369;line=mtj8kl6c','2013-04-29 16:31:37',1.00 ,'26</div>
<div>000000cbed-7lfki4ifz7hz',1260,0,0,'snom720/<a href="http://8.7.3.19">8.7.3.19</a>','sip:172.*.*.33:57369',NULL,'udp:<a href="http://50.57.54.156:5060">50.57.54.156:5060</a>',7999,'2013-04-29 15:31:37',NULL,'<a href="http://all.com">all.com</a>') on duplicate key update username='9*12*1$%$%',co</div>
<div>ntact='sip:9*12*1$%$%@172.*.*.33:57369;line=mtj8kl6c',expires='2013-04-29 16:31:37',q=1.00 ,callid='26000000cbed-7lfki4ifz7hz',cseq=1260,flags=0,cflags=0,user_agent='snom720/<a href="http://8.7.3.19">8.7.3.19</a>',received='sip:1</div>
<div><a href="http://72.12.199.33:57369">72.12.199.33:57369</a>',path=NULL,socket='udp:<a href="http://50.57.54.156:5060">50.57.54.156:5060</a>',methods=7999,last_modified='2013-04-29 15:31:37',sip_instance=NULL,domain='<a href="http://all.com">all.com</a>'</div>
<div>Apr 29 15:31:37 SIPProxy02 /usr/local/sbin/opensips[3104]: WARNING:core:log_expiry: threshold exceeded : msg processing took too long - 519804 us.Source : REGISTER sip:<a href="http://all.com">all.com</a> SIP/2.0#015#012Via: SIP</div>
<div>/2.0/UDP 172.*.*.33:57369;branch=z9hG4bK-clxrqnw5iv48;rport#015#012From: "901-201-5656" <sip:9*12*1$%$%@<a href="http://all.com">all.com</a>>;tag=bs72h6ifw5#015#012To: "901-201-5656" <sip:9*12*1$%$%@<a href="http://all.com">all.com</a>>#015#012Ca</div>
<div>ll-ID: 26000000cbed-7lfki4ifz7hz#015#012CSeq: 1260 REGISTER#015#012Max-Forwards: 69#015#012Contact: <sip:9*12*1$%$%@172.*.*.33:57369;line=mtj8kl6c>;reg-id=1;q=1.0;audio;mobility="fixed";duplex="full";desc</div>
<div>ription="snom720";actor="principal";events="dialog";methods="INVITE,ACK,CANCEL,BYE,REFER,OPTIONS,NOTIFY,SUBSCRIBE,PRACK,MESSAGE,INFO"#015#012User-Agent: snom720/<a href="http://8.7.3.19#015#012Allow-Events">8.7.3.19#015#012Allow-Events</a>: dialog#015#012X-</div>
<div>Real-IP: 192.168.1.71#015#012Supported: path#015#012Authorization: Digest username="9*12*1$%$%",realm="<a href="http://all.com">all.com</a>",nonce="517ed8c7f0973e1dd14a403ead3ffb092efd04c3",uri="sip:<a href="http://all.com">all.com</a>",qop=auth,nc=</div>
<div>00000001,cnonce="649029e8",response="c1cdca29ccd998e22b8caed1454719d2",algorithm=MD5#015#012Expires: 3600#015#012Content-Length: 0#015#012#015#012</div><div>Apr 29 15:31:37 SIPProxy02 /usr/local/sbin/opensips[3104]: WARNING:core:log_expiry: #1 is a core action : 6 - 519586us - line 553</div>
<div>Apr 29 15:31:37 SIPProxy02 /usr/local/sbin/opensips[3104]: WARNING:core:log_expiry: #2 is a core action : 14 - 519573us - line 595</div><div>Apr 29 15:31:37 SIPProxy02 /usr/local/sbin/opensips[3104]: WARNING:core:log_expiry: #3 is a core action : 6 - 519567us - line 594</div>
<div>Apr 29 15:31:37 SIPProxy02 /usr/local/sbin/opensips[3104]: WARNING:core:log_expiry: #4 is a core action : 14 - 519564us - line 967</div><div>Apr 29 15:31:37 SIPProxy02 /usr/local/sbin/opensips[3104]: WARNING:core:log_expiry: #5 is a module action : save - 516033us - line 956</div>
<div>Apr 29 15:31:38 SIPProxy02 /usr/local/sbin/opensips[3106]: WARNING:db_mysql:log_expiry: threshold exceeded : mysql query took too long - 508532 us.Source : insert into location (username,contact,expires,q,ca</div><div>
llid,cseq,flags,cflags,user_agent,received,path,socket,methods,last_modified,sip_instance,domain ) values ('9*12*1$%$%','sip:9*12*1$%$%@172.*.*.33:57369;line=mtj8kl6c','2013-04-29 16:31:37',1.00 ,'26</div>
<div>000000cbed-7lfki4ifz7hz',1260,0,0,'snom720/<a href="http://8.7.3.19">8.7.3.19</a>','sip:172.*.*.33:57369',NULL,'udp:<a href="http://50.57.54.156:5060">50.57.54.156:5060</a>',7999,'2013-04-29 15:31:37',NULL,'<a href="http://all.com">all.com</a>') on duplicate key update username='9*12*1$%$%',co</div>
<div>ntact='sip:9*12*1$%$%@172.*.*.33:57369;line=mtj8kl6c',expires='2013-04-29 16:31:37',q=1.00 ,callid='26000000cbed-7lfki4ifz7hz',cseq=1260,flags=0,cflags=0,user_agent='snom720/<a href="http://8.7.3.19">8.7.3.19</a>',received='sip:1</div>
<div><a href="http://72.12.199.33:57369">72.12.199.33:57369</a>',path=NULL,socket='udp:<a href="http://50.57.54.156:5060">50.57.54.156:5060</a>',methods=7999,last_modified='2013-04-29 15:31:37',sip_instance=NULL,domain='<a href="http://all.com">all.com</a>'</div>
<div>Apr 29 15:31:38 SIPProxy02 /usr/local/sbin/opensips[3106]: WARNING:core:log_expiry: threshold exceeded : msg processing took too long - 513747 us.Source : REGISTER sip:<a href="http://all.com">all.com</a> SIP/2.0#015#012Via: SIP</div>
<div>/2.0/UDP 172.*.*.33:57369;branch=z9hG4bK-clxrqnw5iv48;rport#015#012From: "901-201-5656" <sip:9*12*1$%$%@<a href="http://all.com">all.com</a>>;tag=bs72h6ifw5#015#012To: "901-201-5656" <sip:9*12*1$%$%@<a href="http://all.com">all.com</a>>#015#012Ca</div>
<div>ll-ID: 26000000cbed-7lfki4ifz7hz#015#012CSeq: 1260 REGISTER#015#012Max-Forwards: 69#015#012Contact: <sip:9*12*1$%$%@172.*.*.33:57369;line=mtj8kl6c>;reg-id=1;q=1.0;audio;mobility="fixed";duplex="full";desc</div>
<div>ription="snom720";actor="principal";events="dialog";methods="INVITE,ACK,CANCEL,BYE,REFER,OPTIONS,NOTIFY,SUBSCRIBE,PRACK,MESSAGE,INFO"#015#012User-Agent: snom720/<a href="http://8.7.3.19#015#012Allow-Events">8.7.3.19#015#012Allow-Events</a>: dialog#015#012X-</div>
<div>Real-IP: 192.168.1.71#015#012Supported: path#015#012Authorization: Digest username="9*12*1$%$%",realm="<a href="http://all.com">all.com</a>",nonce="517ed8c7f0973e1dd14a403ead3ffb092efd04c3",uri="sip:<a href="http://all.com">all.com</a>",qop=auth,nc=</div>
<div>00000001,cnonce="649029e8",response="c1cdca29ccd998e22b8caed1454719d2",algorithm=MD5#015#012Expires: 3600#015#012Content-Length: 0#015#012#015#012</div><div>Apr 29 15:31:38 SIPProxy02 /usr/local/sbin/opensips[3106]: WARNING:core:log_expiry: #1 is a core action : 6 - 513533us - line 553</div>
<div>Apr 29 15:31:38 SIPProxy02 /usr/local/sbin/opensips[3106]: WARNING:core:log_expiry: #2 is a core action : 14 - 513520us - line 595</div><div>Apr 29 15:31:38 SIPProxy02 /usr/local/sbin/opensips[3106]: WARNING:core:log_expiry: #3 is a core action : 6 - 513514us - line 594</div>
<div>Apr 29 15:31:38 SIPProxy02 /usr/local/sbin/opensips[3106]: WARNING:core:log_expiry: #4 is a core action : 14 - 513511us - line 967</div><div>Apr 29 15:31:38 SIPProxy02 /usr/local/sbin/opensips[3106]: WARNING:core:log_expiry: #5 is a module action : save - 513126us - line 956</div>
</div></div><div class="gmail_extra"><br><br><div class="gmail_quote">On Mon, Apr 29, 2013 at 3:13 PM, Duane Larson <span dir="ltr"><<a href="mailto:duane.larson@gmail.com" target="_blank">duane.larson@gmail.com</a>></span> wrote:<br>
<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr">Great. I will pop those in the config and see what it tells me.</div><div class="HOEnZb"><div class="h5">
<div class="gmail_extra"><br><br><div class="gmail_quote">On Mon, Apr 29, 2013 at 3:11 PM, Bogdan-Andrei Iancu <span dir="ltr"><<a href="mailto:bogdan@opensips.org" target="_blank">bogdan@opensips.org</a>></span> wrote:<br>
<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><u></u>
<div bgcolor="#ffffff" text="#000000">
<tt>Using the thresholds (script, mysql, etc) may give you some
hints on the source of the delay. See: <br>
<a href="http://www.opensips.org/html/docs/modules/1.9.x/db_mysql.html#id249058" target="_blank">http://www.opensips.org/html/docs/modules/1.9.x/db_mysql.html#id249058</a><br>
<a href="http://www.opensips.org/Documentation/Script-CoreFunctions-1-9#toc51" target="_blank">http://www.opensips.org/Documentation/Script-CoreFunctions-1-9#toc51</a><br>
<br>
Regards,<br>
</tt><div>
<pre cols="72">Bogdan-Andrei Iancu
OpenSIPS Founder and Developer
<a href="http://www.opensips-solutions.com" target="_blank">http://www.opensips-solutions.com</a></pre>
<br></div><div><div>
On 04/29/2013 11:04 PM, Duane Larson wrote:
<blockquote type="cite">
<div dir="ltr">I will try the t_newtran(). I can only guess that
the 500ms is coming from my MySQL database lookup.</div>
<div class="gmail_extra"><br>
<br>
<div class="gmail_quote">On Mon, Apr 29, 2013 at 7:40 AM,
Bogdan-Andrei Iancu <span dir="ltr"><<a href="mailto:bogdan@opensips.org" target="_blank">bogdan@opensips.org</a>></span> wrote:<br>
<blockquote class="gmail_quote" style="margin:0pt 0pt 0pt 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex">
<div bgcolor="#ffffff" text="#000000"> <tt>Hello Duane,<br>
<br>
The Invalid Cseq is actually a side effect of the
REGISTER retransmissions - you have 2 REGISTER (original
+ retransmission) with CSeq: 756 REGISTER . <br>
</tt><tt><br>
First is executed in one process, gets stored and a 200
reply ; the retransmission gets executed in a different
process, and because it has same cseq the storing
generated the error.<br>
<br>
You need to filter out the retransmissions (use a
t_newtran() before the save(location) ) - it should
solve the problem.<br>
<br>
But the question is why does it take for OpenSIPS more
than 500ms to generate the answer (and make the sender
to do retransmission) ??<br>
<br>
Regards,<br>
</tt>
<pre cols="72">Bogdan-Andrei Iancu
OpenSIPS Founder and Developer
<a href="http://www.opensips-solutions.com" target="_blank">http://www.opensips-solutions.com</a></pre>
<div>
<div> <br>
On 04/26/2013 03:23 AM, Duane Larson wrote: </div>
</div>
<blockquote type="cite">
<div>
<div>
<div dir="ltr">I originally posted this via Nabble
but I am not sure if it went to the Opensips User
mailing list so please excuse me if this shows up
as multiple posts.
<div><br>
</div>
<div><br>
</div>
<div><span style="font-size:13px;font-family:Verdana,Geneva,Helvetica,Arial,sans-serif">I
am starting to see this issue a lot lately.
My Snom phones will so as not registered on
their display screen and when I look in the
syslogs I see the following error </span><br style="font-size:13px;font-family:Verdana,Geneva,Helvetica,Arial,sans-serif">
<br style="font-size:13px;font-family:Verdana,Geneva,Helvetica,Arial,sans-serif">
<span style="font-size:13px;font-family:Verdana,Geneva,Helvetica,Arial,sans-serif">ERROR:registrar:update_contacts:
invalid cseq for aor <9*1******@<a href="http://all.com" target="_blank">all.com</a>> </span><br style="font-size:13px;font-family:Verdana,Geneva,Helvetica,Arial,sans-serif">
<br style="font-size:13px;font-family:Verdana,Geneva,Helvetica,Arial,sans-serif">
<br style="font-size:13px;font-family:Verdana,Geneva,Helvetica,Arial,sans-serif">
<span style="font-size:13px;font-family:Verdana,Geneva,Helvetica,Arial,sans-serif">I
am not sure if this started happening because
of updated Snom code or because of updated
OpenSIPS code. Luckily I was able to capture
a SIP trace from one of the Snom phones today.
</span><br style="font-size:13px;font-family:Verdana,Geneva,Helvetica,Arial,sans-serif">
<br style="font-size:13px;font-family:Verdana,Geneva,Helvetica,Arial,sans-serif">
<span style="font-size:13px;font-family:Verdana,Geneva,Helvetica,Arial,sans-serif">Here
is a SIP trace of REGISTERs without the issue </span><br style="font-size:13px;font-family:Verdana,Geneva,Helvetica,Arial,sans-serif">
<a href="http://pastebin.com/RyaZQUBa" rel="nofollow" link="external" style="font-size:13px;color:rgb(85,26,139);font-family:Verdana,Geneva,Helvetica,Arial,sans-serif" target="_blank">http://pastebin.com/RyaZQUBa</a><br style="font-size:13px;font-family:Verdana,Geneva,Helvetica,Arial,sans-serif">
<br style="font-size:13px;font-family:Verdana,Geneva,Helvetica,Arial,sans-serif">
<span style="font-size:13px;font-family:Verdana,Geneva,Helvetica,Arial,sans-serif">Here
is a SIP trace of REGISTER showing the issue </span><br style="font-size:13px;font-family:Verdana,Geneva,Helvetica,Arial,sans-serif">
<a href="http://pastebin.com/YC1AyTJ6" rel="nofollow" link="external" style="font-size:13px;color:rgb(85,26,139);font-family:Verdana,Geneva,Helvetica,Arial,sans-serif" target="_blank">http://pastebin.com/YC1AyTJ6</a><span style="font-size:13px;font-family:Verdana,Geneva,Helvetica,Arial,sans-serif">
<--- The last message in this paste is a
400 Bad Request </span><br style="font-size:13px;font-family:Verdana,Geneva,Helvetica,Arial,sans-serif">
<br style="font-size:13px;font-family:Verdana,Geneva,Helvetica,Arial,sans-serif">
<span style="font-size:13px;font-family:Verdana,Geneva,Helvetica,Arial,sans-serif">So
is the Snom phone doing something wrong or
might it be on the OpenSIPS side?</span><br>
</div>
</div>
</div>
</div>
<pre><fieldset></fieldset>
_______________________________________________
Users mailing list
<a href="mailto:Users@lists.opensips.org" target="_blank">Users@lists.opensips.org</a>
<a href="http://lists.opensips.org/cgi-bin/mailman/listinfo/users" target="_blank">http://lists.opensips.org/cgi-bin/mailman/listinfo/users</a>
</pre>
</blockquote>
</div>
</blockquote>
</div>
<br>
<br clear="all">
<div><br>
</div>
-- <br>
--<br>
*--*--*--*--*--*<br>
Duane<br>
*--*--*--*--*--*<br>
--
</div>
</blockquote>
</div></div></div>
</blockquote></div><br><br clear="all"><div><br></div>-- <br>--<br>*--*--*--*--*--*<br>Duane<br>*--*--*--*--*--*<br>--
</div>
</div></div></blockquote></div><br><br clear="all"><div><br></div>-- <br>--<br>*--*--*--*--*--*<br>Duane<br>*--*--*--*--*--*<br>--
</div>