[asterisk-bugs] [Asterisk 0015118]: [patch] SIP device cycles between Available for 25 seconds and Unavailable for the programmed re-registration period, maybe an h
Asterisk Bug Tracker
noreply at bugs.digium.com
Sun May 17 07:40:04 CDT 2009
A NOTE has been added to this issue.
======================================================================
https://issues.asterisk.org/view.php?id=15118
======================================================================
Reported By: alecdavis
Assigned To: file
======================================================================
Project: Asterisk
Issue ID: 15118
Category: Channels/chan_sip/Registration
Reproducibility: always
Severity: major
Priority: normal
Status: assigned
Asterisk Version: SVN
Regression: No
SVN Branch (only for SVN checkouts, not tarball releases): N/A
SVN Revision (number only!): 192214
Request Review:
======================================================================
Date Submitted: 2009-05-15 05:42 CDT
Last Modified: 2009-05-17 07:40 CDT
======================================================================
Summary: [patch] SIP device cycles between Available for 25
seconds and Unavailable for the programmed re-registration period, maybe an h
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.
======================================================================
----------------------------------------------------------------------
(0104890) alecdavis (reporter) - 2009-05-17 07:40
https://issues.asterisk.org/view.php?id=15118#c104890
----------------------------------------------------------------------
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
Issue History
Date Modified Username Field Change
======================================================================
2009-05-17 07:40 alecdavis Note Added: 0104890
======================================================================
More information about the asterisk-bugs
mailing list