[Dec  4 14:25:09] DEBUG[13459]: chan_sip.c:11268 handle_request: **** Received INVITE (5) - Command in SIP INVITE
[Dec  4 14:25:09] DEBUG[13459]: chan_sip.c:1043 parse_sip_options: * SIP extension value: 7 for call 3c3901450753-c0ti47rilcr9@snom360-000413231E69
[Dec  4 14:25:09] DEBUG[13459]: chan_sip.c:7265 check_user_full: Setting NAT on RTP to 0
[Dec  4 14:25:09] DEBUG[13459]: chan_sip.c:3224 find_call: = Found Their Call ID: 3c3901450753-c0ti47rilcr9@snom360-000413231E69 Their Tag gw2q8wx7me Our tag: as1ff5e674
[Dec  4 14:25:09] DEBUG[13459]: chan_sip.c:11268 handle_request: **** Received ACK (6) - Command in SIP ACK
[Dec  4 14:25:09] DEBUG[13459]: chan_sip.c:1414 __sip_ack: Stopping retransmission on '3c3901450753-c0ti47rilcr9@snom360-000413231E69' of Response 1: Match Found
[Dec  4 14:25:09] DEBUG[13459]: chan_sip.c:3224 find_call: = Found Their Call ID: 3c3901450753-c0ti47rilcr9@snom360-000413231E69 Their Tag gw2q8wx7me Our tag: as1ff5e674
[Dec  4 14:25:09] DEBUG[13459]: chan_sip.c:11268 handle_request: **** Received INVITE (5) - Command in SIP INVITE
[Dec  4 14:25:09] DEBUG[13459]: chan_sip.c:7265 check_user_full: Setting NAT on RTP to 0
[Dec  4 14:25:09] DEBUG[13459]: chan_sip.c:10632 handle_request_invite: Checking SIP call limits for device snom3
[Dec  4 14:25:09] DEBUG[13459]: chan_sip.c:2220 update_call_counter: Updating call counter for incoming call
[Dec  4 14:25:09] DEBUG[13459]: chan_sip.c:6241 build_route: build_route: Contact hop: <sip:snom3@10.3.67.172:2051;line=42qrcm7o>;flow-id=1
[Dec  4 14:25:09] DEBUG[13453]: chan_sip.c:11810 sip_devicestate: Checking device state for peer snom3
[Dec  4 14:25:09] DEBUG[13453]: devicestate.c:187 do_state_change: Changing state for SIP/snom3 - state 2 (In use)
[Dec  4 14:25:09] DEBUG[13463]: pbx.c:1677 pbx_extension_helper: Launching 'Goto'
[Dec  4 14:25:09]     -- Executing Goto("SIP/snom3-081ae418", "edv|s|1") in new stack
[Dec  4 14:25:09]     -- Goto (edv,s,1)
[Dec  4 14:25:09] DEBUG[13463]: pbx.c:1677 pbx_extension_helper: Launching 'Set'
[Dec  4 14:25:09]     -- Executing Set("SIP/snom3-081ae418", "LANGUAGE()=de") in new stack
[Dec  4 14:25:09] DEBUG[13463]: pbx.c:1677 pbx_extension_helper: Launching 'Ringing'
[Dec  4 14:25:09]     -- Executing Ringing("SIP/snom3-081ae418", "") in new stack
[Dec  4 14:25:09] DEBUG[13463]: pbx.c:1677 pbx_extension_helper: Launching 'Wait'
[Dec  4 14:25:09]     -- Executing Wait("SIP/snom3-081ae418", "1") in new stack
[Dec  4 14:25:09] DEBUG[13464]: app_queue.c:500 changethread: Device 'SIP/snom3' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Dec  4 14:25:10] DEBUG[13463]: pbx.c:1677 pbx_extension_helper: Launching 'Answer'
[Dec  4 14:25:10]     -- Executing Answer("SIP/snom3-081ae418", "") in new stack
[Dec  4 14:25:10] DEBUG[13463]: chan_sip.c:2560 sip_answer: sip_answer(SIP/snom3-081ae418)
[Dec  4 14:25:10] DEBUG[13463]: pbx.c:1677 pbx_extension_helper: Launching 'Playback'
[Dec  4 14:25:10]     -- Executing Playback("SIP/snom3-081ae418", "edv") in new stack
[Dec  4 14:25:10] WARNING[13463]: file.c:512 ast_openstream_full: File edv does not exist in any format
[Dec  4 14:25:10] WARNING[13463]: file.c:824 ast_streamfile: Unable to open edv (format ulaw): No such file or directory
[Dec  4 14:25:10] WARNING[13463]: app_playback.c:133 playback_exec: ast_streamfile failed on SIP/snom3-081ae418 for edv
[Dec  4 14:25:10] DEBUG[13463]: pbx.c:1677 pbx_extension_helper: Launching 'SetCIDName'
[Dec  4 14:25:10]     -- Executing SetCIDName("SIP/snom3-081ae418", "Ueber Hotline") in new stack
[Dec  4 14:25:10] WARNING[13463]: app_setcidname.c:71 setcallerid_exec: SetCIDName is deprecated, please use Set(CALLERID(name)=value) instead.
[Dec  4 14:25:10] DEBUG[13463]: pbx.c:1677 pbx_extension_helper: Launching 'Queue'
[Dec  4 14:25:10]     -- Executing Queue("SIP/snom3-081ae418", "edv|tT|300") in new stack
[Dec  4 14:25:10] DEBUG[13463]: app_queue.c:3068 queue_exec: NO QUEUE_PRIO variable found. Using default.
[Dec  4 14:25:10] DEBUG[13463]: app_queue.c:3076 queue_exec: queue: edv, options: tT, url: 300, announce: (null), expires: 0, priority: 0
[Dec  4 14:25:10] DEBUG[13463]: app_queue.c:1170 join_queue: Queue 'edv' Join, Channel 'SIP/snom3-081ae418', Position '1'
[Dec  4 14:25:10] DEBUG[13463]: channel.c:2408 set_format: Set channel SIP/snom3-081ae418 to write format slin
[Dec  4 14:25:10]     -- Started music on hold, class 'default', on channel 'SIP/snom3-081ae418'
[Dec  4 14:25:10] DEBUG[13453]: chan_sip.c:11810 sip_devicestate: Checking device state for peer snom3
[Dec  4 14:25:10] DEBUG[13453]: devicestate.c:187 do_state_change: Changing state for SIP/snom3 - state 2 (In use)
[Dec  4 14:25:10] DEBUG[13463]: app_queue.c:2020 is_our_turn: It's our turn (SIP/snom3-081ae418).
[Dec  4 14:25:10] DEBUG[13463]: app_queue.c:2215 try_calling: SIP/snom3-081ae418 is trying to call a queue member.
[Dec  4 14:25:10] DEBUG[13463]: app_queue.c:2237 try_calling: Queue with URL=300_
[Dec  4 14:25:10] DEBUG[13463]: app_queue.c:2237 try_calling: Queue with URL=300_
[Dec  4 14:25:10] DEBUG[13463]: app_queue.c:2237 try_calling: Queue with URL=300_
[Dec  4 14:25:10] DEBUG[13463]: app_queue.c:1640 ring_one: Trying 'Agent/130' with metric 0
[Dec  4 14:25:10] DEBUG[13463]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-edv-s-7.
[Dec  4 14:25:10] DEBUG[13463]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-edv-s-6.
[Dec  4 14:25:10] DEBUG[13463]: channel.c:2902 ast_channel_inherit_variables: Not copying variable PLAYBACKSTATUS.
[Dec  4 14:25:10] DEBUG[13463]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-edv-s-5.
[Dec  4 14:25:10] DEBUG[13463]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-edv-s-4.
[Dec  4 14:25:10] DEBUG[13463]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-edv-s-3.
[Dec  4 14:25:10] DEBUG[13463]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-edv-s-2.
[Dec  4 14:25:10] DEBUG[13463]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-edv-s-1.
[Dec  4 14:25:10] DEBUG[13463]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-default-111-1.
[Dec  4 14:25:10] DEBUG[13463]: channel.c:2902 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[Dec  4 14:25:10] DEBUG[13463]: channel.c:2902 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT.
[Dec  4 14:25:10] DEBUG[13463]: channel.c:2902 ast_channel_inherit_variables: Not copying variable SIPDOMAIN.
[Dec  4 14:25:10] DEBUG[13463]: channel.c:2902 ast_channel_inherit_variables: Not copying variable SIPURI.
[Dec  4 14:25:10]     -- outgoing agentcall, to agent '130', on 'Local/106@default-5058,1'
[Dec  4 14:25:10]     -- Called Agent/130
[Dec  4 14:25:10] DEBUG[13453]: devicestate.c:187 do_state_change: Changing state for Local/106@default - state 2 (In use)
[Dec  4 14:25:10] DEBUG[13465]: app_queue.c:500 changethread: Device 'SIP/snom3' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Dec  4 14:25:10] DEBUG[13467]: app_queue.c:500 changethread: Device 'Local/106@default' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Dec  4 14:25:10] DEBUG[13466]: pbx.c:1677 pbx_extension_helper: Launching 'Dial'
[Dec  4 14:25:10]     -- Executing Dial("Local/106@default-5058,2", "SIP/snom2||tT") in new stack
[Dec  4 14:25:10] DEBUG[13466]: chan_sip.c:3176 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Dec  4 14:25:10] DEBUG[13466]: chan_sip.c:1888 create_addr_from_peer: Setting NAT on RTP to 0
[Dec  4 14:25:10] DEBUG[13466]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-default-106-1.
[Dec  4 14:25:10] DEBUG[13466]: chan_sip.c:2082 sip_call: Outgoing Call for snom2
[Dec  4 14:25:10] DEBUG[13466]: chan_sip.c:2220 update_call_counter: Updating call counter for outgoing call
[Dec  4 14:25:10]     -- Called snom2
[Dec  4 14:25:10] DEBUG[13459]: chan_sip.c:3224 find_call: = No match Their Call ID: 7ff012c46a7437e351171a284bdca8ab@10.3.67.195 Their Tag  Our tag: as7859fbeb
[Dec  4 14:25:10] DEBUG[13459]: chan_sip.c:3224 find_call: = Found Their Call ID: 3c3901450753-c0ti47rilcr9@snom360-000413231E69 Their Tag gw2q8wx7me Our tag: as310fcad7
[Dec  4 14:25:10] DEBUG[13459]: chan_sip.c:11268 handle_request: **** Received ACK (6) - Command in SIP ACK
[Dec  4 14:25:10] DEBUG[13459]: chan_sip.c:1414 __sip_ack: Stopping retransmission on '3c3901450753-c0ti47rilcr9@snom360-000413231E69' of Response 2: Match Found
[Dec  4 14:25:10] DEBUG[13463]: rtp.c:411 ast_rtcp_read: Got RTCP report of 52 bytes
[Dec  4 14:25:10] DEBUG[13459]: chan_sip.c:3224 find_call: = Found Their Call ID: 7ff012c46a7437e351171a284bdca8ab@10.3.67.195 Their Tag  Our tag: as7859fbeb
[Dec  4 14:25:10] DEBUG[13459]: chan_sip.c:1391 __sip_ack: Acked pending invite 102
[Dec  4 14:25:10] DEBUG[13459]: chan_sip.c:1414 __sip_ack: Stopping retransmission on '7ff012c46a7437e351171a284bdca8ab@10.3.67.195' of Request 102: Match Found
[Dec  4 14:25:10]     -- Got SIP response 302 "Moved Temporarily" back from 10.3.67.121
[Dec  4 14:25:10] DEBUG[13459]: chan_sip.c:9657 parse_moved_contact: Found 302 Redirect to extension '111'
[Dec  4 14:25:10]     -- Now forwarding Local/106@default-5058,2 to 'Local/111@default' (thanks to SIP/snom2-081b6a58)
[Dec  4 14:25:10] DEBUG[13453]: devicestate.c:187 do_state_change: Changing state for Local/111@default - state 2 (In use)
[Dec  4 14:25:10] DEBUG[13468]: app_queue.c:500 changethread: Device 'Local/111@default' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Dec  4 14:25:10] DEBUG[13466]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-default-106-1.
[Dec  4 14:25:10] DEBUG[13466]: channel.c:1367 ast_hangup: Hanging up channel 'SIP/snom2-081b6a58'
[Dec  4 14:25:10] DEBUG[13466]: chan_sip.c:2430 sip_hangup: Hangup call SIP/snom2-081b6a58, SIP callid 7ff012c46a7437e351171a284bdca8ab@10.3.67.195)
[Dec  4 14:25:10] DEBUG[13466]: chan_sip.c:2438 sip_hangup: update_call_counter(snom2) - decrement call limit counter
[Dec  4 14:25:10] DEBUG[13466]: chan_sip.c:2220 update_call_counter: Updating call counter for outgoing call
[Dec  4 14:25:10] DEBUG[13453]: chan_sip.c:11810 sip_devicestate: Checking device state for peer snom2
[Dec  4 14:25:10] DEBUG[13453]: devicestate.c:187 do_state_change: Changing state for SIP/snom2 - state 1 (Not in use)
[Dec  4 14:25:10] DEBUG[13470]: app_queue.c:500 changethread: Device 'SIP/snom2' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Dec  4 14:25:10] DEBUG[13469]: pbx.c:1677 pbx_extension_helper: Launching 'Goto'
[Dec  4 14:25:10]     -- Executing Goto("Local/111@default-f5e6,2", "edv|s|1") in new stack
[Dec  4 14:25:10]     -- Goto (edv,s,1)
[Dec  4 14:25:10] DEBUG[13469]: pbx.c:1677 pbx_extension_helper: Launching 'Set'
[Dec  4 14:25:10]     -- Executing Set("Local/111@default-f5e6,2", "LANGUAGE()=de") in new stack
[Dec  4 14:25:10] DEBUG[13469]: pbx.c:1677 pbx_extension_helper: Launching 'Ringing'
[Dec  4 14:25:10]     -- Executing Ringing("Local/111@default-f5e6,2", "") in new stack
[Dec  4 14:25:10]     -- Local/111@default-f5e6,1 is ringing
[Dec  4 14:25:10]     -- Agent/130 is ringing
[Dec  4 14:25:10] DEBUG[13469]: pbx.c:1677 pbx_extension_helper: Launching 'Wait'
[Dec  4 14:25:10]     -- Executing Wait("Local/111@default-f5e6,2", "1") in new stack
[Dec  4 14:25:10] DEBUG[13463]: channel.c:2030 ast_read: Auto-deactivating generator
[Dec  4 14:25:10] DEBUG[13463]: channel.c:2408 set_format: Set channel SIP/snom3-081ae418 to write format ulaw
[Dec  4 14:25:10]     -- Stopped music on hold on SIP/snom3-081ae418
[Dec  4 14:25:11] DEBUG[13469]: pbx.c:1677 pbx_extension_helper: Launching 'Answer'
[Dec  4 14:25:11]     -- Executing Answer("Local/111@default-f5e6,2", "") in new stack
[Dec  4 14:25:11] DEBUG[13469]: pbx.c:1677 pbx_extension_helper: Launching 'Playback'
[Dec  4 14:25:11]     -- Executing Playback("Local/111@default-f5e6,2", "edv") in new stack
[Dec  4 14:25:11] WARNING[13469]: file.c:512 ast_openstream_full: File edv does not exist in any format
[Dec  4 14:25:11] WARNING[13469]: file.c:824 ast_streamfile: Unable to open edv (format ulaw): No such file or directory
[Dec  4 14:25:11] WARNING[13469]: app_playback.c:133 playback_exec: ast_streamfile failed on Local/111@default-f5e6,2 for edv
[Dec  4 14:25:11] DEBUG[13469]: pbx.c:1677 pbx_extension_helper: Launching 'SetCIDName'
[Dec  4 14:25:11]     -- Executing SetCIDName("Local/111@default-f5e6,2", "Ueber Hotline") in new stack
[Dec  4 14:25:11] DEBUG[13469]: pbx.c:1677 pbx_extension_helper: Launching 'Queue'
[Dec  4 14:25:11]     -- Executing Queue("Local/111@default-f5e6,2", "edv|tT|300") in new stack
[Dec  4 14:25:11] DEBUG[13469]: app_queue.c:3068 queue_exec: NO QUEUE_PRIO variable found. Using default.
[Dec  4 14:25:11] DEBUG[13469]: app_queue.c:3076 queue_exec: queue: edv, options: tT, url: 300, announce: (null), expires: 0, priority: 0
[Dec  4 14:25:11] DEBUG[13469]: app_queue.c:1170 join_queue: Queue 'edv' Join, Channel 'Local/111@default-f5e6,2', Position '2'
[Dec  4 14:25:11] DEBUG[13469]: channel.c:2408 set_format: Set channel Local/111@default-f5e6,2 to write format slin
[Dec  4 14:25:11]     -- Started music on hold, class 'default', on channel 'Local/111@default-f5e6,2'
[Dec  4 14:25:11] DEBUG[13469]: app_queue.c:2024 is_our_turn: It's not our turn (Local/111@default-f5e6,2).
[Dec  4 14:25:11] DEBUG[13469]: channel.c:2408 set_format: Set channel Local/111@default-f5e6,2 to write format ulaw
[Dec  4 14:25:11]     -- Stopped music on hold on Local/111@default-f5e6,2
[Dec  4 14:25:11] DEBUG[13469]: channel.c:2408 set_format: Set channel Local/111@default-f5e6,2 to write format gsm
[Dec  4 14:25:11]     -- Playing 'queue-thereare' (language 'de')
[Dec  4 14:25:11]     -- Local/111@default-f5e6,1 answered Local/106@default-5058,2
[Dec  4 14:25:11] DEBUG[13463]: app_queue.c:1953 wait_for_answer: Dunno what to do with control type -1
[Dec  4 14:25:11]     -- Agent/130 answered SIP/snom3-081ae418
[Dec  4 14:25:11] DEBUG[13463]: app_queue.c:1673 store_next: Next is 'Agent/129' with metric 1
[Dec  4 14:25:11] DEBUG[13463]: app_queue.c:2401 try_calling: app_queue: sendurl=300.
[Dec  4 14:25:11] WARNING[13463]: chan_local.c:146 local_queue_frame: Local/106@default-5058,1 wasn't locked while sending 9/1
[Dec  4 14:25:11] DEBUG[13466]: channel.c:2834 ast_channel_masquerade: Planning to masquerade channel Local/111@default-f5e6,1 into the structure of Local/106@default-5058,1
[Dec  4 14:25:11] DEBUG[13466]: channel.c:2847 ast_channel_masquerade: Done planning to masquerade channel Local/111@default-f5e6,1 into the structure of Local/106@default-5058,1
[Dec  4 14:25:11] DEBUG[13466]: chan_local.c:262 local_write: Not posting to queue since already masked on 'Local/106@default-5058,2'
[Dec  4 14:25:11] DEBUG[13453]: devicestate.c:187 do_state_change: Changing state for Local/111@default - state 2 (In use)
[Dec  4 14:25:11] DEBUG[13453]: devicestate.c:187 do_state_change: Changing state for Local/111@default - state 2 (In use)
[Dec  4 14:25:11] DEBUG[13453]: devicestate.c:187 do_state_change: Changing state for Local/106@default - state 2 (In use)
[Dec  4 14:25:11] DEBUG[13463]: channel.c:2961 ast_do_masquerade: Actually Masquerading Local/111@default-f5e6,1(6) into the structure of Local/106@default-5058,1(6)
[Dec  4 14:25:11] DEBUG[13463]: channel.c:2972 ast_do_masquerade: Got clone lock for masquerade on 'Local/111@default-f5e6,1' at 0x81bc4e4
[Dec  4 14:25:11] DEBUG[13463]: channel.c:3154 ast_do_masquerade: Putting channel Local/111@default-f5e6,1 in 4/4 formats
[Dec  4 14:25:11] DEBUG[13463]: channel.c:3189 ast_do_masquerade: Released clone lock on 'Local/106@default-5058,1<ZOMBIE>'
[Dec  4 14:25:11] DEBUG[13463]: channel.c:3198 ast_do_masquerade: Done Masquerading Local/111@default-f5e6,1 (6)
[Dec  4 14:25:11] DEBUG[13466]: channel.c:3578 ast_channel_bridge: Bridge stops because we're zombie or need a soft hangup: c0=Local/106@default-5058,2, c1=Local/106@default-5058,1<ZOMBIE>, flags: No,No,Yes,Yes
[Dec  4 14:25:11] DEBUG[13466]: channel.c:3669 ast_channel_bridge: Bridge stops bridging channels Local/106@default-5058,2 and Local/106@default-5058,1<ZOMBIE>
[Dec  4 14:25:11] DEBUG[13466]: channel.c:1372 ast_hangup: Hanging up zombie 'Local/106@default-5058,1<ZOMBIE>'
[Dec  4 14:25:11] DEBUG[13466]: app_dial.c:1636 dial_exec_full: Exiting with DIALSTATUS=ANSWER.
[Dec  4 14:25:11] DEBUG[13466]: pbx.c:2316 __ast_pbx_run: Spawn extension (default,106,1) exited non-zero on 'Local/106@default-5058,2'
[Dec  4 14:25:11]   == Spawn extension (default, 106, 1) exited non-zero on 'Local/106@default-5058,2'
[Dec  4 14:25:11] DEBUG[13466]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '"Ueber Hotline" <snom3>'
[Dec  4 14:25:11] DEBUG[13466]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'snom3'
[Dec  4 14:25:11] DEBUG[13466]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '106'
[Dec  4 14:25:11] DEBUG[13466]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'default'
[Dec  4 14:25:11] DEBUG[13466]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'Local/106@default-5058,2'
[Dec  4 14:25:11] DEBUG[13466]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'Local/111@default-f5e6,1'
[Dec  4 14:25:11] DEBUG[13466]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'Dial'
[Dec  4 14:25:11] DEBUG[13466]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'SIP/snom2||tT'
[Dec  4 14:25:11] DEBUG[13466]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-12-04 14:25:10'
[Dec  4 14:25:11] DEBUG[13466]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-12-04 14:25:11'
[Dec  4 14:25:11] DEBUG[13466]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-12-04 14:25:11'
[Dec  4 14:25:11] DEBUG[13466]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '1'
[Dec  4 14:25:11] DEBUG[13466]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '0'
[Dec  4 14:25:11] DEBUG[13466]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'ANSWERED'
[Dec  4 14:25:11] DEBUG[13466]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION'
[Dec  4 14:25:11] DEBUG[13466]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)'
[Dec  4 14:25:11] DEBUG[13466]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '1165238710.2'
[Dec  4 14:25:11] DEBUG[13466]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)'
[Dec  4 14:25:11] DEBUG[13466]: channel.c:1367 ast_hangup: Hanging up channel 'Local/106@default-5058,2'
[Dec  4 14:25:11] DEBUG[13471]: app_queue.c:500 changethread: Device 'Local/111@default' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Dec  4 14:25:11] DEBUG[13472]: app_queue.c:500 changethread: Device 'Local/111@default' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Dec  4 14:25:11] DEBUG[13473]: app_queue.c:500 changethread: Device 'Local/106@default' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Dec  4 14:25:11] DEBUG[13453]: devicestate.c:187 do_state_change: Changing state for Agent/130 - state 3 (Busy)
[Dec  4 14:25:11] DEBUG[13453]: devicestate.c:187 do_state_change: Changing state for Local/106@default - state 0 (Unknown)
[Dec  4 14:25:11] DEBUG[13453]: devicestate.c:187 do_state_change: Changing state for Local/106@default - state 0 (Unknown)
[Dec  4 14:25:11] DEBUG[13453]: devicestate.c:187 do_state_change: Changing state for Local/106@default - state 0 (Unknown)
[Dec  4 14:25:11] DEBUG[13463]: rtp.c:1361 ast_rtp_write: Ooh, format changed from unknown to ulaw
[Dec  4 14:25:11] DEBUG[13474]: app_queue.c:506 changethread: Device 'Agent/130' changed to state '3' (Busy)
[Dec  4 14:25:11] DEBUG[13475]: app_queue.c:500 changethread: Device 'Local/106@default' changed to state '0' (Unknown) but we don't care because they're not a member of any queue.
[Dec  4 14:25:11] DEBUG[13476]: app_queue.c:500 changethread: Device 'Local/106@default' changed to state '0' (Unknown) but we don't care because they're not a member of any queue.
[Dec  4 14:25:11] DEBUG[13477]: app_queue.c:500 changethread: Device 'Local/106@default' changed to state '0' (Unknown) but we don't care because they're not a member of any queue.
[Dec  4 14:25:11] DEBUG[13463]: rtp.c:411 ast_rtcp_read: Got RTCP report of 52 bytes
[Dec  4 14:25:12] DEBUG[13463]: rtp.c:411 ast_rtcp_read: Got RTCP report of 52 bytes
[Dec  4 14:25:13] DEBUG[13469]: channel.c:2408 set_format: Set channel Local/111@default-f5e6,2 to write format ulaw
[Dec  4 14:25:13] DEBUG[13469]: channel.c:2408 set_format: Set channel Local/111@default-f5e6,2 to write format gsm
[Dec  4 14:25:13]     -- Playing 'digits/1' (language 'de')
[Dec  4 14:25:14] DEBUG[13463]: rtp.c:411 ast_rtcp_read: Got RTCP report of 52 bytes
[Dec  4 14:25:14] DEBUG[13469]: channel.c:2408 set_format: Set channel Local/111@default-f5e6,2 to write format ulaw
[Dec  4 14:25:14] DEBUG[13469]: channel.c:2408 set_format: Set channel Local/111@default-f5e6,2 to write format gsm
[Dec  4 14:25:14]     -- Playing 'queue-callswaiting' (language 'de')
[Dec  4 14:25:15] DEBUG[13463]: rtp.c:411 ast_rtcp_read: Got RTCP report of 52 bytes
[Dec  4 14:25:16] DEBUG[13469]: channel.c:2408 set_format: Set channel Local/111@default-f5e6,2 to write format ulaw
[Dec  4 14:25:16]     -- Hold time for edv is 0 minutes 0 seconds
[Dec  4 14:25:16]     -- Told Local/111@default-f5e6,2 in edv their queue position (which was 1)
[Dec  4 14:25:16] DEBUG[13469]: channel.c:2408 set_format: Set channel Local/111@default-f5e6,2 to write format gsm
[Dec  4 14:25:16]     -- Playing 'queue-thankyou' (language 'de')
[Dec  4 14:25:16] DEBUG[13463]: rtp.c:411 ast_rtcp_read: Got RTCP report of 52 bytes
[Dec  4 14:25:17] DEBUG[13463]: rtp.c:411 ast_rtcp_read: Got RTCP report of 52 bytes
[Dec  4 14:25:17] DEBUG[13469]: channel.c:2408 set_format: Set channel Local/111@default-f5e6,2 to write format ulaw
[Dec  4 14:25:17] DEBUG[13469]: channel.c:2408 set_format: Set channel Local/111@default-f5e6,2 to write format slin
[Dec  4 14:25:17]     -- Started music on hold, class 'default', on channel 'Local/111@default-f5e6,2'
[Dec  4 14:25:17] DEBUG[13469]: channel.c:2030 ast_read: Auto-deactivating generator
[Dec  4 14:25:17] DEBUG[13469]: channel.c:2408 set_format: Set channel Local/111@default-f5e6,2 to write format ulaw
[Dec  4 14:25:17]     -- Stopped music on hold on Local/111@default-f5e6,2
[Dec  4 14:25:18] DEBUG[13463]: rtp.c:411 ast_rtcp_read: Got RTCP report of 52 bytes
[Dec  4 14:25:19] DEBUG[13469]: app_queue.c:2020 is_our_turn: It's our turn (Local/111@default-f5e6,2).
[Dec  4 14:25:19] DEBUG[13469]: app_queue.c:2215 try_calling: Local/111@default-f5e6,2 is trying to call a queue member.
[Dec  4 14:25:19] DEBUG[13469]: app_queue.c:2237 try_calling: Queue with URL=300_
[Dec  4 14:25:19] DEBUG[13469]: app_queue.c:2237 try_calling: Queue with URL=300_
[Dec  4 14:25:19] DEBUG[13469]: app_queue.c:2237 try_calling: Queue with URL=300_
[Dec  4 14:25:19] DEBUG[13469]: app_queue.c:1640 ring_one: Trying 'Agent/129' with metric 1
[Dec  4 14:25:19] DEBUG[13469]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-edv-s-7.
[Dec  4 14:25:19] DEBUG[13469]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-edv-s-6.
[Dec  4 14:25:19] DEBUG[13469]: channel.c:2902 ast_channel_inherit_variables: Not copying variable PLAYBACKSTATUS.
[Dec  4 14:25:19] DEBUG[13469]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-edv-s-5.
[Dec  4 14:25:19] DEBUG[13469]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-edv-s-4.
[Dec  4 14:25:19] DEBUG[13469]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-edv-s-3.
[Dec  4 14:25:19] DEBUG[13469]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-edv-s-2.
[Dec  4 14:25:19] DEBUG[13469]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-edv-s-1.
[Dec  4 14:25:19] DEBUG[13469]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-default-111-1.
[Dec  4 14:25:19]     -- outgoing agentcall, to agent '129', on 'Local/105@default-81c4,1'
[Dec  4 14:25:19]     -- Called Agent/129
[Dec  4 14:25:19] DEBUG[13453]: devicestate.c:187 do_state_change: Changing state for Local/105@default - state 2 (In use)
[Dec  4 14:25:19] DEBUG[13478]: pbx.c:1677 pbx_extension_helper: Launching 'Dial'
[Dec  4 14:25:19]     -- Executing Dial("Local/105@default-81c4,2", "SIP/snom1||tT") in new stack
[Dec  4 14:25:19] DEBUG[13478]: chan_sip.c:3176 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Dec  4 14:25:19] DEBUG[13478]: chan_sip.c:1888 create_addr_from_peer: Setting NAT on RTP to 0
[Dec  4 14:25:19] DEBUG[13478]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-default-105-1.
[Dec  4 14:25:19] DEBUG[13478]: chan_sip.c:2082 sip_call: Outgoing Call for snom1
[Dec  4 14:25:19] DEBUG[13478]: chan_sip.c:2220 update_call_counter: Updating call counter for outgoing call
[Dec  4 14:25:19]     -- Called snom1
[Dec  4 14:25:19] DEBUG[13479]: app_queue.c:500 changethread: Device 'Local/105@default' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Dec  4 14:25:19] DEBUG[13459]: chan_sip.c:3224 find_call: = Found Their Call ID: 2fc51cae2b95026261eb579500861c12@10.3.67.195 Their Tag  Our tag: as354d3471
[Dec  4 14:25:19] DEBUG[13459]: chan_sip.c:1467 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '2fc51cae2b95026261eb579500861c12@10.3.67.195' Request 102: Found
[Dec  4 14:25:19] DEBUG[13459]: chan_sip.c:9694 handle_response_invite: SIP response 180 to standard invite
[Dec  4 14:25:19]     -- SIP/snom1-081b6a58 is ringing
[Dec  4 14:25:19]     -- Agent/129 is ringing
[Dec  4 14:25:19] DEBUG[13453]: chan_sip.c:11810 sip_devicestate: Checking device state for peer snom1
[Dec  4 14:25:19] DEBUG[13453]: devicestate.c:187 do_state_change: Changing state for SIP/snom1 - state 6 (Ringing)
[Dec  4 14:25:19] DEBUG[13480]: app_queue.c:506 changethread: Device 'SIP/snom1' changed to state '6' (Ringing)
[Dec  4 14:25:19] DEBUG[13459]: chan_sip.c:3224 find_call: = Found Their Call ID: 2fc51cae2b95026261eb579500861c12@10.3.67.195 Their Tag 6abkp3lr2i Our tag: as354d3471
[Dec  4 14:25:19] DEBUG[13459]: chan_sip.c:1467 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '2fc51cae2b95026261eb579500861c12@10.3.67.195' Request 102: Found
[Dec  4 14:25:19] DEBUG[13459]: chan_sip.c:9694 handle_response_invite: SIP response 180 to standard invite
[Dec  4 14:25:19]     -- SIP/snom1-081b6a58 is ringing
[Dec  4 14:25:19] DEBUG[13459]: chan_sip.c:3224 find_call: = Found Their Call ID: 2fc51cae2b95026261eb579500861c12@10.3.67.195 Their Tag 6abkp3lr2i Our tag: as354d3471
[Dec  4 14:25:19] DEBUG[13459]: chan_sip.c:1467 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '2fc51cae2b95026261eb579500861c12@10.3.67.195' Request 102: Found
[Dec  4 14:25:19] DEBUG[13459]: chan_sip.c:9694 handle_response_invite: SIP response 180 to standard invite
[Dec  4 14:25:19]     -- SIP/snom1-081b6a58 is ringing
[Dec  4 14:25:19] DEBUG[13463]: rtp.c:411 ast_rtcp_read: Got RTCP report of 52 bytes
[Dec  4 14:25:19] DEBUG[13478]: rtp.c:411 ast_rtcp_read: Got RTCP report of 52 bytes
[Dec  4 14:25:19] DEBUG[13459]: chan_sip.c:3224 find_call: = Found Their Call ID: 2fc51cae2b95026261eb579500861c12@10.3.67.195 Their Tag 6abkp3lr2i Our tag: as354d3471
[Dec  4 14:25:19] DEBUG[13459]: chan_sip.c:1391 __sip_ack: Acked pending invite 102
[Dec  4 14:25:19] DEBUG[13459]: chan_sip.c:1414 __sip_ack: Stopping retransmission on '2fc51cae2b95026261eb579500861c12@10.3.67.195' of Request 102: Match Found
[Dec  4 14:25:19] DEBUG[13459]: chan_sip.c:9694 handle_response_invite: SIP response 200 to standard invite
[Dec  4 14:25:19] DEBUG[13459]: chan_sip.c:6241 build_route: build_route: Contact hop: <sip:snom1@10.3.67.149:2051;line=bvnn8r97>;flow-id=1
[Dec  4 14:25:19]     -- SIP/snom1-081b6a58 answered Local/105@default-81c4,2
[Dec  4 14:25:19] DEBUG[13453]: chan_sip.c:11810 sip_devicestate: Checking device state for peer snom1
[Dec  4 14:25:19] DEBUG[13453]: devicestate.c:187 do_state_change: Changing state for SIP/snom1 - state 2 (In use)
[Dec  4 14:25:19] DEBUG[13453]: devicestate.c:187 do_state_change: Changing state for Local/105@default - state 2 (In use)
[Dec  4 14:25:19] DEBUG[13469]: app_queue.c:1953 wait_for_answer: Dunno what to do with control type -1
[Dec  4 14:25:19]     -- Agent/129 answered Local/111@default-f5e6,2
[Dec  4 14:25:19] DEBUG[13469]: app_queue.c:1673 store_next: Next is 'Agent/124' with metric 2
[Dec  4 14:25:19] DEBUG[13469]: app_queue.c:2401 try_calling: app_queue: sendurl=300.
[Dec  4 14:25:19] DEBUG[13453]: devicestate.c:187 do_state_change: Changing state for Local/105@default - state 2 (In use)
[Dec  4 14:25:19] DEBUG[13453]: devicestate.c:187 do_state_change: Changing state for Agent/129 - state 3 (Busy)
[Dec  4 14:25:19] DEBUG[13481]: app_queue.c:506 changethread: Device 'SIP/snom1' changed to state '2' (In use)
[Dec  4 14:25:19] DEBUG[13482]: app_queue.c:500 changethread: Device 'Local/105@default' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Dec  4 14:25:19] DEBUG[13483]: app_queue.c:500 changethread: Device 'Local/105@default' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Dec  4 14:25:19] DEBUG[13484]: app_queue.c:506 changethread: Device 'Agent/129' changed to state '3' (Busy)
[Dec  4 14:25:19] DEBUG[13478]: rtp.c:1361 ast_rtp_write: Ooh, format changed from unknown to ulaw
[Dec  4 14:25:19] DEBUG[13478]: channel.c:2834 ast_channel_masquerade: Planning to masquerade channel SIP/snom1-081b6a58 into the structure of Local/105@default-81c4,1
[Dec  4 14:25:19] DEBUG[13478]: channel.c:2847 ast_channel_masquerade: Done planning to masquerade channel SIP/snom1-081b6a58 into the structure of Local/105@default-81c4,1
[Dec  4 14:25:19] DEBUG[13478]: chan_local.c:262 local_write: Not posting to queue since already masked on 'Local/105@default-81c4,2'
[Dec  4 14:25:19] DEBUG[13469]: channel.c:2961 ast_do_masquerade: Actually Masquerading SIP/snom1-081b6a58(6) into the structure of Local/105@default-81c4,1(6)
[Dec  4 14:25:19] DEBUG[13469]: channel.c:2972 ast_do_masquerade: Got clone lock for masquerade on 'SIP/snom1-081b6a58' at 0x81b4dc4
[Dec  4 14:25:19] DEBUG[13469]: channel.c:3154 ast_do_masquerade: Putting channel SIP/snom1-081b6a58 in 4/4 formats
[Dec  4 14:25:19] DEBUG[13469]: channel.c:3189 ast_do_masquerade: Released clone lock on 'Local/105@default-81c4,1<ZOMBIE>'
[Dec  4 14:25:19] DEBUG[13469]: channel.c:3198 ast_do_masquerade: Done Masquerading SIP/snom1-081b6a58 (6)
[Dec  4 14:25:19] DEBUG[13469]: chan_agent.c:547 agent_read: Bridge on 'SIP/snom1-081b6a58' being set to 'Agent/129' (3)
[Dec  4 14:25:19] DEBUG[13478]: channel.c:3380 ast_generic_bridge: Didn't get a frame from channel: Local/105@default-81c4,2
[Dec  4 14:25:19] DEBUG[13478]: channel.c:3669 ast_channel_bridge: Bridge stops bridging channels Local/105@default-81c4,2 and Local/105@default-81c4,1<ZOMBIE>
[Dec  4 14:25:19] DEBUG[13478]: channel.c:1372 ast_hangup: Hanging up zombie 'Local/105@default-81c4,1<ZOMBIE>'
[Dec  4 14:25:19] DEBUG[13478]: app_dial.c:1636 dial_exec_full: Exiting with DIALSTATUS=ANSWER.
[Dec  4 14:25:19] DEBUG[13478]: pbx.c:2316 __ast_pbx_run: Spawn extension (default,105,1) exited non-zero on 'Local/105@default-81c4,2'
[Dec  4 14:25:19]   == Spawn extension (default, 105, 1) exited non-zero on 'Local/105@default-81c4,2'
[Dec  4 14:25:19] DEBUG[13478]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '"Ueber Hotline" <snom3>'
[Dec  4 14:25:19] DEBUG[13478]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'snom3'
[Dec  4 14:25:19] DEBUG[13478]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '105'
[Dec  4 14:25:19] DEBUG[13478]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'default'
[Dec  4 14:25:19] DEBUG[13478]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'Local/105@default-81c4,2'
[Dec  4 14:25:19] DEBUG[13478]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'SIP/snom1-081b6a58'
[Dec  4 14:25:19] DEBUG[13478]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'Dial'
[Dec  4 14:25:19] DEBUG[13478]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'SIP/snom1||tT'
[Dec  4 14:25:19] DEBUG[13478]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-12-04 14:25:19'
[Dec  4 14:25:19] DEBUG[13478]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-12-04 14:25:19'
[Dec  4 14:25:19] DEBUG[13478]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-12-04 14:25:19'
[Dec  4 14:25:19] DEBUG[13453]: channel.c:771 channel_find_locked: Avoiding initial deadlock for 'Local/105@default-81c4,2'
[Dec  4 14:25:19] DEBUG[13478]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '0'
[Dec  4 14:25:19] DEBUG[13478]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '0'
[Dec  4 14:25:19] DEBUG[13478]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'ANSWERED'
[Dec  4 14:25:19] DEBUG[13478]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION'
[Dec  4 14:25:19] DEBUG[13478]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)'
[Dec  4 14:25:19] DEBUG[13478]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '1165238719.8'
[Dec  4 14:25:19] DEBUG[13478]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)'
[Dec  4 14:25:19] DEBUG[13478]: channel.c:1367 ast_hangup: Hanging up channel 'Local/105@default-81c4,2'
[Dec  4 14:25:19] DEBUG[13453]: devicestate.c:187 do_state_change: Changing state for Local/105@default - state 0 (Unknown)
[Dec  4 14:25:19] DEBUG[13453]: devicestate.c:187 do_state_change: Changing state for Local/105@default - state 0 (Unknown)
[Dec  4 14:25:19] DEBUG[13485]: app_queue.c:500 changethread: Device 'Local/105@default' changed to state '0' (Unknown) but we don't care because they're not a member of any queue.
[Dec  4 14:25:19] DEBUG[13486]: app_queue.c:500 changethread: Device 'Local/105@default' changed to state '0' (Unknown) but we don't care because they're not a member of any queue.
[Dec  4 14:25:19] DEBUG[13469]: channel.c:2834 ast_channel_masquerade: Planning to masquerade channel Agent/129 into the structure of Local/111@default-f5e6,1
[Dec  4 14:25:19] DEBUG[13469]: channel.c:2847 ast_channel_masquerade: Done planning to masquerade channel Agent/129 into the structure of Local/111@default-f5e6,1
[Dec  4 14:25:19] DEBUG[13463]: channel.c:2961 ast_do_masquerade: Actually Masquerading Agent/129(6) into the structure of Local/111@default-f5e6,1(6)
[Dec  4 14:25:19] DEBUG[13463]: channel.c:2972 ast_do_masquerade: Got clone lock for masquerade on 'Agent/129' at 0x81b45c4
[Dec  4 14:25:19] DEBUG[13469]: chan_local.c:262 local_write: Not posting to queue since already masked on 'Local/111@default-f5e6,2'
[Dec  4 14:25:19] DEBUG[13463]: channel.c:3154 ast_do_masquerade: Putting channel Agent/129 in 4/4 formats
[Dec  4 14:25:19] DEBUG[13463]: channel.c:3189 ast_do_masquerade: Released clone lock on 'Local/111@default-f5e6,1<ZOMBIE>'
[Dec  4 14:25:19] DEBUG[13463]: channel.c:3198 ast_do_masquerade: Done Masquerading Agent/129 (6)
[Dec  4 14:25:19] DEBUG[13463]: chan_agent.c:547 agent_read: Bridge on 'Agent/129' being set to 'Agent/130' (3)
[Dec  4 14:25:19] DEBUG[13469]: channel.c:3578 ast_channel_bridge: Bridge stops because we're zombie or need a soft hangup: c0=Local/111@default-f5e6,2, c1=Local/111@default-f5e6,1<ZOMBIE>, flags: No,No,Yes,Yes
[Dec  4 14:25:19] DEBUG[13469]: channel.c:3669 ast_channel_bridge: Bridge stops bridging channels Local/111@default-f5e6,2 and Local/111@default-f5e6,1<ZOMBIE>
[Dec  4 14:25:19] DEBUG[13469]: channel.c:1372 ast_hangup: Hanging up zombie 'Local/111@default-f5e6,1<ZOMBIE>'
[Dec  4 14:25:19] DEBUG[13469]: pbx.c:2316 __ast_pbx_run: Spawn extension (edv,s,7) exited non-zero on 'Local/111@default-f5e6,2'
[Dec  4 14:25:19]   == Spawn extension (edv, s, 7) exited non-zero on 'Local/111@default-f5e6,2'
[Dec  4 14:25:19] DEBUG[13469]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '"Ueber Hotline" <snom3>'
[Dec  4 14:25:19] DEBUG[13469]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'snom3'
[Dec  4 14:25:19] DEBUG[13469]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 's'
[Dec  4 14:25:19] DEBUG[13469]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'edv'
[Dec  4 14:25:19] DEBUG[13469]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'Local/111@default-f5e6,2'
[Dec  4 14:25:19] DEBUG[13469]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'Agent/129'
[Dec  4 14:25:19] DEBUG[13469]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'Queue'
[Dec  4 14:25:19] DEBUG[13469]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'edv|tT|300'
[Dec  4 14:25:19] DEBUG[13469]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-12-04 14:25:10'
[Dec  4 14:25:19] DEBUG[13469]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-12-04 14:25:11'
[Dec  4 14:25:19] DEBUG[13469]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-12-04 14:25:19'
[Dec  4 14:25:19] DEBUG[13469]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '9'
[Dec  4 14:25:19] DEBUG[13469]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '8'
[Dec  4 14:25:19] DEBUG[13469]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'ANSWERED'
[Dec  4 14:25:19] DEBUG[13469]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION'
[Dec  4 14:25:19] DEBUG[13469]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)'
[Dec  4 14:25:19] DEBUG[13469]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '1165238710.6'
[Dec  4 14:25:19] DEBUG[13469]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)'
[Dec  4 14:25:19] DEBUG[13469]: channel.c:1367 ast_hangup: Hanging up channel 'Local/111@default-f5e6,2'
[Dec  4 14:25:19] DEBUG[13453]: devicestate.c:187 do_state_change: Changing state for Local/111@default - state 0 (Unknown)
[Dec  4 14:25:19] DEBUG[13453]: devicestate.c:187 do_state_change: Changing state for Local/111@default - state 0 (Unknown)
[Dec  4 14:25:19] DEBUG[13487]: app_queue.c:500 changethread: Device 'Local/111@default' changed to state '0' (Unknown) but we don't care because they're not a member of any queue.
[Dec  4 14:25:19] DEBUG[13488]: app_queue.c:500 changethread: Device 'Local/111@default' changed to state '0' (Unknown) but we don't care because they're not a member of any queue.
[Dec  4 14:25:20] DEBUG[13459]: chan_sip.c:3224 find_call: = Found Their Call ID: 2fc51cae2b95026261eb579500861c12@10.3.67.195 Their Tag 6abkp3lr2i Our tag: as354d3471
[Dec  4 14:25:20] DEBUG[13459]: chan_sip.c:11268 handle_request: **** Received INVITE (5) - Command in SIP INVITE
[Dec  4 14:25:20] DEBUG[13459]: chan_sip.c:1043 parse_sip_options: * SIP extension value: 7 for call 2fc51cae2b95026261eb579500861c12@10.3.67.195
[Dec  4 14:25:20] DEBUG[13459]: channel.c:2408 set_format: Set channel hì§hì§1@default-f5e6,1<ZOMBIE> to write format slin
[Dec  4 14:25:20]     -- Started music on hold, class 'default', on channel 'hì§hì§1@default-f5e6,1<ZOMBIE>'
[Dec  4 14:25:20] DEBUG[13459]: chan_sip.c:3224 find_call: = Found Their Call ID: 2fc51cae2b95026261eb579500861c12@10.3.67.195 Their Tag 6abkp3lr2i Our tag: as354d3471
[Dec  4 14:25:20] DEBUG[13459]: chan_sip.c:11268 handle_request: **** Received ACK (6) - Command in SIP ACK
[Dec  4 14:25:20] DEBUG[13459]: chan_sip.c:1414 __sip_ack: Stopping retransmission on '2fc51cae2b95026261eb579500861c12@10.3.67.195' of Response 1: Match Found
[Dec  4 14:25:20] DEBUG[13463]: rtp.c:411 ast_rtcp_read: Got RTCP report of 52 bytes
[Dec  4 14:25:21] DEBUG[13459]: chan_sip.c:3224 find_call: = Found Their Call ID: 2fc51cae2b95026261eb579500861c12@10.3.67.195 Their Tag 6abkp3lr2i Our tag: as354d3471
[Dec  4 14:25:21] DEBUG[13459]: chan_sip.c:11268 handle_request: **** Received REFER (9) - Command in SIP REFER
[Dec  4 14:25:21] DEBUG[13459]: chan_sip.c:10782 handle_request_refer: SIP call transfer received for call 2fc51cae2b95026261eb579500861c12@10.3.67.195 (REFER)!
[Dec  4 14:25:21] DEBUG[13459]: chan_sip.c:6988 get_refer_info: Unsupervised transfer to (Refer-To): 106
[Dec  4 14:25:21] DEBUG[13459]: chan_sip.c:6990 get_refer_info: Transferred by  (Referred-by: ) snom1 
[Dec  4 14:25:21] DEBUG[13459]: chan_sip.c:6991 get_refer_info: Transfer Contact Info <sip:snom1@10.3.67.149:2051;line=bvnn8r97>;flow-id=1 (REFER_CONTACT)
[Dec  4 14:25:21] DEBUG[13459]: chan_sip.c:10804 handle_request_refer: 202 Accepted (blind)
[Dec  4 14:25:21] DEBUG[13459]: chan_sip.c:10809 handle_request_refer: Got SIP blind transfer, applying to 'hì§hì§1@default-f5e6,1<ZOMBIE>'
[Dec  4 14:25:21] DEBUG[13459]: channel.c:2408 set_format: Set channel hì§hì§1@default-f5e6,1<ZOMBIE> to write format ulaw
[Dec  4 14:25:21]     -- Stopped music on hold on hì§hì§1@default-f5e6,1<ZOMBIE>
[Dec  4 14:25:21] DEBUG[13459]: channel.c:2834 ast_channel_masquerade: Planning to masquerade channel hì§hì§1@default-f5e6,1<ZOMBIE> into the structure of AsyncGoto/hì§hì§1@default-f5e6,1<ZOMBIE>
[Dec  4 14:25:21] WARNING[13459]: channel.c:659 ast_queue_frame: Unable to write to alert pipe on hì§hì§1@default-f5e6,1<ZOMBIE>, frametype/subclass 5/0 (qlen = 0): Bad file descriptor!
[Dec  4 14:25:21] DEBUG[13459]: channel.c:2847 ast_channel_masquerade: Done planning to masquerade channel hì§hì§1@default-f5e6,1<ZOMBIE> into the structure of AsyncGoto/hì§hì§1@default-f5e6,1<ZOMBIE>
[Dec  4 14:25:21] DEBUG[13459]: channel.c:2961 ast_do_masquerade: Actually Masquerading hì§hì§1@default-f5e6,1<ZOMBIE>(6) into the structure of AsyncGoto/hì§hì§1@default-f5e6,1<ZOMBIE>(6)
[Dec  4 14:25:21] DEBUG[13459]: channel.c:2972 ast_do_masquerade: Got clone lock for masquerade on 'hì§hì§1@default-f5e6,1<ZOMBIE>' at 0x81b45c4
[Dec  4 14:25:21] DEBUG[13459]: channel.c:3154 ast_do_masquerade: Putting channel hì§hì§1@default-f5e6,1<ZOMBIE> in 4/4 formats
[Dec  4 14:25:21] WARNING[13459]: channel.c:3161 ast_do_masquerade: Channel for type 'Agent' could not fixup channel hì§hì§1@default-f5e6,1<ZOMBIE>
[Dec  4 14:25:21] DEBUG[13453]: devicestate.c:187 do_state_change: Changing state for AsyncGoto/hì§hì§1@default - state 4 (Invalid)
[Dec  4 14:25:21] DEBUG[13489]: pbx.c:1677 pbx_extension_helper: Launching 'Dial'
[Dec  4 14:25:21]     -- Executing Dial("hì§hì§1@default-f5e6,1<ZOMBIE>", "SIP/snom2||tT") in new stack
[Dec  4 14:25:21] DEBUG[13489]: chan_sip.c:3176 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Dec  4 14:25:21] DEBUG[13489]: chan_sip.c:1888 create_addr_from_peer: Setting NAT on RTP to 0
[Dec  4 14:25:21] DEBUG[13489]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-default-106-1.
[Dec  4 14:25:21] DEBUG[13489]: channel.c:2902 ast_channel_inherit_variables: Not copying variable BLINDTRANSFER.
[Dec  4 14:25:21] DEBUG[13489]: chan_sip.c:2082 sip_call: Outgoing Call for snom2
[Dec  4 14:25:21] DEBUG[13489]: chan_sip.c:2220 update_call_counter: Updating call counter for outgoing call