*CLI> [Jan  4 16:58:32] DEBUG[497]: chan_sip.c:3176 sip_alloc: Allocating new SIP dialog for NWMzZWM4YTRjNTJlMDk3YzlhNjgzMTk5YWUyODc4NjY. - INVITE (With RTP)
[Jan  4 16:58:32] DEBUG[497]: chan_sip.c:11268 handle_request: **** Received INVITE (5) - Command in SIP INVITE
[Jan  4 16:58:32] DEBUG[497]: chan_sip.c:7265 check_user_full: Setting NAT on RTP to 0
[Jan  4 16:58:32] DEBUG[497]: chan_sip.c:3224 find_call: = Found Their Call ID: NWMzZWM4YTRjNTJlMDk3YzlhNjgzMTk5YWUyODc4NjY. Their Tag 3210603d Our tag: as5c354a55
[Jan  4 16:58:32] DEBUG[497]: chan_sip.c:11268 handle_request: **** Received ACK (6) - Command in SIP ACK
[Jan  4 16:58:32] DEBUG[497]: chan_sip.c:1414 __sip_ack: Stopping retransmission on 'NWMzZWM4YTRjNTJlMDk3YzlhNjgzMTk5YWUyODc4NjY.' of Response 1: Match Found
[Jan  4 16:58:32] DEBUG[497]: chan_sip.c:3224 find_call: = Found Their Call ID: NWMzZWM4YTRjNTJlMDk3YzlhNjgzMTk5YWUyODc4NjY. Their Tag 3210603d Our tag: as5c354a55
[Jan  4 16:58:32] DEBUG[497]: chan_sip.c:11268 handle_request: **** Received INVITE (5) - Command in SIP INVITE
[Jan  4 16:58:32] DEBUG[497]: chan_sip.c:7265 check_user_full: Setting NAT on RTP to 0
[Jan  4 16:58:32] DEBUG[497]: chan_sip.c:10632 handle_request_invite: Checking SIP call limits for device 1608
[Jan  4 16:58:32] DEBUG[497]: chan_sip.c:2220 update_call_counter: Updating call counter for incoming call
[Jan  4 16:58:32] DEBUG[497]: chan_sip.c:6241 build_route: build_route: Contact hop: <sip:1608@192.168.52.154:53712>
[Jan  4 16:58:32] DEBUG[489]: chan_sip.c:11810 sip_devicestate: Checking device state for peer 1608
[Jan  4 16:58:32] DEBUG[489]: devicestate.c:187 do_state_change: Changing state for SIP/1608 - state 2 (In use)
[Jan  4 16:58:32] DEBUG[560]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '160'
[Jan  4 16:58:32] DEBUG[560]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'Rene Kosciol'
[Jan  4 16:58:32] DEBUG[560]: pbx.c:1677 pbx_extension_helper: Launching 'Macro'

[Jan  4 16:58:32]     -- Executing Macro("SIP/1608-b7b77940", "stdexten|105|SIP/105&SIP/1058&SIP/1056|160|Rene Kosciol|1|1|de") in new stack
[Jan  4 16:58:32] ERROR[560]: pbx.c:1382 ast_func_read: Function Len not registered
[Jan  4 16:58:32] DEBUG[560]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '0'
[Jan  4 16:58:32] ERROR[560]: pbx.c:1382 ast_func_read: Function Len not registered
[Jan  4 16:58:32] DEBUG[560]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '0'
[Jan  4 16:58:32] DEBUG[560]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '1'
[Jan  4 16:58:32] DEBUG[560]: pbx.c:1677 pbx_extension_helper: Launching 'Set'

[Jan  4 16:58:32]     -- Executing Set("SIP/1608-b7b77940", "intern=1") in new stack
[Jan  4 16:58:32] DEBUG[560]: pbx.c:1677 pbx_extension_helper: Launching 'Set'

[Jan  4 16:58:32]     -- Executing Set("SIP/1608-b7b77940", "vmbox=1059") in new stack
[Jan  4 16:58:32] DEBUG[560]: pbx.c:1677 pbx_extension_helper: Launching 'Set'

[Jan  4 16:58:32]     -- Executing Set("SIP/1608-b7b77940", "CALLERID(number)=160") in new stack
[Jan  4 16:58:32] DEBUG[560]: pbx.c:1677 pbx_extension_helper: Launching 'Set'

[Jan  4 16:58:32]     -- Executing Set("SIP/1608-b7b77940", "CALLERID(name)=Rene Kosciol") in new stack
[Jan  4 16:58:32] DEBUG[560]: pbx.c:1677 pbx_extension_helper: Launching 'Set'

[Jan  4 16:58:32]     -- Executing Set("SIP/1608-b7b77940", "foo=160") in new stack
[Jan  4 16:58:32] DEBUG[560]: pbx.c:1677 pbx_extension_helper: Launching 'Set'

[Jan  4 16:58:32]     -- Executing Set("SIP/1608-b7b77940", "LANGUAGE()=de") in new stack
[Jan  4 16:58:32] DEBUG[560]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '0'
[Jan  4 16:58:32] DEBUG[560]: pbx.c:1677 pbx_extension_helper: Launching 'GotoIf'

[Jan  4 16:58:32]     -- Executing GotoIf("SIP/1608-b7b77940", "0?8:12") in new stack

[Jan  4 16:58:32]     -- Goto (macro-stdexten,s,12)
[Jan  4 16:58:32] DEBUG[560]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '0'
[Jan  4 16:58:32] DEBUG[560]: pbx.c:1677 pbx_extension_helper: Launching 'GotoIf'

[Jan  4 16:58:32]     -- Executing GotoIf("SIP/1608-b7b77940", "0?15:13") in new stack

[Jan  4 16:58:32]     -- Goto (macro-stdexten,s,13)
[Jan  4 16:58:32] DEBUG[560]: pbx.c:1677 pbx_extension_helper: Launching 'Set'

[Jan  4 16:58:32]     -- Executing Set("SIP/1608-b7b77940", "foo=00490") in new stack
[Jan  4 16:58:32] DEBUG[560]: pbx.c:1677 pbx_extension_helper: Launching 'Goto'

[Jan  4 16:58:32]     -- Executing Goto("SIP/1608-b7b77940", "16") in new stack

[Jan  4 16:58:32]     -- Goto (macro-stdexten,s,16)
[Jan  4 16:58:32] DEBUG[560]: pbx.c:1677 pbx_extension_helper: Launching 'Macro'

[Jan  4 16:58:32]     -- Executing Macro("SIP/1608-b7b77940", "setlanguage|160|de") in new stack
[Jan  4 16:58:32] DEBUG[560]: pbx.c:1677 pbx_extension_helper: Launching 'Set'

[Jan  4 16:58:32]     -- Executing Set("SIP/1608-b7b77940", "LANGUAGE()=de") in new stack
[Jan  4 16:58:32] DEBUG[560]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '0'
[Jan  4 16:58:32] DEBUG[560]: pbx.c:1677 pbx_extension_helper: Launching 'GotoIf'

[Jan  4 16:58:32]     -- Executing GotoIf("SIP/1608-b7b77940", "0?3:4") in new stack

[Jan  4 16:58:32]     -- Goto (macro-setlanguage,s,4)
[Jan  4 16:58:32] DEBUG[560]: pbx.c:1677 pbx_extension_helper: Launching 'Set'

[Jan  4 16:58:32]     -- Executing Set("SIP/1608-b7b77940", "x=1") in new stack
[Jan  4 16:58:32] DEBUG[560]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'Rene Kosciol'
[Jan  4 16:58:32] DEBUG[560]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '12'
[Jan  4 16:58:32] DEBUG[560]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '0'
[Jan  4 16:58:32] DEBUG[560]: pbx.c:1677 pbx_extension_helper: Launching 'GotoIf'

[Jan  4 16:58:32]     -- Executing GotoIf("SIP/1608-b7b77940", "0?18:20") in new stack

[Jan  4 16:58:32]     -- Goto (macro-stdexten,s,20)
[Jan  4 16:58:32] DEBUG[560]: pbx.c:1677 pbx_extension_helper: Launching 'Dial'

[Jan  4 16:58:32]     -- Executing Dial("SIP/1608-b7b77940", "SIP/105&SIP/1058&SIP/1056|12") in new stack
[Jan  4 16:58:32] DEBUG[560]: chan_sip.c:3176 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Jan  4 16:58:32] DEBUG[560]: chan_sip.c:1888 create_addr_from_peer: Setting NAT on RTP to 0
[Jan  4 16:58:32] DEBUG[560]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-20.
[Jan  4 16:58:32] DEBUG[560]: channel.c:2902 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH.
[Jan  4 16:58:32] DEBUG[560]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-17.
[Jan  4 16:58:32] DEBUG[560]: channel.c:2902 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY.
[Jan  4 16:58:32] DEBUG[560]: channel.c:2902 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT.
[Jan  4 16:58:32] DEBUG[560]: channel.c:2902 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN.
[Jan  4 16:58:32] DEBUG[560]: channel.c:2902 ast_channel_inherit_variables: Not copying variable ARG2.
[Jan  4 16:58:32] DEBUG[560]: channel.c:2902 ast_channel_inherit_variables: Not copying variable ARG1.
[Jan  4 16:58:32] DEBUG[560]: channel.c:2902 ast_channel_inherit_variables: Not copying variable x.
[Jan  4 16:58:32] DEBUG[560]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-macro-setlanguage-s-4.
[Jan  4 16:58:32] DEBUG[560]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-macro-setlanguage-s-2.
[Jan  4 16:58:32] DEBUG[560]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-macro-setlanguage-s-1.
[Jan  4 16:58:32] DEBUG[560]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-16.
[Jan  4 16:58:32] DEBUG[560]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-14.
[Jan  4 16:58:32] DEBUG[560]: channel.c:2902 ast_channel_inherit_variables: Not copying variable foo.
[Jan  4 16:58:32] DEBUG[560]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-13.
[Jan  4 16:58:32] DEBUG[560]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-12.
[Jan  4 16:58:32] DEBUG[560]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-7.
[Jan  4 16:58:32] DEBUG[560]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-6.
[Jan  4 16:58:32] DEBUG[560]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-5.
[Jan  4 16:58:32] DEBUG[560]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-4.
[Jan  4 16:58:32] DEBUG[560]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-3.
[Jan  4 16:58:32] DEBUG[560]: channel.c:2902 ast_channel_inherit_variables: Not copying variable vmbox.
[Jan  4 16:58:32] DEBUG[560]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-2.
[Jan  4 16:58:32] DEBUG[560]: channel.c:2902 ast_channel_inherit_variables: Not copying variable intern.
[Jan  4 16:58:32] DEBUG[560]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-1.
[Jan  4 16:58:32] DEBUG[560]: channel.c:2902 ast_channel_inherit_variables: Not copying variable ARG7.
[Jan  4 16:58:32] DEBUG[560]: channel.c:2902 ast_channel_inherit_variables: Not copying variable ARG6.
[Jan  4 16:58:32] DEBUG[560]: channel.c:2902 ast_channel_inherit_variables: Not copying variable ARG5.
[Jan  4 16:58:32] DEBUG[560]: channel.c:2902 ast_channel_inherit_variables: Not copying variable ARG4.
[Jan  4 16:58:32] DEBUG[560]: channel.c:2902 ast_channel_inherit_variables: Not copying variable ARG3.
[Jan  4 16:58:32] DEBUG[560]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-sip-ac-105-1.
[Jan  4 16:58:32] DEBUG[560]: channel.c:2902 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[Jan  4 16:58:32] DEBUG[560]: channel.c:2902 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT.
[Jan  4 16:58:32] DEBUG[560]: channel.c:2902 ast_channel_inherit_variables: Not copying variable SIPDOMAIN.
[Jan  4 16:58:32] DEBUG[560]: channel.c:2902 ast_channel_inherit_variables: Not copying variable SIPURI.
[Jan  4 16:58:32] DEBUG[560]: chan_sip.c:2082 sip_call: Outgoing Call for 105
[Jan  4 16:58:32] DEBUG[560]: chan_sip.c:2220 update_call_counter: Updating call counter for outgoing call
[Jan  4 16:58:32] DEBUG[561]: app_queue.c:500 changethread: Device 'SIP/1608' changed to state '2' (In use) but we don't care because they're not a member of any queue.

[Jan  4 16:58:32]     -- Called 105
[Jan  4 16:58:32] DEBUG[560]: chan_sip.c:3176 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Jan  4 16:58:32] NOTICE[560]: app_dial.c:1056 dial_exec_full: Unable to create channel of type 'SIP' (cause 3 - No route to destination)
[Jan  4 16:58:32] DEBUG[560]: chan_sip.c:3176 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Jan  4 16:58:32] NOTICE[560]: app_dial.c:1056 dial_exec_full: Unable to create channel of type 'SIP' (cause 3 - No route to destination)
[Jan  4 16:58:32] DEBUG[560]: channel.c:2408 set_format: Set channel SIP/105-0982dd68 to read format slin
[Jan  4 16:58:32] DEBUG[560]: channel.c:2408 set_format: Set channel SIP/1608-b7b77940 to write format slin
[Jan  4 16:58:32] DEBUG[560]: channel.c:2408 set_format: Set channel SIP/1608-b7b77940 to read format slin
[Jan  4 16:58:32] DEBUG[560]: channel.c:2408 set_format: Set channel SIP/105-0982dd68 to write format slin
[Jan  4 16:58:32] DEBUG[497]: chan_sip.c:3224 find_call: = Found Their Call ID: 60cbb88407b4bfd12058d0fd7a91d0f7@192.168.53.62 Their Tag  Our tag: as10d2fbc9
[Jan  4 16:58:32] DEBUG[497]: chan_sip.c:1467 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '60cbb88407b4bfd12058d0fd7a91d0f7@192.168.53.62' Request 102: Found
[Jan  4 16:58:32] DEBUG[497]: chan_sip.c:9694 handle_response_invite: SIP response 100 to standard invite
[Jan  4 16:58:32] DEBUG[497]: chan_sip.c:3224 find_call: = Found Their Call ID: 60cbb88407b4bfd12058d0fd7a91d0f7@192.168.53.62 Their Tag 5AEDFD17-185B5498 Our tag: as10d2fbc9
[Jan  4 16:58:32] DEBUG[497]: chan_sip.c:1467 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '60cbb88407b4bfd12058d0fd7a91d0f7@192.168.53.62' Request 102: Found
[Jan  4 16:58:32] DEBUG[497]: chan_sip.c:9694 handle_response_invite: SIP response 180 to standard invite

[Jan  4 16:58:32]     -- SIP/105-0982dd68 is ringing
[Jan  4 16:58:32] DEBUG[489]: chan_sip.c:11810 sip_devicestate: Checking device state for peer 105
[Jan  4 16:58:32] DEBUG[489]: devicestate.c:187 do_state_change: Changing state for SIP/105 - state 6 (Ringing)
[Jan  4 16:58:32] DEBUG[489]: chan_sip.c:11810 sip_devicestate: Checking device state for peer 105
[Jan  4 16:58:32] DEBUG[562]: app_queue.c:500 changethread: Device 'SIP/105' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[Jan  4 16:58:33] DEBUG[497]: chan_sip.c:3224 find_call: = Found Their Call ID: 60cbb88407b4bfd12058d0fd7a91d0f7@192.168.53.62 Their Tag 5AEDFD17-185B5498 Our tag: as10d2fbc9
[Jan  4 16:58:33] DEBUG[497]: chan_sip.c:1391 __sip_ack: Acked pending invite 102
[Jan  4 16:58:33] DEBUG[497]: chan_sip.c:1414 __sip_ack: Stopping retransmission on '60cbb88407b4bfd12058d0fd7a91d0f7@192.168.53.62' of Request 102: Match Found
[Jan  4 16:58:33] DEBUG[497]: chan_sip.c:9694 handle_response_invite: SIP response 200 to standard invite
[Jan  4 16:58:33] DEBUG[497]: chan_sip.c:6241 build_route: build_route: Contact hop: <sip:105@192.168.52.213>

[Jan  4 16:58:33]     -- SIP/105-0982dd68 answered SIP/1608-b7b77940
[Jan  4 16:58:33] DEBUG[489]: chan_sip.c:11810 sip_devicestate: Checking device state for peer 105
[Jan  4 16:58:33] DEBUG[489]: devicestate.c:187 do_state_change: Changing state for SIP/105 - state 2 (In use)
[Jan  4 16:58:33] DEBUG[489]: chan_sip.c:11810 sip_devicestate: Checking device state for peer 105
[Jan  4 16:58:33] DEBUG[489]: chan_sip.c:11810 sip_devicestate: Checking device state for peer 1608
[Jan  4 16:58:33] DEBUG[489]: channel.c:771 channel_find_locked: Avoiding initial deadlock for 'SIP/1608-b7b77940'
[Jan  4 16:58:33] DEBUG[560]: chan_sip.c:2560 sip_answer: sip_answer(SIP/1608-b7b77940)

[Jan  4 16:58:33]     -- Attempting native bridge of SIP/1608-b7b77940 and SIP/105-0982dd68
[Jan  4 16:58:33] DEBUG[560]: chan_sip.c:13077 sip_set_rtp_peer: Deferring reinvite on SIP 'NWMzZWM4YTRjNTJlMDk3YzlhNjgzMTk5YWUyODc4NjY.' - It's audio will be redirected to IP 192.168.52.213
[Jan  4 16:58:33] DEBUG[560]: chan_sip.c:13071 sip_set_rtp_peer: Sending reinvite on SIP '60cbb88407b4bfd12058d0fd7a91d0f7@192.168.53.62' - It's audio soon redirected to IP 192.168.52.154
[Jan  4 16:58:33] DEBUG[563]: app_queue.c:500 changethread: Device 'SIP/105' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jan  4 16:58:33] DEBUG[560]: rtp.c:411 ast_rtcp_read: Got RTCP report of 132 bytes
[Jan  4 16:58:33] DEBUG[489]: devicestate.c:187 do_state_change: Changing state for SIP/1608 - state 2 (In use)
[Jan  4 16:58:33] DEBUG[564]: app_queue.c:500 changethread: Device 'SIP/1608' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jan  4 16:58:33] DEBUG[560]: chan_sip.c:3036 sip_rtp_read: Oooh, format changed to 8
[Jan  4 16:58:33] DEBUG[560]: channel.c:2408 set_format: Set channel SIP/1608-b7b77940 to read format slin
[Jan  4 16:58:33] DEBUG[560]: channel.c:2408 set_format: Set channel SIP/1608-b7b77940 to write format slin
[Jan  4 16:58:33] DEBUG[560]: rtp.c:1361 ast_rtp_write: Ooh, format changed from unknown to alaw
[Jan  4 16:58:33] DEBUG[560]: rtp.c:1361 ast_rtp_write: Ooh, format changed from unknown to alaw
[Jan  4 16:58:34] DEBUG[497]: chan_sip.c:3224 find_call: = Found Their Call ID: 60cbb88407b4bfd12058d0fd7a91d0f7@192.168.53.62 Their Tag 5AEDFD17-185B5498 Our tag: as10d2fbc9
[Jan  4 16:58:34] DEBUG[497]: chan_sip.c:1391 __sip_ack: Acked pending invite 103
[Jan  4 16:58:34] DEBUG[497]: chan_sip.c:1414 __sip_ack: Stopping retransmission on '60cbb88407b4bfd12058d0fd7a91d0f7@192.168.53.62' of Request 103: Match Found
[Jan  4 16:58:34] DEBUG[497]: chan_sip.c:9692 handle_response_invite: SIP response 200 to RE-invite on outgoing call 60cbb88407b4bfd12058d0fd7a91d0f7@192.168.53.62
[Jan  4 16:58:34] DEBUG[497]: chan_sip.c:6184 build_route: build_route: Retaining previous route: <sip:105@192.168.52.213>
[Jan  4 16:58:34] DEBUG[497]: chan_sip.c:3224 find_call: = No match Their Call ID: 60cbb88407b4bfd12058d0fd7a91d0f7@192.168.53.62 Their Tag 5AEDFD17-185B5498 Our tag: as10d2fbc9
[Jan  4 16:58:34] DEBUG[497]: chan_sip.c:3224 find_call: = Found Their Call ID: NWMzZWM4YTRjNTJlMDk3YzlhNjgzMTk5YWUyODc4NjY. Their Tag 3210603d Our tag: as1748eb1a
[Jan  4 16:58:34] DEBUG[497]: chan_sip.c:11268 handle_request: **** Received ACK (6) - Command in SIP ACK
[Jan  4 16:58:34] DEBUG[497]: chan_sip.c:1414 __sip_ack: Stopping retransmission on 'NWMzZWM4YTRjNTJlMDk3YzlhNjgzMTk5YWUyODc4NjY.' of Response 2: Match Found
[Jan  4 16:58:34] DEBUG[497]: chan_sip.c:9677 check_pendings: Sending pending reinvite on 'NWMzZWM4YTRjNTJlMDk3YzlhNjgzMTk5YWUyODc4NjY.'
[Jan  4 16:58:34] DEBUG[497]: chan_sip.c:3224 find_call: = No match Their Call ID: 60cbb88407b4bfd12058d0fd7a91d0f7@192.168.53.62 Their Tag 5AEDFD17-185B5498 Our tag: as10d2fbc9
[Jan  4 16:58:34] DEBUG[497]: chan_sip.c:3224 find_call: = Found Their Call ID: NWMzZWM4YTRjNTJlMDk3YzlhNjgzMTk5YWUyODc4NjY. Their Tag 3210603d Our tag: as1748eb1a
[Jan  4 16:58:34] DEBUG[497]: chan_sip.c:1391 __sip_ack: Acked pending invite 102
[Jan  4 16:58:34] DEBUG[497]: chan_sip.c:1414 __sip_ack: Stopping retransmission on 'NWMzZWM4YTRjNTJlMDk3YzlhNjgzMTk5YWUyODc4NjY.' of Request 102: Match Found
[Jan  4 16:58:34] DEBUG[497]: chan_sip.c:9692 handle_response_invite: SIP response 200 to RE-invite on outgoing call NWMzZWM4YTRjNTJlMDk3YzlhNjgzMTk5YWUyODc4NjY.
[Jan  4 16:58:34] DEBUG[497]: chan_sip.c:6241 build_route: build_route: Contact hop: <sip:1608@192.168.52.154:53712>
[Jan  4 16:58:34] DEBUG[497]: chan_sip.c:3224 find_call: = Found Their Call ID: 60cbb88407b4bfd12058d0fd7a91d0f7@192.168.53.62 Their Tag 5AEDFD17-185B5498 Our tag: as10d2fbc9
[Jan  4 16:58:34] DEBUG[497]: chan_sip.c:11268 handle_request: **** Received INVITE (5) - Command in SIP INVITE
[Jan  4 16:58:34] DEBUG[497]: chan_sip.c:1043 parse_sip_options: * SIP extension value: 3 for call 60cbb88407b4bfd12058d0fd7a91d0f7@192.168.53.62

[Jan  4 16:58:34]     -- Started music on hold, class 'default', on SIP/1608-b7b77940
[Jan  4 16:58:34] DEBUG[497]: channel.c:1755 ast_settimeout: Scheduling timer at 160 sample intervals
[Jan  4 16:58:34] DEBUG[560]: rtp.c:1676 ast_rtp_bridge: Oooh, 'SIP/105-0982dd68' changed end address to 0.0.0.0:2244 (format 8)
[Jan  4 16:58:34] DEBUG[560]: rtp.c:1678 ast_rtp_bridge: Oooh, 'SIP/105-0982dd68' changed end vaddress to 0.0.0.0:0 (format 8)
[Jan  4 16:58:34] DEBUG[560]: rtp.c:1680 ast_rtp_bridge: Oooh, 'SIP/105-0982dd68' was 192.168.52.213:2244/(format 8)
[Jan  4 16:58:34] DEBUG[560]: rtp.c:1682 ast_rtp_bridge: Oooh, 'SIP/105-0982dd68' was 0.0.0.0:0/(format 8)
[Jan  4 16:58:34] DEBUG[560]: chan_sip.c:13071 sip_set_rtp_peer: Sending reinvite on SIP 'NWMzZWM4YTRjNTJlMDk3YzlhNjgzMTk5YWUyODc4NjY.' - It's audio soon redirected to IP 192.168.53.62
[Jan  4 16:58:34] DEBUG[560]: channel.c:2021 ast_read: Generator got voice, switching to phase locked mode
[Jan  4 16:58:34] DEBUG[560]: channel.c:1755 ast_settimeout: Scheduling timer at 0 sample intervals
[Jan  4 16:58:34] WARNING[560]: file.c:512 ast_openstream_full: File /var/lib/asterisk/mohmp3/fpm-calm-river does not exist in any format
[Jan  4 16:58:34] WARNING[560]: res_musiconhold.c:228 ast_moh_files_next: Unable to open file '/var/lib/asterisk/mohmp3/fpm-calm-river': No such file or directory
[Jan  4 16:58:34] DEBUG[560]: channel.c:2030 ast_read: Auto-deactivating generator

[Jan  4 16:58:34]     -- Stopped music on hold on SIP/1608-b7b77940
[Jan  4 16:58:34] DEBUG[560]: channel.c:1755 ast_settimeout: Scheduling timer at 0 sample intervals
[Jan  4 16:58:34] DEBUG[497]: chan_sip.c:3224 find_call: = Found Their Call ID: 60cbb88407b4bfd12058d0fd7a91d0f7@192.168.53.62 Their Tag 5AEDFD17-185B5498 Our tag: as10d2fbc9
[Jan  4 16:58:34] DEBUG[497]: chan_sip.c:11268 handle_request: **** Received ACK (6) - Command in SIP ACK
[Jan  4 16:58:34] DEBUG[497]: chan_sip.c:1414 __sip_ack: Stopping retransmission on '60cbb88407b4bfd12058d0fd7a91d0f7@192.168.53.62' of Response 1: Match Found
[Jan  4 16:58:35] DEBUG[497]: chan_sip.c:3224 find_call: = No match Their Call ID: 60cbb88407b4bfd12058d0fd7a91d0f7@192.168.53.62 Their Tag 5AEDFD17-185B5498 Our tag: as10d2fbc9
[Jan  4 16:58:35] DEBUG[497]: chan_sip.c:3224 find_call: = Found Their Call ID: NWMzZWM4YTRjNTJlMDk3YzlhNjgzMTk5YWUyODc4NjY. Their Tag 3210603d Our tag: as1748eb1a
[Jan  4 16:58:35] DEBUG[497]: chan_sip.c:1391 __sip_ack: Acked pending invite 103
[Jan  4 16:58:35] DEBUG[497]: chan_sip.c:1414 __sip_ack: Stopping retransmission on 'NWMzZWM4YTRjNTJlMDk3YzlhNjgzMTk5YWUyODc4NjY.' of Request 103: Match Found
[Jan  4 16:58:35] DEBUG[497]: chan_sip.c:9692 handle_response_invite: SIP response 200 to RE-invite on outgoing call NWMzZWM4YTRjNTJlMDk3YzlhNjgzMTk5YWUyODc4NjY.
[Jan  4 16:58:35] DEBUG[497]: chan_sip.c:6184 build_route: build_route: Retaining previous route: <sip:1608@192.168.52.154:53712>
[Jan  4 16:58:37] DEBUG[560]: rtp.c:411 ast_rtcp_read: Got RTCP report of 200 bytes
[Jan  4 16:58:38] DEBUG[497]: chan_sip.c:3176 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jan  4 16:58:38] DEBUG[497]: chan_sip.c:3176 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jan  4 16:58:39] DEBUG[497]: chan_sip.c:3176 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jan  4 16:58:39] DEBUG[497]: chan_sip.c:3224 find_call: = No match Their Call ID: 47e9ea36732b37196365db8425055547@192.168.53.62 Their Tag  Our tag: as0362a92e
[Jan  4 16:58:39] DEBUG[497]: chan_sip.c:3224 find_call: = No match Their Call ID: 7896491954cb936e3282a70d3041dba1@192.168.53.62 Their Tag  Our tag: as3db94bca
[Jan  4 16:58:39] DEBUG[497]: chan_sip.c:3224 find_call: = Found Their Call ID: 2a6878fb0aa31a4a72a3f48357f7b691@192.168.53.62 Their Tag  Our tag: as105019e2
[Jan  4 16:58:39] DEBUG[497]: chan_sip.c:1414 __sip_ack: Stopping retransmission on '2a6878fb0aa31a4a72a3f48357f7b691@192.168.53.62' of Request 102: Match Found
[Jan  4 16:58:39] DEBUG[497]: chan_sip.c:3224 find_call: = Found Their Call ID: 47e9ea36732b37196365db8425055547@192.168.53.62 Their Tag  Our tag: as0362a92e
[Jan  4 16:58:39] DEBUG[497]: chan_sip.c:1414 __sip_ack: Stopping retransmission on '47e9ea36732b37196365db8425055547@192.168.53.62' of Request 102: Match Found
[Jan  4 16:58:39] DEBUG[497]: chan_sip.c:3224 find_call: = Found Their Call ID: 7896491954cb936e3282a70d3041dba1@192.168.53.62 Their Tag  Our tag: as3db94bca
[Jan  4 16:58:39] DEBUG[497]: chan_sip.c:1414 __sip_ack: Stopping retransmission on '7896491954cb936e3282a70d3041dba1@192.168.53.62' of Request 102: Match Found
[Jan  4 16:58:40] DEBUG[560]: rtp.c:411 ast_rtcp_read: Got RTCP report of 44 bytes
[Jan  4 16:58:40] DEBUG[560]: rtp.c:411 ast_rtcp_read: Got RTCP report of 44 bytes
[Jan  4 16:58:40] DEBUG[497]: chan_sip.c:3224 find_call: = Found Their Call ID: 60cbb88407b4bfd12058d0fd7a91d0f7@192.168.53.62 Their Tag 5AEDFD17-185B5498 Our tag: as10d2fbc9
[Jan  4 16:58:40] DEBUG[497]: chan_sip.c:11268 handle_request: **** Received REFER (9) - Command in SIP REFER
[Jan  4 16:58:40] DEBUG[497]: chan_sip.c:10782 handle_request_refer: SIP call transfer received for call 60cbb88407b4bfd12058d0fd7a91d0f7@192.168.53.62 (REFER)!
[Jan  4 16:58:40] DEBUG[497]: chan_sip.c:6966 get_refer_info: Assigning Replace-Call-ID Info 5645a8d0-23b8923e-56e700cf@192.168.52.213 to REPLACE_CALL_ID
[Jan  4 16:58:40] NOTICE[497]: chan_sip.c:6980 get_refer_info: Supervised transfer requested, but unable to find callid '5645a8d0-23b8923e-56e700cf@192.168.52.213'.  Both legs must reside on Asterisk box to transfer at this time.
[Jan  4 16:58:40] DEBUG[497]: chan_sip.c:11466 sipsock_read: SIP message could not be handled, bad request: 60cbb88407b4bfd12058d0fd7a91d0f7@192.168.53.62                        
[Jan  4 16:58:40] DEBUG[560]: rtp.c:411 ast_rtcp_read: Got RTCP report of 200 bytes
[Jan  4 16:58:44] DEBUG[560]: rtp.c:411 ast_rtcp_read: Got RTCP report of 200 bytes
P[ 1] % GOT L2 Activate Info.
P[ 1]  --> found chan: 1
P[ 1] set_channel: bc->channel:1 channel:-1
P[ 1]  --> PTMP but channel requested
P[ 1] I IND :SETUP oad: dad: pid:2 state:none
P[ 1]  --> channel:1 mode:NT cause:16 ocause:16 rad: cad:
P[ 1]  --> info_dad: onumplan:  dnumplan:  rnumplan:  cpnnumplan:0
P[ 1]  --> caps:Audio 3.1k pi:3 keypad: sending_complete:0
P[ 1]  --> screen:0 --> pres:0
P[ 1]  --> addr:0 l3id:7c0040 b_stid:0 layer_id:0
P[ 1]  --> facility:FAC_NONE out_facility:FAC_NONE
P[ 1]  --> bc_state:BCHAN_CLEANED
P[ 1]  --> Bearer: Audio 3.1k
P[ 1]  --> Codec: Alaw
P[ 0]  --> * NEW CHANNEL dad: oad:
P[ 1]  --> CTON: Unknown
P[ 1]  --> EXPORT_PID: pid:2
P[ 1]  --> PRES: Restricted (0)
P[ 1]  --> SCREEN: Unscreened (0)
P[ 1] * Queuing chan 0x9919850
P[ 1] I SEND:SETUP_ACKNOWLEDGE oad: dad: pid:2
P[ 1]  --> bc_state:BCHAN_CLEANED
P[ 1]  --> channel:1 mode:NT cause:16 ocause:16 rad: cad:
P[ 1]  --> info_dad: onumplan:  dnumplan:  rnumplan:  cpnnumplan:0
P[ 1]  --> caps:Audio 3.1k pi:3 keypad: sending_complete:0
P[ 1]  --> screen:0 --> pres:0
P[ 1]  --> addr:0 l3id:7c0040 b_stid:0 layer_id:0
P[ 1]  --> facility:FAC_NONE out_facility:FAC_NONE
P[ 1] setup_bc: with dsp
P[ 1]  --> Channel is 1
P[ 1]  --> TRANSPARENT Mode
P[ 1]  --> Dial
[Jan  4 16:58:44] DEBUG[489]: devicestate.c:187 do_state_change: Changing state for mISDN/1 - state 6 (Ringing)
[Jan  4 16:58:44] DEBUG[489]: channel.c:771 channel_find_locked: Avoiding initial deadlock for 'mISDN/1-1'
[Jan  4 16:58:44] DEBUG[571]: app_queue.c:500 changethread: Device 'mISDN/1' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[Jan  4 16:58:44] DEBUG[520]: channel.c:2213 ast_prod: Prodding channel 'mISDN/1-1'
P[ 1] misdn_write: zero write
[Jan  4 16:58:44] DEBUG[520]: channel.c:2408 set_format: Set channel mISDN/1-1 to write format slin
[Jan  4 16:58:44] DEBUG[520]: channel.c:1755 ast_settimeout: Scheduling timer at 160 sample intervals
P[ 1] Starting Playtones
P[ 1] BCHAN: bchan ACT Confirm pid:2
[Jan  4 16:58:44] DEBUG[489]: devicestate.c:187 do_state_change: Changing state for mISDN/1 - state 6 (Ringing)
[Jan  4 16:58:44] DEBUG[572]: app_queue.c:500 changethread: Device 'mISDN/1' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.