Hi Duane,
I'm glad it help - is now your problem solved (with the REGISTERs) ?
Regards,
Bogdan-Andrei Iancu
OpenSIPS Founder and Developer
http://www.opensips-solutions.com
On 04/29/2013 11:41 PM, Duane Larson wrote:
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
<http://8.7.3.19>','sip:172.*.*.33:57369',NULL,'udp:50.57.54.156:5060
<http://50.57.54.156:5060>',7999,'2013-04-29 15:31:37',NULL,'all.com
<http://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
<http://8.7.3.19>',received='sip:1
72.12.199.33:57369
<http://72.12.199.33:57369>',path=NULL,socket='udp:50.57.54.156:5060
<http://50.57.54.156:5060>',methods=7999,last_modified='2013-04-29
15:31:37',sip_instance=NULL,domain='all.com <http://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 <http://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
<http://all.com>>;tag=bs72h6ifw5#015#012To: "901-201-5656"
<sip:9*12*1$%$%@all.com <http://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
<http://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
<http://all.com>",nonce="517ed8c7f0973e1dd14a403ead3ffb092efd04c3",uri="sip:all.com
<http://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
<http://8.7.3.19>','sip:172.*.*.33:57369',NULL,'udp:50.57.54.156:5060
<http://50.57.54.156:5060>',7999,'2013-04-29 15:31:37',NULL,'all.com
<http://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
<http://8.7.3.19>',received='sip:1
72.12.199.33:57369
<http://72.12.199.33:57369>',path=NULL,socket='udp:50.57.54.156:5060
<http://50.57.54.156:5060>',methods=7999,last_modified='2013-04-29
15:31:37',sip_instance=NULL,domain='all.com <http://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 <http://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
<http://all.com>>;tag=bs72h6ifw5#015#012To: "901-201-5656"
<sip:9*12*1$%$%@all.com <http://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
<http://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
<http://all.com>",nonce="517ed8c7f0973e1dd14a403ead3ffb092efd04c3",uri="sip:all.com
<http://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 <[email protected]
<mailto:[email protected]>> 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
<[email protected] <mailto:[email protected]>> 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 Developer
http://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
<[email protected] <mailto:[email protected]>> 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 Developer
http://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 <http://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 list
[email protected] <mailto:[email protected]>
http://lists.opensips.org/cgi-bin/mailman/listinfo/users
--
--
*--*--*--*--*--*
Duane
*--*--*--*--*--*
--
--
--
*--*--*--*--*--*
Duane
*--*--*--*--*--*
--
--
--
*--*--*--*--*--*
Duane
*--*--*--*--*--*
--
_______________________________________________
Users mailing list
[email protected]
http://lists.opensips.org/cgi-bin/mailman/listinfo/users
