[Jul  8 17:24:53] DEBUG[29819] chan_sip.c: Checking device state for peer 9004
[Jul  8 17:24:53] DEBUG[29853] app_queue.c: Device 'SIP/9004' changed to state '2' (In use)
[Jul  8 17:24:53] DEBUG[22266] pbx.c: Function result is '9004'
[Jul  8 17:24:53] DEBUG[29819] devicestate.c: No provider found, checking channel drivers for SIP - 9004
[Jul  8 17:24:53] DEBUG[29819] chan_sip.c: Checking device state for peer 9004
[Jul  8 17:24:53] VERBOSE[29819] logger.c:  Extension Changed 9004[default-local] new state InUse for Notify User 9007
[Jul  8 17:24:53] DEBUG[29819] devicestate.c: No provider found, checking channel drivers for SIP - 9004-08395220
[Jul  8 17:24:53] DEBUG[29819] chan_sip.c: Checking device state for peer 9004-08395220
[Jul  8 17:24:53] DEBUG[22266] pbx.c: Launching 'Set'
[Jul  8 17:24:53] VERBOSE[22266] logger.c:     -- Executing [3333@default-default:1] Set("SIP/9004-08395220", "GROUP(OUTGOING)=9004") in new stack
[Jul  8 17:24:53] DEBUG[29819] devicestate.c: Changing state for SIP/9004-08395220 - state 4 (Invalid)
[Jul  8 17:24:53] DEBUG[29819] devicestate.c: No provider found, checking channel drivers for SIP - 9004
[Jul  8 17:24:53] DEBUG[29819] chan_sip.c: Checking device state for peer 9004
[Jul  8 17:24:53] DEBUG[29819] devicestate.c: Changing state for SIP/9004 - state 2 (In use)
[Jul  8 17:24:53] DEBUG[29819] devicestate.c: No provider found, checking channel drivers for SIP - 9004
[Jul  8 17:24:53] DEBUG[29819] chan_sip.c: Checking device state for peer 9004
[Jul  8 17:24:53] DEBUG[29853] app_queue.c: Device 'SIP/9004-08395220' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
[Jul  8 17:24:53] DEBUG[29853] app_queue.c: Device 'SIP/9004' changed to state '2' (In use)
[Jul  8 17:24:53] DEBUG[22266] pbx.c: Launching 'Answer'
[Jul  8 17:24:53] VERBOSE[22266] logger.c:     -- Executing [3333@default-default:2] Answer("SIP/9004-08395220", "") in new stack
[Jul  8 17:24:53] DEBUG[22266] devicestate.c: Notification of state change to be queued on device/channel SIP/9004-08395220
[Jul  8 17:24:53] DEBUG[29819] devicestate.c: No provider found, checking channel drivers for SIP - 9004-08395220
[Jul  8 17:24:53] DEBUG[29819] chan_sip.c: Checking device state for peer 9004-08395220
[Jul  8 17:24:53] DEBUG[22266] devicestate.c: Notification of state change to be queued on device/channel SIP/9004
[Jul  8 17:24:53] DEBUG[29819] devicestate.c: Changing state for SIP/9004-08395220 - state 4 (Invalid)
[Jul  8 17:24:53] DEBUG[29819] devicestate.c: No provider found, checking channel drivers for SIP - 9004
[Jul  8 17:24:53] DEBUG[29819] chan_sip.c: Checking device state for peer 9004
[Jul  8 17:24:53] DEBUG[29819] devicestate.c: Changing state for SIP/9004 - state 2 (In use)
[Jul  8 17:24:53] DEBUG[29819] devicestate.c: No provider found, checking channel drivers for SIP - 9004
[Jul  8 17:24:53] DEBUG[29819] chan_sip.c: Checking device state for peer 9004
[Jul  8 17:24:53] DEBUG[29853] app_queue.c: Device 'SIP/9004-08395220' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
[Jul  8 17:24:53] DEBUG[29853] app_queue.c: Device 'SIP/9004' changed to state '2' (In use)
[Jul  8 17:24:53] DEBUG[22266] chan_sip.c: SIP answering channel: SIP/9004-08395220
[Jul  8 17:24:53] DEBUG[22266] chan_sip.c: Setting framing from config on incoming call
[Jul  8 17:24:53] DEBUG[22266] chan_sip.c: ** Our capability: 0x8 (alaw) Video flag: True
[Jul  8 17:24:53] DEBUG[22266] chan_sip.c: ** Our prefcodec: 0x0 (nothing)
[Jul  8 17:24:53] DEBUG[22266] chan_sip.c: -- Done with adding codecs to SDP
[Jul  8 17:24:53] DEBUG[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[Jul  8 17:24:53] DEBUG[22266] chan_sip.c: Done building SDP. Settling with this capability: 0x8 (alaw)
[Jul  8 17:24:53] DEBUG[22266] pbx.c: Launching 'Goto'
[Jul  8 17:24:53] VERBOSE[22266] logger.c:     -- Executing [3333@default-default:3] Goto("SIP/9004-08395220", "default-application-acd-test|s|1") in new stack
[Jul  8 17:24:53] VERBOSE[22266] logger.c:     -- Goto (default-application-acd-test,s,1)
[Jul  8 17:24:53] DEBUG[22266] pbx.c: Launching 'NoOp'
[Jul  8 17:24:53] VERBOSE[22266] logger.c:     -- Executing [s@default-application-acd-test:1] NoOp("SIP/9004-08395220", ""=== START QUEUE (default-test) ==="") in new stack
[Jul  8 17:24:53] DEBUG[22266] pbx.c: Launching 'Set'
[Jul  8 17:24:53] VERBOSE[22266] logger.c:     -- Executing [s@default-application-acd-test:2] Set("SIP/9004-08395220", "__QUEUENAME=default-test") in new stack
[Jul  8 17:24:53] DEBUG[22266] pbx.c: Launching 'Set'
[Jul  8 17:24:53] VERBOSE[22266] logger.c:     -- Executing [s@default-application-acd-test:3] Set("SIP/9004-08395220", "TIMEOUT(digit)=1") in new stack
[Jul  8 17:24:53] VERBOSE[22266] logger.c:     -- Digit timeout set to 1
[Jul  8 17:24:53] DEBUG[22266] pbx.c: Launching 'Set'
[Jul  8 17:24:53] VERBOSE[22266] logger.c:     -- Executing [s@default-application-acd-test:4] Set("SIP/9004-08395220", "TIMEOUT(response)=1") in new stack
[Jul  8 17:24:53] VERBOSE[22266] logger.c:     -- Response timeout set to 1
[Jul  8 17:24:53] DEBUG[22266] pbx.c: Launching 'Set'
[Jul  8 17:24:53] VERBOSE[22266] logger.c:     -- Executing [s@default-application-acd-test:5] Set("SIP/9004-08395220", "QUEUE_PRIO=0") in new stack
[Jul  8 17:24:53] DEBUG[22266] pbx.c: Launching 'BackGround'
[Jul  8 17:24:53] VERBOSE[22266] logger.c:     -- Executing [s@default-application-acd-test:6] BackGround("SIP/9004-08395220", "custom/exit") in new stack
[Jul  8 17:24:53] DEBUG[22266] channel.c: Set channel SIP/9004-08395220 to write format slin
[Jul  8 17:24:53] DEBUG[22266] rtp.c: Ooh, format changed from unknown to alaw
[Jul  8 17:24:53] DEBUG[22266] rtp.c: Created smoother: format: 8 ms: 20 len: 160
[Jul  8 17:24:53] DEBUG[22266] channel.c: Scheduling timer at 160 sample intervals
[Jul  8 17:24:53] VERBOSE[22266] logger.c:     -- <SIP/9004-08395220> Playing 'custom/exit' (language 'en')
[Jul  8 17:24:53] VERBOSE[22210] logger.c:     -- Remote UNIX connection disconnected
[Jul  8 17:24:53] DEBUG[29823] chan_sip.c: = Found Their Call ID: 3c2fcacbd1f6-lp0yipjq94ag@snom300-0004132853BA Their Tag v6etp8u5u5 Our tag: as4d32d693
[Jul  8 17:24:53] DEBUG[29823] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[Jul  8 17:24:53] DEBUG[29823] chan_sip.c: Stopping retransmission on '3c2fcacbd1f6-lp0yipjq94ag@snom300-0004132853BA' of Response 2: Match Found
[Jul  8 17:24:53] DEBUG[22266] rtp.c: Got RTCP report of 52 bytes
[Jul  8 17:24:54] DEBUG[29823] chan_sip.c: = No match Their Call ID: 3c2fcacbd1f6-lp0yipjq94ag@snom300-0004132853BA Their Tag v6etp8u5u5 Our tag: as4d32d693
[Jul  8 17:24:54] DEBUG[29823] chan_sip.c: = No match Their Call ID: 3c26700d7ef4-ps3y5dvpx10v@snom300-00041325D78A Their Tag 4q83n4ijgi Our tag: as4cf4b9e9
[Jul  8 17:24:54] DEBUG[29823] chan_sip.c: = No match Their Call ID: 3c26700d72bf-0qfq3azp1tku@snom300-0004132574EB Their Tag 2kylud1t3o Our tag: as2bc154da
[Jul  8 17:24:54] DEBUG[29823] chan_sip.c: = No match Their Call ID: 121d4d71-df4be8b3-79b0d8bc@192.168.21.238 Their Tag 36359425-C942AE06 Our tag: as46d76742
[Jul  8 17:24:54] DEBUG[29823] chan_sip.c: = No match Their Call ID: 509d78da-4fd92ef4-27e22c49@192.168.21.238 Their Tag 858C517E-FD4B83CB Our tag: as544f162c
[Jul  8 17:24:54] DEBUG[29823] chan_sip.c: = No match Their Call ID: 23be4e0f-c0305621-3f283ed2@192.168.21.238 Their Tag 26DE71E3-3F077C2C Our tag: as374f954a
[Jul  8 17:24:54] DEBUG[29823] chan_sip.c: = No match Their Call ID: 10457120-f98c73ca-4fe6aca7@192.168.21.238 Their Tag B940A064-4A3F2AF9 Our tag: as28165b3c
[Jul  8 17:24:54] DEBUG[29823] chan_sip.c: = Found Their Call ID: de3d94dd-d22dce3f-14763bd8@192.168.21.238 Their Tag A9F20AD1-E3EDF7C2 Our tag: as6faca760
[Jul  8 17:24:54] DEBUG[29823] chan_sip.c: Acked pending invite 112
[Jul  8 17:24:54] DEBUG[29823] chan_sip.c: Stopping retransmission on 'de3d94dd-d22dce3f-14763bd8@192.168.21.238' of Request 112: Match Found
[Jul  8 17:24:55] DEBUG[29823] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jul  8 17:24:58] DEBUG[22266] channel.c: Scheduling timer at 138 sample intervals
[Jul  8 17:24:58] DEBUG[29851] manager.c: Manager received command 'show uptime'
[Jul  8 17:24:58] DEBUG[29851] manager.c: Manager received command 'show uptime'
[Jul  8 17:24:58] DEBUG[29851] manager.c: Manager received command 'Command'
[Jul  8 17:24:58] DEBUG[22266] channel.c: Scheduling timer at 0 sample intervals
[Jul  8 17:24:58] DEBUG[22266] channel.c: Scheduling timer at 0 sample intervals
[Jul  8 17:24:58] DEBUG[22266] channel.c: Set channel SIP/9004-08395220 to write format alaw
[Jul  8 17:24:58] DEBUG[22266] pbx.c: Launching 'Set'
[Jul  8 17:24:58] VERBOSE[22266] logger.c:     -- Executing [s@default-application-acd-test:7] Set("SIP/9004-08395220", "__ACD_TO_OUTGOING=1") in new stack
[Jul  8 17:24:58] DEBUG[22266] pbx.c: Launching 'Set'
[Jul  8 17:24:58] VERBOSE[22266] logger.c:     -- Executing [s@default-application-acd-test:8] Set("SIP/9004-08395220", "CHANNEL(musicclass)=default") in new stack
[Jul  8 17:24:58] DEBUG[22266] pbx.c: Launching 'Set'
[Jul  8 17:24:58] VERBOSE[22266] logger.c:     -- Executing [s@default-application-acd-test:9] Set("SIP/9004-08395220", "__ALLOW_TRANSFER=t") in new stack
[Jul  8 17:24:58] DEBUG[22266] pbx.c: Launching 'Queue'
[Jul  8 17:24:58] VERBOSE[22266] logger.c:     -- Executing [s@default-application-acd-test:10] Queue("SIP/9004-08395220", "default-test|t|||300") in new stack
[Jul  8 17:24:58] DEBUG[22266] app_queue.c: SIP/9004-08395220: Got priority 0 from ${QUEUE_PRIO}.
[Jul  8 17:24:58] DEBUG[22266] app_queue.c: queue: default-test, options: t, url: , announce: , expires: 1215530998, priority: 0
[Jul  8 17:24:58] DEBUG[22266] app_queue.c: Queue default-test has no realtime members defined. No need for update
[Jul  8 17:24:58] DEBUG[22266] app_queue.c: Queue 'default-test' Join, Channel 'SIP/9004-08395220', Position '1'
[Jul  8 17:24:58] DEBUG[22266] channel.c: Set channel SIP/9004-08395220 to write format slin
[Jul  8 17:24:58] VERBOSE[22266] logger.c:     -- Started music on hold, class 'default', on channel 'SIP/9004-08395220'
[Jul  8 17:24:58] DEBUG[22266] channel.c: Scheduling timer at 160 sample intervals
[Jul  8 17:24:58] DEBUG[22266] app_queue.c: There are 1 available members.
[Jul  8 17:24:58] DEBUG[22266] app_queue.c: It's our turn (SIP/9004-08395220).
[Jul  8 17:24:58] DEBUG[22266] app_queue.c: SIP/9004-08395220 is trying to call a queue member.
[Jul  8 17:24:58] DEBUG[22266] app_queue.c: Trying 'Local/9005@default-agent/n' with metric 1000
[Jul  8 17:24:58] DEBUG[22266] channel.c: Copying hard-transferable variable ALLOW_TRANSFER.
[Jul  8 17:24:58] DEBUG[22266] channel.c: Copying hard-transferable variable ACD_TO_OUTGOING.
[Jul  8 17:24:58] DEBUG[22266] channel.c: Not copying variable QUEUE_PRIO.
[Jul  8 17:24:58] DEBUG[22266] channel.c: Copying hard-transferable variable QUEUENAME.
[Jul  8 17:24:58] DEBUG[22266] channel.c: Not copying variable SPYGROUP.
[Jul  8 17:24:58] DEBUG[22266] channel.c: Not copying variable INBOUND_GROUP.
[Jul  8 17:24:58] DEBUG[22266] channel.c: Not copying variable SIPCALLID.
[Jul  8 17:24:58] DEBUG[22266] channel.c: Not copying variable SIPUSERAGENT.
[Jul  8 17:24:58] DEBUG[22266] channel.c: Not copying variable SIPDOMAIN.
[Jul  8 17:24:58] DEBUG[22266] channel.c: Not copying variable SIPURI.
[Jul  8 17:24:58] DEBUG[22329] pbx.c: Launching 'NoCDR'
[Jul  8 17:24:58] VERBOSE[22329] logger.c:     -- Executing [9005@default-agent:1] NoCDR("Local/9005@default-agent-c6fe,2", "") in new stack
[Jul  8 17:24:58] DEBUG[22329] db.c: Unable to find key '9005/DoNotDisturb' in family 'default'
[Jul  8 17:24:58] DEBUG[22329] func_db.c: DB: default/9005/DoNotDisturb not found in database.
[Jul  8 17:24:58] DEBUG[22329] pbx.c: Function result is ''
[Jul  8 17:24:58] DEBUG[22329] pbx.c: Launching 'Set'
[Jul  8 17:24:58] VERBOSE[22329] logger.c:     -- Executing [9005@default-agent:2] Set("Local/9005@default-agent-c6fe,2", "DND=") in new stack
[Jul  8 17:24:58] DEBUG[22329] pbx.c: Expression result is '0'
[Jul  8 17:24:58] DEBUG[22329] pbx.c: Launching 'GotoIf'
[Jul  8 17:24:58] VERBOSE[22329] logger.c:     -- Executing [9005@default-agent:3] GotoIf("Local/9005@default-agent-c6fe,2", "0?20") in new stack
[Jul  8 17:24:58] DEBUG[22329] pbx.c: Not taking any branch
[Jul  8 17:24:58] DEBUG[22329] pbx.c: Function result is '0'
[Jul  8 17:24:58] DEBUG[22329] pbx.c: Function result is '0'
[Jul  8 17:24:58] DEBUG[22329] pbx.c: Expression result is '0'
[Jul  8 17:24:58] DEBUG[22329] pbx.c: Launching 'Set'
[Jul  8 17:24:58] VERBOSE[22329] logger.c:     -- Executing [9005@default-agent:4] Set("Local/9005@default-agent-c6fe,2", "GROUPCOUNT=0") in new stack
[Jul  8 17:24:58] DEBUG[22329] db.c: Unable to find key 'agent/9010/maxcalls' in family 'default'
[Jul  8 17:24:58] DEBUG[22329] func_db.c: DB: default/agent/9010/maxcalls not found in database.
[Jul  8 17:24:58] DEBUG[22329] pbx.c: Function result is ''
[Jul  8 17:24:58] DEBUG[22329] pbx.c: Launching 'Set'
[Jul  8 17:24:58] VERBOSE[22329] logger.c:     -- Executing [9005@default-agent:5] Set("Local/9005@default-agent-c6fe,2", "AGENTMAXCALL=") in new stack
[Jul  8 17:24:58] DEBUG[22329] pbx.c: Expression result is '1'
[Jul  8 17:24:58] DEBUG[22329] pbx.c: Expression result is '7'
[Jul  8 17:24:58] DEBUG[22329] pbx.c: Expression result is '8'
[Jul  8 17:24:58] DEBUG[22329] pbx.c: Launching 'GotoIf'
[Jul  8 17:24:58] VERBOSE[22329] logger.c:     -- Executing [9005@default-agent:6] GotoIf("Local/9005@default-agent-c6fe,2", "1?7:8") in new stack
[Jul  8 17:24:58] VERBOSE[22329] logger.c:     -- Goto (default-agent,9005,7)
[Jul  8 17:24:58] DEBUG[22329] pbx.c: Launching 'Set'
[Jul  8 17:24:58] VERBOSE[22329] logger.c:     -- Executing [9005@default-agent:7] Set("Local/9005@default-agent-c6fe,2", "AGENTMAXCALL=1") in new stack
[Jul  8 17:24:58] DEBUG[22329] pbx.c: Expression result is '0'
[Jul  8 17:24:58] DEBUG[22329] pbx.c: Launching 'GotoIf'
[Jul  8 17:24:58] VERBOSE[22329] logger.c:     -- Executing [9005@default-agent:8] GotoIf("Local/9005@default-agent-c6fe,2", "0?20") in new stack
[Jul  8 17:24:58] DEBUG[22329] pbx.c: Not taking any branch
[Jul  8 17:24:58] DEBUG[22329] pbx.c: Expression result is '1'
[Jul  8 17:24:58] DEBUG[22329] pbx.c: Expression result is '12'
[Jul  8 17:24:58] DEBUG[22329] pbx.c: Launching 'GotoIf'
[Jul  8 17:24:58] VERBOSE[22329] logger.c:     -- Executing [9005@default-agent:9] GotoIf("Local/9005@default-agent-c6fe,2", "1?12") in new stack
[Jul  8 17:24:58] VERBOSE[22329] logger.c:     -- Goto (default-agent,9005,12)
[Jul  8 17:24:58] DEBUG[22329] pbx.c: Launching 'Set'
[Jul  8 17:24:58] VERBOSE[22329] logger.c:     -- Executing [9005@default-agent:12] Set("Local/9005@default-agent-c6fe,2", "OUTBOUND_GROUP_ONCE=9005@INCOMING") in new stack
[Jul  8 17:24:58] DEBUG[22329] pbx.c: Launching 'Set'
[Jul  8 17:24:58] VERBOSE[22329] logger.c:     -- Executing [9005@default-agent:13] Set("Local/9005@default-agent-c6fe,2", "DB(default/wrapup/9005/lastcall)=1215530698.113") in new stack
[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[22266] channel.c: Generator got voice, switching to phase locked mode
[Jul  8 17:24:58] DEBUG[22266] channel.c: Scheduling timer at 0 sample intervals
[Jul  8 17:24:58] DEBUG[22329] pbx.c: Launching 'Goto'
[Jul  8 17:24:58] VERBOSE[22329] logger.c:     -- Executing [9005@default-agent:14] Goto("Local/9005@default-agent-c6fe,2", "default-local-devices|9005|1") in new stack
[Jul  8 17:24:58] VERBOSE[22329] logger.c:     -- Goto (default-local-devices,9005,1)
[Jul  8 17:24:58] DEBUG[22329] pbx.c: Launching 'Set'
[Jul  8 17:24:58] VERBOSE[22329] logger.c:     -- Executing [9005@default-local-devices:1] Set("Local/9005@default-agent-c6fe,2", "DB(default/wrapup/9005/lastcall)=1215530698.113") in new stack
[Jul  8 17:24:58] DEBUG[22329] pbx.c: Launching 'Dial'
[Jul  8 17:24:58] VERBOSE[22329] logger.c:     -- Executing [9005@default-local-devices:2] Dial("Local/9005@default-agent-c6fe,2", "SIP/9005||t") in new stack
[Jul  8 17:24:58] DEBUG[22329] chan_sip.c: Asked to create a SIP channel with formats: 0x8 (alaw)
[Jul  8 17:24:58] DEBUG[22329] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Jul  8 17:24:58] DEBUG[22329] chan_sip.c: Setting NAT on RTP to Off
[Jul  8 17:24:58] DEBUG[22329] chan_sip.c: *** Our native formats are 0x8 (alaw)
[Jul  8 17:24:58] DEBUG[22329] chan_sip.c: *** Joint capabilities are 0x0 (nothing)
[Jul  8 17:24:58] DEBUG[22329] chan_sip.c: *** Our capabilities are 0x8 (alaw)
[Jul  8 17:24:58] DEBUG[22329] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x8 (alaw)
[Jul  8 17:24:58] DEBUG[22329] chan_sip.c: *** Our preferred formats from the incoming channel are 0x8 (alaw)
[Jul  8 17:24:58] DEBUG[22329] chan_sip.c: This channel will not be able to handle video.
[Jul  8 17:24:58] DEBUG[22329] rtp.c: Channel 'Local/9005@default-agent-c6fe,2' has no RTP, not doing anything
[Jul  8 17:24:58] DEBUG[22329] channel.c: Not copying variable AGENTMAXCALL.
[Jul  8 17:24:58] DEBUG[22329] channel.c: Not copying variable GROUPCOUNT.
[Jul  8 17:24:58] DEBUG[22329] channel.c: Not copying variable DND.
[Jul  8 17:24:58] DEBUG[22329] channel.c: Copying hard-transferable variable ALLOW_TRANSFER.
[Jul  8 17:24:58] DEBUG[22329] channel.c: Copying hard-transferable variable ACD_TO_OUTGOING.
[Jul  8 17:24:58] DEBUG[22329] channel.c: Copying hard-transferable variable QUEUENAME.
[Jul  8 17:24:58] DEBUG[22329] chan_sip.c: Outgoing Call for 9005
[Jul  8 17:24:58] DEBUG[22329] chan_sip.c: Updating call counter for outgoing call
[Jul  8 17:24:58] DEBUG[22329] chan_sip.c: Call to peer '9005' is 1 out of 16
[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:24:58] VERBOSE[22329] logger.c:     -- Called 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[29823] chan_sip.c: = No match Their Call ID: 02ef1ea82eb4c2e23b3808c43c19d1b8@192.168.21.203 Their Tag  Our tag: as4eef6f44
[Jul  8 17:24:58] DEBUG[29823] chan_sip.c: = No match Their Call ID: 043b140646b05f5566ed54b563ba84ad@172.17.0.200 Their Tag  Our tag: as02b29eda
[Jul  8 17:24:58] DEBUG[29823] chan_sip.c: = No match Their Call ID: 3c2fcacbd1f6-lp0yipjq94ag@snom300-0004132853BA Their Tag v6etp8u5u5 Our tag: as4d32d693
[Jul  8 17:24:58] DEBUG[29823] chan_sip.c: = No match Their Call ID: 3c26700d7ef4-ps3y5dvpx10v@snom300-00041325D78A Their Tag 4q83n4ijgi Our tag: as4cf4b9e9
[Jul  8 17:24:58] DEBUG[29823] chan_sip.c: = No match Their Call ID: 3c26700d72bf-0qfq3azp1tku@snom300-0004132574EB Their Tag 2kylud1t3o Our tag: as2bc154da
[Jul  8 17:24:58] DEBUG[29823] chan_sip.c: = Found Their Call ID: 121d4d71-df4be8b3-79b0d8bc@192.168.21.238 Their Tag 36359425-C942AE06 Our tag: as46d76742
[Jul  8 17:24:58] DEBUG[29823] chan_sip.c: Acked pending invite 114
[Jul  8 17:24:58] DEBUG[29823] chan_sip.c: Stopping retransmission on '121d4d71-df4be8b3-79b0d8bc@192.168.21.238' of Request 114: Match Found
[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[29823] chan_sip.c: = Found Their Call ID: 02ef1ea82eb4c2e23b3808c43c19d1b8@192.168.21.203 Their Tag  Our tag: as4eef6f44
[Jul  8 17:24:58] DEBUG[29823] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '02ef1ea82eb4c2e23b3808c43c19d1b8@192.168.21.203' Request 102: Found
[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[29823] chan_sip.c: SIP response 180 to standard invite
[Jul  8 17:24:58] DEBUG[29823] devicestate.c: Notification of state change to be queued on device/channel SIP/9005-083658e0
[Jul  8 17:24:58] DEBUG[29819] devicestate.c: No provider found, checking channel drivers for SIP - 9005-083658e0
[Jul  8 17:24:58] DEBUG[29819] chan_sip.c: Checking device state for peer 9005-083658e0
[Jul  8 17:24:58] DEBUG[29823] devicestate.c: Notification of state change to be queued on device/channel SIP/9005
[Jul  8 17:24:58] VERBOSE[22329] logger.c:     -- SIP/9005-083658e0 is ringing
[Jul  8 17:24:58] DEBUG[22329] rtp.c: Channel 'Local/9005@default-agent-c6fe,2' has no RTP, not doing anything
[Jul  8 17:24:58] DEBUG[29819] devicestate.c: Changing state for SIP/9005-083658e0 - state 4 (Invalid)
[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[29853] app_queue.c: Device 'SIP/9005-083658e0' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
[Jul  8 17:24:58] DEBUG[29853] app_queue.c: Device 'SIP/9005' changed to state '6' (Ringing)
[Jul  8 17:24:58] VERBOSE[22266] logger.c:     -- Local/9005@default-agent-c6fe,1 is ringing
[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[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[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[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[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[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[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[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[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[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[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[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[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[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[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[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[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[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[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[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[Jul  8 17:24:58] DEBUG[22266] rtp.c: Got RTCP report of 52 bytes
[Jul  8 17:24:59] DEBUG[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[Jul  8 17:24:59] DEBUG[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[Jul  8 17:24:59] DEBUG[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[Jul  8 17:24:59] DEBUG[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[Jul  8 17:24:59] DEBUG[29823] chan_sip.c: = Found Their Call ID: 02ef1ea82eb4c2e23b3808c43c19d1b8@192.168.21.203 Their Tag kcuqp5v171 Our tag: as4eef6f44
[Jul  8 17:24:59] DEBUG[29823] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '02ef1ea82eb4c2e23b3808c43c19d1b8@192.168.21.203' Request 102: Found
[Jul  8 17:24:59] DEBUG[29823] chan_sip.c: SIP response 180 to standard invite
[Jul  8 17:24:59] VERBOSE[22329] logger.c:     -- SIP/9005-083658e0 is ringing
[Jul  8 17:24:59] DEBUG[22329] rtp.c: Channel 'Local/9005@default-agent-c6fe,2' has no RTP, not doing anything
[Jul  8 17:24:59] DEBUG[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[Jul  8 17:24:59] DEBUG[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[Jul  8 17:24:59] DEBUG[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[Jul  8 17:24:59] DEBUG[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[Jul  8 17:24:59] DEBUG[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[Jul  8 17:24:59] DEBUG[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[Jul  8 17:24:59] DEBUG[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[Jul  8 17:24:59] DEBUG[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[Jul  8 17:24:59] DEBUG[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[Jul  8 17:24:59] DEBUG[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[Jul  8 17:24:59] DEBUG[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[Jul  8 17:24:59] DEBUG[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[Jul  8 17:24:59] DEBUG[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[Jul  8 17:24:59] DEBUG[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[Jul  8 17:24:59] DEBUG[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[Jul  8 17:24:59] DEBUG[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[Jul  8 17:24:59] DEBUG[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[Jul  8 17:24:59] DEBUG[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[Jul  8 17:24:59] DEBUG[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[Jul  8 17:24:59] DEBUG[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[Jul  8 17:24:59] DEBUG[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[Jul  8 17:24:59] DEBUG[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[Jul  8 17:24:59] DEBUG[29823] chan_sip.c: Destroying SIP dialog 043b140646b05f5566ed54b563ba84ad@172.17.0.200
[Jul  8 17:24:59] VERBOSE[29823] logger.c: Really destroying SIP dialog '043b140646b05f5566ed54b563ba84ad@172.17.0.200' Method: OPTIONS
[Jul  8 17:24:59] DEBUG[29823] devicestate.c: Notification of state change to be queued on device/channel SIP/5099
[Jul  8 17:24:59] DEBUG[29819] devicestate.c: No provider found, checking channel drivers for SIP - 5099
[Jul  8 17:24:59] DEBUG[29819] chan_sip.c: Checking device state for peer 5099
[Jul  8 17:24:59] DEBUG[29819] devicestate.c: Changing state for SIP/5099 - state 5 (Unavailable)
[Jul  8 17:24:59] DEBUG[29853] app_queue.c: Device 'SIP/5099' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue.
[Jul  8 17:24:59] DEBUG[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[Jul  8 17:24:59] DEBUG[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[Jul  8 17:24:59] DEBUG[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[Jul  8 17:24:59] DEBUG[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[Jul  8 17:24:59] DEBUG[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[Jul  8 17:24:59] DEBUG[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[Jul  8 17:24:59] DEBUG[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[Jul  8 17:24:59] DEBUG[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[Jul  8 17:24:59] DEBUG[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[Jul  8 17:24:59] DEBUG[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[Jul  8 17:24:59] DEBUG[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[Jul  8 17:24:59] DEBUG[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)
[Jul  8 17:24:59] DEBUG[22266] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=66)