core show h[Feb 1 15:33:25] DEBUG[15879]: chan_iax2.c:4773 raw_hangup: Raw Hangup 204.239.10.89:2756, src=0, dst=0 ints -= Registered Asterisk Dial Plan Hints =- 8716@private-extensions : SIP/8716 State:Unavailable Watchers 0 8715@private-extensions : SIP/8715 State:Unavailable Watchers 0 8714@private-extensions : SIP/8714 State:Unavailable Watchers 0 8713@private-extensions : SIP/8713 State:Unavailable Watchers 0 8712@private-extensions : SIP/8712 State:Unavailable Watchers 0 8711@private-extensions : SIP/8711 State:Unavailable Watchers 0 8710@private-extensions : SIP/8710 State:Unavailable Watchers 0 8696@private-extensions : SIP/8696 State:Unavailable Watchers 0 8695@private-extensions : SIP/8695 State:Unavailable Watchers 0 8694@private-extensions : SIP/8694 State:Unavailable Watchers 0 8693@private-extensions : SIP/8693 State:Unavailable Watchers 0 8692@private-extensions : SIP/8692 State:Unavailable Watchers 0 8691@private-extensions : SIP/8691 State:Unavailable Watchers 0 8690@private-extensions : SIP/8690 State:Unavailable Watchers 0 8169@private-extensions : SIP/8169 State:Unavailable Watchers 0 8168@private-extensions : SIP/8168 State:Unavailable Watchers 0 8166@private-extensions : SIP/8166 State:Unavailable Watchers 0 8162@private-extensions : SIP/8162 State:Unavailable Watchers 0 8161@private-extensions : SIP/8161 State:Unavailable Watchers 0 8160@private-extensions : SIP/8160 State:Unavailable Watchers 0 8159@private-extensions : SIP/8159 State:Unavailable Watchers 0 8158@private-extensions : SIP/8158 State:Unavailable Watchers 0 8157@private-extensions : SIP/8157 State:Unavailable Watchers 0 8156@private-extensions : SIP/8156 State:Unavailable Watchers 0 8155@private-extensions : SIP/8155 State:Unavailable Watchers 0 8154@private-extensions : SIP/8154 State:Unavailable Watchers 0 8153@private-extensions : SIP/8153 State:Unavailable Watchers 0 8152@private-extensions : SIP/8152 State:Unavailable Watchers 0 8151@private-extensions : SIP/8151 State:Unavailable Watchers 0 8150@private-extensions : SIP/8150 State:Unavailable Watchers 0 8016@private-extensions : SIP/8016 State:Unavailable Watchers 0 8015@private-extensions : SIP/8015 State:Unavailable Watchers 0 8014@private-extensions : SIP/8014 State:Unavailable Watchers 0 8013@private-extensions : SIP/8013 State:Unavailable Watchers 0 8012@private-extensions : SIP/8012 State:Unavailable Watchers 0 8011@private-extensions : SIP/8011 State:Unavailable Watchers 0 8010@private-extensions : SIP/8010 State:Unavailable Watchers 0 8009@private-extensions : SIP/8009 State:Unavailable Watchers 0 8008@private-extensions : SIP/8008 State:Unavailable Watchers 0 8007@private-extensions : SIP/8007 State:Unavailable Watchers 0 8006@private-extensions : SIP/8006 State:Unavailable Watchers 0 8005@private-extensions : SIP/8005 State:Unavailable Watchers 0 8004@private-extensions : SIP/8004 State:Unavailable Watchers 0 8003@private-extensions : SIP/8003 State:Unavailable Watchers 0 8002@private-extensions : SIP/8002 State:Unavailable Watchers 0 8001@private-extensions : SIP/8001 State:Unavailable Watchers 0 4012@private-extensions : SIP/4012 State:Idle Watchers 1 4011@private-extensions : SIP/4011 State:Idle Watchers 1 4010@private-extensions : SIP/4010 State:Idle Watchers 0 4009@private-extensions : SIP/4009 State:Unavailable Watchers 0 4008@private-extensions : SIP/4008 State:Unavailable Watchers 0 4007@private-extensions : SIP/4007 State:Unavailable Watchers 0 4006@private-extensions : SIP/4006 State:Unavailable Watchers 0 4005@private-extensions : SIP/4005 State:Unavailable Watchers 0 4004@private-extensions : SIP/4004 State:Unavailable Watchers 0 4003@private-extensions : SIP/4003 State:Unavailable Watchers 0 4002@private-extensions : SIP/4002 State:Unavailable Watchers 0 4001@private-extensions : SIP/4001 State:Unavailable Watchers 0 3844@public-extensions : SIP/3844 State:Unavailable Watchers 0 3842@public-extensions : SIP/3842 State:Unavailable Watchers 0 3838@public-extensions : SIP/3838 State:Unavailable Watchers 0 3727@public-extensions : SIP/3727 State:Unavailable Watchers 0 3712@public-extensions : SIP/3712 State:Unavailable Watchers 0 3711@public-extensions : SIP/3711 State:Unavailable Watchers 0 3700@public-extensions : SIP/3700 State:Unavailable Watchers 0 3690@public-extensions : SIP/3690 State:Unavailable Watchers 0 3681@public-extensions : SIP/3681 State:Unavailable Watchers 0 3675@public-extensions : SIP/3675 State:Unavailable Watchers 0 3674@public-extensions : SIP/3674 State:Unavailable Watchers 0 3673@public-extensions : SIP/3673 State:Unavailable Watchers 0 3672@public-extensions : SIP/3672 State:Unavailable Watchers 0 3671@public-extensions : SIP/3671 State:Unavailable Watchers 0 3670@public-extensions : SIP/3670 State:Unavailable Watchers 0 3668@public-extensions : SIP/3668 State:Unavailable Watchers 0 3667@public-extensions : SIP/3667 State:Unavailable Watchers 0 3665@public-extensions : SIP/3665 State:Unavailable Watchers 0 3664@public-extensions : SIP/3664 State:Unavailable Watchers 0 3663@public-extensions : SIP/3663 State:Unavailable Watchers 0 3662@public-extensions : SIP/3662 State:Unavailable Watchers 0 3661@public-extensions : SIP/3661 State:Unavailable Watchers 0 3660@public-extensions : SIP/3660 State:Unavailable Watchers 0 3658@public-extensions : SIP/3658 State:Unavailable Watchers 0 3655@public-extensions : SIP/3655 State:Unavailable Watchers 0 3654@public-extensions : SIP/3654 State:Unavailable Watchers 0 3653@public-extensions : SIP/3653 State:Unavailable Watchers 0 3652@public-extensions : SIP/3652 State:Unavailable Watchers 0 3651@public-extensions : SIP/3651 State:Unavailable Watchers 0 3031@public-extensions : SIP/3031 State:Unavailable Watchers 0 3030@public-extensions : SIP/3030 State:Unavailable Watchers 0 2499@public-extensions : SIP/2499 State:Unavailable Watchers 0 2488@public-extensions : SIP/2488 State:Unavailable Watchers 0 2485@public-extensions : SIP/2485 State:Unavailable Watchers 0 2478@public-extensions : SIP/2478 State:Unavailable Watchers 0 2472@public-extensions : SIP/2472 State:Unavailable Watchers 0 2471@public-extensions : SIP/2471 State:Idle Watchers 0 2470@public-extensions : SIP/2470 State:Unavailable Watchers 0 2469@public-extensions : SIP/2469 State:Unavailable Watchers 0 2468@public-extensions : SIP/2468 State:Unavailable Watchers 0 2457@public-extensions : SIP/2457 State:Unavailable Watchers 0 2456@public-extensions : SIP/2456 State:Unavailable Watchers 0 2448@public-extensions : SIP/2448 State:Unavailable Watchers 0 2440@public-extensions : SIP/2440 State:Unavailable Watchers 0 2439@public-extensions : SIP/2439 State:Unavailable Watchers 0 2438@public-extensions : SIP/2438 State:Unavailable Watchers 0 2426@public-extensions : SIP/2426 State:Unavailable Watchers 0 2420@public-extensions : SIP/2420 State:Idle Watchers 0 2412@public-extensions : SIP/2412 State:Unavailable Watchers 0 2397@public-extensions : SIP/2397 State:Unavailable Watchers 0 2390@public-extensions : SIP/2390 State:Unavailable Watchers 0 2382@public-extensions : SIP/2382 State:Unavailable Watchers 0 2381@public-extensions : SIP/2381 State:Unavailable Watchers 0 2380@public-extensions : SIP/2380 State:Unavailable Watchers 0 2372@public-extensions : SIP/2372 State:Unavailable Watchers 0 2348@public-extensions : SIP/2348-Polycom State:Unavailable Watchers 0 2331@public-extensions : SIP/2331 State:Unavailable Watchers 0 2323@public-extensions : SIP/2323 State:Unavailable Watchers 0 2313@public-extensions : SIP/2313 State:Unavailable Watchers 0 2312@public-extensions : SIP/2312 State:Idle Watchers 0 2309@public-extensions : SIP/2309 State:Unavailable Watchers 0 2308@public-extensions : SIP/2308 State:Unavailable Watchers 0 2306@public-extensions : SIP/2306-Polycom&SIP State:Unavailable Watchers 0 2305@public-extensions : SIP/2305 State:Unavailable Watchers 0 2304@public-extensions : SIP/2304 State:Unavailable Watchers 0 2303@public-extensions : SIP/2303 State:Unavailable Watchers 0 2301@public-extensions : SIP/2301 State:Unavailable Watchers 0 2295@public-extensions : SIP/2295 State:Unavailable Watchers 0 2290@public-extensions : SIP/2290-ridgej State:Unavailable Watchers 0 2266@public-extensions : SIP/2266 State:Unavailable Watchers 0 2238@public-extensions : SIP/2238 State:Unavailable Watchers 0 2235@public-extensions : SIP/2235 State:Unavailable Watchers 0 2230@public-extensions : SIP/2230 State:Unavailable Watchers 0 2229@public-extensions : SIP/2229 State:Unavailable Watchers 0 2228@public-extensions : SIP/2228 State:Unavailable Watchers 0 2226@public-extensions : SIP/2226 State:Unavailable Watchers 0 2225@public-extensions : SIP/2225 State:Unavailable Watchers 0 2218@public-extensions : SIP/2218 State:Unavailable Watchers 0 2209@public-extensions : SIP/2206-mitchells&S State:Unavailable Watchers 0 2206@public-extensions : SIP/2206-ridgej State:Unavailable Watchers 0 ---------------- - 138 hints registered *CLI> core[Feb 1 15:33:29] DEBUG[15881]: chan_iax2.c:7097 socket_process: Peer gabriola-out: got pong, lastms 17, historicms 17, maxms 2000 sip show inuse * User name In use Limit 4012 0 200 4011 0 200 4010 0 200 2348-Polycom 0 200 * Peer name In use Limit 4012 0/0 200 4011 0/0 200 4010 0/0 200 2348-Polycom 0/0 200 *CLI> [Feb 1 15:33:39] DEBUG[15885]: chan_sip.c:4299 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Feb 1 15:33:39] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: 780c85433e316a4033b12561174b3fb1@172.16.16.12 Their Tag Our tag: as1dca7f07 [Feb 1 15:33:39] DEBUG[15885]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '780c85433e316a4033b12561174b3fb1@172.16.16.12' of Request 102: Match Not Found [Feb 1 15:33:39] DEBUG[15885]: chan_sip.c:4299 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Feb 1 15:33:39] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: 79b95b7b1d0d3a282ef3bf3866d0abe0@172.16.16.12 Their Tag Our tag: as12e4d682 [Feb 1 15:33:39] DEBUG[15885]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '79b95b7b1d0d3a282ef3bf3866d0abe0@172.16.16.12' of Request 102: Match Not Found [Feb 1 15:33:39] DEBUG[15885]: chan_sip.c:4299 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Feb 1 15:33:39] DEBUG[15885]: chan_sip.c:4299 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Feb 1 15:33:39] DEBUG[15885]: chan_sip.c:4350 find_call: = No match Their Call ID: 6dafea067ba31a442bad9a1d257665d3@172.16.16.12 Their Tag Our tag: as3b74e2bb [Feb 1 15:33:39] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: 002be1672b2932875528ecca6568477e@172.16.16.12 Their Tag Our tag: as684cbdc6 [Feb 1 15:33:39] DEBUG[15885]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '002be1672b2932875528ecca6568477e@172.16.16.12' of Request 102: Match Not Found [Feb 1 15:33:39] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: 6dafea067ba31a442bad9a1d257665d3@172.16.16.12 Their Tag Our tag: as3b74e2bb [Feb 1 15:33:39] DEBUG[15885]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '6dafea067ba31a442bad9a1d257665d3@172.16.16.12' of Request 102: Match Not Found [Feb 1 15:33:39] DEBUG[15885]: chan_sip.c:4299 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Feb 1 15:33:39] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: 11c6aba5047be41647618b68590ac694@172.16.16.12 Their Tag Our tag: as38999daa [Feb 1 15:33:39] DEBUG[15885]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '11c6aba5047be41647618b68590ac694@172.16.16.12' of Request 102: Match Not Found [Feb 1 15:33:39] Really destroying SIP dialog '11c6aba5047be41647618b68590ac694@172.16.16.12' Method: OPTIONS [Feb 1 15:33:39] Really destroying SIP dialog '6dafea067ba31a442bad9a1d257665d3@172.16.16.12' Method: OPTIONS [Feb 1 15:33:39] Really destroying SIP dialog '002be1672b2932875528ecca6568477e@172.16.16.12' Method: OPTIONS [Feb 1 15:33:39] Really destroying SIP dialog '79b95b7b1d0d3a282ef3bf3866d0abe0@172.16.16.12' Method: OPTIONS [Feb 1 15:33:39] Really destroying SIP dialog '780c85433e316a4033b12561174b3fb1@172.16.16.12' Method: OPTIONS [Feb 1 15:33:47] DEBUG[15885]: chan_sip.c:4299 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Feb 1 15:33:48] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: 33e44ed41ce0577d6b1a62d308e4e1da@172.16.16.12 Their Tag Our tag: as1c2a2655 [Feb 1 15:33:48] DEBUG[15885]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '33e44ed41ce0577d6b1a62d308e4e1da@172.16.16.12' of Request 102: Match Not Found [Feb 1 15:33:48] DEBUG[15885]: chan_sip.c:4299 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Feb 1 15:33:48] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: 5d6f33ff2eaf6e3e7d19351c0ffe0b9f@172.16.16.12 Their Tag Our tag: as7c434c7e [Feb 1 15:33:48] DEBUG[15885]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '5d6f33ff2eaf6e3e7d19351c0ffe0b9f@172.16.16.12' of Request 102: Match Not Found [Feb 1 15:33:48] DEBUG[15885]: chan_sip.c:4299 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Feb 1 15:33:48] Really destroying SIP dialog '5d6f33ff2eaf6e3e7d19351c0ffe0b9f@172.16.16.12' Method: OPTIONS [Feb 1 15:33:48] Really destroying SIP dialog '33e44ed41ce0577d6b1a62d308e4e1da@172.16.16.12' Method: OPTIONS [Feb 1 15:33:48] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: 2d606a955e4832e80a7a860b72c743d1@172.16.16.12 Their Tag Our tag: as563c9cd5 [Feb 1 15:33:48] DEBUG[15885]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '2d606a955e4832e80a7a860b72c743d1@172.16.16.12' of Request 102: Match Not Found [Feb 1 15:33:48] Really destroying SIP dialog '2d606a955e4832e80a7a860b72c743d1@172.16.16.12' Method: OPTIONS [Feb 1 15:33:48] DEBUG[15885]: chan_sip.c:4350 find_call: = No match Their Call ID: 6649a393-ca48eeb9-2b6dffc4@172.16.16.135 Their Tag 872B3D6F-720D4382 Our tag: as14ab44b8 [Feb 1 15:33:48] DEBUG[15885]: chan_sip.c:4350 find_call: = No match Their Call ID: ab3d9dbe-818638ec-45e789b@172.16.16.135 Their Tag 60ADF86A-A3525C81 Our tag: as702f5b89 [Feb 1 15:33:48] DEBUG[15885]: chan_sip.c:2575 do_setnat: Setting NAT on RTP to Off [Feb 1 15:33:48] DEBUG[15885]: chan_sip.c:4299 sip_alloc: Allocating new SIP dialog for 4c0b74e8-8da8f9c6-52afc3e1@172.16.16.101 - INVITE (With RTP) [Feb 1 15:33:48] DEBUG[15885]: chan_sip.c:14571 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Feb 1 15:33:48] DEBUG[15885]: chan_sip.c:2575 do_setnat: Setting NAT on RTP to Off [Feb 1 15:33:48] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: 4c0b74e8-8da8f9c6-52afc3e1@172.16.16.101 Their Tag BA290F54-E0AB60A7 Our tag: as353b799a [Feb 1 15:33:48] DEBUG[15885]: chan_sip.c:14571 handle_request: **** Received ACK (6) - Command in SIP ACK [Feb 1 15:33:48] DEBUG[15885]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '4c0b74e8-8da8f9c6-52afc3e1@172.16.16.101' of Response 1: Match Not Found [Feb 1 15:33:48] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: 4c0b74e8-8da8f9c6-52afc3e1@172.16.16.101 Their Tag BA290F54-E0AB60A7 Our tag: as353b799a [Feb 1 15:33:48] DEBUG[15885]: chan_sip.c:14571 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Feb 1 15:33:48] DEBUG[15885]: chan_sip.c:2575 do_setnat: Setting NAT on RTP to Off [Feb 1 15:33:48] DEBUG[15885]: chan_sip.c:5105 process_sdp: T38 state changed to 0 on channel [Feb 1 15:33:48] DEBUG[15885]: chan_sip.c:5182 process_sdp: We're settling with these formats: 0x4 (ulaw) [Feb 1 15:33:48] DEBUG[15885]: chan_sip.c:13359 handle_request_invite: Checking SIP call limits for device 4011 [Feb 1 15:33:48] DEBUG[15885]: chan_sip.c:3002 update_call_counter: Updating call counter for incoming call [Feb 1 15:33:48] DEBUG[15885]: chan_sip.c:3076 update_call_counter: Call from peer '4011' is 1 out of 200 [Feb 1 15:33:48] DEBUG[15885]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4011 [Feb 1 15:33:48] DEBUG[15885]: chan_sip.c:3802 sip_new: *** Our native formats are 0x4 (ulaw) [Feb 1 15:33:48] DEBUG[15885]: chan_sip.c:3803 sip_new: *** Joint capabilities are 0x4 (ulaw) [Feb 1 15:33:48] DEBUG[15885]: chan_sip.c:3804 sip_new: *** Our capabilities are 0x6 (gsm|ulaw) [Feb 1 15:33:48] DEBUG[15885]: chan_sip.c:3805 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Feb 1 15:33:48] DEBUG[15885]: chan_sip.c:3828 sip_new: This channel will not be able to handle video. [Feb 1 15:33:48] DEBUG[15885]: chan_sip.c:7950 build_route: build_route: Contact hop: [Feb 1 15:33:48] DEBUG[15885]: chan_sip.c:13434 handle_request_invite: SIP/4011-0a09e3d8: New call is still down.... Trying... [Feb 1 15:33:48] DEBUG[15885]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4011-0a09e3d8 [Feb 1 15:33:48] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4011 [Feb 1 15:33:48] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4011 [Feb 1 15:33:48] DEBUG[15871]: devicestate.c:287 do_state_change: Changing state for SIP/4011 - state 2 (In use) [Feb 1 15:33:48] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4011 [Feb 1 15:33:48] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4011 [Feb 1 15:33:48] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4011 [Feb 1 15:33:48] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4011 [Feb 1 15:33:48] Extension Changed 4011 new state InUse for Notify User 4010 [Feb 1 15:33:48] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4011 [Feb 1 15:33:48] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4011 [Feb 1 15:33:48] DEBUG[15871]: devicestate.c:287 do_state_change: Changing state for SIP/4011 - state 2 (In use) [Feb 1 15:33:48] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4011 [Feb 1 15:33:48] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4011 [Feb 1 15:33:48] DEBUG[15912]: pbx.c:1769 pbx_extension_helper: Launching 'Goto' [Feb 1 15:33:48] -- Executing [4012@internal:1] Goto("SIP/4011-0a09e3d8", "ITS|4012|1") in new stack [Feb 1 15:33:48] -- Goto (ITS,4012,1) [Feb 1 15:33:48] DEBUG[15912]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '4011' [Feb 1 15:33:48] DEBUG[15912]: pbx.c:1769 pbx_extension_helper: Launching 'Macro' [Feb 1 15:33:48] -- Executing [4012@ITS:1] Macro("SIP/4011-0a09e3d8", "dnv-incoming-call-handler|4011|4012") in new stack [Feb 1 15:33:48] DEBUG[15912]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'ITS Test 3' [Feb 1 15:33:48] DEBUG[15912]: pbx.c:1769 pbx_extension_helper: Launching 'NoOp' [Feb 1 15:33:48] -- Executing [s@macro-dnv-incoming-call-handler:1] NoOp("SIP/4011-0a09e3d8", "ITS Test 3") in new stack [Feb 1 15:33:48] DEBUG[15912]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'ITS Test 3' [Feb 1 15:33:48] DEBUG[15912]: pbx.c:1690 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 1 15:33:48] DEBUG[15912]: pbx.c:1769 pbx_extension_helper: Launching 'GotoIf' [Feb 1 15:33:48] -- Executing [s@macro-dnv-incoming-call-handler:2] GotoIf("SIP/4011-0a09e3d8", "0?SetVoiceMailContext") in new stack [Feb 1 15:33:48] DEBUG[15912]: pbx.c:5947 pbx_builtin_gotoif: Not taking any branch [Feb 1 15:33:48] DEBUG[15912]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'SIP' [Feb 1 15:33:48] DEBUG[15912]: pbx.c:1690 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 1 15:33:48] DEBUG[15912]: pbx.c:1769 pbx_extension_helper: Launching 'GotoIf' [Feb 1 15:33:48] -- Executing [s@macro-dnv-incoming-call-handler:3] GotoIf("SIP/4011-0a09e3d8", "1?:SetVoiceMailContext") in new stack [Feb 1 15:33:48] DEBUG[15912]: pbx.c:5947 pbx_builtin_gotoif: Not taking any branch [Feb 1 15:33:48] DEBUG[15912]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'ITS Test 3' [Feb 1 15:33:48] DEBUG[15912]: pbx.c:1769 pbx_extension_helper: Launching 'SIPCalledRPID' [Feb 1 15:33:48] -- Executing [s@macro-dnv-incoming-call-handler:4] SIPCalledRPID("SIP/4011-0a09e3d8", "ITS Test 3|4012") in new stack [Feb 1 15:33:48] DEBUG[15912]: pbx.c:1690 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 1 15:33:48] DEBUG[15912]: pbx.c:1769 pbx_extension_helper: Launching 'GotoIf' [Feb 1 15:33:48] -- Executing [s@macro-dnv-incoming-call-handler:5] GotoIf("SIP/4011-0a09e3d8", "0?:NVDPL") in new stack [Feb 1 15:33:48] -- Goto (macro-dnv-incoming-call-handler,s,8) [Feb 1 15:33:48] DEBUG[15912]: pbx.c:1690 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 1 15:33:48] DEBUG[15912]: pbx.c:1769 pbx_extension_helper: Launching 'GotoIf' [Feb 1 15:33:48] -- Executing [s@macro-dnv-incoming-call-handler:8] GotoIf("SIP/4011-0a09e3d8", "0?:Default") in new stack [Feb 1 15:33:48] -- Goto (macro-dnv-incoming-call-handler,s,12) [Feb 1 15:33:48] DEBUG[15912]: pbx.c:1769 pbx_extension_helper: Launching 'Set' [Feb 1 15:33:48] -- Executing [s@macro-dnv-incoming-call-handler:12] Set("SIP/4011-0a09e3d8", "vm_context=default") in new stack [Feb 1 15:33:48] DEBUG[15912]: pbx.c:1690 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 1 15:33:48] DEBUG[15912]: pbx.c:1690 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 1 15:33:48] DEBUG[15912]: pbx.c:1690 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 1 15:33:48] DEBUG[15912]: pbx.c:1690 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 1 15:33:48] DEBUG[15912]: pbx.c:1690 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 1 15:33:48] DEBUG[15912]: pbx.c:1769 pbx_extension_helper: Launching 'GotoIf' [Feb 1 15:33:48] -- Executing [s@macro-dnv-incoming-call-handler:13] GotoIf("SIP/4011-0a09e3d8", "0?:Proceed") in new stack [Feb 1 15:33:48] -- Goto (macro-dnv-incoming-call-handler,s,19) [Feb 1 15:33:48] DEBUG[15912]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '"ITS Test 2" <4011>' [Feb 1 15:33:48] DEBUG[15912]: pbx.c:1769 pbx_extension_helper: Launching 'NoOp' [Feb 1 15:33:48] -- Executing [s@macro-dnv-incoming-call-handler:19] NoOp("SIP/4011-0a09e3d8", ""ITS Test 2" <4011>") in new stack [Feb 1 15:33:48] DEBUG[15912]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '4011' [Feb 1 15:33:48] DEBUG[15912]: pbx.c:1690 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 1 15:33:48] DEBUG[15912]: pbx.c:1769 pbx_extension_helper: Launching 'GotoIf' [Feb 1 15:33:48] -- Executing [s@macro-dnv-incoming-call-handler:20] GotoIf("SIP/4011-0a09e3d8", "0?:IdentifyCID") in new stack [Feb 1 15:33:48] -- Goto (macro-dnv-incoming-call-handler,s,24) [Feb 1 15:33:48] DEBUG[15912]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '4011' [Feb 1 15:33:48] DEBUG[15912]: pbx.c:1690 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 1 15:33:48] DEBUG[15912]: pbx.c:1769 pbx_extension_helper: Launching 'GotoIf' [Feb 1 15:33:48] -- Executing [s@macro-dnv-incoming-call-handler:24] GotoIf("SIP/4011-0a09e3d8", "0?:Finish") in new stack [Feb 1 15:33:48] -- Goto (macro-dnv-incoming-call-handler,s,26) [Feb 1 15:33:48] DEBUG[15912]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '"ITS Test 2" <4011>' [Feb 1 15:33:48] DEBUG[15912]: pbx.c:1769 pbx_extension_helper: Launching 'NoOp' [Feb 1 15:33:48] -- Executing [s@macro-dnv-incoming-call-handler:26] NoOp("SIP/4011-0a09e3d8", ""ITS Test 2" <4011>") in new stack [Feb 1 15:33:48] DEBUG[15912]: pbx.c:1769 pbx_extension_helper: Launching 'Macro' [Feb 1 15:33:48] -- Executing [4012@ITS:2] Macro("SIP/4011-0a09e3d8", "dnv-standard-dialer|SIP/4012|20|o") in new stack [Feb 1 15:33:48] DEBUG[15912]: pbx.c:1769 pbx_extension_helper: Launching 'Dial' [Feb 1 15:33:48] -- Executing [s@macro-dnv-standard-dialer:1] Dial("SIP/4011-0a09e3d8", "SIP/4012|20|o") in new stack [Feb 1 15:33:48] DEBUG[15912]: chan_sip.c:15236 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Feb 1 15:33:48] DEBUG[15912]: chan_sip.c:4299 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Feb 1 15:33:48] DEBUG[15912]: chan_sip.c:2575 do_setnat: Setting NAT on RTP to Off [Feb 1 15:33:48] DEBUG[15912]: chan_sip.c:3802 sip_new: *** Our native formats are 0x4 (ulaw) [Feb 1 15:33:48] DEBUG[15912]: chan_sip.c:3803 sip_new: *** Joint capabilities are 0x0 (nothing) [Feb 1 15:33:48] DEBUG[15912]: chan_sip.c:3804 sip_new: *** Our capabilities are 0x6 (gsm|ulaw) [Feb 1 15:33:48] DEBUG[15912]: chan_sip.c:3805 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Feb 1 15:33:48] DEBUG[15912]: chan_sip.c:3807 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Feb 1 15:33:48] DEBUG[15912]: chan_sip.c:3828 sip_new: This channel will not be able to handle video. [Feb 1 15:33:48] DEBUG[15912]: channel.c:3294 ast_channel_inherit_variables: Not copying variable STACK-macro-dnv-standard-dialer-s-1. [Feb 1 15:33:48] DEBUG[15912]: channel.c:3294 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. [Feb 1 15:33:48] DEBUG[15912]: channel.c:3294 ast_channel_inherit_variables: Not copying variable ARG3. [Feb 1 15:33:48] DEBUG[15912]: channel.c:3294 ast_channel_inherit_variables: Not copying variable ARG2. [Feb 1 15:33:48] DEBUG[15912]: channel.c:3294 ast_channel_inherit_variables: Not copying variable ARG1. [Feb 1 15:33:48] DEBUG[15912]: channel.c:3294 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY. [Feb 1 15:33:48] DEBUG[15912]: channel.c:3294 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT. [Feb 1 15:33:48] DEBUG[15912]: channel.c:3294 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN. [Feb 1 15:33:48] DEBUG[15912]: channel.c:3294 ast_channel_inherit_variables: Not copying variable STACK-ITS-4012-2. [Feb 1 15:33:48] DEBUG[15912]: channel.c:3294 ast_channel_inherit_variables: Not copying variable STACK-macro-dnv-incoming-call-handler-s-26. [Feb 1 15:33:48] DEBUG[15912]: channel.c:3294 ast_channel_inherit_variables: Not copying variable STACK-macro-dnv-incoming-call-handler-s-24. [Feb 1 15:33:48] DEBUG[15912]: channel.c:3294 ast_channel_inherit_variables: Not copying variable STACK-macro-dnv-incoming-call-handler-s-20. [Feb 1 15:33:48] DEBUG[15912]: channel.c:3294 ast_channel_inherit_variables: Not copying variable STACK-macro-dnv-incoming-call-handler-s-19. [Feb 1 15:33:48] DEBUG[15912]: channel.c:3294 ast_channel_inherit_variables: Not copying variable STACK-macro-dnv-incoming-call-handler-s-13. [Feb 1 15:33:48] DEBUG[15912]: channel.c:3294 ast_channel_inherit_variables: Not copying variable vm_context. [Feb 1 15:33:48] DEBUG[15912]: channel.c:3294 ast_channel_inherit_variables: Not copying variable STACK-macro-dnv-incoming-call-handler-s-12. [Feb 1 15:33:48] DEBUG[15912]: channel.c:3294 ast_channel_inherit_variables: Not copying variable STACK-macro-dnv-incoming-call-handler-s-8. [Feb 1 15:33:48] DEBUG[15912]: channel.c:3294 ast_channel_inherit_variables: Not copying variable STACK-macro-dnv-incoming-call-handler-s-5. [Feb 1 15:33:48] DEBUG[15912]: channel.c:3294 ast_channel_inherit_variables: Not copying variable STACK-macro-dnv-incoming-call-handler-s-4. [Feb 1 15:33:48] DEBUG[15912]: channel.c:3294 ast_channel_inherit_variables: Not copying variable STACK-macro-dnv-incoming-call-handler-s-3. [Feb 1 15:33:48] DEBUG[15912]: channel.c:3294 ast_channel_inherit_variables: Not copying variable STACK-macro-dnv-incoming-call-handler-s-2. [Feb 1 15:33:48] DEBUG[15912]: channel.c:3294 ast_channel_inherit_variables: Not copying variable STACK-macro-dnv-incoming-call-handler-s-1. [Feb 1 15:33:48] DEBUG[15912]: channel.c:3294 ast_channel_inherit_variables: Not copying variable STACK-ITS-4012-1. [Feb 1 15:33:48] DEBUG[15912]: channel.c:3294 ast_channel_inherit_variables: Not copying variable STACK-internal-4012-1. [Feb 1 15:33:48] DEBUG[15912]: channel.c:3294 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Feb 1 15:33:48] DEBUG[15912]: channel.c:3294 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Feb 1 15:33:48] DEBUG[15912]: channel.c:3294 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Feb 1 15:33:48] DEBUG[15912]: channel.c:3294 ast_channel_inherit_variables: Not copying variable SIPURI. [Feb 1 15:33:48] DEBUG[15912]: chan_sip.c:2830 sip_call: Outgoing Call for 4012 [Feb 1 15:33:48] DEBUG[15912]: chan_sip.c:3002 update_call_counter: Updating call counter for outgoing call [Feb 1 15:33:48] DEBUG[15912]: chan_sip.c:3076 update_call_counter: Call to peer '4012' is 1 out of 200 [Feb 1 15:33:48] DEBUG[15912]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4012 [Feb 1 15:33:48] DEBUG[15912]: chan_sip.c:2844 sip_call: Our T38 capability (0), joint T38 capability (0) [Feb 1 15:33:48] DEBUG[15912]: chan_sip.c:6175 add_sdp: ** Our capability: 0x6 (gsm|ulaw) Video flag: False [Feb 1 15:33:48] DEBUG[15912]: chan_sip.c:6176 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Feb 1 15:33:48] DEBUG[15912]: chan_sip.c:6307 add_sdp: -- Done with adding codecs to SDP [Feb 1 15:33:48] DEBUG[15912]: channel.c:2374 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=22) [Feb 1 15:33:48] DEBUG[15912]: chan_sip.c:6352 add_sdp: Done building SDP. Settling with this capability: 0x6 (gsm|ulaw) [Feb 1 15:33:48] -- Called 4012 [Feb 1 15:33:48] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4012 [Feb 1 15:33:48] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4012 [Feb 1 15:33:48] DEBUG[15871]: devicestate.c:287 do_state_change: Changing state for SIP/4012 - state 6 (Ringing) [Feb 1 15:33:48] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4012 [Feb 1 15:33:48] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4012 [Feb 1 15:33:48] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4012 [Feb 1 15:33:48] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4012 [Feb 1 15:33:48] Extension Changed 4012 new state Ringing for Notify User 4010 [Feb 1 15:33:48] DEBUG[15913]: app_queue.c:546 changethread: Device 'SIP/4011' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 1 15:33:48] DEBUG[15914]: app_queue.c:546 changethread: Device 'SIP/4011' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 1 15:33:48] DEBUG[15915]: app_queue.c:546 changethread: Device 'SIP/4012' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Feb 1 15:33:48] DEBUG[15885]: chan_sip.c:4350 find_call: = No match Their Call ID: 4cb7a7a22cc6d21272df86c2692bde39@172.16.16.12 Their Tag Our tag: as1956d2de [Feb 1 15:33:48] DEBUG[15885]: chan_sip.c:4350 find_call: = No match Their Call ID: 4c0b74e8-8da8f9c6-52afc3e1@172.16.16.101 Their Tag BA290F54-E0AB60A7 Our tag: as2eb93749 [Feb 1 15:33:48] DEBUG[15885]: chan_sip.c:4350 find_call: = No match Their Call ID: 6649a393-ca48eeb9-2b6dffc4@172.16.16.135 Their Tag 872B3D6F-720D4382 Our tag: as14ab44b8 [Feb 1 15:33:48] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: ab3d9dbe-818638ec-45e789b@172.16.16.135 Their Tag 60ADF86A-A3525C81 Our tag: as702f5b89 [Feb 1 15:33:48] DEBUG[15885]: chan_sip.c:2089 __sip_ack: Stopping retransmission on 'ab3d9dbe-818638ec-45e789b@172.16.16.135' of Request 103: Match Not Found [Feb 1 15:33:48] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: 4cb7a7a22cc6d21272df86c2692bde39@172.16.16.12 Their Tag Our tag: as1956d2de [Feb 1 15:33:48] DEBUG[15885]: chan_sip.c:2131 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '4cb7a7a22cc6d21272df86c2692bde39@172.16.16.12' Request 102: Found [Feb 1 15:33:48] DEBUG[15885]: chan_sip.c:11606 handle_response_invite: SIP response 100 to standard invite [Feb 1 15:33:48] DEBUG[15885]: chan_sip.c:4350 find_call: = No match Their Call ID: 4cb7a7a22cc6d21272df86c2692bde39@172.16.16.12 Their Tag E7DE8526-F0EF4CC1 Our tag: as1956d2de [Feb 1 15:33:48] DEBUG[15885]: chan_sip.c:4350 find_call: = No match Their Call ID: 4c0b74e8-8da8f9c6-52afc3e1@172.16.16.101 Their Tag BA290F54-E0AB60A7 Our tag: as2eb93749 [Feb 1 15:33:48] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: 6649a393-ca48eeb9-2b6dffc4@172.16.16.135 Their Tag 872B3D6F-720D4382 Our tag: as14ab44b8 [Feb 1 15:33:48] DEBUG[15885]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '6649a393-ca48eeb9-2b6dffc4@172.16.16.135' of Request 103: Match Not Found [Feb 1 15:33:49] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: 4cb7a7a22cc6d21272df86c2692bde39@172.16.16.12 Their Tag E7DE8526-F0EF4CC1 Our tag: as1956d2de [Feb 1 15:33:49] DEBUG[15885]: chan_sip.c:2131 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '4cb7a7a22cc6d21272df86c2692bde39@172.16.16.12' Request 102: Found [Feb 1 15:33:49] DEBUG[15885]: chan_sip.c:11606 handle_response_invite: SIP response 180 to standard invite [Feb 1 15:33:49] DEBUG[15885]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4012-09fb7940 [Feb 1 15:33:49] -- SIP/4012-09fb7940 is ringing [Feb 1 15:33:49] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4012 [Feb 1 15:33:49] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4012 [Feb 1 15:33:49] DEBUG[15871]: devicestate.c:287 do_state_change: Changing state for SIP/4012 - state 6 (Ringing) [Feb 1 15:33:49] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4012 [Feb 1 15:33:49] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4012 [Feb 1 15:33:49] DEBUG[15916]: app_queue.c:546 changethread: Device 'SIP/4012' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Feb 1 15:33:49] DEBUG[15885]: chan_sip.c:4299 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Feb 1 15:33:49] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: 445e047a66de68d51e0a11e851ee60bd@172.16.16.12 Their Tag Our tag: as1fdabff2 [Feb 1 15:33:49] DEBUG[15885]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '445e047a66de68d51e0a11e851ee60bd@172.16.16.12' of Request 102: Match Not Found [Feb 1 15:33:49] Really destroying SIP dialog '445e047a66de68d51e0a11e851ee60bd@172.16.16.12' Method: OPTIONS [Feb 1 15:33:49] DEBUG[15885]: chan_sip.c:4299 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Feb 1 15:33:49] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: 2572922537e561127e0955605b788960@172.16.16.12 Their Tag Our tag: as62cdfce7 [Feb 1 15:33:49] DEBUG[15885]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '2572922537e561127e0955605b788960@172.16.16.12' of Request 102: Match Not Found [Feb 1 15:33:49] Really destroying SIP dialog '2572922537e561127e0955605b788960@172.16.16.12' Method: OPTIONS [Feb 1 15:33:50] DEBUG[15885]: chan_sip.c:4299 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Feb 1 15:33:50] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: 5f59150676f514833d84d3386ae53dcd@172.16.16.12 Their Tag Our tag: as173f385a [Feb 1 15:33:50] DEBUG[15885]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '5f59150676f514833d84d3386ae53dcd@172.16.16.12' of Request 102: Match Not Found [Feb 1 15:33:50] DEBUG[15885]: chan_sip.c:4299 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Feb 1 15:33:50] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: 088a5e70174354f27b25383e446f6308@172.16.16.12 Their Tag Our tag: as466f3a92 [Feb 1 15:33:50] DEBUG[15885]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '088a5e70174354f27b25383e446f6308@172.16.16.12' of Request 102: Match Not Found [Feb 1 15:33:51] DEBUG[15885]: chan_sip.c:4350 find_call: = No match Their Call ID: 088a5e70174354f27b25383e446f6308@172.16.16.12 Their Tag 10027684-26263499 Our tag: as466f3a92 [Feb 1 15:33:51] DEBUG[15885]: chan_sip.c:4350 find_call: = No match Their Call ID: 5f59150676f514833d84d3386ae53dcd@172.16.16.12 Their Tag 6F8A6DC4-9B084E7D Our tag: as173f385a [Feb 1 15:33:51] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: 4cb7a7a22cc6d21272df86c2692bde39@172.16.16.12 Their Tag E7DE8526-F0EF4CC1 Our tag: as1956d2de [Feb 1 15:33:51] DEBUG[15885]: chan_sip.c:2071 __sip_ack: Acked pending invite 102 [Feb 1 15:33:51] DEBUG[15885]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '4cb7a7a22cc6d21272df86c2692bde39@172.16.16.12' of Request 102: Match Not Found [Feb 1 15:33:51] DEBUG[15885]: chan_sip.c:11606 handle_response_invite: SIP response 200 to standard invite [Feb 1 15:33:51] DEBUG[15885]: chan_sip.c:5105 process_sdp: T38 state changed to 0 on channel SIP/4012-09fb7940 [Feb 1 15:33:51] DEBUG[15885]: chan_sip.c:5182 process_sdp: We're settling with these formats: 0x4 (ulaw) [Feb 1 15:33:51] DEBUG[15885]: chan_sip.c:5189 process_sdp: We have an owner, now see if we need to change this call [Feb 1 15:33:51] DEBUG[15885]: chan_sip.c:3002 update_call_counter: Updating call counter for outgoing call [Feb 1 15:33:51] DEBUG[15885]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4012 [Feb 1 15:33:51] DEBUG[15885]: chan_sip.c:7950 build_route: build_route: Contact hop: [Feb 1 15:33:51] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4012 [Feb 1 15:33:51] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4012 [Feb 1 15:33:51] DEBUG[15871]: devicestate.c:287 do_state_change: Changing state for SIP/4012 - state 2 (In use) [Feb 1 15:33:51] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4012 [Feb 1 15:33:51] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4012 [Feb 1 15:33:51] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4012 [Feb 1 15:33:51] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4012 [Feb 1 15:33:51] Extension Changed 4012 new state InUse for Notify User 4010 [Feb 1 15:33:51] DEBUG[15912]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4012-09fb7940 [Feb 1 15:33:51] -- SIP/4012-09fb7940 answered SIP/4011-0a09e3d8 [Feb 1 15:33:51] DEBUG[15912]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4011-0a09e3d8 [Feb 1 15:33:51] DEBUG[15912]: chan_sip.c:3455 sip_answer: SIP answering channel: SIP/4011-0a09e3d8 [Feb 1 15:33:51] DEBUG[15912]: chan_sip.c:6409 transmit_response_with_sdp: Setting framing from config on incoming call [Feb 1 15:33:51] DEBUG[15912]: chan_sip.c:6175 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Feb 1 15:33:51] DEBUG[15912]: chan_sip.c:6176 add_sdp: ** Our prefcodec: 0x0 (nothing) [Feb 1 15:33:51] DEBUG[15912]: chan_sip.c:6307 add_sdp: -- Done with adding codecs to SDP [Feb 1 15:33:51] DEBUG[15912]: channel.c:2374 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=19) [Feb 1 15:33:51] DEBUG[15912]: chan_sip.c:6352 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Feb 1 15:33:51] -- Packet2Packet bridging SIP/4011-0a09e3d8 and SIP/4012-09fb7940 [Feb 1 15:33:51] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4012 [Feb 1 15:33:51] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4012 [Feb 1 15:33:51] DEBUG[15871]: devicestate.c:287 do_state_change: Changing state for SIP/4012 - state 2 (In use) [Feb 1 15:33:51] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4012 [Feb 1 15:33:51] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4012 [Feb 1 15:33:51] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4011 [Feb 1 15:33:51] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4011 [Feb 1 15:33:51] DEBUG[15871]: devicestate.c:287 do_state_change: Changing state for SIP/4011 - state 2 (In use) [Feb 1 15:33:51] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4011 [Feb 1 15:33:51] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4011 [Feb 1 15:33:51] DEBUG[15920]: app_queue.c:546 changethread: Device 'SIP/4012' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 1 15:33:51] DEBUG[15921]: app_queue.c:546 changethread: Device 'SIP/4012' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 1 15:33:51] DEBUG[15922]: app_queue.c:546 changethread: Device 'SIP/4011' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 1 15:33:51] DEBUG[15885]: chan_sip.c:4350 find_call: = No match Their Call ID: 088a5e70174354f27b25383e446f6308@172.16.16.12 Their Tag 10027684-26263499 Our tag: as466f3a92 [Feb 1 15:33:51] DEBUG[15885]: chan_sip.c:4350 find_call: = No match Their Call ID: 5f59150676f514833d84d3386ae53dcd@172.16.16.12 Their Tag 6F8A6DC4-9B084E7D Our tag: as173f385a [Feb 1 15:33:51] DEBUG[15885]: chan_sip.c:4350 find_call: = No match Their Call ID: 4cb7a7a22cc6d21272df86c2692bde39@172.16.16.12 Their Tag E7DE8526-F0EF4CC1 Our tag: as1956d2de [Feb 1 15:33:51] DEBUG[15885]: chan_sip.c:4350 find_call: = No match Their Call ID: 4c0b74e8-8da8f9c6-52afc3e1@172.16.16.101 Their Tag BA290F54-E0AB60A7 Our tag: as2eb93749 [Feb 1 15:33:51] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: 6649a393-ca48eeb9-2b6dffc4@172.16.16.135 Their Tag 872B3D6F-720D4382 Our tag: as14ab44b8 [Feb 1 15:33:51] DEBUG[15885]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '6649a393-ca48eeb9-2b6dffc4@172.16.16.135' of Request 104: Match Not Found [Feb 1 15:33:51] DEBUG[15885]: chan_sip.c:4350 find_call: = No match Their Call ID: 088a5e70174354f27b25383e446f6308@172.16.16.12 Their Tag 10027684-26263499 Our tag: as466f3a92 [Feb 1 15:33:51] DEBUG[15885]: chan_sip.c:4350 find_call: = No match Their Call ID: 5f59150676f514833d84d3386ae53dcd@172.16.16.12 Their Tag 6F8A6DC4-9B084E7D Our tag: as173f385a [Feb 1 15:33:51] DEBUG[15885]: chan_sip.c:4350 find_call: = No match Their Call ID: 4cb7a7a22cc6d21272df86c2692bde39@172.16.16.12 Their Tag E7DE8526-F0EF4CC1 Our tag: as1956d2de [Feb 1 15:33:51] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: 4c0b74e8-8da8f9c6-52afc3e1@172.16.16.101 Their Tag BA290F54-E0AB60A7 Our tag: as2eb93749 [Feb 1 15:33:51] DEBUG[15885]: chan_sip.c:14571 handle_request: **** Received ACK (6) - Command in SIP ACK [Feb 1 15:33:51] DEBUG[15885]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '4c0b74e8-8da8f9c6-52afc3e1@172.16.16.101' of Response 2: Match Not Found [Feb 1 15:33:51] Really destroying SIP dialog '088a5e70174354f27b25383e446f6308@172.16.16.12' Method: OPTIONS [Feb 1 15:33:51] Really destroying SIP dialog '5f59150676f514833d84d3386ae53dcd@172.16.16.12' Method: OPTIONS [Feb 1 15:33:52] DEBUG[15912]: rtp.c:871 ast_rtcp_read: Got RTCP report of 84 bytes [Feb 1 15:33:53] DEBUG[15885]: chan_sip.c:4350 find_call: = No match Their Call ID: 4cb7a7a22cc6d21272df86c2692bde39@172.16.16.12 Their Tag E7DE8526-F0EF4CC1 Our tag: as1956d2de [Feb 1 15:33:53] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: 4c0b74e8-8da8f9c6-52afc3e1@172.16.16.101 Their Tag BA290F54-E0AB60A7 Our tag: as2eb93749 [Feb 1 15:33:53] DEBUG[15885]: chan_sip.c:14571 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Feb 1 15:33:53] DEBUG[15885]: chan_sip.c:5105 process_sdp: T38 state changed to 0 on channel SIP/4011-0a09e3d8 [Feb 1 15:33:53] DEBUG[15885]: chan_sip.c:5182 process_sdp: We're settling with these formats: 0x4 (ulaw) [Feb 1 15:33:53] DEBUG[15885]: chan_sip.c:5189 process_sdp: We have an owner, now see if we need to change this call [Feb 1 15:33:53] DEBUG[15885]: chan_sip.c:13507 handle_request_invite: SIP/4011-0a09e3d8: This call is UP.... [Feb 1 15:33:53] DEBUG[15885]: chan_sip.c:6409 transmit_response_with_sdp: Setting framing from config on incoming call [Feb 1 15:33:53] DEBUG[15885]: chan_sip.c:6175 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Feb 1 15:33:53] DEBUG[15885]: chan_sip.c:6176 add_sdp: ** Our prefcodec: 0x0 (nothing) [Feb 1 15:33:53] DEBUG[15885]: chan_sip.c:6307 add_sdp: -- Done with adding codecs to SDP [Feb 1 15:33:53] DEBUG[15885]: channel.c:2374 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=19) [Feb 1 15:33:53] DEBUG[15885]: chan_sip.c:6352 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Feb 1 15:33:53] DEBUG[15912]: channel.c:2838 set_format: Set channel SIP/4012-09fb7940 to write format slin [Feb 1 15:33:53] -- Started music on hold, class 'default', on channel 'SIP/4012-09fb7940' [Feb 1 15:33:53] DEBUG[15912]: channel.c:1991 ast_settimeout: Scheduling timer at 160 sample intervals [Feb 1 15:33:53] DEBUG[15912]: channel.c:2374 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=22) [Feb 1 15:33:53] DEBUG[15912]: channel.c:2325 __ast_read: Generator got voice, switching to phase locked mode [Feb 1 15:33:53] DEBUG[15912]: channel.c:1991 ast_settimeout: Scheduling timer at 0 sample intervals [Feb 1 15:33:53] DEBUG[15912]: channel.c:2334 __ast_read: Auto-deactivating generator [Feb 1 15:33:53] DEBUG[15912]: channel.c:2838 set_format: Set channel SIP/4012-09fb7940 to write format ulaw [Feb 1 15:33:53] -- Stopped music on hold on SIP/4012-09fb7940 [Feb 1 15:33:53] DEBUG[15912]: channel.c:1991 ast_settimeout: Scheduling timer at 0 sample intervals [Feb 1 15:33:54] DEBUG[15885]: chan_sip.c:4350 find_call: = No match Their Call ID: 4cb7a7a22cc6d21272df86c2692bde39@172.16.16.12 Their Tag E7DE8526-F0EF4CC1 Our tag: as1956d2de [Feb 1 15:33:54] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: 4c0b74e8-8da8f9c6-52afc3e1@172.16.16.101 Their Tag BA290F54-E0AB60A7 Our tag: as2eb93749 [Feb 1 15:33:54] DEBUG[15885]: chan_sip.c:14571 handle_request: **** Received ACK (6) - Command in SIP ACK [Feb 1 15:33:54] DEBUG[15885]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '4c0b74e8-8da8f9c6-52afc3e1@172.16.16.101' of Response 3: Match Not Found [Feb 1 15:33:55] DEBUG[15912]: rtp.c:871 ast_rtcp_read: Got RTCP report of 84 bytes [Feb 1 15:33:55] DEBUG[15876]: chan_iax2.c:4773 raw_hangup: Raw Hangup 204.239.10.89:2822, src=0, dst=0 [Feb 1 15:33:56] DEBUG[15885]: chan_sip.c:4350 find_call: = No match Their Call ID: 4cb7a7a22cc6d21272df86c2692bde39@172.16.16.12 Their Tag E7DE8526-F0EF4CC1 Our tag: as1956d2de [Feb 1 15:33:56] DEBUG[15885]: chan_sip.c:4350 find_call: = No match Their Call ID: 4c0b74e8-8da8f9c6-52afc3e1@172.16.16.101 Their Tag BA290F54-E0AB60A7 Our tag: as2eb93749 [Feb 1 15:33:56] DEBUG[15885]: chan_sip.c:4350 find_call: = No match Their Call ID: 6649a393-ca48eeb9-2b6dffc4@172.16.16.135 Their Tag 872B3D6F-720D4382 Our tag: as14ab44b8 [Feb 1 15:33:56] DEBUG[15885]: chan_sip.c:4350 find_call: = No match Their Call ID: ab3d9dbe-818638ec-45e789b@172.16.16.135 Their Tag 60ADF86A-A3525C81 Our tag: as702f5b89 [Feb 1 15:33:56] DEBUG[15885]: chan_sip.c:2575 do_setnat: Setting NAT on RTP to Off [Feb 1 15:33:56] DEBUG[15885]: chan_sip.c:4299 sip_alloc: Allocating new SIP dialog for f7c7e776-68885084-acc1ce97@172.16.16.101 - INVITE (With RTP) [Feb 1 15:33:56] DEBUG[15885]: chan_sip.c:14571 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Feb 1 15:33:56] DEBUG[15885]: chan_sip.c:2575 do_setnat: Setting NAT on RTP to Off [Feb 1 15:33:57] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: f7c7e776-68885084-acc1ce97@172.16.16.101 Their Tag 5834A1C2-8A117DCD Our tag: as0e6a4039 [Feb 1 15:33:57] DEBUG[15885]: chan_sip.c:14571 handle_request: **** Received ACK (6) - Command in SIP ACK [Feb 1 15:33:57] DEBUG[15885]: chan_sip.c:2089 __sip_ack: Stopping retransmission on 'f7c7e776-68885084-acc1ce97@172.16.16.101' of Response 1: Match Not Found [Feb 1 15:33:57] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: f7c7e776-68885084-acc1ce97@172.16.16.101 Their Tag 5834A1C2-8A117DCD Our tag: as0e6a4039 [Feb 1 15:33:57] DEBUG[15885]: chan_sip.c:14571 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Feb 1 15:33:57] DEBUG[15885]: chan_sip.c:2575 do_setnat: Setting NAT on RTP to Off [Feb 1 15:33:57] DEBUG[15885]: chan_sip.c:5105 process_sdp: T38 state changed to 0 on channel [Feb 1 15:33:57] DEBUG[15885]: chan_sip.c:5182 process_sdp: We're settling with these formats: 0x4 (ulaw) [Feb 1 15:33:57] DEBUG[15885]: chan_sip.c:13359 handle_request_invite: Checking SIP call limits for device 4011 [Feb 1 15:33:57] DEBUG[15885]: chan_sip.c:3002 update_call_counter: Updating call counter for incoming call [Feb 1 15:33:57] DEBUG[15885]: chan_sip.c:3076 update_call_counter: Call from peer '4011' is 2 out of 200 [Feb 1 15:33:57] DEBUG[15885]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4011 [Feb 1 15:33:57] DEBUG[15885]: chan_sip.c:3802 sip_new: *** Our native formats are 0x4 (ulaw) [Feb 1 15:33:57] DEBUG[15885]: chan_sip.c:3803 sip_new: *** Joint capabilities are 0x4 (ulaw) [Feb 1 15:33:57] DEBUG[15885]: chan_sip.c:3804 sip_new: *** Our capabilities are 0x6 (gsm|ulaw) [Feb 1 15:33:57] DEBUG[15885]: chan_sip.c:3805 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Feb 1 15:33:57] DEBUG[15885]: chan_sip.c:3828 sip_new: This channel will not be able to handle video. [Feb 1 15:33:57] DEBUG[15885]: chan_sip.c:7950 build_route: build_route: Contact hop: [Feb 1 15:33:57] DEBUG[15885]: chan_sip.c:13434 handle_request_invite: SIP/4011-0a0a7840: New call is still down.... Trying... [Feb 1 15:33:57] DEBUG[15885]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4011-0a0a7840 [Feb 1 15:33:57] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4011 [Feb 1 15:33:57] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4011 [Feb 1 15:33:57] DEBUG[15871]: devicestate.c:287 do_state_change: Changing state for SIP/4011 - state 2 (In use) [Feb 1 15:33:57] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4011 [Feb 1 15:33:57] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4011 [Feb 1 15:33:57] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4011 [Feb 1 15:33:57] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4011 [Feb 1 15:33:57] DEBUG[15871]: devicestate.c:287 do_state_change: Changing state for SIP/4011 - state 2 (In use) [Feb 1 15:33:57] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4011 [Feb 1 15:33:57] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4011 [Feb 1 15:33:57] DEBUG[15923]: pbx.c:1769 pbx_extension_helper: Launching 'Goto' [Feb 1 15:33:57] -- Executing [4010@internal:1] Goto("SIP/4011-0a0a7840", "ITS|4010|1") in new stack [Feb 1 15:33:57] -- Goto (ITS,4010,1) [Feb 1 15:33:57] DEBUG[15923]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '4011' [Feb 1 15:33:57] DEBUG[15923]: pbx.c:1769 pbx_extension_helper: Launching 'Macro' [Feb 1 15:33:57] -- Executing [4010@ITS:1] Macro("SIP/4011-0a0a7840", "dnv-incoming-call-handler|4011|4010") in new stack [Feb 1 15:33:57] DEBUG[15923]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'ITS Test 1' [Feb 1 15:33:57] DEBUG[15923]: pbx.c:1769 pbx_extension_helper: Launching 'NoOp' [Feb 1 15:33:57] -- Executing [s@macro-dnv-incoming-call-handler:1] NoOp("SIP/4011-0a0a7840", "ITS Test 1") in new stack [Feb 1 15:33:57] DEBUG[15923]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'ITS Test 1' [Feb 1 15:33:57] DEBUG[15923]: pbx.c:1690 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 1 15:33:57] DEBUG[15923]: pbx.c:1769 pbx_extension_helper: Launching 'GotoIf' [Feb 1 15:33:57] -- Executing [s@macro-dnv-incoming-call-handler:2] GotoIf("SIP/4011-0a0a7840", "0?SetVoiceMailContext") in new stack [Feb 1 15:33:57] DEBUG[15923]: pbx.c:5947 pbx_builtin_gotoif: Not taking any branch [Feb 1 15:33:57] DEBUG[15923]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'SIP' [Feb 1 15:33:57] DEBUG[15923]: pbx.c:1690 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 1 15:33:57] DEBUG[15923]: pbx.c:1769 pbx_extension_helper: Launching 'GotoIf' [Feb 1 15:33:57] -- Executing [s@macro-dnv-incoming-call-handler:3] GotoIf("SIP/4011-0a0a7840", "1?:SetVoiceMailContext") in new stack [Feb 1 15:33:57] DEBUG[15923]: pbx.c:5947 pbx_builtin_gotoif: Not taking any branch [Feb 1 15:33:57] DEBUG[15923]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'ITS Test 1' [Feb 1 15:33:57] DEBUG[15923]: pbx.c:1769 pbx_extension_helper: Launching 'SIPCalledRPID' [Feb 1 15:33:57] -- Executing [s@macro-dnv-incoming-call-handler:4] SIPCalledRPID("SIP/4011-0a0a7840", "ITS Test 1|4010") in new stack [Feb 1 15:33:57] DEBUG[15923]: pbx.c:1690 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 1 15:33:57] DEBUG[15923]: pbx.c:1769 pbx_extension_helper: Launching 'GotoIf' [Feb 1 15:33:57] -- Executing [s@macro-dnv-incoming-call-handler:5] GotoIf("SIP/4011-0a0a7840", "0?:NVDPL") in new stack [Feb 1 15:33:57] -- Goto (macro-dnv-incoming-call-handler,s,8) [Feb 1 15:33:57] DEBUG[15923]: pbx.c:1690 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 1 15:33:57] DEBUG[15923]: pbx.c:1769 pbx_extension_helper: Launching 'GotoIf' [Feb 1 15:33:57] -- Executing [s@macro-dnv-incoming-call-handler:8] GotoIf("SIP/4011-0a0a7840", "0?:Default") in new stack [Feb 1 15:33:57] -- Goto (macro-dnv-incoming-call-handler,s,12) [Feb 1 15:33:57] DEBUG[15923]: pbx.c:1769 pbx_extension_helper: Launching 'Set' [Feb 1 15:33:57] -- Executing [s@macro-dnv-incoming-call-handler:12] Set("SIP/4011-0a0a7840", "vm_context=default") in new stack [Feb 1 15:33:57] DEBUG[15923]: pbx.c:1690 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 1 15:33:57] DEBUG[15923]: pbx.c:1690 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 1 15:33:57] DEBUG[15923]: pbx.c:1690 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 1 15:33:57] DEBUG[15923]: pbx.c:1690 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 1 15:33:57] DEBUG[15923]: pbx.c:1690 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 1 15:33:57] DEBUG[15923]: pbx.c:1769 pbx_extension_helper: Launching 'GotoIf' [Feb 1 15:33:57] -- Executing [s@macro-dnv-incoming-call-handler:13] GotoIf("SIP/4011-0a0a7840", "0?:Proceed") in new stack [Feb 1 15:33:57] -- Goto (macro-dnv-incoming-call-handler,s,19) [Feb 1 15:33:57] DEBUG[15923]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '"ITS Test 2" <4011>' [Feb 1 15:33:57] DEBUG[15923]: pbx.c:1769 pbx_extension_helper: Launching 'NoOp' [Feb 1 15:33:57] -- Executing [s@macro-dnv-incoming-call-handler:19] NoOp("SIP/4011-0a0a7840", ""ITS Test 2" <4011>") in new stack [Feb 1 15:33:57] DEBUG[15923]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '4011' [Feb 1 15:33:57] DEBUG[15923]: pbx.c:1690 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 1 15:33:57] DEBUG[15923]: pbx.c:1769 pbx_extension_helper: Launching 'GotoIf' [Feb 1 15:33:57] -- Executing [s@macro-dnv-incoming-call-handler:20] GotoIf("SIP/4011-0a0a7840", "0?:IdentifyCID") in new stack [Feb 1 15:33:57] -- Goto (macro-dnv-incoming-call-handler,s,24) [Feb 1 15:33:57] DEBUG[15923]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '4011' [Feb 1 15:33:57] DEBUG[15923]: pbx.c:1690 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 1 15:33:57] DEBUG[15923]: pbx.c:1769 pbx_extension_helper: Launching 'GotoIf' [Feb 1 15:33:57] -- Executing [s@macro-dnv-incoming-call-handler:24] GotoIf("SIP/4011-0a0a7840", "0?:Finish") in new stack [Feb 1 15:33:57] -- Goto (macro-dnv-incoming-call-handler,s,26) [Feb 1 15:33:57] DEBUG[15923]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '"ITS Test 2" <4011>' [Feb 1 15:33:57] DEBUG[15923]: pbx.c:1769 pbx_extension_helper: Launching 'NoOp' [Feb 1 15:33:57] -- Executing [s@macro-dnv-incoming-call-handler:26] NoOp("SIP/4011-0a0a7840", ""ITS Test 2" <4011>") in new stack [Feb 1 15:33:57] DEBUG[15923]: pbx.c:1769 pbx_extension_helper: Launching 'Macro' [Feb 1 15:33:57] -- Executing [4010@ITS:2] Macro("SIP/4011-0a0a7840", "dnv-standard-dialer|SIP/4010|20|o") in new stack [Feb 1 15:33:57] DEBUG[15923]: pbx.c:1769 pbx_extension_helper: Launching 'Dial' [Feb 1 15:33:57] -- Executing [s@macro-dnv-standard-dialer:1] Dial("SIP/4011-0a0a7840", "SIP/4010|20|o") in new stack [Feb 1 15:33:57] DEBUG[15923]: chan_sip.c:15236 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Feb 1 15:33:57] DEBUG[15923]: chan_sip.c:4299 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Feb 1 15:33:57] DEBUG[15923]: chan_sip.c:2575 do_setnat: Setting NAT on RTP to Off [Feb 1 15:33:57] DEBUG[15923]: chan_sip.c:3802 sip_new: *** Our native formats are 0x4 (ulaw) [Feb 1 15:33:57] DEBUG[15923]: chan_sip.c:3803 sip_new: *** Joint capabilities are 0x0 (nothing) [Feb 1 15:33:57] DEBUG[15923]: chan_sip.c:3804 sip_new: *** Our capabilities are 0x6 (gsm|ulaw) [Feb 1 15:33:57] DEBUG[15923]: chan_sip.c:3805 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Feb 1 15:33:57] DEBUG[15923]: chan_sip.c:3807 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Feb 1 15:33:57] DEBUG[15923]: chan_sip.c:3828 sip_new: This channel will not be able to handle video. [Feb 1 15:33:57] DEBUG[15923]: channel.c:3294 ast_channel_inherit_variables: Not copying variable STACK-macro-dnv-standard-dialer-s-1. [Feb 1 15:33:57] DEBUG[15923]: channel.c:3294 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. [Feb 1 15:33:57] DEBUG[15923]: channel.c:3294 ast_channel_inherit_variables: Not copying variable ARG3. [Feb 1 15:33:57] DEBUG[15923]: channel.c:3294 ast_channel_inherit_variables: Not copying variable ARG2. [Feb 1 15:33:57] DEBUG[15923]: channel.c:3294 ast_channel_inherit_variables: Not copying variable ARG1. [Feb 1 15:33:57] DEBUG[15923]: channel.c:3294 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY. [Feb 1 15:33:57] DEBUG[15923]: channel.c:3294 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT. [Feb 1 15:33:57] DEBUG[15923]: channel.c:3294 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN. [Feb 1 15:33:57] DEBUG[15923]: channel.c:3294 ast_channel_inherit_variables: Not copying variable STACK-ITS-4010-2. [Feb 1 15:33:57] DEBUG[15923]: channel.c:3294 ast_channel_inherit_variables: Not copying variable STACK-macro-dnv-incoming-call-handler-s-26. [Feb 1 15:33:57] DEBUG[15923]: channel.c:3294 ast_channel_inherit_variables: Not copying variable STACK-macro-dnv-incoming-call-handler-s-24. [Feb 1 15:33:57] DEBUG[15923]: channel.c:3294 ast_channel_inherit_variables: Not copying variable STACK-macro-dnv-incoming-call-handler-s-20. [Feb 1 15:33:57] DEBUG[15923]: channel.c:3294 ast_channel_inherit_variables: Not copying variable STACK-macro-dnv-incoming-call-handler-s-19. [Feb 1 15:33:57] DEBUG[15923]: channel.c:3294 ast_channel_inherit_variables: Not copying variable STACK-macro-dnv-incoming-call-handler-s-13. [Feb 1 15:33:57] DEBUG[15923]: channel.c:3294 ast_channel_inherit_variables: Not copying variable vm_context. [Feb 1 15:33:57] DEBUG[15923]: channel.c:3294 ast_channel_inherit_variables: Not copying variable STACK-macro-dnv-incoming-call-handler-s-12. [Feb 1 15:33:57] DEBUG[15923]: channel.c:3294 ast_channel_inherit_variables: Not copying variable STACK-macro-dnv-incoming-call-handler-s-8. [Feb 1 15:33:57] DEBUG[15923]: channel.c:3294 ast_channel_inherit_variables: Not copying variable STACK-macro-dnv-incoming-call-handler-s-5. [Feb 1 15:33:57] DEBUG[15923]: channel.c:3294 ast_channel_inherit_variables: Not copying variable STACK-macro-dnv-incoming-call-handler-s-4. [Feb 1 15:33:57] DEBUG[15923]: channel.c:3294 ast_channel_inherit_variables: Not copying variable STACK-macro-dnv-incoming-call-handler-s-3. [Feb 1 15:33:57] DEBUG[15923]: channel.c:3294 ast_channel_inherit_variables: Not copying variable STACK-macro-dnv-incoming-call-handler-s-2. [Feb 1 15:33:57] DEBUG[15923]: channel.c:3294 ast_channel_inherit_variables: Not copying variable STACK-macro-dnv-incoming-call-handler-s-1. [Feb 1 15:33:57] DEBUG[15923]: channel.c:3294 ast_channel_inherit_variables: Not copying variable STACK-ITS-4010-1. [Feb 1 15:33:57] DEBUG[15923]: channel.c:3294 ast_channel_inherit_variables: Not copying variable STACK-internal-4010-1. [Feb 1 15:33:57] DEBUG[15923]: channel.c:3294 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Feb 1 15:33:57] DEBUG[15923]: channel.c:3294 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Feb 1 15:33:57] DEBUG[15923]: channel.c:3294 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Feb 1 15:33:57] DEBUG[15923]: channel.c:3294 ast_channel_inherit_variables: Not copying variable SIPURI. [Feb 1 15:33:57] DEBUG[15923]: chan_sip.c:2830 sip_call: Outgoing Call for 4010 [Feb 1 15:33:57] DEBUG[15923]: chan_sip.c:3002 update_call_counter: Updating call counter for outgoing call [Feb 1 15:33:57] DEBUG[15923]: chan_sip.c:3076 update_call_counter: Call to peer '4010' is 1 out of 200 [Feb 1 15:33:57] DEBUG[15923]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4010 [Feb 1 15:33:57] DEBUG[15923]: chan_sip.c:2844 sip_call: Our T38 capability (0), joint T38 capability (0) [Feb 1 15:33:57] DEBUG[15923]: chan_sip.c:6175 add_sdp: ** Our capability: 0x6 (gsm|ulaw) Video flag: False [Feb 1 15:33:57] DEBUG[15923]: chan_sip.c:6176 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Feb 1 15:33:57] DEBUG[15923]: chan_sip.c:6307 add_sdp: -- Done with adding codecs to SDP [Feb 1 15:33:57] DEBUG[15923]: channel.c:2374 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=28) [Feb 1 15:33:57] DEBUG[15923]: chan_sip.c:6352 add_sdp: Done building SDP. Settling with this capability: 0x6 (gsm|ulaw) [Feb 1 15:33:57] -- Called 4010 [Feb 1 15:33:57] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4010 [Feb 1 15:33:57] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4010 [Feb 1 15:33:57] DEBUG[15871]: devicestate.c:287 do_state_change: Changing state for SIP/4010 - state 6 (Ringing) [Feb 1 15:33:57] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4010 [Feb 1 15:33:57] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4010 [Feb 1 15:33:57] DEBUG[15924]: app_queue.c:546 changethread: Device 'SIP/4011' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 1 15:33:57] DEBUG[15925]: app_queue.c:546 changethread: Device 'SIP/4011' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 1 15:33:57] DEBUG[15926]: app_queue.c:546 changethread: Device 'SIP/4010' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Feb 1 15:33:57] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: 005a69bd632866a500db6a9f79946c2f@172.16.16.12 Their Tag Our tag: as076107cc [Feb 1 15:33:57] DEBUG[15885]: chan_sip.c:2131 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '005a69bd632866a500db6a9f79946c2f@172.16.16.12' Request 102: Found [Feb 1 15:33:57] DEBUG[15885]: chan_sip.c:11606 handle_response_invite: SIP response 100 to standard invite [Feb 1 15:33:57] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: 005a69bd632866a500db6a9f79946c2f@172.16.16.12 Their Tag 97CA0E29-E81B8C74 Our tag: as076107cc [Feb 1 15:33:57] DEBUG[15885]: chan_sip.c:2131 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '005a69bd632866a500db6a9f79946c2f@172.16.16.12' Request 102: Found [Feb 1 15:33:57] DEBUG[15885]: chan_sip.c:11606 handle_response_invite: SIP response 180 to standard invite [Feb 1 15:33:57] DEBUG[15885]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4010-0a0ab7b0 [Feb 1 15:33:57] -- SIP/4010-0a0ab7b0 is ringing [Feb 1 15:33:57] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4010 [Feb 1 15:33:57] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4010 [Feb 1 15:33:57] DEBUG[15871]: devicestate.c:287 do_state_change: Changing state for SIP/4010 - state 6 (Ringing) [Feb 1 15:33:57] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4010 [Feb 1 15:33:57] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4010 [Feb 1 15:33:57] DEBUG[15927]: app_queue.c:546 changethread: Device 'SIP/4010' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Feb 1 15:34:02] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: 005a69bd632866a500db6a9f79946c2f@172.16.16.12 Their Tag 97CA0E29-E81B8C74 Our tag: as076107cc [Feb 1 15:34:02] DEBUG[15885]: chan_sip.c:2071 __sip_ack: Acked pending invite 102 [Feb 1 15:34:02] DEBUG[15885]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '005a69bd632866a500db6a9f79946c2f@172.16.16.12' of Request 102: Match Not Found [Feb 1 15:34:02] DEBUG[15885]: chan_sip.c:11606 handle_response_invite: SIP response 200 to standard invite [Feb 1 15:34:02] DEBUG[15885]: chan_sip.c:5105 process_sdp: T38 state changed to 0 on channel SIP/4010-0a0ab7b0 [Feb 1 15:34:02] DEBUG[15885]: chan_sip.c:5182 process_sdp: We're settling with these formats: 0x4 (ulaw) [Feb 1 15:34:02] DEBUG[15885]: chan_sip.c:5189 process_sdp: We have an owner, now see if we need to change this call [Feb 1 15:34:02] DEBUG[15885]: chan_sip.c:3002 update_call_counter: Updating call counter for outgoing call [Feb 1 15:34:02] DEBUG[15885]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4010 [Feb 1 15:34:02] DEBUG[15885]: chan_sip.c:7950 build_route: build_route: Contact hop: [Feb 1 15:34:02] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4010 [Feb 1 15:34:02] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4010 [Feb 1 15:34:02] DEBUG[15871]: devicestate.c:287 do_state_change: Changing state for SIP/4010 - state 2 (In use) [Feb 1 15:34:02] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4010 [Feb 1 15:34:02] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4010 [Feb 1 15:34:02] DEBUG[15923]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4010-0a0ab7b0 [Feb 1 15:34:02] -- SIP/4010-0a0ab7b0 answered SIP/4011-0a0a7840 [Feb 1 15:34:02] DEBUG[15923]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4011-0a0a7840 [Feb 1 15:34:02] DEBUG[15923]: chan_sip.c:3455 sip_answer: SIP answering channel: SIP/4011-0a0a7840 [Feb 1 15:34:02] DEBUG[15923]: chan_sip.c:6409 transmit_response_with_sdp: Setting framing from config on incoming call [Feb 1 15:34:02] DEBUG[15923]: chan_sip.c:6175 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Feb 1 15:34:02] DEBUG[15923]: chan_sip.c:6176 add_sdp: ** Our prefcodec: 0x0 (nothing) [Feb 1 15:34:02] DEBUG[15923]: chan_sip.c:6307 add_sdp: -- Done with adding codecs to SDP [Feb 1 15:34:02] DEBUG[15923]: channel.c:2374 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Feb 1 15:34:02] DEBUG[15923]: chan_sip.c:6352 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Feb 1 15:34:02] -- Packet2Packet bridging SIP/4011-0a0a7840 and SIP/4010-0a0ab7b0 [Feb 1 15:34:02] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4010 [Feb 1 15:34:02] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4010 [Feb 1 15:34:02] DEBUG[15871]: devicestate.c:287 do_state_change: Changing state for SIP/4010 - state 2 (In use) [Feb 1 15:34:02] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4010 [Feb 1 15:34:02] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4010 [Feb 1 15:34:02] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4011 [Feb 1 15:34:02] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4011 [Feb 1 15:34:02] DEBUG[15871]: devicestate.c:287 do_state_change: Changing state for SIP/4011 - state 2 (In use) [Feb 1 15:34:02] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4011 [Feb 1 15:34:02] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4011 [Feb 1 15:34:02] DEBUG[15928]: app_queue.c:546 changethread: Device 'SIP/4010' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 1 15:34:02] DEBUG[15929]: app_queue.c:546 changethread: Device 'SIP/4010' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 1 15:34:02] DEBUG[15930]: app_queue.c:546 changethread: Device 'SIP/4011' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 1 15:34:02] DEBUG[15885]: chan_sip.c:4350 find_call: = No match Their Call ID: 005a69bd632866a500db6a9f79946c2f@172.16.16.12 Their Tag 97CA0E29-E81B8C74 Our tag: as076107cc [Feb 1 15:34:02] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: f7c7e776-68885084-acc1ce97@172.16.16.101 Their Tag 5834A1C2-8A117DCD Our tag: as6965be42 [Feb 1 15:34:02] DEBUG[15885]: chan_sip.c:14571 handle_request: **** Received ACK (6) - Command in SIP ACK [Feb 1 15:34:02] DEBUG[15885]: chan_sip.c:2089 __sip_ack: Stopping retransmission on 'f7c7e776-68885084-acc1ce97@172.16.16.101' of Response 2: Match Not Found [Feb 1 15:34:04] DEBUG[15885]: chan_sip.c:4350 find_call: = No match Their Call ID: 005a69bd632866a500db6a9f79946c2f@172.16.16.12 Their Tag 97CA0E29-E81B8C74 Our tag: as076107cc [Feb 1 15:34:04] DEBUG[15885]: chan_sip.c:4350 find_call: = No match Their Call ID: f7c7e776-68885084-acc1ce97@172.16.16.101 Their Tag 5834A1C2-8A117DCD Our tag: as6965be42 [Feb 1 15:34:04] DEBUG[15885]: chan_sip.c:4350 find_call: = No match Their Call ID: 4cb7a7a22cc6d21272df86c2692bde39@172.16.16.12 Their Tag E7DE8526-F0EF4CC1 Our tag: as1956d2de [Feb 1 15:34:04] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: 4c0b74e8-8da8f9c6-52afc3e1@172.16.16.101 Their Tag BA290F54-E0AB60A7 Our tag: as2eb93749 [Feb 1 15:34:04] DEBUG[15885]: chan_sip.c:14571 handle_request: **** Received REFER (9) - Command in SIP REFER [Feb 1 15:34:04] DEBUG[15885]: chan_sip.c:8682 get_refer_info: Attended transfer: Will use Replace-Call-ID : f7c7e776-68885084-acc1ce97@172.16.16.101 (No check of from/to tags) [Feb 1 15:34:04] DEBUG[15885]: chan_sip.c:8536 get_sip_pvt_byid_locked: Looking for callid f7c7e776-68885084-acc1ce97@172.16.16.101 (fromtag 5834A1C2-8A117DCD totag as6965be42) [Feb 1 15:34:04] DEBUG[15885]: chan_sip.c:8560 get_sip_pvt_byid_locked: Matched INCOMING call - their tag is 5834A1C2-8A117DCD Our tag is as6965be42 [Feb 1 15:34:04] DEBUG[15885]: chan_sip.c:12693 attempt_transfer: Sip transfer:-------------------- [Feb 1 15:34:04] DEBUG[15885]: chan_sip.c:12695 attempt_transfer: -- Transferer to PBX channel: SIP/4011-0a09e3d8 State Up [Feb 1 15:34:04] DEBUG[15885]: chan_sip.c:12699 attempt_transfer: -- Transferer to PBX second channel (target): SIP/4011-0a0a7840 State Up [Feb 1 15:34:04] DEBUG[15885]: chan_sip.c:12703 attempt_transfer: -- Bridged call to transferee: SIP/4012-09fb7940 State Up [Feb 1 15:34:04] DEBUG[15885]: chan_sip.c:12707 attempt_transfer: -- Bridged call to transfer target: SIP/4010-0a0ab7b0 State Up [Feb 1 15:34:04] DEBUG[15885]: chan_sip.c:12710 attempt_transfer: -- END Sip transfer:-------------------- [Feb 1 15:34:04] DEBUG[15885]: chan_sip.c:12718 attempt_transfer: SIP transfer: Four channels to handle [Feb 1 15:34:04] DEBUG[15885]: chan_sip.c:12749 attempt_transfer: SIP transfer: trying to masquerade SIP/4012-09fb7940 into SIP/4011-0a0a7840 [Feb 1 15:34:04] DEBUG[15885]: channel.c:3227 ast_channel_masquerade: Planning to masquerade channel SIP/4012-09fb7940 into the structure of SIP/4011-0a0a7840 [Feb 1 15:34:04] DEBUG[15885]: channel.c:3241 ast_channel_masquerade: Done planning to masquerade channel SIP/4012-09fb7940 into the structure of SIP/4011-0a0a7840 [Feb 1 15:34:04] DEBUG[15885]: chan_sip.c:12754 attempt_transfer: SIP transfer: Succeeded to masquerade channels. [Feb 1 15:34:04] DEBUG[15885]: chan_sip.c:13711 local_attended_transfer: SIP attended transfer: Unlocking channel SIP/4011-0a0a7840 [Feb 1 15:34:04] DEBUG[15912]: rtp.c:3038 bridge_p2p_loop: Oooh, something is weird, backing out [Feb 1 15:34:04] -- Packet2Packet bridging SIP/4011-0a09e3d8 and SIP/4012-09fb7940 [Feb 1 15:34:04] DEBUG[15912]: rtp.c:3038 bridge_p2p_loop: Oooh, something is weird, backing out [Feb 1 15:34:04] -- Packet2Packet bridging SIP/4011-0a09e3d8 and SIP/4012-09fb7940 [Feb 1 15:34:04] DEBUG[15912]: rtp.c:3038 bridge_p2p_loop: Oooh, something is weird, backing out [Feb 1 15:34:04] -- Packet2Packet bridging SIP/4011-0a09e3d8 and SIP/4012-09fb7940 [Feb 1 15:34:04] DEBUG[15912]: rtp.c:3038 bridge_p2p_loop: Oooh, something is weird, backing out [Feb 1 15:34:04] -- Packet2Packet bridging SIP/4011-0a09e3d8 and SIP/4012-09fb7940 [Feb 1 15:34:04] DEBUG[15912]: rtp.c:3038 bridge_p2p_loop: Oooh, something is weird, backing out [Feb 1 15:34:04] -- Packet2Packet bridging SIP/4011-0a09e3d8 and SIP/4012-09fb7940 [Feb 1 15:34:04] DEBUG[15912]: rtp.c:3038 bridge_p2p_loop: Oooh, something is weird, backing out [Feb 1 15:34:04] -- Packet2Packet bridging SIP/4011-0a09e3d8 and SIP/4012-09fb7940 [Feb 1 15:34:04] DEBUG[15912]: rtp.c:3038 bridge_p2p_loop: Oooh, something is weird, backing out [Feb 1 15:34:04] -- Packet2Packet bridging SIP/4011-0a09e3d8 and SIP/4012-09fb7940 [Feb 1 15:34:04] DEBUG[15923]: channel.c:3358 ast_do_masquerade: Actually Masquerading SIP/4012-09fb7940(6) into the structure of SIP/4011-0a0a7840(6) [Feb 1 15:34:04] DEBUG[15923]: channel.c:3370 ast_do_masquerade: Got clone lock for masquerade on 'SIP/4012-09fb7940' at 0x9fbcd08 [Feb 1 15:34:04] DEBUG[15923]: chan_sip.c:3580 sip_fixup: SIP Fixup: New owner for dialogue f7c7e776-68885084-acc1ce97@172.16.16.101: SIP/4012-09fb7940 (Old parent: SIP/4012-09fb7940) [Feb 1 15:34:04] DEBUG[15923]: chan_sip.c:3306 sip_hangup: Hangup call SIP/4012-09fb7940, SIP callid f7c7e776-68885084-acc1ce97@172.16.16.101) [Feb 1 15:34:04] DEBUG[15923]: chan_sip.c:3002 update_call_counter: Updating call counter for incoming call [Feb 1 15:34:04] DEBUG[15923]: chan_sip.c:3050 update_call_counter: Call from peer '4011' removed from call limit 200 [Feb 1 15:34:04] DEBUG[15923]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4011 [Feb 1 15:34:04] DEBUG[15923]: channel.c:3565 ast_do_masquerade: Putting channel SIP/4012-09fb7940 in 4/4 formats [Feb 1 15:34:04] DEBUG[15923]: chan_sip.c:3580 sip_fixup: SIP Fixup: New owner for dialogue 4cb7a7a22cc6d21272df86c2692bde39@172.16.16.12: SIP/4012-09fb7940 (Old parent: SIP/4011-0a0a7840) [Feb 1 15:34:04] DEBUG[15923]: channel.c:3601 ast_do_masquerade: Released clone lock on 'SIP/4011-0a0a7840' [Feb 1 15:34:04] DEBUG[15923]: channel.c:3611 ast_do_masquerade: Done Masquerading SIP/4012-09fb7940 (6) [Feb 1 15:34:04] DEBUG[15923]: rtp.c:3038 bridge_p2p_loop: Oooh, something is weird, backing out [Feb 1 15:34:04] -- Packet2Packet bridging SIP/4012-09fb7940 and SIP/4010-0a0ab7b0 [Feb 1 15:34:04] DEBUG[15912]: rtp.c:3038 bridge_p2p_loop: Oooh, something is weird, backing out [Feb 1 15:34:04] DEBUG[15912]: channel.c:4012 ast_channel_bridge: Bridge stops because we're zombie or need a soft hangup: c0=SIP/4011-0a09e3d8, c1=SIP/4011-0a0a7840, flags: No,No,Yes,Yes [Feb 1 15:34:04] DEBUG[15912]: channel.c:4111 ast_channel_bridge: Bridge stops bridging channels SIP/4011-0a09e3d8 and SIP/4011-0a0a7840 [Feb 1 15:34:04] DEBUG[15912]: channel.c:1692 ast_hangup: Hanging up zombie 'SIP/4011-0a0a7840' [Feb 1 15:34:04] DEBUG[15912]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4011-0a0a7840 [Feb 1 15:34:04] DEBUG[15912]: rtp.c:1474 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Feb 1 15:34:04] DEBUG[15912]: app_dial.c:1643 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Feb 1 15:34:04] DEBUG[15912]: app_macro.c:253 _macro_exec: Spawn extension (macro-dnv-standard-dialer,s,1) exited non-zero on 'SIP/4011-0a09e3d8' in macro 'dnv-standard-dialer' [Feb 1 15:34:04] DEBUG[15912]: pbx.c:2367 __ast_pbx_run: Spawn extension (macro-dnv-standard-dialer,s,1) exited non-zero on 'SIP/4011-0a09e3d8' [Feb 1 15:34:04] == Spawn extension (macro-dnv-standard-dialer, s, 1) exited non-zero on 'SIP/4011-0a09e3d8' [Feb 1 15:34:04] DEBUG[15912]: channel.c:1687 ast_hangup: Hanging up channel 'SIP/4011-0a09e3d8' [Feb 1 15:34:04] DEBUG[15912]: chan_sip.c:3291 sip_hangup: SIP Transfer: Not hanging up right now... Rescheduling hangup for 4c0b74e8-8da8f9c6-52afc3e1@172.16.16.101. [Feb 1 15:34:04] DEBUG[15912]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4011-0a09e3d8 [Feb 1 15:34:04] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4011 [Feb 1 15:34:04] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4011 [Feb 1 15:34:04] DEBUG[15871]: devicestate.c:287 do_state_change: Changing state for SIP/4011 - state 2 (In use) [Feb 1 15:34:04] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4011 [Feb 1 15:34:04] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4011 [Feb 1 15:34:04] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4011 [Feb 1 15:34:04] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4011 [Feb 1 15:34:04] DEBUG[15871]: devicestate.c:287 do_state_change: Changing state for SIP/4011 - state 2 (In use) [Feb 1 15:34:04] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4011 [Feb 1 15:34:04] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4011 [Feb 1 15:34:04] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4011 [Feb 1 15:34:04] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4011 [Feb 1 15:34:04] DEBUG[15871]: devicestate.c:287 do_state_change: Changing state for SIP/4011 - state 2 (In use) [Feb 1 15:34:04] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4011 [Feb 1 15:34:04] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4011 [Feb 1 15:34:04] DEBUG[15931]: app_queue.c:546 changethread: Device 'SIP/4011' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 1 15:34:04] DEBUG[15932]: app_queue.c:546 changethread: Device 'SIP/4011' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 1 15:34:04] DEBUG[15933]: app_queue.c:546 changethread: Device 'SIP/4011' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 1 15:34:04] DEBUG[15923]: rtp.c:2670 ast_rtp_write: Ooh, format changed from unknown to ulaw [Feb 1 15:34:04] DEBUG[15923]: rtp.c:2687 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Feb 1 15:34:04] DEBUG[15885]: chan_sip.c:4350 find_call: = No match Their Call ID: 005a69bd632866a500db6a9f79946c2f@172.16.16.12 Their Tag 97CA0E29-E81B8C74 Our tag: as076107cc [Feb 1 15:34:04] DEBUG[15885]: chan_sip.c:4350 find_call: = No match Their Call ID: f7c7e776-68885084-acc1ce97@172.16.16.101 Their Tag 5834A1C2-8A117DCD Our tag: as6965be42 [Feb 1 15:34:04] DEBUG[15885]: chan_sip.c:4350 find_call: = No match Their Call ID: 4cb7a7a22cc6d21272df86c2692bde39@172.16.16.12 Their Tag E7DE8526-F0EF4CC1 Our tag: as1956d2de [Feb 1 15:34:04] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: 4c0b74e8-8da8f9c6-52afc3e1@172.16.16.101 Their Tag BA290F54-E0AB60A7 Our tag: as2eb93749 [Feb 1 15:34:04] DEBUG[15885]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '4c0b74e8-8da8f9c6-52afc3e1@172.16.16.101' of Request 102: Match Not Found [Feb 1 15:34:04] DEBUG[15885]: chan_sip.c:4350 find_call: = No match Their Call ID: 005a69bd632866a500db6a9f79946c2f@172.16.16.12 Their Tag 97CA0E29-E81B8C74 Our tag: as076107cc [Feb 1 15:34:04] DEBUG[15885]: chan_sip.c:4350 find_call: = No match Their Call ID: f7c7e776-68885084-acc1ce97@172.16.16.101 Their Tag 5834A1C2-8A117DCD Our tag: as6965be42 [Feb 1 15:34:04] DEBUG[15885]: chan_sip.c:4350 find_call: = No match Their Call ID: 4cb7a7a22cc6d21272df86c2692bde39@172.16.16.12 Their Tag E7DE8526-F0EF4CC1 Our tag: as1956d2de [Feb 1 15:34:04] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: 4c0b74e8-8da8f9c6-52afc3e1@172.16.16.101 Their Tag BA290F54-E0AB60A7 Our tag: as2eb93749 [Feb 1 15:34:04] DEBUG[15885]: chan_sip.c:14571 handle_request: **** Received BYE (8) - Command in SIP BYE [Feb 1 15:34:04] DEBUG[15885]: chan_sip.c:1633 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 4c0b74e8-8da8f9c6-52afc3e1@172.16.16.101 [Feb 1 15:34:04] DEBUG[15885]: chan_sip.c:14152 handle_request_bye: Received bye, no owner, selfdestruct soon. [Feb 1 15:34:04] DEBUG[15885]: chan_sip.c:4350 find_call: = No match Their Call ID: 005a69bd632866a500db6a9f79946c2f@172.16.16.12 Their Tag 97CA0E29-E81B8C74 Our tag: as076107cc [Feb 1 15:34:04] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: f7c7e776-68885084-acc1ce97@172.16.16.101 Their Tag 5834A1C2-8A117DCD Our tag: as6965be42 [Feb 1 15:34:04] DEBUG[15885]: chan_sip.c:2089 __sip_ack: Stopping retransmission on 'f7c7e776-68885084-acc1ce97@172.16.16.101' of Request 102: Match Not Found [Feb 1 15:34:05] DEBUG[15923]: rtp.c:871 ast_rtcp_read: Got RTCP report of 84 bytes [Feb 1 15:34:05] Really destroying SIP dialog 'f7c7e776-68885084-acc1ce97@172.16.16.101' Method: ACK [Feb 1 15:34:12] DEBUG[15923]: rtp.c:871 ast_rtcp_read: Got RTCP report of 84 bytes [Feb 1 15:34:12] DEBUG[15885]: chan_sip.c:4350 find_call: = No match Their Call ID: 005a69bd632866a500db6a9f79946c2f@172.16.16.12 Their Tag 97CA0E29-E81B8C74 Our tag: as076107cc [Feb 1 15:34:12] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: 4cb7a7a22cc6d21272df86c2692bde39@172.16.16.12 Their Tag E7DE8526-F0EF4CC1 Our tag: as1956d2de [Feb 1 15:34:12] DEBUG[15885]: chan_sip.c:14571 handle_request: **** Received BYE (8) - Command in SIP BYE [Feb 1 15:34:12] DEBUG[15885]: chan_sip.c:1633 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 4cb7a7a22cc6d21272df86c2692bde39@172.16.16.12 [Feb 1 15:34:12] DEBUG[15885]: chan_sip.c:14148 handle_request_bye: Received bye, issuing owner hangup [Feb 1 15:34:12] DEBUG[15923]: rtp.c:3069 bridge_p2p_loop: Oooh, got a hangup [Feb 1 15:34:12] DEBUG[15923]: channel.c:4041 ast_channel_bridge: Returning from native bridge, channels: SIP/4012-09fb7940, SIP/4010-0a0ab7b0 [Feb 1 15:34:12] DEBUG[15923]: channel.c:1687 ast_hangup: Hanging up channel 'SIP/4010-0a0ab7b0' [Feb 1 15:34:12] DEBUG[15923]: chan_sip.c:3306 sip_hangup: Hangup call SIP/4010-0a0ab7b0, SIP callid 005a69bd632866a500db6a9f79946c2f@172.16.16.12) [Feb 1 15:34:12] DEBUG[15923]: chan_sip.c:3002 update_call_counter: Updating call counter for outgoing call [Feb 1 15:34:12] DEBUG[15923]: chan_sip.c:3050 update_call_counter: Call to peer '4010' removed from call limit 200 [Feb 1 15:34:12] DEBUG[15923]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4010 [Feb 1 15:34:12] DEBUG[15923]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4010-0a0ab7b0 [Feb 1 15:34:12] DEBUG[15923]: rtp.c:1474 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Feb 1 15:34:12] DEBUG[15923]: app_dial.c:1643 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Feb 1 15:34:12] DEBUG[15923]: app_macro.c:253 _macro_exec: Spawn extension (macro-dnv-standard-dialer,s,1) exited non-zero on 'SIP/4012-09fb7940' in macro 'dnv-standard-dialer' [Feb 1 15:34:12] DEBUG[15923]: pbx.c:2367 __ast_pbx_run: Spawn extension (macro-dnv-standard-dialer,s,1) exited non-zero on 'SIP/4012-09fb7940' [Feb 1 15:34:12] == Spawn extension (macro-dnv-standard-dialer, s, 1) exited non-zero on 'SIP/4012-09fb7940' [Feb 1 15:34:12] DEBUG[15923]: channel.c:1687 ast_hangup: Hanging up channel 'SIP/4012-09fb7940' [Feb 1 15:34:12] DEBUG[15923]: chan_sip.c:3306 sip_hangup: Hangup call SIP/4012-09fb7940, SIP callid 4cb7a7a22cc6d21272df86c2692bde39@172.16.16.12) [Feb 1 15:34:12] DEBUG[15923]: chan_sip.c:3002 update_call_counter: Updating call counter for outgoing call [Feb 1 15:34:12] DEBUG[15923]: chan_sip.c:3050 update_call_counter: Call to peer '4012' removed from call limit 200 [Feb 1 15:34:12] DEBUG[15923]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4012 [Feb 1 15:34:12] DEBUG[15923]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4012-09fb7940 [Feb 1 15:34:12] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4010 [Feb 1 15:34:12] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4010 [Feb 1 15:34:12] DEBUG[15871]: devicestate.c:287 do_state_change: Changing state for SIP/4010 - state 1 (Not in use) [Feb 1 15:34:12] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4010 [Feb 1 15:34:12] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4010 [Feb 1 15:34:12] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4010 [Feb 1 15:34:12] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4010 [Feb 1 15:34:12] DEBUG[15871]: devicestate.c:287 do_state_change: Changing state for SIP/4010 - state 1 (Not in use) [Feb 1 15:34:12] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4010 [Feb 1 15:34:12] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4010 [Feb 1 15:34:12] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4012 [Feb 1 15:34:12] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4012 [Feb 1 15:34:12] DEBUG[15871]: devicestate.c:287 do_state_change: Changing state for SIP/4012 - state 1 (Not in use) [Feb 1 15:34:12] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4012 [Feb 1 15:34:12] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4012 [Feb 1 15:34:12] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4012 [Feb 1 15:34:12] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4012 [Feb 1 15:34:12] Extension Changed 4012 new state Idle for Notify User 4010 [Feb 1 15:34:12] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4012 [Feb 1 15:34:12] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4012 [Feb 1 15:34:12] DEBUG[15871]: devicestate.c:287 do_state_change: Changing state for SIP/4012 - state 1 (Not in use) [Feb 1 15:34:12] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4012 [Feb 1 15:34:12] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4012 [Feb 1 15:34:12] DEBUG[15934]: app_queue.c:546 changethread: Device 'SIP/4010' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 1 15:34:12] DEBUG[15935]: app_queue.c:546 changethread: Device 'SIP/4010' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 1 15:34:12] DEBUG[15936]: app_queue.c:546 changethread: Device 'SIP/4012' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 1 15:34:12] DEBUG[15937]: app_queue.c:546 changethread: Device 'SIP/4012' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 1 15:34:12] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: 005a69bd632866a500db6a9f79946c2f@172.16.16.12 Their Tag 97CA0E29-E81B8C74 Our tag: as076107cc [Feb 1 15:34:12] DEBUG[15885]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '005a69bd632866a500db6a9f79946c2f@172.16.16.12' of Request 103: Match Not Found [Feb 1 15:34:12] Really destroying SIP dialog '005a69bd632866a500db6a9f79946c2f@172.16.16.12' Method: INVITE [Feb 1 15:34:12] Really destroying SIP dialog '4cb7a7a22cc6d21272df86c2692bde39@172.16.16.12' Method: BYE [Feb 1 15:34:13] DEBUG[15885]: chan_sip.c:4350 find_call: = No match Their Call ID: 4c0b74e8-8da8f9c6-52afc3e1@172.16.16.101 Their Tag BA290F54-E0AB60A7 Our tag: as2eb93749 [Feb 1 15:34:13] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: 6649a393-ca48eeb9-2b6dffc4@172.16.16.135 Their Tag 872B3D6F-720D4382 Our tag: as14ab44b8 [Feb 1 15:34:13] DEBUG[15885]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '6649a393-ca48eeb9-2b6dffc4@172.16.16.135' of Request 105: Match Not Found [Feb 1 15:34:25] DEBUG[15877]: chan_iax2.c:4773 raw_hangup: Raw Hangup 204.239.10.89:2890, src=0, dst=0 sip show inusecore show hints -= Registered Asterisk Dial Plan Hints =- 8716@private-extensions : SIP/8716 State:Unavailable Watchers 0 8715@private-extensions : SIP/8715 State:Unavailable Watchers 0 8714@private-extensions : SIP/8714 State:Unavailable Watchers 0 8713@private-extensions : SIP/8713 State:Unavailable Watchers 0 8712@private-extensions : SIP/8712 State:Unavailable Watchers 0 8711@private-extensions : SIP/8711 State:Unavailable Watchers 0 8710@private-extensions : SIP/8710 State:Unavailable Watchers 0 8696@private-extensions : SIP/8696 State:Unavailable Watchers 0 8695@private-extensions : SIP/8695 State:Unavailable Watchers 0 8694@private-extensions : SIP/8694 State:Unavailable Watchers 0 8693@private-extensions : SIP/8693 State:Unavailable Watchers 0 8692@private-extensions : SIP/8692 State:Unavailable Watchers 0 8691@private-extensions : SIP/8691 State:Unavailable Watchers 0 8690@private-extensions : SIP/8690 State:Unavailable Watchers 0 8169@private-extensions : SIP/8169 State:Unavailable Watchers 0 8168@private-extensions : SIP/8168 State:Unavailable Watchers 0 8166@private-extensions : SIP/8166 State:Unavailable Watchers 0 8162@private-extensions : SIP/8162 State:Unavailable Watchers 0 8161@private-extensions : SIP/8161 State:Unavailable Watchers 0 8160@private-extensions : SIP/8160 State:Unavailable Watchers 0 8159@private-extensions : SIP/8159 State:Unavailable Watchers 0 8158@private-extensions : SIP/8158 State:Unavailable Watchers 0 8157@private-extensions : SIP/8157 State:Unavailable Watchers 0 8156@private-extensions : SIP/8156 State:Unavailable Watchers 0 8155@private-extensions : SIP/8155 State:Unavailable Watchers 0 8154@private-extensions : SIP/8154 State:Unavailable Watchers 0 8153@private-extensions : SIP/8153 State:Unavailable Watchers 0 8152@private-extensions : SIP/8152 State:Unavailable Watchers 0 8151@private-extensions : SIP/8151 State:Unavailable Watchers 0 8150@private-extensions : SIP/8150 State:Unavailable Watchers 0 8016@private-extensions : SIP/8016 State:Unavailable Watchers 0 8015@private-extensions : SIP/8015 State:Unavailable Watchers 0 8014@private-extensions : SIP/8014 State:Unavailable Watchers 0 8013@private-extensions : SIP/8013 State:Unavailable Watchers 0 8012@private-extensions : SIP/8012 State:Unavailable Watchers 0 8011@private-extensions : SIP/8011 State:Unavailable Watchers 0 8010@private-extensions : SIP/8010 State:Unavailable Watchers 0 8009@private-extensions : SIP/8009 State:Unavailable Watchers 0 8008@private-extensions : SIP/8008 State:Unavailable Watchers 0 8007@private-extensions : SIP/8007 State:Unavailable Watchers 0 8006@private-extensions : SIP/8006 State:Unavailable Watchers 0 8005@private-extensions : SIP/8005 State:Unavailable Watchers 0 8004@private-extensions : SIP/8004 State:Unavailable Watchers 0 8003@private-extensions : SIP/8003 State:Unavailable Watchers 0 8002@private-extensions : SIP/8002 State:Unavailable Watchers 0 8001@private-extensions : SIP/8001 State:Unavailable Watchers 0 4012@private-extensions : SIP/4012 State:Idle Watchers 1 4011@private-extensions : SIP/4011 State:InUse Watchers 1 4010@private-extensions : SIP/4010 State:Idle Watchers 0 4009@private-extensions : SIP/4009 State:Unavailable Watchers 0 4008@private-extensions : SIP/4008 State:Unavailable Watchers 0 4007@private-extensions : SIP/4007 State:Unavailable Watchers 0 4006@private-extensions : SIP/4006 State:Unavailable Watchers 0 4005@private-extensions : SIP/4005 State:Unavailable Watchers 0 4004@private-extensions : SIP/4004 State:Unavailable Watchers 0 4003@private-extensions : SIP/4003 State:Unavailable Watchers 0 4002@private-extensions : SIP/4002 State:Unavailable Watchers 0 4001@private-extensions : SIP/4001 State:Unavailable Watchers 0 3844@public-extensions : SIP/3844 State:Unavailable Watchers 0 3842@public-extensions : SIP/3842 State:Unavailable Watchers 0 3838@public-extensions : SIP/3838 State:Unavailable Watchers 0 3727@public-extensions : SIP/3727 State:Unavailable Watchers 0 3712@public-extensions : SIP/3712 State:Unavailable Watchers 0 3711@public-extensions : SIP/3711 State:Unavailable Watchers 0 3700@public-extensions : SIP/3700 State:Unavailable Watchers 0 3690@public-extensions : SIP/3690 State:Unavailable Watchers 0 3681@public-extensions : SIP/3681 State:Unavailable Watchers 0 3675@public-extensions : SIP/3675 State:Unavailable Watchers 0 3674@public-extensions : SIP/3674 State:Unavailable Watchers 0 3673@public-extensions : SIP/3673 State:Unavailable Watchers 0 3672@public-extensions : SIP/3672 State:Unavailable Watchers 0 3671@public-extensions : SIP/3671 State:Unavailable Watchers 0 3670@public-extensions : SIP/3670 State:Unavailable Watchers 0 3668@public-extensions : SIP/3668 State:Unavailable Watchers 0 3667@public-extensions : SIP/3667 State:Unavailable Watchers 0 3665@public-extensions : SIP/3665 State:Unavailable Watchers 0 3664@public-extensions : SIP/3664 State:Unavailable Watchers 0 3663@public-extensions : SIP/3663 State:Unavailable Watchers 0 3662@public-extensions : SIP/3662 State:Unavailable Watchers 0 3661@public-extensions : SIP/3661 State:Unavailable Watchers 0 3660@public-extensions : SIP/3660 State:Unavailable Watchers 0 3658@public-extensions : SIP/3658 State:Unavailable Watchers 0 3655@public-extensions : SIP/3655 State:Unavailable Watchers 0 3654@public-extensions : SIP/3654 State:Unavailable Watchers 0 3653@public-extensions : SIP/3653 State:Unavailable Watchers 0 3652@public-extensions : SIP/3652 State:Unavailable Watchers 0 3651@public-extensions : SIP/3651 State:Unavailable Watchers 0 3031@public-extensions : SIP/3031 State:Unavailable Watchers 0 3030@public-extensions : SIP/3030 State:Unavailable Watchers 0 2499@public-extensions : SIP/2499 State:Unavailable Watchers 0 2488@public-extensions : SIP/2488 State:Unavailable Watchers 0 2485@public-extensions : SIP/2485 State:Unavailable Watchers 0 2478@public-extensions : SIP/2478 State:Unavailable Watchers 0 2472@public-extensions : SIP/2472 State:Unavailable Watchers 0 2471@public-extensions : SIP/2471 State:Idle Watchers 0 2470@public-extensions : SIP/2470 State:Unavailable Watchers 0 2469@public-extensions : SIP/2469 State:Unavailable Watchers 0 2468@public-extensions : SIP/2468 State:Unavailable Watchers 0 2457@public-extensions : SIP/2457 State:Unavailable Watchers 0 2456@public-extensions : SIP/2456 State:Unavailable Watchers 0 2448@public-extensions : SIP/2448 State:Unavailable Watchers 0 2440@public-extensions : SIP/2440 State:Unavailable Watchers 0 2439@public-extensions : SIP/2439 State:Unavailable Watchers 0 2438@public-extensions : SIP/2438 State:Unavailable Watchers 0 2426@public-extensions : SIP/2426 State:Unavailable Watchers 0 2420@public-extensions : SIP/2420 State:Idle Watchers 0 2412@public-extensions : SIP/2412 State:Unavailable Watchers 0 2397@public-extensions : SIP/2397 State:Unavailable Watchers 0 2390@public-extensions : SIP/2390 State:Unavailable Watchers 0 2382@public-extensions : SIP/2382 State:Unavailable Watchers 0 2381@public-extensions : SIP/2381 State:Unavailable Watchers 0 2380@public-extensions : SIP/2380 State:Unavailable Watchers 0 2372@public-extensions : SIP/2372 State:Unavailable Watchers 0 2348@public-extensions : SIP/2348-Polycom State:Unavailable Watchers 0 2331@public-extensions : SIP/2331 State:Unavailable Watchers 0 2323@public-extensions : SIP/2323 State:Unavailable Watchers 0 2313@public-extensions : SIP/2313 State:Unavailable Watchers 0 2312@public-extensions : SIP/2312 State:Idle Watchers 0 2309@public-extensions : SIP/2309 State:Unavailable Watchers 0 2308@public-extensions : SIP/2308 State:Unavailable Watchers 0 2306@public-extensions : SIP/2306-Polycom&SIP State:Unavailable Watchers 0 2305@public-extensions : SIP/2305 State:Unavailable Watchers 0 2304@public-extensions : SIP/2304 State:Unavailable Watchers 0 2303@public-extensions : SIP/2303 State:Unavailable Watchers 0 2301@public-extensions : SIP/2301 State:Unavailable Watchers 0 2295@public-extensions : SIP/2295 State:Unavailable Watchers 0 2290@public-extensions : SIP/2290-ridgej State:Unavailable Watchers 0 2266@public-extensions : SIP/2266 State:Unavailable Watchers 0 2238@public-extensions : SIP/2238 State:Unavailable Watchers 0 2235@public-extensions : SIP/2235 State:Unavailable Watchers 0 2230@public-extensions : SIP/2230 State:Unavailable Watchers 0 2229@public-extensions : SIP/2229 State:Unavailable Watchers 0 2228@public-extensions : SIP/2228 State:Unavailable Watchers 0 2226@public-extensions : SIP/2226 State:Unavailable Watchers 0 2225@public-extensions : SIP/2225 State:Unavailable Watchers 0 2218@public-extensions : SIP/2218 State:Unavailable Watchers 0 2209@public-extensions : SIP/2206-mitchells&S State:Unavailable Watchers 0 2206@public-extensions : SIP/2206-ridgej State:Unavailable Watchers 0 ---------------- - 138 hints registered *CLI> core show hintssip show inuse * User name In use Limit 4012 0 200 4011 0 200 4010 0 200 2348-Polycom 0 200 * Peer name In use Limit 4012 0/0 200 4011 1/0 200 4010 0/0 200 2348-Polycom 0/0 200 *CLI> [Feb 1 15:34:30] DEBUG[15879]: chan_iax2.c:7097 socket_process: Peer gabriola-out: got pong, lastms 20, historicms 20, maxms 2000 [Feb 1 15:34:35] DEBUG[15885]: chan_sip.c:4350 find_call: = No match Their Call ID: 4c0b74e8-8da8f9c6-52afc3e1@172.16.16.101 Their Tag BA290F54-E0AB60A7 Our tag: as2eb93749 [Feb 1 15:34:35] DEBUG[15885]: chan_sip.c:4350 find_call: = No match Their Call ID: 6649a393-ca48eeb9-2b6dffc4@172.16.16.135 Their Tag 872B3D6F-720D4382 Our tag: as14ab44b8 [Feb 1 15:34:35] DEBUG[15885]: chan_sip.c:4350 find_call: = No match Their Call ID: ab3d9dbe-818638ec-45e789b@172.16.16.135 Their Tag 60ADF86A-A3525C81 Our tag: as702f5b89 [Feb 1 15:34:35] DEBUG[15885]: chan_sip.c:4299 sip_alloc: Allocating new SIP dialog for d9a691f5-21ad15db-d52639ca@172.16.16.101 - SUBSCRIBE (No RTP) [Feb 1 15:34:35] DEBUG[15885]: chan_sip.c:14571 handle_request: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Feb 1 15:34:35] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: d9a691f5-21ad15db-d52639ca@172.16.16.101 Their Tag 3B0D4BB1-708473F8 Our tag: as152efef8 [Feb 1 15:34:35] DEBUG[15885]: chan_sip.c:14571 handle_request: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Feb 1 15:34:35] DEBUG[15885]: chan_sip.c:14380 handle_request_subscribe: Adding subscription for extension 4012 context internal for peer 4011 [Feb 1 15:34:35] DEBUG[15885]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4012 [Feb 1 15:34:35] DEBUG[15885]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4012 [Feb 1 15:34:35] DEBUG[15885]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4012 [Feb 1 15:34:35] DEBUG[15885]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4012 [Feb 1 15:34:35] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: d9a691f5-21ad15db-d52639ca@172.16.16.101 Their Tag 3B0D4BB1-708473F8 Our tag: as152efef8 [Feb 1 15:34:35] DEBUG[15885]: chan_sip.c:2089 __sip_ack: Stopping retransmission on 'd9a691f5-21ad15db-d52639ca@172.16.16.101' of Request 102: Match Not Found [Feb 1 15:34:35] -- Incoming call: Got SIP response 500 "Internal Server Error" back from 172.16.16.101 [Feb 1 15:34:36] DEBUG[15885]: chan_sip.c:2010 __sip_autodestruct: Auto destroying SIP dialog '4c0b74e8-8da8f9c6-52afc3e1@172.16.16.101' [Feb 1 15:34:36] DEBUG[15885]: chan_sip.c:2017 __sip_autodestruct: Finally hanging up channel after transfer: 4c0b74e8-8da8f9c6-52afc3e1@172.16.16.101 [Feb 1 15:34:36] DEBUG[15885]: chan_sip.c:4350 find_call: = No match Their Call ID: d9a691f5-21ad15db-d52639ca@172.16.16.101 Their Tag 3B0D4BB1-708473F8 Our tag: as152efef8 [Feb 1 15:34:36] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: 4c0b74e8-8da8f9c6-52afc3e1@172.16.16.101 Their Tag BA290F54-E0AB60A7 Our tag: as2eb93749 [Feb 1 15:34:36] DEBUG[15885]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '4c0b74e8-8da8f9c6-52afc3e1@172.16.16.101' of Request 103: Match Not Found [Feb 1 15:34:39] DEBUG[15885]: chan_sip.c:4299 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Feb 1 15:34:39] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: 42ac884404434026293dda9c31c8390c@172.16.16.12 Their Tag Our tag: as78b18938 [Feb 1 15:34:39] DEBUG[15885]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '42ac884404434026293dda9c31c8390c@172.16.16.12' of Request 102: Match Not Found [Feb 1 15:34:39] DEBUG[15885]: chan_sip.c:4299 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Feb 1 15:34:39] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: 5269edcc586d2dd477c740bb1e281087@172.16.16.12 Their Tag Our tag: as08a02946 [Feb 1 15:34:39] DEBUG[15885]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '5269edcc586d2dd477c740bb1e281087@172.16.16.12' of Request 102: Match Not Found [Feb 1 15:34:39] Really destroying SIP dialog '5269edcc586d2dd477c740bb1e281087@172.16.16.12' Method: OPTIONS [Feb 1 15:34:39] Really destroying SIP dialog '42ac884404434026293dda9c31c8390c@172.16.16.12' Method: OPTIONS [Feb 1 15:34:39] Really destroying SIP dialog '4c0b74e8-8da8f9c6-52afc3e1@172.16.16.101' Method: BYE [Feb 1 15:34:39] DEBUG[15885]: chan_sip.c:3002 update_call_counter: Updating call counter for incoming call [Feb 1 15:34:39] DEBUG[15885]: chan_sip.c:3050 update_call_counter: Call from peer '4011' removed from call limit 200 [Feb 1 15:34:39] DEBUG[15885]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4011 [Feb 1 15:34:39] DEBUG[15885]: chan_sip.c:2893 __sip_destroy: This call did not properly clean up call limits. Call ID 4c0b74e8-8da8f9c6-52afc3e1@172.16.16.101 [Feb 1 15:34:39] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4011 [Feb 1 15:34:39] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4011 [Feb 1 15:34:39] DEBUG[15871]: devicestate.c:287 do_state_change: Changing state for SIP/4011 - state 1 (Not in use) [Feb 1 15:34:39] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4011 [Feb 1 15:34:39] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4011 [Feb 1 15:34:39] DEBUG[15871]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4011 [Feb 1 15:34:39] DEBUG[15871]: chan_sip.c:15170 sip_devicestate: Checking device state for peer 4011 [Feb 1 15:34:39] Extension Changed 4011 new state Idle for Notify User 4010 [Feb 1 15:34:39] DEBUG[15941]: app_queue.c:546 changethread: Device 'SIP/4011' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 1 15:34:39] DEBUG[15885]: chan_sip.c:4350 find_call: = No match Their Call ID: d9a691f5-21ad15db-d52639ca@172.16.16.101 Their Tag 3B0D4BB1-708473F8 Our tag: as152efef8 [Feb 1 15:34:39] DEBUG[15885]: chan_sip.c:4350 find_call: = No match Their Call ID: 6649a393-ca48eeb9-2b6dffc4@172.16.16.135 Their Tag 872B3D6F-720D4382 Our tag: as14ab44b8 [Feb 1 15:34:39] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: ab3d9dbe-818638ec-45e789b@172.16.16.135 Their Tag 60ADF86A-A3525C81 Our tag: as702f5b89 [Feb 1 15:34:39] DEBUG[15885]: chan_sip.c:2089 __sip_ack: Stopping retransmission on 'ab3d9dbe-818638ec-45e789b@172.16.16.135' of Request 104: Match Not Found s[Feb 1 15:34:39] DEBUG[15885]: chan_sip.c:4299 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Feb 1 15:34:39] DEBUG[15885]: chan_sip.c:4299 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Feb 1 15:34:39] DEBUG[15885]: chan_sip.c:4350 find_call: = No match Their Call ID: 3125032016d938da4e7bcf5074ed1e01@172.16.16.12 Their Tag Our tag: as1c5a2db8 [Feb 1 15:34:39] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: 78a1ca7700fbd79504486e9207037385@172.16.16.12 Their Tag Our tag: as6c62aebb [Feb 1 15:34:39] DEBUG[15885]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '78a1ca7700fbd79504486e9207037385@172.16.16.12' of Request 102: Match Not Found [Feb 1 15:34:39] DEBUG[15885]: chan_sip.c:4299 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Feb 1 15:34:39] Really destroying SIP dialog '78a1ca7700fbd79504486e9207037385@172.16.16.12' Method: OPTIONS [Feb 1 15:34:39] DEBUG[15885]: chan_sip.c:4350 find_call: = No match Their Call ID: 0380bbea1ea3ec36153fa5e31603572e@172.16.16.12 Their Tag Our tag: as594b5903 [Feb 1 15:34:39] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: 3125032016d938da4e7bcf5074ed1e01@172.16.16.12 Their Tag Our tag: as1c5a2db8 [Feb 1 15:34:39] DEBUG[15885]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '3125032016d938da4e7bcf5074ed1e01@172.16.16.12' of Request 102: Match Not Found [Feb 1 15:34:39] Really destroying SIP dialog '3125032016d938da4e7bcf5074ed1e01@172.16.16.12' Method: OPTIONS [Feb 1 15:34:39] DEBUG[15885]: chan_sip.c:4350 find_call: = Found Their Call ID: 0380bbea1ea3ec36153fa5e31603572e@172.16.16.12 Their Tag Our tag: as594b5903 [Feb 1 15:34:39] DEBUG[15885]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '0380bbea1ea3ec36153fa5e31603572e@172.16.16.12' of Request 102: Match Not Found [Feb 1 15:34:39] Really destroying SIP dialog '0380bbea1ea3ec36153fa5e31603572e@172.16.16.12' Method: OPTIONS top when convenient Waiting for inactivity to perform halt [Feb 1 15:34:44] Waiting for inactivity to perform halt... [Feb 1 15:34:44] Executing last minute cleanups [Feb 1 15:34:44] == Destroying musiconhold processes [Feb 1 15:34:44] Asterisk cleanly ending (0). [Feb 1 15:34:44] DEBUG[15867]: asterisk.c:1192 quit_handler: Asterisk ending (0).