[OpenSIPS-Users] ERROR:registrar:update_contacts: invalid cseq for aor

Duane Larson duane.larson at gmail.com
Mon Apr 29 22:41:38 CEST 2013 

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.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>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 <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 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 at lists.opensips.orghttp://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/20130429/31083775/attachment-0001.htm>

More information about the Users mailing list