[Jul  8 17:35:56] DEBUG[5971] pbx.c: Function result is ''
[Jul  8 17:35:56] DEBUG[5971] pbx.c: Launching 'NoOp'
[Jul  8 17:35:56] VERBOSE[5971] logger.c:     -- Executing [0821@default-9000-incoming:3] NoOp("SIP/9000-08874ce0", ""INCOMING CALL FROM CALLER ID: 0117972050 ()"") in new stack
[Jul  8 17:35:56] DEBUG[5971] pbx.c: Launching 'Set'
[Jul  8 17:35:56] VERBOSE[5971] logger.c:     -- Executing [0821@default-9000-incoming:4] Set("SIP/9000-08874ce0", "__INCOMING_DNIS=0821") in new stack
[Jul  8 17:35:56] DEBUG[5971] pbx.c: Launching 'Set'
[Jul  8 17:35:56] VERBOSE[5971] logger.c:     -- Executing [0821@default-9000-incoming:5] Set("SIP/9000-08874ce0", "CDR(userfield)=0821") in new stack
[Jul  8 17:35:56] DEBUG[5971] pbx.c: Launching 'Goto'
[Jul  8 17:35:56] VERBOSE[5971] logger.c:     -- Executing [0821@default-9000-incoming:6] Goto("SIP/9000-08874ce0", "10") in new stack
[Jul  8 17:35:56] VERBOSE[5971] logger.c:     -- Goto (default-9000-incoming,0821,10)
[Jul  8 17:35:56] DEBUG[5971] pbx.c: Launching 'AGI'
[Jul  8 17:35:56] VERBOSE[5971] logger.c:     -- Executing [0821@default-9000-incoming:10] AGI("SIP/9000-08874ce0", "/var/www/scopserv/telephony/scripts/agi/fixcidname.php") in new stack
[Jul  8 17:35:56] VERBOSE[5971] logger.c:     -- Launched AGI Script /var/www/scopserv/telephony/scripts/agi/fixcidname.php
[Jul  8 17:35:56] DEBUG[8924] chan_sip.c: Stopping retransmission on 'call-71D38FC5-0B2F-2B10-040B-CECE@192.168.0.2' of Response 2: Match Found
[Jul  8 17:35:56] VERBOSE[5971] logger.c:     -- AGI Script /var/www/scopserv/telephony/scripts/agi/fixcidname.php completed, returning 0
[Jul  8 17:35:56] DEBUG[5971] pbx.c: Launching 'Set'
[Jul  8 17:35:56] VERBOSE[5971] logger.c:     -- Executing [0821@default-9000-incoming:11] Set("SIP/9000-08874ce0", "CALLFILENAME=1215531356.39") in new stack
[Jul  8 17:35:56] DEBUG[5971] pbx.c: Launching 'MixMonitor'
[Jul  8 17:35:56] VERBOSE[5971] logger.c:     -- Executing [0821@default-9000-incoming:12] MixMonitor("SIP/9000-08874ce0", "1215531356.39.WAV|b") in new stack
[Jul  8 17:35:56] DEBUG[5971] pbx.c: Launching 'Set'
[Jul  8 17:35:56] VERBOSE[5971] logger.c:     -- Executing [0821@default-9000-incoming:13] Set("SIP/9000-08874ce0", "__INCOMINGLINE=1") in new stack
[Jul  8 17:35:56] DEBUG[5971] pbx.c: Function result is '0117972050'
[Jul  8 17:35:56] DEBUG[5971] pbx.c: Expression result is '0'
[Jul  8 17:35:56] DEBUG[5971] pbx.c: Launching 'GotoIf'
[Jul  8 17:35:56] VERBOSE[5971] logger.c:     -- Executing [0821@default-9000-incoming:14] GotoIf("SIP/9000-08874ce0", "0?15:16") in new stack
[Jul  8 17:35:56] VERBOSE[5971] logger.c:     -- Goto (default-9000-incoming,0821,16)
[Jul  8 17:35:56] DEBUG[5971] pbx.c: Launching 'Set'
[Jul  8 17:35:56] VERBOSE[5971] logger.c:     -- Executing [0821@default-9000-incoming:16] Set("SIP/9000-08874ce0", "CHANNEL(language)=en") in new stack
[Jul  8 17:35:56] DEBUG[5971] pbx.c: Launching 'Goto'
[Jul  8 17:35:56] VERBOSE[5971] logger.c:     -- Executing [0821@default-9000-incoming:17] Goto("SIP/9000-08874ce0", "default-application-acd-spares_department|s|1") in new stack
[Jul  8 17:35:56] VERBOSE[5971] logger.c:     -- Goto (default-application-acd-spares_department,s,1)
[Jul  8 17:35:56] DEBUG[5971] pbx.c: Launching 'NoOp'
[Jul  8 17:35:56] VERBOSE[5971] logger.c:     -- Executing [s@default-application-acd-spares_department:1] NoOp("SIP/9000-08874ce0", ""=== START QUEUE (default-spares_department) ==="") in new stack
[Jul  8 17:35:56] DEBUG[5971] pbx.c: Launching 'Set'
[Jul  8 17:35:56] VERBOSE[5971] logger.c:     -- Executing [s@default-application-acd-spares_department:2] Set("SIP/9000-08874ce0", "__QUEUENAME=default-spares_department") in new stack
[Jul  8 17:35:56] DEBUG[5971] pbx.c: Launching 'Set'
[Jul  8 17:35:56] VERBOSE[5971] logger.c:     -- Executing [s@default-application-acd-spares_department:3] Set("SIP/9000-08874ce0", "TIMEOUT(digit)=1") in new stack
[Jul  8 17:35:56] VERBOSE[5971] logger.c:     -- Digit timeout set to 1
[Jul  8 17:35:56] DEBUG[5971] pbx.c: Launching 'Set'
[Jul  8 17:35:56] VERBOSE[5971] logger.c:     -- Executing [s@default-application-acd-spares_department:4] Set("SIP/9000-08874ce0", "TIMEOUT(response)=1") in new stack
[Jul  8 17:35:56] VERBOSE[5971] logger.c:     -- Response timeout set to 1
[Jul  8 17:35:56] DEBUG[5971] pbx.c: Launching 'Set'
[Jul  8 17:35:56] VERBOSE[5971] logger.c:     -- Executing [s@default-application-acd-spares_department:5] Set("SIP/9000-08874ce0", "QUEUE_PRIO=0") in new stack
[Jul  8 17:35:56] DEBUG[5971] pbx.c: Launching 'Set'
[Jul  8 17:35:56] VERBOSE[5971] logger.c:     -- Executing [s@default-application-acd-spares_department:6] Set("SIP/9000-08874ce0", "__ACD_TO_OUTGOING=1") in new stack
[Jul  8 17:35:56] DEBUG[5971] pbx.c: Launching 'Set'
[Jul  8 17:35:56] VERBOSE[5971] logger.c:     -- Executing [s@default-application-acd-spares_department:7] Set("SIP/9000-08874ce0", "CHANNEL(musicclass)=default") in new stack
[Jul  8 17:35:56] DEBUG[5971] pbx.c: Launching 'Set'
[Jul  8 17:35:56] VERBOSE[5971] logger.c:     -- Executing [s@default-application-acd-spares_department:8] Set("SIP/9000-08874ce0", "__ALLOW_TRANSFER=t") in new stack
[Jul  8 17:35:56] DEBUG[5971] pbx.c: Launching 'Queue'
[Jul  8 17:35:56] VERBOSE[5971] logger.c:     -- Executing [s@default-application-acd-spares_department:9] Queue("SIP/9000-08874ce0", "default-spares_department|t|||900") in new stack
[Jul  8 17:35:56] DEBUG[5971] app_queue.c: SIP/9000-08874ce0: Got priority 0 from ${QUEUE_PRIO}.
[Jul  8 17:35:56] DEBUG[5971] app_queue.c: queue: default-spares_department, options: t, url: , announce: , expires: 1215532256, priority: 0
[Jul  8 17:35:56] DEBUG[5971] app_queue.c: Queue default-spares_department has no realtime members defined. No need for update
[Jul  8 17:35:56] DEBUG[5971] app_queue.c: Queue 'default-spares_department' Join, Channel 'SIP/9000-08874ce0', Position '1'
[Jul  8 17:35:56] DEBUG[5971] channel.c: Set channel SIP/9000-08874ce0 to write format slin
[Jul  8 17:35:56] VERBOSE[5971] logger.c:     -- Started music on hold, class 'default', on channel 'SIP/9000-08874ce0'
[Jul  8 17:35:56] DEBUG[5971] channel.c: Scheduling timer at 160 sample intervals
[Jul  8 17:35:56] DEBUG[5971] app_queue.c: There are 2 available members.
[Jul  8 17:35:56] DEBUG[5971] app_queue.c: It's our turn (SIP/9000-08874ce0).
[Jul  8 17:35:56] DEBUG[5971] app_queue.c: SIP/9000-08874ce0 is trying to call a queue member.
[Jul  8 17:35:56] DEBUG[5971] app_queue.c: Trying 'Local/1820@default-agent/n' with metric 0
[Jul  8 17:35:56] DEBUG[5971] channel.c: Copying hard-transferable variable ALLOW_TRANSFER.
[Jul  8 17:35:56] DEBUG[5971] channel.c: Copying hard-transferable variable ACD_TO_OUTGOING.
[Jul  8 17:35:56] DEBUG[5971] channel.c: Not copying variable QUEUE_PRIO.
[Jul  8 17:35:56] DEBUG[5971] channel.c: Copying hard-transferable variable QUEUENAME.
[Jul  8 17:35:56] DEBUG[5971] channel.c: Copying hard-transferable variable INCOMINGLINE.
[Jul  8 17:35:56] DEBUG[5971] channel.c: Not copying variable MIXMONITOR_FILENAME.
[Jul  8 17:35:56] DEBUG[5971] channel.c: Not copying variable CALLFILENAME.
[Jul  8 17:35:56] DEBUG[5971] channel.c: Not copying variable AGISTATUS.
[Jul  8 17:35:56] DEBUG[5971] channel.c: Copying hard-transferable variable INCOMING_DNIS.
[Jul  8 17:35:56] DEBUG[5971] channel.c: Not copying variable SIPCALLID.
[Jul  8 17:35:56] DEBUG[5971] channel.c: Not copying variable SIPUSERAGENT.
[Jul  8 17:35:56] DEBUG[5971] channel.c: Not copying variable SIPDOMAIN.
[Jul  8 17:35:56] DEBUG[5971] channel.c: Not copying variable SIPURI.
[Jul  8 17:35:56] DEBUG[5971] channel.c: Generator got voice, switching to phase locked mode
[Jul  8 17:35:56] DEBUG[5971] channel.c: Scheduling timer at 0 sample intervals
[Jul  8 17:35:56] VERBOSE[5979] logger.c:   == Begin MixMonitor Recording SIP/9000-08874ce0
[Jul  8 17:35:56] DEBUG[5980] pbx.c: Launching 'NoCDR'
[Jul  8 17:35:56] VERBOSE[5980] logger.c:     -- Executing [1820@default-agent:1] NoCDR("Local/1820@default-agent-60a9,2", "") in new stack
[Jul  8 17:35:56] DEBUG[5980] db.c: Unable to find key '1820/DoNotDisturb' in family 'default'
[Jul  8 17:35:56] DEBUG[5980] func_db.c: DB: default/1820/DoNotDisturb not found in database.
[Jul  8 17:35:56] DEBUG[5980] pbx.c: Function result is ''
[Jul  8 17:35:56] DEBUG[5980] pbx.c: Launching 'Set'
[Jul  8 17:35:56] VERBOSE[5980] logger.c:     -- Executing [1820@default-agent:2] Set("Local/1820@default-agent-60a9,2", "DND=") in new stack
[Jul  8 17:35:56] DEBUG[5980] pbx.c: Expression result is '0'
[Jul  8 17:35:56] DEBUG[5980] pbx.c: Launching 'GotoIf'
[Jul  8 17:35:56] VERBOSE[5980] logger.c:     -- Executing [1820@default-agent:3] GotoIf("Local/1820@default-agent-60a9,2", "0?20") in new stack
[Jul  8 17:35:56] DEBUG[5980] pbx.c: Not taking any branch
[Jul  8 17:35:56] DEBUG[5980] pbx.c: Function result is '0'
[Jul  8 17:35:56] DEBUG[5980] pbx.c: Function result is '0'
[Jul  8 17:35:56] DEBUG[5980] pbx.c: Expression result is '0'
[Jul  8 17:35:56] DEBUG[5980] pbx.c: Launching 'Set'
[Jul  8 17:35:56] VERBOSE[5980] logger.c:     -- Executing [1820@default-agent:4] Set("Local/1820@default-agent-60a9,2", "GROUPCOUNT=0") in new stack
[Jul  8 17:35:56] DEBUG[5980] db.c: Unable to find key 'agent/1820/maxcalls' in family 'default'
[Jul  8 17:35:56] DEBUG[5980] func_db.c: DB: default/agent/1820/maxcalls not found in database.
[Jul  8 17:35:56] DEBUG[5980] pbx.c: Function result is ''
[Jul  8 17:35:56] DEBUG[5980] pbx.c: Launching 'Set'
[Jul  8 17:35:56] VERBOSE[5980] logger.c:     -- Executing [1820@default-agent:5] Set("Local/1820@default-agent-60a9,2", "AGENTMAXCALL=") in new stack
[Jul  8 17:35:56] DEBUG[5980] pbx.c: Expression result is '1'
[Jul  8 17:35:56] DEBUG[5980] pbx.c: Expression result is '7'
[Jul  8 17:35:56] DEBUG[5980] pbx.c: Expression result is '8'
[Jul  8 17:35:56] DEBUG[5980] pbx.c: Launching 'GotoIf'
[Jul  8 17:35:56] VERBOSE[5980] logger.c:     -- Executing [1820@default-agent:6] GotoIf("Local/1820@default-agent-60a9,2", "1?7:8") in new stack
[Jul  8 17:35:56] VERBOSE[5980] logger.c:     -- Goto (default-agent,1820,7)
[Jul  8 17:35:56] DEBUG[5980] pbx.c: Launching 'Set'
[Jul  8 17:35:56] VERBOSE[5980] logger.c:     -- Executing [1820@default-agent:7] Set("Local/1820@default-agent-60a9,2", "AGENTMAXCALL=1") in new stack
[Jul  8 17:35:56] DEBUG[5980] pbx.c: Expression result is '0'
[Jul  8 17:35:56] DEBUG[5980] pbx.c: Launching 'GotoIf'
[Jul  8 17:35:56] VERBOSE[5980] logger.c:     -- Executing [1820@default-agent:8] GotoIf("Local/1820@default-agent-60a9,2", "0?20") in new stack
[Jul  8 17:35:56] DEBUG[5980] pbx.c: Not taking any branch
[Jul  8 17:35:56] DEBUG[5980] pbx.c: Expression result is '1'
[Jul  8 17:35:56] DEBUG[5980] pbx.c: Expression result is '12'
[Jul  8 17:35:56] DEBUG[5980] pbx.c: Launching 'GotoIf'
[Jul  8 17:35:56] VERBOSE[5980] logger.c:     -- Executing [1820@default-agent:9] GotoIf("Local/1820@default-agent-60a9,2", "1?12") in new stack
[Jul  8 17:35:56] VERBOSE[5980] logger.c:     -- Goto (default-agent,1820,12)
[Jul  8 17:35:56] DEBUG[5980] pbx.c: Launching 'Set'
[Jul  8 17:35:56] VERBOSE[5980] logger.c:     -- Executing [1820@default-agent:12] Set("Local/1820@default-agent-60a9,2", "OUTBOUND_GROUP_ONCE=1820@INCOMING") in new stack
[Jul  8 17:35:56] DEBUG[5980] pbx.c: Launching 'Set'
[Jul  8 17:35:56] VERBOSE[5980] logger.c:     -- Executing [1820@default-agent:13] Set("Local/1820@default-agent-60a9,2", "DB(default/wrapup/1820/lastcall)=1215531356.41") in new stack
[Jul  8 17:35:56] DEBUG[5979] audiohook.c: Failed to get 160 samples from write factory 0x8844be4
[Jul  8 17:35:57] DEBUG[5971] audiohook.c: Flushing audiohook 0x88440b0 so it remains in sync
[Jul  8 17:35:57] DEBUG[5971] rtp.c: Ooh, format changed from unknown to alaw
[Jul  8 17:35:57] DEBUG[5979] audiohook.c: Read factory 0x88441c8 was pretty quick last time, waiting for them.
[Jul  8 17:35:57] DEBUG[5971] rtp.c: Created smoother: format: 8 ms: 20 len: 160
[Jul  8 17:35:57] DEBUG[5980] pbx.c: Launching 'Goto'
[Jul  8 17:35:57] VERBOSE[5980] logger.c:     -- Executing [1820@default-agent:14] Goto("Local/1820@default-agent-60a9,2", "default-local-devices|1820|1") in new stack
[Jul  8 17:35:57] VERBOSE[5980] logger.c:     -- Goto (default-local-devices,1820,1)
[Jul  8 17:35:57] DEBUG[5980] pbx.c: Launching 'Set'
[Jul  8 17:35:57] VERBOSE[5980] logger.c:     -- Executing [1820@default-local-devices:1] Set("Local/1820@default-agent-60a9,2", "DB(default/wrapup/1820/lastcall)=1215531356.41") in new stack
[Jul  8 17:35:57] DEBUG[5980] pbx.c: Launching 'Dial'
[Jul  8 17:35:57] VERBOSE[5980] logger.c:     -- Executing [1820@default-local-devices:2] Dial("Local/1820@default-agent-60a9,2", "SIP/1820||t") in new stack
[Jul  8 17:35:57] DEBUG[5980] chan_sip.c: Asked to create a SIP channel with formats: 0x8 (alaw)
[Jul  8 17:35:57] DEBUG[5980] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Jul  8 17:35:57] DEBUG[5980] chan_sip.c: Setting NAT on RTP to Off
[Jul  8 17:35:57] DEBUG[5980] chan_sip.c: *** Our native formats are 0x8 (alaw)
[Jul  8 17:35:57] DEBUG[5980] chan_sip.c: *** Joint capabilities are 0x0 (nothing)
[Jul  8 17:35:57] DEBUG[5980] chan_sip.c: *** Our capabilities are 0xa (gsm|alaw)
[Jul  8 17:35:57] DEBUG[5980] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x8 (alaw)
[Jul  8 17:35:57] DEBUG[5980] chan_sip.c: *** Our preferred formats from the incoming channel are 0x8 (alaw)
[Jul  8 17:35:57] DEBUG[5980] chan_sip.c: This channel will not be able to handle video.
[Jul  8 17:35:57] DEBUG[5980] rtp.c: Channel 'Local/1820@default-agent-60a9,2' has no RTP, not doing anything
[Jul  8 17:35:57] DEBUG[5980] channel.c: Not copying variable AGENTMAXCALL.
[Jul  8 17:35:57] DEBUG[5980] channel.c: Not copying variable GROUPCOUNT.
[Jul  8 17:35:57] DEBUG[5980] channel.c: Not copying variable DND.
[Jul  8 17:35:57] DEBUG[5980] channel.c: Copying hard-transferable variable ALLOW_TRANSFER.
[Jul  8 17:35:57] DEBUG[5980] channel.c: Copying hard-transferable variable ACD_TO_OUTGOING.
[Jul  8 17:35:57] DEBUG[5980] channel.c: Copying hard-transferable variable QUEUENAME.
[Jul  8 17:35:57] DEBUG[5980] channel.c: Copying hard-transferable variable INCOMINGLINE.
[Jul  8 17:35:57] DEBUG[5980] channel.c: Copying hard-transferable variable INCOMING_DNIS.
[Jul  8 17:35:57] DEBUG[5980] chan_sip.c: Outgoing Call for 1820
[Jul  8 17:35:57] DEBUG[5980] chan_sip.c: Updating call counter for outgoing call
[Jul  8 17:35:57] DEBUG[5980] chan_sip.c: Call to peer '1820' is 1 out of 4
[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@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@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@default-agent-60a9,2' has no RTP, not doing anything
[Jul  8 17:35:57] VERBOSE[5971] logger.c:     -- Local/1820@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.