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

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:392	Unable ...
-> REGISTER				06:11:49:876	Unable ...
-> 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

On Sun, Jun 5, 2016 at 3:48 AM, Michael Maier <m1278468 at allmail.net>
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:392    Unable ...
> -> REGISTER                             06:11:49:876    Unable ...
> -> 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
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.digium.com/pipermail/asterisk-users/attachments/20160606/f9a448e8/attachment.html>

On 06/06/2016 at 04:40 PM, Richard Mudgett wrote:
> On Sun, Jun 5, 2016 at 3:48 AM, Michael Maier <m1278468 at
allmail.net> 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:392    Unable ...
>> -> REGISTER                             06:11:49:876    Unable ...
>> -> 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

On 06/06/2016 at 04:40 PM Richard Mudgett wrote:
> On Sun, Jun 5, 2016 at 3:48 AM, Michael Maier <m1278468 at
allmail.net> 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