[Home]

Summary:ASTERISK-14138: [patch] SIP device cycles between Available for 25 seconds and Unavailable for the programmed re-registration period, maybe an h
Reporter:Alec Davis (alecdavis)Labels:
Date Opened:2009-05-15 05:42:48Date Closed:2009-05-26 08:47:49
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Channels/chan_sip/Registration
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) chan_sip_unregister.diff2.txt
( 1) chan_sip_unregister.diff3.txt
Description:If a device is unregistered from the asterisk console using 'sip unregister 100', the device will re-register in it's own re-registation time, but then asterisk make in unavailable again after 25 seconds, the device still thinks it's registered.

Thus if the re-registration period is 1 hour, 3600 seconds, then phone is unavailable for most of the time. You can make calls from them, but just not receive calls.



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

Before patch: Sequence below has phone re-registration period set to 60 seconds to aid debug.

asterix*CLI> sip unregister bt100
Unregistered peer 'bt100'

[May 15 22:09:30] NOTICE[4412]: chan_sip.c:15293 sip_unregister: ALEC peer->name=bt100  peer->expire=27
[May 15 22:09:30] NOTICE[4412]: chan_sip.c:11414 expire_register: ALEC peer->name=bt100 peer->expire=27

[May 15 22:09:37] NOTICE[4401]: chan_sip.c:11776 parse_register_contact: ALEC ast_sched_add (expire_register)  peer->name=bt100 peer->expire=30 expire=70000
   -- Registered SIP 'bt100' at 192.168.124.31 port 5060
[May 15 22:10:02] NOTICE[4401]: chan_sip.c:11414 expire_register: ALEC peer->name=bt100 peer->expire=30

[May 15 22:10:22] NOTICE[4401]: chan_sip.c:11776 parse_register_contact: ALEC ast_sched_add (expire_register)  peer->name=bt100 peer->expire=33 expire=70000
   -- Registered SIP 'bt100' at 192.168.124.31 port 5060
[May 15 22:10:47] NOTICE[4401]: chan_sip.c:11414 expire_register: ALEC peer->name=bt100 peer->expire=33

[May 15 22:11:07] NOTICE[4401]: chan_sip.c:11776 parse_register_contact: ALEC ast_sched_add (expire_register)  peer->name=bt100 peer->expire=36 expire=70000
   -- Registered SIP 'bt100' at 192.168.124.31 port 5060
[May 15 22:11:32] NOTICE[4401]: chan_sip.c:11414 expire_register: ALEC peer->name=bt100 peer->expire=36

[May 15 22:11:52] NOTICE[4401]: chan_sip.c:11776 parse_register_contact: ALEC ast_sched_add (expire_register)  peer->name=bt100 peer->expire=39 expire=70000
   -- Registered SIP 'bt100' at 192.168.124.31 port 5060

===============================================================================

After patch:

[May 15 22:13:22] NOTICE[6106]: chan_sip.c:11776 parse_register_contact: ALEC ast_sched_add (expire_register)  peer->name=bt100 peer->expire=22 expire=70000
[May 15 22:13:22] NOTICE[6106]: chan_sip.c:11781 parse_register_contact: ALEC peer->name=bt100 peer->expire=22 pvt->expiry=0 expire=60
asterix*CLI> sip unregister bt100
Unregistered peer 'bt100'

[May 15 22:13:48] NOTICE[6117]: chan_sip.c:15293 sip_unregister: ALEC peer->name=bt100  peer->expire=22
[May 15 22:14:08] NOTICE[6106]: chan_sip.c:11776 parse_register_contact: ALEC ast_sched_add (expire_register)  peer->name=bt100 peer->expire=25 expire=70000
[May 15 22:14:08] NOTICE[6106]: chan_sip.c:11781 parse_register_contact: ALEC peer->name=bt100 peer->expire=25 pvt->expiry=0 expire=60
[May 15 22:14:53] NOTICE[6106]: chan_sip.c:11776 parse_register_contact: ALEC ast_sched_add (expire_register)  peer->name=bt100 peer->expire=28 expire=70000
[May 15 22:14:53] NOTICE[6106]: chan_sip.c:11781 parse_register_contact: ALEC peer->name=bt100 peer->expire=28 pvt->expiry=0 expire=60
[May 15 22:15:38] NOTICE[6106]: chan_sip.c:11776 parse_register_contact: ALEC ast_sched_add (expire_register)  peer->name=bt100 peer->expire=31 expire=70000
[May 15 22:15:38] NOTICE[6106]: chan_sip.c:11781 parse_register_contact: ALEC peer->name=bt100 peer->expire=31 pvt->expiry=0 expire=60
asterix*CLI>
Comments:By: Alec Davis (alecdavis) 2009-05-15 05:58:13

Below one of the debug print's I caught (before patch), with an expire schedule ID of 4294967295

The phone didn't re-register within the next minute or so, and I don't think it was going to either, so rebooted it.

[May 15 22:04:37] NOTICE[4401]: chan_sip.c:11414 expire_register: ALEC peer->name=bt100 peer->expire=4294967295

Post patch, also confirmed that asterisk actually does expire the device when is physically disconnected.


By: Alec Davis (alecdavis) 2009-05-15 06:46:23

Patch chan_sip_unregister.diff.txt is not right. Please remove it.
I should have tested after removing debug prints, I culled 1 extra required line...

Uploaded chan_sip_unregister.diff2.txt
-----------------------------------
Expire -1 is set when 'sip unregister bt100' is executed
SIP/bt100 is unavailable after 'sip unregister ...' until device re-registers.
Asterisk reports registered/available, while connected to network.
Asterisk times out device after removal from network.


By: Alec Davis (alecdavis) 2009-05-16 07:13:31

Uploaded chan_sip_unregister.diff3.txt

The previous check chan_sip_unregister.diff2.txt was too specific, only for 'sip unregister'.

Now any call to expire_register will remove the peers scheduled 'expire_register' event.
By: Alec Davis (alecdavis) 2009-05-17 07:40:04

Further analysis: chan_sip_unregister.diff3.txt fixes the behaviour below.

Adding ast_sched_dump to chan_sip.c expire_register: and chan_sip.c parse_register_contact: revealed as suspected, 2 scheduled events with a call abck to expire_register, out of sync.

Dump from expire_register: Schedule ID 33
[May 18 00:13:58] DEBUG[29878] chan_sip.c: ALEC expire_register: peer->name=bt100, peer->expire=33
[May 18 00:13:58] DEBUG[29878] sched.c: Asterisk Schedule Dump (4 in Q, 34 Total, 7 Cache, 12 high-water)
[May 18 00:13:58] DEBUG[29878] sched.c: =============================================================
[May 18 00:13:58] DEBUG[29878] sched.c: |ID    Callback          Data              Time  (sec:ms)   |
[May 18 00:13:58] DEBUG[29878] sched.c: +-----+-----------------+-----------------+-----------------+
[May 18 00:13:58] DEBUG[29878] sched.c: |0034 | 0xb6f4c4df      | 0xb6a01640      | 000007 : 073771 |
[May 18 00:13:58] DEBUG[29878] sched.c: |0033 | 0xb6f7269a      | 0x9e33fe0       | 000045 : 060597 |
[May 18 00:13:58] DEBUG[29878] sched.c: |0006 | 0xb6f7269a      | 0x9e353a0       | 003370 : 074316 |
[May 18 00:13:58] DEBUG[29878] sched.c: |0002 | 0xb6f7269a      | 0x9e32cb0       | 003370 : 073515 |
[May 18 00:13:58] DEBUG[29878] sched.c: =============================================================


Dump from parse_register_contact as phone re-registers:
ID36 = New expire time of 69 seconds, but previous ID33 has 24 seconds before expire.
[May 18 00:14:18] DEBUG[29878] chan_sip.c: ALEC Registered: SIP peer->name=bt100 peer->expire=36
[May 18 00:14:18] DEBUG[29878] sched.c: Asterisk Schedule Dump (4 in Q, 36 Total, 8 Cache, 12 high-water)
[May 18 00:14:18] DEBUG[29878] sched.c: =============================================================
[May 18 00:14:18] DEBUG[29878] sched.c: |ID    Callback          Data              Time  (sec:ms)   |
[May 18 00:14:18] DEBUG[29878] sched.c: +-----+-----------------+-----------------+-----------------+
[May 18 00:14:18] DEBUG[29878] sched.c: |0033 | 0xb6f7269a      | 0x9e33fe0       | 000024 : 932691 |   <<<this is the 25 second culprit
[May 18 00:14:18] DEBUG[29878] sched.c: |0036 | 0xb6f7269a      | 0x9e33fe0       | 000069 : 999810 |
[May 18 00:14:18] DEBUG[29878] sched.c: |0006 | 0xb6f7269a      | 0x9e353a0       | 003349 : 946410 |
[May 18 00:14:18] DEBUG[29878] sched.c: |0002 | 0xb6f7269a      | 0x9e32cb0       | 003349 : 945609 |
[May 18 00:14:18] DEBUG[29878] sched.c: =============================================================

25 seconds later: We are expired!
ID33 has gone.
[May 18 00:14:43] DEBUG[29878] chan_sip.c: ALEC expire_register: peer->name=bt100, peer->expire=36
[May 18 00:14:43] DEBUG[29878] sched.c: Asterisk Schedule Dump (4 in Q, 37 Total, 7 Cache, 12 high-water)
[May 18 00:14:43] DEBUG[29878] sched.c: =============================================================
[May 18 00:14:43] DEBUG[29878] sched.c: |ID    Callback          Data              Time  (sec:ms)   |
[May 18 00:14:43] DEBUG[29878] sched.c: +-----+-----------------+-----------------+-----------------+
[May 18 00:14:43] DEBUG[29878] sched.c: |0037 | 0xb6f4c4df      | 0xb6a01640      | 000007 : 075933 |
[May 18 00:14:43] DEBUG[29878] sched.c: |0036 | 0xb6f7269a      | 0x9e33fe0       | 000045 : 063750 |
[May 18 00:14:43] DEBUG[29878] sched.c: |0006 | 0xb6f7269a      | 0x9e353a0       | 003325 : 010350 |
[May 18 00:14:43] DEBUG[29878] sched.c: |0002 | 0xb6f7269a      | 0x9e32cb0       | 003325 : 009549 |
[May 18 00:14:43] DEBUG[29878] sched.c: =============================================================

Dump from parse_register_contact as phone re-registers:
[May 18 00:15:03] DEBUG[29878] chan_sip.c: ALEC Registered: SIP peer->name=bt100 peer->expire=39
[May 18 00:15:03] DEBUG[29878] sched.c: Asterisk Schedule Dump (4 in Q, 39 Total, 8 Cache, 12 high-water)
[May 18 00:15:03] DEBUG[29878] sched.c: =============================================================
[May 18 00:15:03] DEBUG[29878] sched.c: |ID    Callback          Data              Time  (sec:ms)   |
[May 18 00:15:03] DEBUG[29878] sched.c: +-----+-----------------+-----------------+-----------------+
[May 18 00:15:03] DEBUG[29878] sched.c: |0036 | 0xb6f7269a      | 0x9e33fe0       | 000024 : 936177 |   <<<this is next the 25 second culprit
[May 18 00:15:03] DEBUG[29878] sched.c: |0039 | 0xb6f7269a      | 0x9e33fe0       | 000069 : 999876 |
[May 18 00:15:03] DEBUG[29878] sched.c: |0006 | 0xb6f7269a      | 0x9e353a0       | 003304 : 882777 |
[May 18 00:15:03] DEBUG[29878] sched.c: |0002 | 0xb6f7269a      | 0x9e32cb0       | 003304 : 881976 |
[May 18 00:15:03] DEBUG[29878] sched.c: =============================================================

25 seconds later: We are expired! and so on.
[May 18 00:15:28] DEBUG[29878] chan_sip.c: ALEC expire_register: peer->name=bt100, peer->expire=39
By: Alec Davis (alecdavis) 2009-05-24 03:32:53

As commented on asterisk-dev by Russel Bryant;
chan_sip_unregister.diff2.txt which targets sip_unregister bug directly, 'sounds perfect'.

chan_sip_unregister.diff3.txt seems like overkill.
Please remove chan_sip_unregister.diff3.txt.

'Thanks for the excellent detective work', must be worth more than 1 karma point! :)

Alec
By: Digium Subversion (svnbot) 2009-05-26 08:43:14

Repository: asterisk
Revision: 196721

U   trunk/channels/chan_sip.c

------------------------------------------------------------------------
r196721 | file | 2009-05-26 08:43:14 -0500 (Tue, 26 May 2009) | 7 lines

Fix a bug where the sip unregister CLI command did not completely unregister the peer.

(closes issue ASTERISK-14138)
Reported by: alecdavis
Patches:
     chan_sip_unregister.diff2.txt uploaded by alecdavis (license 585)

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=196721
By: Digium Subversion (svnbot) 2009-05-26 08:44:48

Repository: asterisk
Revision: 196722

_U  branches/1.6.0/
U   branches/1.6.0/channels/chan_sip.c

------------------------------------------------------------------------
r196722 | file | 2009-05-26 08:44:48 -0500 (Tue, 26 May 2009) | 14 lines

Merged revisions 196721 via svnmerge from
https://origsvn.digium.com/svn/asterisk/trunk

........
 r196721 | file | 2009-05-26 10:43:13 -0300 (Tue, 26 May 2009) | 7 lines
 
 Fix a bug where the sip unregister CLI command did not completely unregister the peer.
 
 (closes issue ASTERISK-14138)
 Reported by: alecdavis
 Patches:
       chan_sip_unregister.diff2.txt uploaded by alecdavis (license 585)
........

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=196722
By: Digium Subversion (svnbot) 2009-05-26 08:46:39

Repository: asterisk
Revision: 196723

_U  branches/1.6.1/
U   branches/1.6.1/channels/chan_sip.c

------------------------------------------------------------------------
r196723 | file | 2009-05-26 08:46:39 -0500 (Tue, 26 May 2009) | 14 lines

Merged revisions 196721 via svnmerge from
https://origsvn.digium.com/svn/asterisk/trunk

........
 r196721 | file | 2009-05-26 10:43:13 -0300 (Tue, 26 May 2009) | 7 lines
 
 Fix a bug where the sip unregister CLI command did not completely unregister the peer.
 
 (closes issue ASTERISK-14138)
 Reported by: alecdavis
 Patches:
       chan_sip_unregister.diff2.txt uploaded by alecdavis (license 585)
........

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=196723
By: Digium Subversion (svnbot) 2009-05-26 08:47:49

Repository: asterisk
Revision: 196724

_U  branches/1.6.2/
U   branches/1.6.2/channels/chan_sip.c

------------------------------------------------------------------------
r196724 | file | 2009-05-26 08:47:48 -0500 (Tue, 26 May 2009) | 14 lines

Merged revisions 196721 via svnmerge from
https://origsvn.digium.com/svn/asterisk/trunk

........
 r196721 | file | 2009-05-26 10:43:13 -0300 (Tue, 26 May 2009) | 7 lines
 
 Fix a bug where the sip unregister CLI command did not completely unregister the peer.
 
 (closes issue ASTERISK-14138)
 Reported by: alecdavis
 Patches:
       chan_sip_unregister.diff2.txt uploaded by alecdavis (license 585)
........

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=196724