[asterisk-bugs] [Asterisk 0012680]: Extension state change random delay
noreply at bugs.digium.com
noreply at bugs.digium.com
Thu Oct 30 11:21:35 CDT 2008
A NOTE has been added to this issue.
======================================================================
http://bugs.digium.com/view.php?id=12680
======================================================================
Reported By: corruptor
Assigned To:
======================================================================
Project: Asterisk
Issue ID: 12680
Category: Channels/chan_sip/Subscriptions
Reproducibility: always
Severity: minor
Priority: normal
Status: feedback
Asterisk Version: 1.4.20
SVN Branch (only for SVN checkouts, not tarball releases): N/A
SVN Revision (number only!):
Disclaimer on File?: N/A
Request Review:
======================================================================
Date Submitted: 05-19-2008 05:04 CDT
Last Modified: 07-10-2008 11:52 CDT
======================================================================
Summary: Extension state change random delay
Description:
asterisk-1.4.20-rc3
Grandstream GXP-2000 is registered as 1100 and subscribed to receive
changes about extensions states.
SIP/1101 is Linksys 942
SIP/1102 is SjPhone.
I've also set notifyringing=yes.
1102 calls 1101. 1101 sends RINGING but asterisk sends NOTIFY to
Grandstream with 3 sec delay. You can see (log is attached) that RINGING
was at 19:11:27 and NOTIFY is sent at 19:11:30.
Later when 1101 answers you can see that device state is changed 9 seconds
after call have been established (19:11:50] DEBUG[24559] devicestate.c:
Changing state for SIP/1102-09551818 - state 4 (Invalid))
When call is over asterisk changes state for one of the extensions almost
instantly but there is 20 seconds delay for 1102 (19:12:20).
Please help to debug this problem.
======================================================================
----------------------------------------------------------------------
aragon - 07-10-08 11:52
----------------------------------------------------------------------
IMHO bug 9668 should be re-opened because
The revision broke state changes creating multiple bug reports 12771 12680
12627 12672 by creating a problem with DNS failures which result in hung
channels and hints.
If it is easier then a patch could be written for 12680 and relationships
added to the other open tickets while leaving 9668 closed.
Reverting the revision 96575 fixes the apparently fictitious "race
condition"
Have a look at these DNS errors responsible for delaying the extension
states.
The problem is when the SIP channel is tagged with a - and a random tag as
in SIP/1820-08845b70 and the DNS lookup fails.
[Jul 8 17:24:58] DEBUG[22329] devicestate.c: Notification of state change
to be queued on device/channel SIP/9005
[Jul 8 17:24:58] DEBUG[22266] channel.c: Internal timing is disabled
(option_internal_timing=0 chan->timingfd=66)
[Jul 8 17:24:58] DEBUG[29819] devicestate.c: No provider found, checking
channel drivers for SIP - 9005
[Jul 8 17:24:58] DEBUG[29819] chan_sip.c: Checking device state for peer
9005
[Jul 8 17:24:58] DEBUG[29819] devicestate.c: Changing state for SIP/9005
- state 6 (Ringing)
[Jul 8 17:24:58] DEBUG[29819] devicestate.c: No provider found, checking
channel drivers for SIP - 9005
[Jul 8 17:24:58] DEBUG[29819] chan_sip.c: Checking device state for peer
9005
[Jul 8 17:24:58] DEBUG[29819] devicestate.c: No provider found, checking
channel drivers for SIP - 9005
[Jul 8 17:24:58] DEBUG[29819] chan_sip.c: Checking device state for peer
9005
[Jul 8 17:24:58] VERBOSE[29819] logger.c: Extension Changed
9005[default-local] new state Ringing for Notify User 9007
[Jul 8 17:24:58] DEBUG[29853] app_queue.c: Device 'SIP/9005' changed to
state '6' (Ringing)
[Jul 8 17:24:58] DEBUG[22329] chan_sip.c: Our T38 capability (0), joint
T38 capability (0)
[Jul 8 17:24:58] DEBUG[22329] chan_sip.c: ** Our capability: 0x8 (alaw)
Video flag: False
[Jul 8 17:24:58] DEBUG[22329] chan_sip.c: ** Our prefcodec: 0x8 (alaw)
[Jul 8 17:24:58] DEBUG[22329] chan_sip.c: -- Done with adding codecs to
SDP
[Jul 8 17:24:58] DEBUG[22329] channel.c: Internal timing is disabled
(option_internal_timing=0 chan->timingfd=70)
[Jul 8 17:24:58] DEBUG[22329] chan_sip.c: Done building SDP. Settling
with this capability: 0x8 (alaw)
[Jul 8 17:35:57] DEBUG[5980] devicestate.c: Notification of state change
to be queued on device/channel SIP/1820
[Jul 8 17:35:57] DEBUG[5980] chan_sip.c: Our T38 capability (0), joint
T38 capability (0)
[Jul 8 17:35:57] DEBUG[5980] chan_sip.c: ** Our capability: 0xa
(gsm|alaw) Video flag: False
[Jul 8 17:35:57] DEBUG[5980] chan_sip.c: ** Our prefcodec: 0x8 (alaw)
[Jul 8 17:35:57] DEBUG[5980] chan_sip.c: -- Done with adding codecs to
SDP
[Jul 8 17:35:57] DEBUG[5980] chan_sip.c: Done building SDP. Settling with
this capability: 0xa (gsm|alaw)
[Jul 8 17:35:57] VERBOSE[5980] logger.c: -- Called 1820
[Jul 8 17:35:57] DEBUG[8924] chan_sip.c: (Provisional) Stopping
retransmission (but retaining packet) on
'098cca77047e2253118b86f561fbb742 at 192.168.21.250' Request 102: Found
[Jul 8 17:35:57] DEBUG[8945] manager.c: Manager received command
'Command'
[Jul 8 17:35:57] DEBUG[8945] app_queue.c: Queue default-service_centre
has no realtime members defined. No need for update
[Jul 8 17:35:57] DEBUG[8945] manager.c: Manager received command
'Command'
[Jul 8 17:35:57] DEBUG[8945] app_queue.c: Queue default-spares_department
has no realtime members defined. No need for update
[Jul 8 17:35:57] DEBUG[8945] manager.c: Manager received command
'Command'
[Jul 8 17:35:57] DEBUG[8924] chan_sip.c: (Provisional) Stopping
retransmission (but retaining packet) on
'098cca77047e2253118b86f561fbb742 at 192.168.21.250' Request 102: Found
[Jul 8 17:35:57] DEBUG[8924] devicestate.c: Notification of state change
to be queued on device/channel SIP/1820-08845b70
[Jul 8 17:35:57] DEBUG[8924] devicestate.c: Notification of state change
to be queued on device/channel SIP/1820
[Jul 8 17:35:57] VERBOSE[5980] logger.c: -- SIP/1820-08845b70 is
ringing
[Jul 8 17:35:57] DEBUG[5980] rtp.c: Channel
'Local/1820 at default-agent-60a9,2' has no RTP, not doing anything
[Jul 8 17:35:57] VERBOSE[5971] logger.c: --
Local/1820 at default-agent-60a9,1 is ringing
[Jul 8 17:35:57] DEBUG[8945] manager.c: Manager received command
'Command'
[Jul 8 17:35:57] DEBUG[8945] app_queue.c: Queue default-internal_sales
has no realtime members defined. No need for update
[Jul 8 17:35:57] DEBUG[5979] audiohook.c: Read factory 0x88441c8 was
pretty quick last time, waiting for them.
tcpdump -i any port 53 -n -l
15:42:29.089068 IP 192.168.13.3.39661 > 128.63.2.53.domain: 19578 A?
1815-b67b5b58. (31) 15:42:30.077827 IP 192.168.13.3.39661 >
192.228.79.201.domain: 12403 [1au] A? 9000-08f8a300. (42) 15:42:32.079329
IP 192.168.13.3.39661 > 192.33.4.12.domain: 21764 [1au] A? 9000-08f8a300.
(42) 15:42:32.090282 IP 192.168.13.3.39661 > 192.36.148.17.domain: 12227 A?
1815-b67b5b58. (31)
5:42:58.067823 IP 127.0.0.1.51503 > 127.0.0.1.domain: 43072+ A?
9000-08f8a300. (31) 15:42:58.076865 IP 127.0.0.1.domain > 127.0.0.1.51501:
22664 ServFail 0/0/0 (31) 15:42:58.076884 IP 127.0.0.1.domain >
127.0.0.1.51501: 22664 ServFail 0/0/0 (31)
Issue History
Date Modified Username Field Change
======================================================================
07-10-08 11:52 aragon Note Added: 0090027
======================================================================
More information about the asterisk-bugs
mailing list