Wow those thresholds give you a good amount of info. I'll have to see how I can make my MySQL service quicker.
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 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 000000cbed-7lfki4ifz7hz',1260,0,0,'snom720/8.7.3.19 ','sip:172.*.*.33:57369',NULL,'udp:50.57.54.156:5060',7999,'2013-04-29 15:31:37',NULL,'all.com') on duplicate key update username='9*12*1$%$%',co 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/ 8.7.3.19',received='sip:1 72.12.199.33:57369',path=NULL,socket='udp:50.57.54.156:5060',methods=7999,last_modified='2013-04-29 15:31:37',sip_instance=NULL,domain='all.com' 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:all.com SIP/2.0#015#012Via: SIP /2.0/UDP 172.*.*.33:57369;branch=z9hG4bK-clxrqnw5iv48;rport#015#012From: "901-201-5656" <sip:9*12*1$%$%@all.com>;tag=bs72h6ifw5#015#012To: "901-201-5656" <sip:9*12*1$%$%@all.com>#015#012Ca 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 ription="snom720";actor="principal";events="dialog";methods="INVITE,ACK,CANCEL,BYE,REFER,OPTIONS,NOTIFY,SUBSCRIBE,PRACK,MESSAGE,INFO"#015#012User-Agent: snom720/8.7.3.19#015#012Allow-Events: dialog#015#012X- Real-IP: 192.168.1.71#015#012Supported: path#015#012Authorization: Digest username="9*12*1$%$%",realm="all.com ",nonce="517ed8c7f0973e1dd14a403ead3ffb092efd04c3",uri="sip:all.com ",qop=auth,nc= 00000001,cnonce="649029e8",response="c1cdca29ccd998e22b8caed1454719d2",algorithm=MD5#015#012Expires: 3600#015#012Content-Length: 0#015#012#015#012 Apr 29 15:31:37 SIPProxy02 /usr/local/sbin/opensips[3104]: WARNING:core:log_expiry: #1 is a core action : 6 - 519586us - line 553 Apr 29 15:31:37 SIPProxy02 /usr/local/sbin/opensips[3104]: WARNING:core:log_expiry: #2 is a core action : 14 - 519573us - line 595 Apr 29 15:31:37 SIPProxy02 /usr/local/sbin/opensips[3104]: WARNING:core:log_expiry: #3 is a core action : 6 - 519567us - line 594 Apr 29 15:31:37 SIPProxy02 /usr/local/sbin/opensips[3104]: WARNING:core:log_expiry: #4 is a core action : 14 - 519564us - line 967 Apr 29 15:31:37 SIPProxy02 /usr/local/sbin/opensips[3104]: WARNING:core:log_expiry: #5 is a module action : save - 516033us - line 956 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 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 000000cbed-7lfki4ifz7hz',1260,0,0,'snom720/8.7.3.19 ','sip:172.*.*.33:57369',NULL,'udp:50.57.54.156:5060',7999,'2013-04-29 15:31:37',NULL,'all.com') on duplicate key update username='9*12*1$%$%',co 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/ 8.7.3.19',received='sip:1 72.12.199.33:57369',path=NULL,socket='udp:50.57.54.156:5060',methods=7999,last_modified='2013-04-29 15:31:37',sip_instance=NULL,domain='all.com' 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:all.com SIP/2.0#015#012Via: SIP /2.0/UDP 172.*.*.33:57369;branch=z9hG4bK-clxrqnw5iv48;rport#015#012From: "901-201-5656" <sip:9*12*1$%$%@all.com>;tag=bs72h6ifw5#015#012To: "901-201-5656" <sip:9*12*1$%$%@all.com>#015#012Ca 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 ription="snom720";actor="principal";events="dialog";methods="INVITE,ACK,CANCEL,BYE,REFER,OPTIONS,NOTIFY,SUBSCRIBE,PRACK,MESSAGE,INFO"#015#012User-Agent: snom720/8.7.3.19#015#012Allow-Events: dialog#015#012X- Real-IP: 192.168.1.71#015#012Supported: path#015#012Authorization: Digest username="9*12*1$%$%",realm="all.com ",nonce="517ed8c7f0973e1dd14a403ead3ffb092efd04c3",uri="sip:all.com ",qop=auth,nc= 00000001,cnonce="649029e8",response="c1cdca29ccd998e22b8caed1454719d2",algorithm=MD5#015#012Expires: 3600#015#012Content-Length: 0#015#012#015#012 Apr 29 15:31:38 SIPProxy02 /usr/local/sbin/opensips[3106]: WARNING:core:log_expiry: #1 is a core action : 6 - 513533us - line 553 Apr 29 15:31:38 SIPProxy02 /usr/local/sbin/opensips[3106]: WARNING:core:log_expiry: #2 is a core action : 14 - 513520us - line 595 Apr 29 15:31:38 SIPProxy02 /usr/local/sbin/opensips[3106]: WARNING:core:log_expiry: #3 is a core action : 6 - 513514us - line 594 Apr 29 15:31:38 SIPProxy02 /usr/local/sbin/opensips[3106]: WARNING:core:log_expiry: #4 is a core action : 14 - 513511us - line 967 Apr 29 15:31:38 SIPProxy02 /usr/local/sbin/opensips[3106]: WARNING:core:log_expiry: #5 is a module action : save - 513126us - line 956 On Mon, Apr 29, 2013 at 3:13 PM, Duane Larson <duane.lar...@gmail.com>wrote: > Great. I will pop those in the config and see what it tells me. > > > On Mon, Apr 29, 2013 at 3:11 PM, Bogdan-Andrei Iancu > <bog...@opensips.org>wrote: > >> ** >> Using the thresholds (script, mysql, etc) may give you some hints on the >> source of the delay. See: >> >> http://www.opensips.org/html/docs/modules/1.9.x/db_mysql.html#id249058 >> >> http://www.opensips.org/Documentation/Script-CoreFunctions-1-9#toc51 >> >> Regards, >> >> Bogdan-Andrei Iancu >> OpenSIPS Founder and Developerhttp://www.opensips-solutions.com >> >> >> On 04/29/2013 11:04 PM, Duane Larson wrote: >> >> I will try the t_newtran(). I can only guess that the 500ms is coming >> from my MySQL database lookup. >> >> >> On Mon, Apr 29, 2013 at 7:40 AM, Bogdan-Andrei Iancu <bog...@opensips.org >> > wrote: >> >>> Hello Duane, >>> >>> The Invalid Cseq is actually a side effect of the REGISTER >>> retransmissions - you have 2 REGISTER (original + retransmission) with >>> CSeq: 756 REGISTER . >>> >>> 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. >>> >>> You need to filter out the retransmissions (use a t_newtran() before the >>> save(location) ) - it should solve the problem. >>> >>> But the question is why does it take for OpenSIPS more than 500ms to >>> generate the answer (and make the sender to do retransmission) ?? >>> >>> Regards, >>> >>> Bogdan-Andrei Iancu >>> OpenSIPS Founder and Developerhttp://www.opensips-solutions.com >>> >>> >>> On 04/26/2013 03:23 AM, Duane Larson wrote: >>> >>> 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. >>> >>> >>> 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 >>> >>> ERROR:registrar:update_contacts: invalid cseq for aor <9*1******@all.com >>> > >>> >>> >>> 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. >>> >>> Here is a SIP trace of REGISTERs without the issue >>> http://pastebin.com/RyaZQUBa >>> >>> Here is a SIP trace of REGISTER showing the issue >>> http://pastebin.com/YC1AyTJ6 <--- The last message in this paste is >>> a 400 Bad Request >>> >>> So is the Snom phone doing something wrong or might it be on the >>> OpenSIPS side? >>> >>> >>> _______________________________________________ >>> Users mailing >>> listUsers@lists.opensips.orghttp://lists.opensips.org/cgi-bin/mailman/listinfo/users >>> >>> >> >> >> -- >> -- >> *--*--*--*--*--* >> Duane >> *--*--*--*--*--* >> -- >> >> > > > -- > -- > *--*--*--*--*--* > Duane > *--*--*--*--*--* > -- > -- -- *--*--*--*--*--* Duane *--*--*--*--*--* --
_______________________________________________ Users mailing list Users@lists.opensips.org http://lists.opensips.org/cgi-bin/mailman/listinfo/users