[Home]

Summary:ASTERISK-16282: REGISTER attempts with stale nonce
Reporter:dtryba (dtryba)Labels:
Date Opened:2010-06-23 05:29:33Date Closed:2011-06-07 14:04:56
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Channels/chan_sip/Registration
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) noregister.txt
( 1) rereg.txt
( 2) stalenonce.txt
Description:Reregistration fails, resulting in new calls getting a 403 Forbidden. Problem gets solved by issuing "sip reload" on the client.

This issue occurs on a 1.6.2.6 (tcp) and a 1.6.2.7 (udp) asterisk client connection to a 1.6.2.6 asterisk server.

tcpdump/sip debug is from the 1.6.2.6 client, still waiting for the 1.6.2.7 to fail.

Don't see anything related to this in the 1.6.2.9 Changelog.

****** ADDITIONAL INFORMATION ******

Server:

[Jun 23 09:45:50] NOTICE[6613] chan_sip.c: Failed to authenticate device "Pocos
B.V." <sip:04029XXXXX@88.159.8.123>;tag=as464b94b4
[Jun 23 09:46:45] NOTICE[6613] chan_sip.c: Failed to authenticate device "Pocos
B.V." <sip:04029XXXXX@88.159.8.123>;tag=as06ea81a7

Client:

[Jun 23 09:44:26] NOTICE[3581] chan_sip.c:    -- Re-registration for  trunk@voip.pocos.nl
[Jun 23 09:44:46] NOTICE[3581] chan_sip.c:    -- Registration for 'trunk@voip.pocos.nl' timed out, trying again (Attempt #1)
[Jun 23 09:45:06] NOTICE[3581] chan_sip.c:    -- Registration for 'trunk@voip.pocos.nl' timed out, trying again (Attempt #2)
[Jun 23 09:45:26] NOTICE[3581] chan_sip.c:    -- Registration for 'trunk@voip.pocos.nl' timed out, trying again (Attempt #3)
[Jun 23 09:45:46] NOTICE[3581] chan_sip.c:    -- Registration for 'trunk@voip.pocos.nl' timed out, trying again (Attempt #4)
[Jun 23 09:45:50] WARNING[3590] chan_sip.c: Received response: "Forbidden" from '"Pocos B.V." <sip:04029XXXXX@88.159.8.123>;tag=as464b94b4'
[Jun 23 09:46:06] NOTICE[3581] chan_sip.c:    -- Registration for 'trunk@voip.pocos.nl' timed out, trying again (Attempt ASTERISK-1)
[Jun 23 09:46:26] NOTICE[3581] chan_sip.c:    -- Registration for 'trunk@voip.pocos.nl' timed out, trying again (Attempt ASTERISK-2)
[Jun 23 09:46:45] WARNING[3590] chan_sip.c: Received response: "Forbidden" from '"Pocos B.V." <sip:04029XXXXX@88.159.8.123>;tag=as06ea81a7'
[Jun 23 09:46:46] NOTICE[3581] chan_sip.c:    -- Registration for 'trunk@voip.pocos.nl' timed out, trying again (Attempt ASTERISK-3)
[Jun 23 09:47:06] NOTICE[3581] chan_sip.c:    -- Registration for 'trunk@voip.pocos.nl' timed out, trying again (Attempt ASTERISK-4)


tcpdump (one of the many REGISTER requests with nonce 62252dc4 where the server returns nonce 693228d5):

REGISTER sip:voip.pocos.nl SIP/2.0
Via: SIP/2.0/TCP 88.159.8.123:5060;branch=z9hG4bK0488e123;rport
Max-Forwards: 70
From: <sip:trunk@voip.pocos.nl>;tag=as149945f1
To: <sip:trunk@voip.pocos.nl>
Call-ID: 65dae72529ecb8101f3a90e646d6efd4@127.0.1.1
CSeq: 1652 REGISTER
User-Agent: Asterisk PBX 1.6.2.6-1
Authorization: Digest username="trunk", realm="asterisk", algorithm=MD5, uri="sip:voip.pocos.nl", nonce="62252dc4", response="fe31a595ceab3682421f23b3699290e3"
Expires: 120
Contact: <sip:voiptrunk@88.159.8.123;transport=TCP>
Content-Length: 0

SIP/2.0 401 Unauthorized
Via: SIP/2.0/TCP 88.159.8.123:5060;branch=z9hG4bK0488e123;received=88.159.8.123;rport=57508
From: <sip:trunk@voip.pocos.nl>;tag=as149945f1
To: <sip:trunk@voip.pocos.nl>;tag=as63d62235
Call-ID: 65dae72529ecb8101f3a90e646d6efd4@127.0.1.1
CSeq: 1652 REGISTER
Server: Asterisk PBX 1.6.2.6-1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="693228d5", stale=true
Content-Length: 0
Comments:By: Paul Belanger (pabelanger) 2010-06-23 06:54:09

Include debug logs (see below) from both sides.
---
We require a complete debug log to help triage the issue.

This document will provide instructions on how to collect debugging logs from an Asterisk machine for the purpose of helping bug marshals troubleshoot an issue:

http://svn.digium.com/svn/asterisk/trunk/doc/HOWTO_collect_debug_information.txt
By: dtryba (dtryba) 2010-06-25 09:18:36

On the 1.6.2.6 client, increasing debug changed the apparent behavior:
There are no REGISTER attempts with stale nonces. The problem I'm now seeing is a lack of REGISTER attempts.

The client REGISTERs at 13:40:38 with expires: 120 returned from server. An INVITE at 13:42:47 gets unauthorized and retries with authorization. The next INVITE at 13:48:32 gets a forbidden, all INVITES get a forbidden till the next REGISTER which occurs at 13:50:43. From that moment REGISTERs occur at every 105s again.

see noregister.txt for a client dump (since there are no registers going to the server there is no serverside log).

The 1.6.2.7 client also borked, analyzing that one next.
By: dtryba (dtryba) 2010-06-25 09:48:52

The 1.6.2.7 client exhibits the same behaviour, suddenly the client just doesn't register any more:
[Jun 25 12:45:37] DEBUG[24767] chan_sip.c:  REGISTER...
[Jun 25 12:47:22] DEBUG[24767] chan_sip.c:  REGISTER...
[Jun 25 12:49:07] DEBUG[24767] chan_sip.c:  REGISTER...
[Jun 25 12:50:52] DEBUG[24767] chan_sip.c:  REGISTER...
[Jun 25 12:52:37] DEBUG[24767] chan_sip.c:  REGISTER...
[Jun 25 13:07:09] DEBUG[24767] chan_sip.c:  REGISTER...
[Jun 25 13:08:54] DEBUG[24767] chan_sip.c:  REGISTER...
[Jun 25 13:10:39] DEBUG[24767] chan_sip.c:  REGISTER...
[Jun 25 13:17:39] DEBUG[24767] chan_sip.c:  REGISTER...
[Jun 25 13:19:24] DEBUG[24767] chan_sip.c:  REGISTER...
[Jun 25 13:21:09] DEBUG[24767] chan_sip.c:  REGISTER...
[Jun 25 13:22:54] DEBUG[24767] chan_sip.c:  REGISTER...
By: Paul Belanger (pabelanger) 2010-06-25 10:08:34

As mentioned in the first post, we need debug logs.

Edit: Just noticed your attachment, we will need a log from both sides.


By: dtryba (dtryba) 2010-06-25 11:43:02

There is no log from the other side. This bug report contains 2 completely different causes for call rejections. The only common factor is that the server had it's registration from these peers expired.

The Forbidden is completely correct IMHO since the client has gone away (registration expired/failed), the only usefull stuff logged by the server is:
[Jun 25 13:50:29] VERBOSE[24242] chan_sip.c: No matching peer for '0402938661' from '88.159.8.123:37115'
[Jun 25 13:50:29] NOTICE[24242] chan_sip.c: Failed to authenticate device "0402938661" <sip:0402938661@88.159.8.123>;tag=as0975824e

This problem only appeared after upgrading from 1.4 to 1.6.2. All 1.4 clients are running just fine and only 2 of the 1.6.2 misbehave (so far).

According to the RFC a 403 means the receiver should not retry. One could argue that the server might sent a 401 instead since in the past a peer was registered at this ip/port pair. And after a successful registration this ip/port pair is still used.
By: dtryba (dtryba) 2010-07-01 10:26:45

Didn't see any stale nonce registers so far. All Forbidden messages are due to expired registers. Summary/subject should be changed (or closing this bug in favour of a new one about missing registers).

Asterisk clients just don't make any attempts to register:
register 11:11:30
register 11:13:15
invite   11:16:44 (response Forbidden from server)
register 11:16:47
register 11:18:32
register 11:20:17

It's very obvious a register attempt should have happened at 11:15:00 since the requested expires is 120s and the client makes a note to refresh in 105s:

[Jun 30 11:13:15] DEBUG[18340] chan_sip.c:  Header  0 [ 14]: SIP/2.0 200 OK
[Jun 30 11:13:15] DEBUG[18340] chan_sip.c:  Header  1 [ 91]: Via: SIP/2.0/TCP 88.159.8.123:5060;branch=z9hG4bK45519b91;received=88.159.8.123;rport=37115
[Jun 30 11:13:15] DEBUG[18340] chan_sip.c:  Header  2 [ 56]: From: <sip:officevoiptrunk@voip.pocos.nl>;tag=as654e4560
[Jun 30 11:13:15] DEBUG[18340] chan_sip.c:  Header  3 [ 54]: To: <sip:officevoiptrunk@voip.pocos.nl>;tag=as6435c1ab
[Jun 30 11:13:15] DEBUG[18340] chan_sip.c:  Header  4 [ 51]: Call-ID: 6bb4064737243c9b23c372371340e514@127.0.1.1
[Jun 30 11:13:15] DEBUG[18340] chan_sip.c:  Header  5 [ 19]: CSeq: 1351 REGISTER
[Jun 30 11:13:15] DEBUG[18340] chan_sip.c:  Header  6 [ 30]: Server: Asterisk PBX 1.6.2.6-1
[Jun 30 11:13:15] DEBUG[18340] chan_sip.c:  Header  7 [ 72]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
[Jun 30 11:13:15] DEBUG[18340] chan_sip.c:  Header  8 [ 26]: Supported: replaces, timer
[Jun 30 11:13:15] DEBUG[18340] chan_sip.c:  Header  9 [ 12]: Expires: 120
[Jun 30 11:13:15] DEBUG[18340] chan_sip.c:  Header 10 [ 63]: Contact: <sip:voiptrunk@88.159.8.123;transport=TCP>;expires=120
[Jun 30 11:13:15] DEBUG[18340] chan_sip.c:  Header 11 [ 35]: Date: Wed, 30 Jun 2010 09:13:15 GMT
[Jun 30 11:13:15] DEBUG[18340] chan_sip.c:  Header 12 [ 17]: Content-Length: 0
[Jun 30 11:13:15] DEBUG[18340] chan_sip.c:  Header 13 [  0]:
[Jun 30 11:13:15] VERBOSE[18340] chan_sip.c: --- (13 headers 0 lines) ---
[Jun 30 11:13:15] DEBUG[18340] chan_sip.c: Registration successful
[Jun 30 11:13:15] DEBUG[18340] chan_sip.c: Cancelling timeout 2793039
[Jun 30 11:13:15] DEBUG[18340] chan_sip.c: SIP Registry voip.pocos.nl: refcount now 2
[Jun 30 11:13:15] DEBUG[18340] chan_sip.c: SIP Registry voip.pocos.nl: refcount now 1
[Jun 30 11:13:15] VERBOSE[18340] chan_sip.c: Scheduling destruction of SIP dialog '6bb4064737243c9b23c372371340e514@127.0.1.1' in 32000 ms (Method: REGISTER)
[Jun 30 11:13:15] NOTICE[18340] chan_sip.c: Outbound Registration: Expiry for voip.pocos.nl is 120 sec (Scheduling reregistration in 105 s)
[Jun 30 11:13:15] DEBUG[18340] chan_sip.c: SIP Registry voip.pocos.nl: refcount now 2

When the next register will happen is random, between 3m and 30m was observed.

Things the 2 bad behaving clients have common:
-32bit Linux: 2.6.26-2-686/2.6.18-194.3.1.el5PAE
-no dahdi hardware, using res_timing_pthread.so/res_timing_dahdi.so

The correctly behaving 1.6.2.6 clients are running 64bit versions and have Digium PRI cards.
By: Leif Madsen (lmadsen) 2010-07-21 12:24:48

You mention using res_timing_pthread -- if you use it past revision http://svn.digium.com/view/asterisk?view=rev&revision=278465 do you still have this issue?
By: Paul Belanger (pabelanger) 2010-08-04 11:56:54

Suspended due to lack of activity. Please request a bug marshal in #asterisk-bugs on the IRC network irc.freenode.net to reopen the issue should you have the additional information requested.

Further information can be found at http://www.asterisk.org/developers/bug-guidelines