Re: [asterisk-users] pjsip: occasional sip_transactio Unable to register REGISTER transaction (key exists)

[Richard Mudgett]

On Wed, Jun 8, 2016 at 11:57 AM, Michael Maier  wrote:

> On 06/06/2016 at 04:40 PM Richard Mudgett wrote:
> > On Sun, Jun 5, 2016 at 3:48 AM, Michael Maier 
> wrote:
> >
> >> Hello!
> >>
> >> I occasionally can see warnings like these during *idle* times in
> >> asterisk log (asterisk 13.7.2):
> >>
> >> [2016-06-05 06:11:51] WARNING[27817] pjsip: sip_transactio Unable to
> >> register REGISTER transaction (key xists)
> >> [2016-06-05 06:11:51] WARNING[27817] pjsip: sip_transactio Unable to
> >> register REGISTER transaction (key exists)
>
> [...]
>
> > Those key exist messages are due to a race condition.  From what I've
> > seen in the code the messages seem to be benign.
>
> Please - could you tell, where you found them? Unfortunately, I wasn't
> able to find them!
>

Those messages are created inside the PJSIP library code.  Specifically in
the
sip_transaction.c file.  Asterisk is just passing the message on.

Richard
-- 
_
-- Bandwidth and Colocation Provided by http://www.api-digital.com --
New to Asterisk? Join us for a live introductory webinar every Thurs:
   http://www.asterisk.org/hello

asterisk-users mailing list
To UNSUBSCRIBE or update options visit:
   http://lists.digium.com/mailman/listinfo/asterisk-users

Re: [asterisk-users] pjsip: occasional sip_transactio Unable to register REGISTER transaction (key exists)

[Michael Maier]

On 06/06/2016 at 04:40 PM Richard Mudgett wrote:
> On Sun, Jun 5, 2016 at 3:48 AM, Michael Maier  wrote:
> 
>> Hello!
>>
>> I occasionally can see warnings like these during *idle* times in
>> asterisk log (asterisk 13.7.2):
>>
>> [2016-06-05 06:11:51] WARNING[27817] pjsip: sip_transactio Unable to
>> register REGISTER transaction (key xists)
>> [2016-06-05 06:11:51] WARNING[27817] pjsip: sip_transactio Unable to
>> register REGISTER transaction (key exists)

[...]

> Those key exist messages are due to a race condition.  From what I've
> seen in the code the messages seem to be benign.

Please - could you tell, where you found them? Unfortunately, I wasn't
able to find them!


Thanks,
Michael

-- 
_
-- Bandwidth and Colocation Provided by http://www.api-digital.com --
New to Asterisk? Join us for a live introductory webinar every Thurs:
   http://www.asterisk.org/hello

asterisk-users mailing list
To UNSUBSCRIBE or update options visit:
   http://lists.digium.com/mailman/listinfo/asterisk-users

Re: [asterisk-users] pjsip: occasional sip_transactio Unable to register REGISTER transaction (key exists)

[Michael Maier]

On 06/06/2016 at 04:40 PM, Richard Mudgett wrote:
> On Sun, Jun 5, 2016 at 3:48 AM, Michael Maier  wrote:
> 
>> Hello!
>>
>> I occasionally can see warnings like these during *idle* times in
>> asterisk log (asterisk 13.7.2):
>>
>> [2016-06-05 06:11:51] WARNING[27817] pjsip: sip_transactio Unable to
>> register REGISTER transaction (key xists)
>> [2016-06-05 06:11:51] WARNING[27817] pjsip: sip_transactio Unable to
>> register REGISTER transaction (key exists)
>>
>> Nothing more. The third REGISTER package works as expected.
>>
>>
>> What's going on:
>> My phone regularly (each 7.5 minutes) sends REGISTER. Sometimes, those
>> REGISTERs are denied like seen above (mostly already the second REGISTER
>> works and no third REGISTER is needed).
>>
>> The reRegistering of the phone normally works like this (as seen in
>> wireshark):
>>
>> -> REGISTER 06:04:19:285
>> <- 401 Unauthorized 06:04:19:287
>> -> REGISTER 06:04:19:316
>> <- 200 OK   06:04:19:376
>>
>>
>> If warnings happen like the one mentioned above, the following can be
>> seen in wireshark:
>>
>> -> REGISTER 06:11:49:359
>> <- 401 Unauthorized 06:11:49:362
>> -> REGISTER 06:11:49:392Unable ...
>> -> REGISTER 06:11:49:876Unable ...
>> -> REGISTER 06:11:50:868
>> <- 200 OK   06:11:51:634
>>
>> The second, third and fourth register package look completely identical
>> to me according wireshark regarding SIP.
>>
>> Notice the big latency between the fourth register and the following 200
>> OK: there are nearly 0.8 seconds in between in the problem case - but
>> normally, there are just 0.06 seconds between REGISTER and 200 OK!
>>
>> What happened during these 0.8 seconds? Asterisk (and the complete
>> machine) has been completely idle at this time - there wasn't any call
>> or anything other to process.
>>
>> I've got the complete wireshark trace of the situation described above.
>>
> 
> Those key exist messages are due to a race condition.  From what I've

It should be impossible - there couldn't be any race condition at this time.

> seen in the code the messages seem to be benign.
> 
> How may endpoints are registering to your Asterisk?

1 device, which registers 2 different numbers *serially*. Asterisk
didn't do any other things at the time those warnings came up. It was
idle. Completely.

> How often?

Each 7.5 minutes.

> Do you use realtime? 

No.


Regards,
Michael

-- 
_
-- Bandwidth and Colocation Provided by http://www.api-digital.com --
New to Asterisk? Join us for a live introductory webinar every Thurs:
   http://www.asterisk.org/hello

asterisk-users mailing list
To UNSUBSCRIBE or update options visit:
   http://lists.digium.com/mailman/listinfo/asterisk-users

Re: [asterisk-users] pjsip: occasional sip_transactio Unable to register REGISTER transaction (key exists)

[Richard Mudgett]

On Sun, Jun 5, 2016 at 3:48 AM, Michael Maier  wrote:

> Hello!
>
> I occasionally can see warnings like these during *idle* times in
> asterisk log (asterisk 13.7.2):
>
> [2016-06-05 06:11:51] WARNING[27817] pjsip: sip_transactio Unable to
> register REGISTER transaction (key xists)
> [2016-06-05 06:11:51] WARNING[27817] pjsip: sip_transactio Unable to
> register REGISTER transaction (key exists)
>
> Nothing more. The third REGISTER package works as expected.
>
>
> What's going on:
> My phone regularly (each 7.5 minutes) sends REGISTER. Sometimes, those
> REGISTERs are denied like seen above (mostly already the second REGISTER
> works and no third REGISTER is needed).
>
> The reRegistering of the phone normally works like this (as seen in
> wireshark):
>
> -> REGISTER 06:04:19:285
> <- 401 Unauthorized 06:04:19:287
> -> REGISTER 06:04:19:316
> <- 200 OK   06:04:19:376
>
>
> If warnings happen like the one mentioned above, the following can be
> seen in wireshark:
>
> -> REGISTER 06:11:49:359
> <- 401 Unauthorized 06:11:49:362
> -> REGISTER 06:11:49:392Unable ...
> -> REGISTER 06:11:49:876Unable ...
> -> REGISTER 06:11:50:868
> <- 200 OK   06:11:51:634
>
> The second, third and fourth register package look completely identical
> to me according wireshark regarding SIP.
>
> Notice the big latency between the fourth register and the following 200
> OK: there are nearly 0.8 seconds in between in the problem case - but
> normally, there are just 0.06 seconds between REGISTER and 200 OK!
>
> What happened during these 0.8 seconds? Asterisk (and the complete
> machine) has been completely idle at this time - there wasn't any call
> or anything other to process.
>
> I've got the complete wireshark trace of the situation described above.
>

Those key exist messages are due to a race condition.  From what I've
seen in the code the messages seem to be benign.

How may endpoints are registering to your Asterisk? How often?
Do you use realtime?  Is your realtime database on the same machine?

Richard
-- 
_
-- Bandwidth and Colocation Provided by http://www.api-digital.com --
New to Asterisk? Join us for a live introductory webinar every Thurs:
   http://www.asterisk.org/hello

asterisk-users mailing list
To UNSUBSCRIBE or update options visit:
   http://lists.digium.com/mailman/listinfo/asterisk-users

[asterisk-users] pjsip: occasional sip_transactio Unable to register REGISTER transaction (key exists)

[Michael Maier]

Hello!

I occasionally can see warnings like these during *idle* times in
asterisk log (asterisk 13.7.2):

[2016-06-05 06:11:51] WARNING[27817] pjsip: sip_transactio Unable to
register REGISTER transaction (key xists)
[2016-06-05 06:11:51] WARNING[27817] pjsip: sip_transactio Unable to
register REGISTER transaction (key exists)

Nothing more. The third REGISTER package works as expected.


What's going on:
My phone regularly (each 7.5 minutes) sends REGISTER. Sometimes, those
REGISTERs are denied like seen above (mostly already the second REGISTER
works and no third REGISTER is needed).

The reRegistering of the phone normally works like this (as seen in
wireshark):

-> REGISTER 06:04:19:285
<- 401 Unauthorized 06:04:19:287
-> REGISTER 06:04:19:316
<- 200 OK   06:04:19:376


If warnings happen like the one mentioned above, the following can be
seen in wireshark:

-> REGISTER 06:11:49:359
<- 401 Unauthorized 06:11:49:362
-> REGISTER 06:11:49:392Unable ...
-> REGISTER 06:11:49:876Unable ...
-> REGISTER 06:11:50:868
<- 200 OK   06:11:51:634

The second, third and fourth register package look completely identical
to me according wireshark regarding SIP.

Notice the big latency between the fourth register and the following 200
OK: there are nearly 0.8 seconds in between in the problem case - but
normally, there are just 0.06 seconds between REGISTER and 200 OK!

What happened during these 0.8 seconds? Asterisk (and the complete
machine) has been completely idle at this time - there wasn't any call
or anything other to process.

I've got the complete wireshark trace of the situation described above.



Any idea?
Kind regards,
Michael

-- 
_
-- Bandwidth and Colocation Provided by http://www.api-digital.com --
New to Asterisk? Join us for a live introductory webinar every Thurs:
   http://www.asterisk.org/hello

asterisk-users mailing list
To UNSUBSCRIBE or update options visit:
   http://lists.digium.com/mailman/listinfo/asterisk-users