Hi,
If we park a call there is a roughly 20 second delay before the BLF fields update. Watching the asterisk console and watching the log we will see that a call will be parked and then about 20 seconds later this shows up (repeated for each watching user):
[2010-04-10 16:54:29] VERBOSE[2903] logger.c: Extension Changed 701[park-hints] new state InUse for Notify User 111
followed by (for each watching user):
[2010-04-10 16:54:29] DEBUG[2933] chan_sip.c: Acked pending invite 176
[2010-04-10 16:54:29] DEBUG[2933] chan_sip.c: Stopping retransmission on ‘[email protected]’ of Request 176: Match Found
and the BLF light turns on at the same time as these messages appear. If the call is picked up/hung up etc we see the same thing. If the parked call times out there is no delay with the message or the BLF field.
Anyone know why this might happen?
Thanks,
Joe
This is more than likely the result of a slow DNS server. Do you have a caching DNS setup on the server running Asterisk?
You need to turn debug and verbose on and see what command is hanging.
I don’t have a caching DNS server setup, but when using nslookup there is no discernable delay in the response.
After maxing out the verbosity and debug in the log, I get the following:
The transfer actually occurs here
[2010-04-17 15:43:37] DEBUG[17268] chan_sip.c: SIP Call parked on extension ‘701’
[2010-04-17 15:43:37] DEBUG[2933] chan_sip.c: = Found Their Call ID: [email protected] Their Tag cdedbca951d999ec Our tag: as4b8f1a08
[2010-04-17 15:43:37] DEBUG[2933] chan_sip.c: Stopping retransmission on ‘[email protected]’ of Request 103: Match Found
[2010-04-17 15:43:37] VERBOSE[2933] logger.c: Really destroying SIP dialog ‘[email protected]’ Method: BYE
The below happens about 5 times
[2010-04-17 15:43:40] DEBUG[2903] devicestate.c: Changing state for SIP/145-09d72338 - state 4 (Invalid)
[2010-04-17 15:43:40] DEBUG[2930] app_queue.c: Device ‘SIP/145-09d72338’ changed to state ‘4’ (Invalid) but we don’t care because they’re not a member of any queue.
[2010-04-17 15:43:40] DEBUG[2903] devicestate.c: No provider found, checking channel drivers for SIP - 145
[2010-04-17 15:43:40] DEBUG[2903] chan_sip.c: Checking device state for peer 145
[2010-04-17 15:43:40] DEBUG[2903] devicestate.c: Changing state for SIP/145 - state 2 (In use)
[2010-04-17 15:43:40] DEBUG[2930] app_queue.c: Device ‘SIP/145’ changed to state ‘2’ (In use) but we don’t care because they’re not a member of any queue.
[2010-04-17 15:43:40] DEBUG[2903] devicestate.c: No provider found, checking channel drivers for SIP - 145
[2010-04-17 15:43:40] DEBUG[2903] chan_sip.c: Checking device state for peer 145
[2010-04-17 15:43:40] DEBUG[2903] devicestate.c: No provider found, checking channel drivers for SIP - 111
[2010-04-17 15:43:40] DEBUG[2903] chan_sip.c: Checking device state for peer 111
[2010-04-17 15:43:40] DEBUG[2903] devicestate.c: Changing state for SIP/111 - state 1 (Not in use)
[2010-04-17 15:43:40] DEBUG[2930] app_queue.c: Device ‘SIP/111’ changed to state ‘1’ (Not in use) but we don’t care because they’re not a member of any queue.
[2010-04-17 15:43:40] DEBUG[2903] devicestate.c: No provider found, checking channel drivers for SIP - 111
[2010-04-17 15:43:40] DEBUG[2903] chan_sip.c: Checking device state for peer 111
[2010-04-17 15:43:40] DEBUG[2903] devicestate.c: No provider found, checking channel drivers for SIP - 111-09ec73f8
[2010-04-17 15:43:40] DEBUG[2903] chan_sip.c: Checking device state for peer 111-09ec73f8
each time it repeats, we get ~ 140 lines of the following:
[2010-04-17 15:43:41] DEBUG[2904] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=85)
These repeats are consuming most of the average 10-20 second delay.
Then we get the following and the status actually changes and the lights change
[2010-04-17 15:43:49] DEBUG[2903] devicestate.c: No provider found, checking channel drivers for SIPPeer - SIP/111-09ec73f8
[2010-04-17 15:43:49] DEBUG[2903] devicestate.c: Changing state for SIPPeer/SIP/111-09ec73f8 - state 4 (Invalid)
[2010-04-17 15:43:49] DEBUG[2930] app_queue.c: Device ‘SIPPeer/SIP/111-09ec73f8’ changed to state ‘4’ (Invalid) but we don’t care because they’re not a member of any queue.
[2010-04-17 15:43:49] DEBUG[2903] devicestate.c: No provider found, checking channel drivers for SIPPeer - SIP/111
[2010-04-17 15:43:49] DEBUG[2903] devicestate.c: Changing state for SIPPeer/SIP/111 - state 4 (Invalid)
[2010-04-17 15:43:49] DEBUG[2930] app_queue.c: Device ‘SIPPeer/SIP/111’ changed to state ‘4’ (Invalid) but we don’t care because they’re not a member of any queue.
[2010-04-17 15:43:49] DEBUG[2903] devicestate.c: No provider found, checking channel drivers for Parking - SIP/145-09d72338
[2010-04-17 15:43:49] DEBUG[2903] devicestate.c: Changing state for Parking/SIP/145-09d72338 - state 4 (Invalid)
[2010-04-17 15:43:49] DEBUG[2930] app_queue.c: Device ‘Parking/SIP/145-09d72338’ changed to state ‘4’ (Invalid) but we don’t care because they’re not a member of any queue.
[2010-04-17 15:43:49] DEBUG[2903] devicestate.c: No provider found, checking channel drivers for Parking - SIP/145
[2010-04-17 15:43:49] DEBUG[2903] devicestate.c: Changing state for Parking/SIP/145 - state 4 (Invalid)
[2010-04-17 15:43:49] DEBUG[2930] app_queue.c: Device ‘Parking/SIP/145’ changed to state ‘4’ (Invalid) but we don’t care because they’re not a member of any queue.
[2010-04-17 15:43:49] DEBUG[2903] devicestate.c: Checking if I can find provider for “park” - number: 701@parkedcalls
[2010-04-17 15:43:49] DEBUG[2903] devicestate.c: Checking provider SLA with park
[2010-04-17 15:43:49] DEBUG[2903] devicestate.c: Checking provider Meetme with park
[2010-04-17 15:43:49] DEBUG[2903] devicestate.c: Checking provider Park with park
[2010-04-17 15:43:49] DEBUG[2903] res_features.c: Checking state of exten 701 in context parkedcalls
[2010-04-17 15:43:49] DEBUG[2903] devicestate.c: Changing state for park:701@parkedcalls - state 2 (In use)
[2010-04-17 15:43:49] DEBUG[2903] devicestate.c: Checking if I can find provider for “park” - number: 701@parkedcalls
[2010-04-17 15:43:49] DEBUG[2903] devicestate.c: Checking provider SLA with park
[2010-04-17 15:43:49] DEBUG[2903] devicestate.c: Checking provider Meetme with park
[2010-04-17 15:43:49] DEBUG[2903] devicestate.c: Checking provider Park with park
[2010-04-17 15:43:49] DEBUG[2903] res_features.c: Checking state of exten 701 in context parkedcalls
[2010-04-17 15:43:49] DEBUG[2903] devicestate.c: Checking if I can find provider for “park” - number: 701@parkedcalls
[2010-04-17 15:43:49] DEBUG[2903] devicestate.c: Checking provider SLA with park
[2010-04-17 15:43:49] DEBUG[2903] devicestate.c: Checking provider Meetme with park
[2010-04-17 15:43:49] DEBUG[2903] devicestate.c: Checking provider Park with park
[2010-04-17 15:43:49] DEBUG[2903] res_features.c: Checking state of exten 701 in context parkedcalls
[2010-04-17 15:43:49] VERBOSE[2903] logger.c: Extension Changed 701[park-hints] new state InUse for Notify User 111
[2010-04-17 15:43:49] DEBUG[2903] devicestate.c: Checking if I can find provider for “park” - number: 701@parkedcalls
[2010-04-17 15:43:49] DEBUG[2903] devicestate.c: Checking provider SLA with park
[2010-04-17 15:43:49] DEBUG[2903] devicestate.c: Checking provider Meetme with park
[2010-04-17 15:43:49] DEBUG[2903] devicestate.c: Checking provider Park with park
[2010-04-17 15:43:49] DEBUG[2903] res_features.c: Checking state of exten 701 in context parkedcalls
[2010-04-17 15:43:49] VERBOSE[2903] logger.c: Extension Changed 701[park-hints] new state InUse for Notify User 134
etc, etc for each user
*Hi, I still cannot figure out the problem.
*I don’t know what is causing the delay, as there is a 12 second gap between when the call is parked here:
[2010-04-17 15:43:37] DEBUG[17268] chan_sip.c: SIP Call parked on extension ‘701’
*and the next message about that extension, rather than the extensions involved in the original call, 145 and 111:
[2010-04-17 15:43:49] DEBUG[2903] devicestate.c: Checking if I can find provider for “park” - number: 701@parkedcalls
*immediately where after it actually updates the state and the lights change.
*What fills up the rest of the space are the following:
*I see it throughout the log, repeating many times a second, when the problem is ocuring and not.
[2010-04-17 15:43:41] DEBUG[2904] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=85)
*Or this, which repeats several times in the delay for both of the involved extensions, 145 and 111:
[2010-04-17 15:43:49] DEBUG[2903] devicestate.c: No provider found, checking channel drivers for SIPPeer - SIP/111-09ec73f8
[2010-04-17 15:43:49] DEBUG[2903] devicestate.c: Changing state for SIPPeer/SIP/111-09ec73f8 - state 4 (Invalid)
[2010-04-17 15:43:49] DEBUG[2930] app_queue.c: Device ‘SIPPeer/SIP/111-09ec73f8’ changed to state ‘4’ (Invalid) but we don’t care because they’re not a member of any queue.