[OpenSIPS-Users] ERROR:registrar:update_contacts: invalid cseq for aor
Bogdan-Andrei Iancu
bogdan at opensips.org
Tue Apr 30 09:55:07 CEST 2013
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 <duane.larson at gmail.com
> <mailto:duane.larson at 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
> <bogdan at opensips.org <mailto:bogdan at 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 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
>> <bogdan at opensips.org <mailto:bogdan at 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 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
>>> Users at lists.opensips.org <mailto:Users at lists.opensips.org>
>>> http://lists.opensips.org/cgi-bin/mailman/listinfo/users
>>
>>
>>
>>
>> --
>> --
>> *--*--*--*--*--*
>> Duane
>> *--*--*--*--*--*
>> --
>
>
>
>
> --
> --
> *--*--*--*--*--*
> Duane
> *--*--*--*--*--*
> --
>
>
>
>
> --
> --
> *--*--*--*--*--*
> Duane
> *--*--*--*--*--*
> --
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.opensips.org/pipermail/users/attachments/20130430/c2f6e441/attachment-0001.htm>
More information about the Users
mailing list