[Dec 1 10:00:43] VERBOSE[25090] config.c: == Parsing '/etc/asterisk/logger.conf': [Dec 1 10:00:43] VERBOSE[25090] config.c: == Found [Dec 1 10:00:43] VERBOSE[25090] logger.c: Asterisk Queue Logger restarted [Dec 1 10:00:47] DEBUG[25511] chan_iax2.c: ip callno count decremented to 0 for 69.64.11.13 [Dec 1 10:00:47] DEBUG[25515] chan_iax2.c: ip callno count incremented to 1 for 69.64.11.13 [Dec 1 10:00:47] DEBUG[25518] chan_iax2.c: schedule decrement of callno used for 69.64.11.13 in 60 seconds [Dec 1 10:00:47] DEBUG[25518] chan_iax2.c: Peer routing_out: got pong, lastms 11, historicms 11, maxms 1000 [Dec 1 10:00:51] DEBUG[25528] chan_sip.c: Allocating new SIP dialog for 49fa3519439c76e605ce8de54a57d3d5@216.135.89.226:0 - OPTIONS (No RTP) [Dec 1 10:00:51] DEBUG[25528] acl.c: For destination '172.16.100.195', our source address is '172.16.100.1'. [Dec 1 10:00:51] DEBUG[25528] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 172.16.100.1:5060 [Dec 1 10:00:51] DEBUG[25528] chan_sip.c: Initializing initreq for method OPTIONS - callid 00968e09185eab2741bf39927ad34774@172.16.100.1:5060 [Dec 1 10:00:51] DEBUG[25528] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 172.16.100.195:5060 [Dec 1 10:00:51] DEBUG[25528] chan_sip.c: = Looking for Call ID: 00968e09185eab2741bf39927ad34774@172.16.100.1:5060 (Checking To) --From tag as6794c464 --To-tag D20E4C5F-83DCF0B2 [Dec 1 10:00:51] DEBUG[25528] chan_sip.c: Stopping retransmission on '00968e09185eab2741bf39927ad34774@172.16.100.1:5060' of Request 102: Match Found [Dec 1 10:00:51] DEBUG[25528] chan_sip.c: Destroying SIP dialog 00968e09185eab2741bf39927ad34774@172.16.100.1:5060 [Dec 1 10:00:53] DEBUG[25528] chan_sip.c: Allocating new SIP dialog for 2722d1554d3649e04575f29969181061@216.135.89.226:0 - OPTIONS (No RTP) [Dec 1 10:00:53] DEBUG[25528] acl.c: For destination '69.64.11.6', our source address is '216.135.89.226'. [Dec 1 10:00:53] DEBUG[25528] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 216.135.89.226:5060 [Dec 1 10:00:53] DEBUG[25528] chan_sip.c: Initializing initreq for method OPTIONS - callid 2bccf2211be5f04c1f75ef75503fa53c@216.135.89.226:5060 [Dec 1 10:00:53] DEBUG[25528] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 69.64.11.6:5060 [Dec 1 10:00:53] DEBUG[25528] chan_sip.c: = Looking for Call ID: 2bccf2211be5f04c1f75ef75503fa53c@216.135.89.226:5060 (Checking To) --From tag as3ead82eb --To-tag as6682e78e [Dec 1 10:00:53] DEBUG[25528] chan_sip.c: Stopping retransmission on '2bccf2211be5f04c1f75ef75503fa53c@216.135.89.226:5060' of Request 102: Match Found [Dec 1 10:00:53] DEBUG[25528] chan_sip.c: Destroying SIP dialog 2bccf2211be5f04c1f75ef75503fa53c@216.135.89.226:5060 [Dec 1 10:00:53] DEBUG[25528] chan_sip.c: Allocating new SIP dialog for 10de91a515998beb03f37bd70fe58e68@216.135.89.226:0 - OPTIONS (No RTP) [Dec 1 10:00:53] DEBUG[25528] acl.c: For destination '69.64.11.13', our source address is '216.135.89.226'. [Dec 1 10:00:53] DEBUG[25528] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 216.135.89.226:5060 [Dec 1 10:00:53] DEBUG[25528] chan_sip.c: Initializing initreq for method OPTIONS - callid 11091b806e9de4f63aca5eb5244fa648@216.135.89.226:5060 [Dec 1 10:00:53] DEBUG[25528] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 69.64.11.13:5060 [Dec 1 10:00:53] DEBUG[25528] chan_sip.c: = Looking for Call ID: 11091b806e9de4f63aca5eb5244fa648@216.135.89.226:5060 (Checking To) --From tag as69314296 --To-tag as06e2b7eb [Dec 1 10:00:53] DEBUG[25528] chan_sip.c: Stopping retransmission on '11091b806e9de4f63aca5eb5244fa648@216.135.89.226:5060' of Request 102: Match Found [Dec 1 10:00:53] DEBUG[25528] chan_sip.c: Destroying SIP dialog 11091b806e9de4f63aca5eb5244fa648@216.135.89.226:5060 [Dec 1 10:00:55] DEBUG[25528] chan_sip.c: = Looking for Call ID: 204219c40ba4413d0a9de0370492c34e@69.64.11.6 (Checking From) --From tag as644953f0 --To-tag [Dec 1 10:00:55] DEBUG[25528] acl.c: For destination '69.64.11.6', our source address is '216.135.89.226'. [Dec 1 10:00:55] DEBUG[25528] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 216.135.89.226:5060 [Dec 1 10:00:55] DEBUG[25528] chan_sip.c: Allocating new SIP dialog for 204219c40ba4413d0a9de0370492c34e@69.64.11.6 - OPTIONS (No RTP) [Dec 1 10:00:55] DEBUG[25528] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Dec 1 10:00:55] DEBUG[25528] chan_sip.c: Trying to put 'SIP/2.0 404' onto UDP socket destined for 69.64.11.6:5060 [Dec 1 10:00:55] DEBUG[25528] chan_sip.c: SIP message could not be handled, bad request: 204219c40ba4413d0a9de0370492c34e@69.64.11.6 [Dec 1 10:00:57] DEBUG[25528] chan_sip.c: Allocating new SIP dialog for 532f0d027a7c5cdd6a8dd6942667b36b@216.135.89.226:0 - OPTIONS (No RTP) [Dec 1 10:00:57] DEBUG[25528] acl.c: For destination '69.64.11.20', our source address is '216.135.89.226'. [Dec 1 10:00:57] DEBUG[25528] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 216.135.89.226:5060 [Dec 1 10:00:57] DEBUG[25528] chan_sip.c: Initializing initreq for method OPTIONS - callid 4ba35d5e05814b2e65a6fd397faeb711@216.135.89.226:5060 [Dec 1 10:00:57] DEBUG[25528] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 69.64.11.20:5060 [Dec 1 10:00:57] DEBUG[25528] chan_sip.c: = Looking for Call ID: 4ba35d5e05814b2e65a6fd397faeb711@216.135.89.226:5060 (Checking To) --From tag as7082071d --To-tag as6e61af4b [Dec 1 10:00:57] DEBUG[25528] chan_sip.c: Stopping retransmission on '4ba35d5e05814b2e65a6fd397faeb711@216.135.89.226:5060' of Request 102: Match Found [Dec 1 10:00:57] DEBUG[25528] chan_sip.c: Destroying SIP dialog 4ba35d5e05814b2e65a6fd397faeb711@216.135.89.226:5060 [Dec 1 10:01:05] DEBUG[25528] chan_sip.c: = Looking for Call ID: fc80d54e-24baae26@172.16.100.186 (Checking From) --From tag 5a09427ee4b293d2o0 --To-tag [Dec 1 10:01:05] DEBUG[25528] acl.c: For destination '172.16.100.186', our source address is '172.16.100.1'. [Dec 1 10:01:05] DEBUG[25528] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 172.16.100.1:5060 [Dec 1 10:01:05] DEBUG[25528] chan_sip.c: Allocating new SIP dialog for fc80d54e-24baae26@172.16.100.186 - REGISTER (No RTP) [Dec 1 10:01:05] DEBUG[25528] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Dec 1 10:01:05] DEBUG[25528] netsock2.c: Splitting '172.16.100.186:5060' gives... [Dec 1 10:01:05] DEBUG[25528] netsock2.c: ...host '172.16.100.186' and port '5060'. [Dec 1 10:01:05] DEBUG[25528] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 172.16.100.186:5060 [Dec 1 10:01:05] DEBUG[25528] chan_sip.c: = Looking for Call ID: 3c2c91c6-2d115c0e@172.16.100.186 (Checking From) --From tag a498ed1e4195e9b2o1 --To-tag [Dec 1 10:01:05] DEBUG[25528] acl.c: For destination '172.16.100.186', our source address is '172.16.100.1'. [Dec 1 10:01:05] DEBUG[25528] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 172.16.100.1:5060 [Dec 1 10:01:05] DEBUG[25528] chan_sip.c: Allocating new SIP dialog for 3c2c91c6-2d115c0e@172.16.100.186 - REGISTER (No RTP) [Dec 1 10:01:05] DEBUG[25528] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Dec 1 10:01:05] DEBUG[25528] netsock2.c: Splitting '172.16.100.186:5061' gives... [Dec 1 10:01:05] DEBUG[25528] netsock2.c: ...host '172.16.100.186' and port '5061'. [Dec 1 10:01:05] DEBUG[25528] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 172.16.100.186:5061 [Dec 1 10:01:05] DEBUG[25528] chan_sip.c: = Looking for Call ID: fc80d54e-24baae26@172.16.100.186 (Checking From) --From tag 5a09427ee4b293d2o0 --To-tag [Dec 1 10:01:05] DEBUG[25528] netsock2.c: Splitting '172.16.100.1' gives... [Dec 1 10:01:05] DEBUG[25528] netsock2.c: ...host '172.16.100.1' and port '(null)'. [Dec 1 10:01:05] DEBUG[25528] netsock2.c: Splitting '172.16.100.1' gives... [Dec 1 10:01:05] DEBUG[25528] netsock2.c: ...host '172.16.100.1' and port '(null)'. [Dec 1 10:01:05] DEBUG[25528] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Dec 1 10:01:05] DEBUG[25528] netsock2.c: Splitting '172.16.100.186:5060' gives... [Dec 1 10:01:05] DEBUG[25528] netsock2.c: ...host '172.16.100.186' and port '5060'. [Dec 1 10:01:05] DEBUG[25528] chan_sip.c: Store REGISTER's Contact header for call routing. [Dec 1 10:01:05] DEBUG[25528] netsock2.c: Splitting '172.16.100.186:5060' gives... [Dec 1 10:01:05] DEBUG[25528] netsock2.c: ...host '172.16.100.186' and port '5060'. [Dec 1 10:01:05] DEBUG[25528] chan_sip.c: Allocating new SIP dialog for 5e582f0f149100294e6f980815b77f21@216.135.89.226:0 - OPTIONS (No RTP) [Dec 1 10:01:05] DEBUG[25506] manager.c: Examining event: Event: PeerStatus Privilege: system,all ChannelType: SIP Peer: SIP/202 PeerStatus: Registered Address: 172.16.100.186:5060 [Dec 1 10:01:05] DEBUG[25528] acl.c: For destination '172.16.100.186', our source address is '172.16.100.1'. [Dec 1 10:01:05] DEBUG[25528] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 172.16.100.1:5060 [Dec 1 10:01:05] DEBUG[25528] chan_sip.c: Initializing initreq for method OPTIONS - callid 7334a85c604d3ed40d9b052261eae2ab@172.16.100.1:5060 [Dec 1 10:01:05] DEBUG[25528] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 172.16.100.186:5060 [Dec 1 10:01:05] DEBUG[25528] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 172.16.100.186:5060 [Dec 1 10:01:05] DEBUG[25496] devicestate.c: No provider found, checking channel drivers for SIP - 202 [Dec 1 10:01:05] DEBUG[25496] chan_sip.c: Checking device state for peer 202 [Dec 1 10:01:05] DEBUG[25496] devicestate.c: Changing state for SIP/202 - state 1 (Not in use) [Dec 1 10:01:05] DEBUG[25496] devicestate.c: device 'SIP/202' state '1' [Dec 1 10:01:05] DEBUG[25528] chan_sip.c: = Looking for Call ID: 3c2c91c6-2d115c0e@172.16.100.186 (Checking From) --From tag a498ed1e4195e9b2o1 --To-tag [Dec 1 10:01:05] DEBUG[25528] netsock2.c: Splitting '172.16.100.1' gives... [Dec 1 10:01:05] DEBUG[25528] netsock2.c: ...host '172.16.100.1' and port '(null)'. [Dec 1 10:01:05] DEBUG[25528] netsock2.c: Splitting '172.16.100.1' gives... [Dec 1 10:01:05] DEBUG[25528] netsock2.c: ...host '172.16.100.1' and port '(null)'. [Dec 1 10:01:05] DEBUG[25528] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Dec 1 10:01:05] DEBUG[25528] netsock2.c: Splitting '172.16.100.186:5061' gives... [Dec 1 10:01:05] DEBUG[25528] netsock2.c: ...host '172.16.100.186' and port '5061'. [Dec 1 10:01:05] DEBUG[25528] chan_sip.c: Store REGISTER's Contact header for call routing. [Dec 1 10:01:05] DEBUG[25528] netsock2.c: Splitting '172.16.100.186:5061' gives... [Dec 1 10:01:05] DEBUG[25528] netsock2.c: ...host '172.16.100.186' and port '5061'. [Dec 1 10:01:05] DEBUG[25506] manager.c: Examining event: Event: PeerStatus Privilege: system,all ChannelType: SIP Peer: SIP/207 PeerStatus: Registered Address: 172.16.100.186:5061 [Dec 1 10:01:05] DEBUG[25528] chan_sip.c: Allocating new SIP dialog for 29a0727b390e2eb35ea8a037570f7200@216.135.89.226:0 - OPTIONS (No RTP) [Dec 1 10:01:05] DEBUG[25528] acl.c: For destination '172.16.100.186', our source address is '172.16.100.1'. [Dec 1 10:01:05] DEBUG[25528] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 172.16.100.1:5060 [Dec 1 10:01:05] DEBUG[25528] chan_sip.c: Initializing initreq for method OPTIONS - callid 56fae2bd7d01ec271ac97338046d56fd@172.16.100.1:5060 [Dec 1 10:01:05] DEBUG[25528] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 172.16.100.186:5061 [Dec 1 10:01:05] DEBUG[25528] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 172.16.100.186:5061 [Dec 1 10:01:05] DEBUG[25496] devicestate.c: No provider found, checking channel drivers for SIP - 207 [Dec 1 10:01:05] DEBUG[25496] chan_sip.c: Checking device state for peer 207 [Dec 1 10:01:05] DEBUG[25496] devicestate.c: Changing state for SIP/207 - state 1 (Not in use) [Dec 1 10:01:05] DEBUG[25496] devicestate.c: device 'SIP/207' state '1' [Dec 1 10:01:05] DEBUG[25528] chan_sip.c: = Looking for Call ID: 7334a85c604d3ed40d9b052261eae2ab@172.16.100.1:5060 (Checking To) --From tag as1f1ac3a2 --To-tag 221878ee710f5022i0 [Dec 1 10:01:05] DEBUG[25528] chan_sip.c: Stopping retransmission on '7334a85c604d3ed40d9b052261eae2ab@172.16.100.1:5060' of Request 102: Match Found [Dec 1 10:01:05] DEBUG[25528] chan_sip.c: Destroying SIP dialog 7334a85c604d3ed40d9b052261eae2ab@172.16.100.1:5060 [Dec 1 10:01:05] DEBUG[25528] chan_sip.c: = Looking for Call ID: 56fae2bd7d01ec271ac97338046d56fd@172.16.100.1:5060 (Checking To) --From tag as0de371bc --To-tag b17f528e77ed4302i1 [Dec 1 10:01:05] DEBUG[25528] chan_sip.c: Stopping retransmission on '56fae2bd7d01ec271ac97338046d56fd@172.16.100.1:5060' of Request 102: Match Found [Dec 1 10:01:05] DEBUG[25528] chan_sip.c: Destroying SIP dialog 56fae2bd7d01ec271ac97338046d56fd@172.16.100.1:5060 [Dec 1 10:01:05] DEBUG[25542] app_queue.c: Device 'SIP/202' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Dec 1 10:01:05] DEBUG[25542] app_queue.c: Device 'SIP/207' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Dec 1 10:01:06] DEBUG[25528] chan_sip.c: Allocating new SIP dialog for 2c8f3ae43ab2dd1219bf461654f74d38@216.135.89.226:0 - OPTIONS (No RTP) [Dec 1 10:01:06] DEBUG[25528] acl.c: For destination '172.16.100.183', our source address is '172.16.100.1'. [Dec 1 10:01:06] DEBUG[25528] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 172.16.100.1:5060 [Dec 1 10:01:06] DEBUG[25528] chan_sip.c: Initializing initreq for method OPTIONS - callid 308254cf13a18af91d4faa014dbc5ca2@172.16.100.1:5060 [Dec 1 10:01:06] DEBUG[25528] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 172.16.100.183:5060 [Dec 1 10:01:06] DEBUG[25528] chan_sip.c: = Looking for Call ID: 308254cf13a18af91d4faa014dbc5ca2@172.16.100.1:5060 (Checking To) --From tag as5c846643 --To-tag 2B32DC25-7B90C546 [Dec 1 10:01:06] DEBUG[25528] chan_sip.c: Stopping retransmission on '308254cf13a18af91d4faa014dbc5ca2@172.16.100.1:5060' of Request 102: Match Found [Dec 1 10:01:06] DEBUG[25528] chan_sip.c: Destroying SIP dialog 308254cf13a18af91d4faa014dbc5ca2@172.16.100.1:5060 [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: = Looking for Call ID: b176b300-269bca7b@172.16.100.186 (Checking From) --From tag d9d3a13c1d6b516fo0 --To-tag [Dec 1 10:01:07] DEBUG[25528] acl.c: For destination '172.16.100.186', our source address is '172.16.100.1'. [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 172.16.100.1:5060 [Dec 1 10:01:07] VERBOSE[25528] netsock.c: == Using UDPTL TOS bits 184 [Dec 1 10:01:07] VERBOSE[25528] netsock.c: == Using UDPTL CoS mark 5 [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: Setting NAT on UDPTL to Off [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: Allocating new SIP dialog for b176b300-269bca7b@172.16.100.186 - INVITE (No RTP) [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Dec 1 10:01:07] DEBUG[25528] sip/reqresp_parser.c: Begin: parsing SIP "Supported: x-sipura, replaces" [Dec 1 10:01:07] DEBUG[25528] sip/reqresp_parser.c: Found SIP option: -x-sipura- [Dec 1 10:01:07] DEBUG[25528] sip/reqresp_parser.c: Found private SIP option, not supported: x-sipura [Dec 1 10:01:07] DEBUG[25528] sip/reqresp_parser.c: Found SIP option: -replaces- [Dec 1 10:01:07] DEBUG[25528] sip/reqresp_parser.c: Matched SIP option: replaces [Dec 1 10:01:07] DEBUG[25528] netsock2.c: Splitting '172.16.100.186:5060' gives... [Dec 1 10:01:07] DEBUG[25528] netsock2.c: ...host '172.16.100.186' and port '5060'. [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: Setting NAT on UDPTL to Off [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 172.16.100.186:5060 [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: = Looking for Call ID: b176b300-269bca7b@172.16.100.186 (Checking From) --From tag d9d3a13c1d6b516fo0 --To-tag as4a888d23 [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: Stopping retransmission on 'b176b300-269bca7b@172.16.100.186' of Response 101: Match Found [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: = Looking for Call ID: b176b300-269bca7b@172.16.100.186 (Checking From) --From tag d9d3a13c1d6b516fo0 --To-tag [Dec 1 10:01:07] DEBUG[25528] netsock2.c: Splitting '172.16.100.1' gives... [Dec 1 10:01:07] DEBUG[25528] netsock2.c: ...host '172.16.100.1' and port '(null)'. [Dec 1 10:01:07] DEBUG[25528] netsock2.c: Splitting '172.16.100.1' gives... [Dec 1 10:01:07] DEBUG[25528] netsock2.c: ...host '172.16.100.1' and port '(null)'. [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Dec 1 10:01:07] DEBUG[25528] netsock2.c: Splitting '172.16.100.186:5060' gives... [Dec 1 10:01:07] DEBUG[25528] netsock2.c: ...host '172.16.100.186' and port '5060'. [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: Setting NAT on UDPTL to Off [Dec 1 10:01:07] DEBUG[25528] rtp_engine.c: Using engine 'asterisk' for RTP instance '0xb6c1a9e8' [Dec 1 10:01:07] DEBUG[25528] res_rtp_asterisk.c: Allocated port 17424 for RTP instance '0xb6c1a9e8' [Dec 1 10:01:07] DEBUG[25528] rtp_engine.c: RTP instance '0xb6c1a9e8' is setup and ready to go [Dec 1 10:01:07] DEBUG[25528] res_rtp_asterisk.c: Setup RTCP on RTP instance '0xb6c1a9e8' [Dec 1 10:01:07] VERBOSE[25528] netsock2.c: == Using SIP RTP TOS bits 184 [Dec 1 10:01:07] VERBOSE[25528] netsock2.c: == Using SIP RTP CoS mark 5 [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: Setting NAT on RTP to Off [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: Setting NAT on UDPTL to Off [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: Processing session-level SDP o=- 181776124 181776124 IN IP4 172.16.100.186... UNSUPPORTED. [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: Processing session-level SDP s=-... UNSUPPORTED. [Dec 1 10:01:07] DEBUG[25528] netsock2.c: Splitting '172.16.100.186' gives... [Dec 1 10:01:07] DEBUG[25528] netsock2.c: ...host '172.16.100.186' and port '(null)'. [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: Processing session-level SDP c=IN IP4 172.16.100.186... OK. [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Dec 1 10:01:07] DEBUG[25528] rtp_engine.c: Setting payload 0 based on m type on 0xb76154f0 [Dec 1 10:01:07] DEBUG[25528] rtp_engine.c: Setting payload 4 based on m type on 0xb76154f0 [Dec 1 10:01:07] DEBUG[25528] rtp_engine.c: Setting payload 8 based on m type on 0xb76154f0 [Dec 1 10:01:07] DEBUG[25528] rtp_engine.c: Setting payload 18 based on m type on 0xb76154f0 [Dec 1 10:01:07] DEBUG[25528] rtp_engine.c: Setting payload 101 based on m type on 0xb76154f0 [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:2 G726-32/8000... OK. [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:4 G723/8000... OK. [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729a/8000... OK. [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED. [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: Processing media-level (audio) SDP a=ptime:30... OK. [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Dec 1 10:01:07] DEBUG[25528] rtp_engine.c: Incorporating payload 0 on 0xb76154f0 [Dec 1 10:01:07] DEBUG[25528] rtp_engine.c: Incorporating payload 2 on 0xb76154f0 [Dec 1 10:01:07] DEBUG[25528] rtp_engine.c: Incorporating payload 4 on 0xb76154f0 [Dec 1 10:01:07] DEBUG[25528] rtp_engine.c: Incorporating payload 8 on 0xb76154f0 [Dec 1 10:01:07] DEBUG[25528] rtp_engine.c: Incorporating payload 18 on 0xb76154f0 [Dec 1 10:01:07] DEBUG[25528] rtp_engine.c: Incorporating payload 101 on 0xb76154f0 [Dec 1 10:01:07] DEBUG[25528] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb6c1a9e8' [Dec 1 10:01:07] DEBUG[25528] rtp_engine.c: Copying payload 0 from 0xb76154f0 to 0xb6c1ab94 [Dec 1 10:01:07] DEBUG[25528] rtp_engine.c: Copying payload 2 from 0xb76154f0 to 0xb6c1ab94 [Dec 1 10:01:07] DEBUG[25528] rtp_engine.c: Copying payload 4 from 0xb76154f0 to 0xb6c1ab94 [Dec 1 10:01:07] DEBUG[25528] rtp_engine.c: Copying payload 8 from 0xb76154f0 to 0xb6c1ab94 [Dec 1 10:01:07] DEBUG[25528] rtp_engine.c: Copying payload 18 from 0xb76154f0 to 0xb6c1ab94 [Dec 1 10:01:07] DEBUG[25528] rtp_engine.c: Copying payload 101 from 0xb76154f0 to 0xb6c1ab94 [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: Checking SIP call limits for device 202 [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: Updating call counter for incoming call [Dec 1 10:01:07] DEBUG[25496] devicestate.c: No provider found, checking channel drivers for SIP - 202 [Dec 1 10:01:07] DEBUG[25496] chan_sip.c: Checking device state for peer 202 [Dec 1 10:01:07] DEBUG[25496] devicestate.c: Changing state for SIP/202 - state 2 (In use) [Dec 1 10:01:07] DEBUG[25496] devicestate.c: device 'SIP/202' state '2' [Dec 1 10:01:07] DEBUG[25497] app_queue.c: Extension '202@local-extensions' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Dec 1 10:01:07] DEBUG[25542] app_queue.c: Device 'SIP/202' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: ExtensionStatus Privilege: call,all Exten: 202 Context: local-extensions Hint: SIP/202 Status: 1 [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: *** Joint capabilities are 0x4 (ulaw) [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: *** Our capabilities are 0x4 (ulaw) [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: This channel will not be able to handle video. [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: build_route: Contact hop: Erik Smith [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: SIP/202-000000a0: New call is still down.... Trying... [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 172.16.100.186:5060 [Dec 1 10:01:07] DEBUG[25496] devicestate.c: No provider found, checking channel drivers for SIP - 202 [Dec 1 10:01:07] DEBUG[25496] chan_sip.c: Checking device state for peer 202 [Dec 1 10:01:07] DEBUG[25496] devicestate.c: Changing state for SIP/202 - state 2 (In use) [Dec 1 10:01:07] DEBUG[25496] devicestate.c: device 'SIP/202' state '2' [Dec 1 10:01:07] DEBUG[25542] app_queue.c: Device 'SIP/202' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newchannel Privilege: call,all Channel: SIP/202-000000a0 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 202 CallerIDName: Downstairs AccountCode: Exten: 18006262001 Context: from-inside Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'Macro' [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: SIPURI Value: sip:202@172.16.100.186:5060 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: SIPDOMAIN Value: 172.16.100.1 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: SIPCALLID Value: b176b300-269bca7b@172.16.100.186 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: SIP/202-000000a0 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 202 CallerIDName: Downstairs Uniqueid: 1291215667.365 [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [18006262001@from-inside:1] Macro("SIP/202-000000a0", "tl-set-variables2,from-inside-redir,") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: from-inside Extension: 18006262001 Priority: 1 Application: Macro AppData: tl-set-variables2,from-inside-redir, Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_EXTEN Value: 18006262001 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_CONTEXT Value: from-inside Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_PRIORITY Value: 1 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: ARG1 Value: from-inside-redir Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: ARG2 Value: Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'ARG2' is '' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'Set' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-set-variables2:1] Set("SIP/202-000000a0", "__tenant=") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-set-variables2 Extension: s Priority: 1 Application: Set AppData: __tenant= Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: __tenant Value: Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: Set [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'ARG2' is '' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'Set' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-set-variables2:2] Set("SIP/202-000000a0", "CDR(userfield)=") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-set-variables2 Extension: s Priority: 2 Application: Set AppData: CDR(userfield)= Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: Set [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'Set' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-set-variables2:3] Set("SIP/202-000000a0", "__FROM_INSIDE=1") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-set-variables2 Extension: s Priority: 3 Application: Set AppData: __FROM_INSIDE=1 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: __FROM_INSIDE Value: 1 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: Set [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'TL_DASH' is NULL [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'ARG2' is '' [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: DB_RESULT Value: default Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Function result is 'default' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'Set' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-set-variables2:4] Set("SIP/202-000000a0", "__MOH=default") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-set-variables2 Extension: s Priority: 4 Application: Set AppData: __MOH=default Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: __MOH Value: default Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: Set [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'MOH' is 'default' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Expression result is '1' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'GotoIf' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-set-variables2:5] GotoIf("SIP/202-000000a0", "1 ?setmoh") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-set-variables2 Extension: s Priority: 5 Application: GotoIf AppData: 1 ?setmoh Uniqueid: 1291215667.365 [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Goto (macro-tl-set-variables2,s,7) [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: GotoIf [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'MOH' is 'default' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'Set' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-set-variables2:7] Set("SIP/202-000000a0", "CHANNEL(musicclass)=default") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-set-variables2 Extension: s Priority: 7 Application: Set AppData: CHANNEL(musicclass)=default Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: Set [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'ARG1' is 'from-inside-redir' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'MACRO_EXTEN' is '18006262001' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'Goto' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-set-variables2:8] Goto("SIP/202-000000a0", "from-inside-redir,18006262001,1") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-set-variables2 Extension: s Priority: 8 Application: Goto AppData: from-inside-redir,18006262001,1 Uniqueid: 1291215667.365 [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Goto (from-inside-redir,18006262001,1) [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: Goto [Dec 1 10:01:07] VERBOSE[25126] app_macro.c: == Channel 'SIP/202-000000a0' jumping out of macro 'tl-set-variables2' [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 0 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'Macro' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [18006262001@from-inside-redir:1] Macro("SIP/202-000000a0", "tl-dialout-1-trunk,60,SIP/GW01EEMAN,+,0") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: from-inside-redir Extension: 18006262001 Priority: 1 Application: Macro AppData: tl-dialout-1-trunk,60,SIP/GW01EEMAN,+,0 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_EXTEN Value: 18006262001 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_CONTEXT Value: from-inside-redir Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_PRIORITY Value: 1 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: ARG1 Value: 60 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: ARG2 Value: SIP/GW01EEMAN Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: ARG3 Value: + Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: ARG4 Value: 0 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'MACRO_EXTEN' is '18006262001' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Expression result is '0' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'GotoIf' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-dialout-1-trunk:1] GotoIf("SIP/202-000000a0", "0?dial") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-1-trunk Extension: s Priority: 1 Application: GotoIf AppData: 0?dial Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Not taking any branch [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: GotoIf [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'MACRO_EXTEN' is '18006262001' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'Set' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-dialout-1-trunk:2] Set("SIP/202-000000a0", "__DIALED_NUMBER=18006262001") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-1-trunk Extension: s Priority: 2 Application: Set AppData: __DIALED_NUMBER=18006262001 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: __DIALED_NUMBER Value: 18006262001 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: Set [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'ARG1' is '60' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'ARG2' is 'SIP/GW01EEMAN' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'ARG3' is '+' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'ARG4' is '0' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'ARG5' is NULL [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'Macro' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-dialout-1-trunk:3] Macro("SIP/202-000000a0", "tl-dialout-base,60,SIP/GW01EEMAN,+,0,") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-1-trunk Extension: s Priority: 3 Application: Macro AppData: tl-dialout-base,60,SIP/GW01EEMAN,+,0, Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_EXTEN Value: s Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_CONTEXT Value: macro-tl-dialout-1-trunk Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_PRIORITY Value: 3 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: ARG1 Value: 60 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: ARG2 Value: SIP/GW01EEMAN Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: ARG3 Value: + Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: ARG4 Value: 0 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: ARG5 Value: Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'tenant' is '' [Dec 1 10:01:07] DEBUG[25126] db.c: Unable to find key 'TENANT//status' in family 'TL' [Dec 1 10:01:07] DEBUG[25126] func_db.c: DB: TL/TENANT//status not found in database. [Dec 1 10:01:07] DEBUG[25126] pbx.c: Function result is '' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'Set' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-dialout-base:1] Set("SIP/202-000000a0", "status=") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: s Priority: 1 Application: Set AppData: status= Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: status Value: Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: Set [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'status' is '' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Expression result is '1' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'GotoIf' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-dialout-base:2] GotoIf("SIP/202-000000a0", "1?enabled") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: s Priority: 2 Application: GotoIf AppData: 1?enabled Uniqueid: 1291215667.365 [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Goto (macro-tl-dialout-base,s,5) [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: GotoIf [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'TL_ENABLE_MAXCALLS_CHECK' is NULL [Dec 1 10:01:07] DEBUG[25126] pbx.c: Expression result is '1' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'GotoIf' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-dialout-base:5] GotoIf("SIP/202-000000a0", "1?allclear") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: s Priority: 5 Application: GotoIf AppData: 1?allclear Uniqueid: 1291215667.365 [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Goto (macro-tl-dialout-base,s,13) [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: GotoIf [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'Set' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-dialout-base:13] Set("SIP/202-000000a0", "i=2") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: s Priority: 13 Application: Set AppData: i=2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: i Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: Set [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'Macro' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-dialout-base:14] Macro("SIP/202-000000a0", "tl-set-myvariables") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: s Priority: 14 Application: Macro AppData: tl-set-myvariables Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_EXTEN Value: s Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_CONTEXT Value: macro-tl-dialout-base Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_PRIORITY Value: 14 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 3 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 3 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Evaluating 'CHANNEL' (from 'CHANNEL}' len 7) [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'CHANNEL' is 'SIP/202-000000a0' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Function result is '202-000000a0' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'Set' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-set-myvariables:1] Set("SIP/202-000000a0", "MY_CHAN=202-000000a0") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-set-myvariables Extension: s Priority: 1 Application: Set AppData: MY_CHAN=202-000000a0 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MY_CHAN Value: 202-000000a0 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: Set [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 3 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'CHANNEL' is 'SIP/202-000000a0' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'NoOp' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-set-myvariables:2] NoOp("SIP/202-000000a0", "THECHANNEL=SIP/202-000000a0") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-set-myvariables Extension: s Priority: 2 Application: NoOp AppData: THECHANNEL=SIP/202-000000a0 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: NoOp [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 3 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'CHANNEL' is 'SIP/202-000000a0' [Dec 1 10:01:07] DEBUG[25126] func_strings.c: FUNCTION REGEX (^Zap/|^DAHDI/)(SIP/202-000000a0) [Dec 1 10:01:07] DEBUG[25126] pbx.c: Function result is '0' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'Set' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-set-myvariables:3] Set("SIP/202-000000a0", "zap=0") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-set-myvariables Extension: s Priority: 3 Application: Set AppData: zap=0 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: zap Value: 0 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: Set [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 3 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'zap' is '0' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Expression result is '1' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'GotoIf' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-set-myvariables:4] GotoIf("SIP/202-000000a0", "1?usechannel") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-set-myvariables Extension: s Priority: 4 Application: GotoIf AppData: 1?usechannel Uniqueid: 1291215667.365 [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Goto (macro-tl-set-myvariables,s,9) [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: GotoIf [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 3 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'CHANNEL' is 'SIP/202-000000a0' [Dec 1 10:01:07] DEBUG[25126] func_strings.c: FUNCTION REGEX (^Local/)(SIP/202-000000a0) [Dec 1 10:01:07] DEBUG[25126] pbx.c: Function result is '0' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'Set' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-set-myvariables:9] Set("SIP/202-000000a0", "local=0") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-set-myvariables Extension: s Priority: 9 Application: Set AppData: local=0 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: local Value: 0 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: Set [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 3 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'local' is '0' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Expression result is '1' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'GotoIf' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-set-myvariables:10] GotoIf("SIP/202-000000a0", "1?useit") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-set-myvariables Extension: s Priority: 10 Application: GotoIf AppData: 1?useit Uniqueid: 1291215667.365 [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Goto (macro-tl-set-myvariables,s,12) [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: GotoIf [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 3 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Evaluating 'MY_CHAN' (from 'MY_CHAN}' len 7) [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'MY_CHAN' is '202-000000a0' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Function result is '202' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'Set' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-set-myvariables:12] Set("SIP/202-000000a0", "__MYEXTENSION=202") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-set-myvariables Extension: s Priority: 12 Application: Set AppData: __MYEXTENSION=202 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: __MYEXTENSION Value: 202 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: Set [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 3 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'tenant' is '' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'TL_DASH' is NULL [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'MYEXTENSION' is '202' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'Set' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-set-myvariables:13] Set("SIP/202-000000a0", "__MYID=202") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-set-myvariables Extension: s Priority: 13 Application: Set AppData: __MYID=202 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: __MYID Value: 202 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: Set [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_EXTEN Value: s Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_CONTEXT Value: macro-tl-dialout-1-trunk Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_PRIORITY Value: 3 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: Macro [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'SetAMAFlags' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-dialout-base:15] SetAMAFlags("SIP/202-000000a0", "billing") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: s Priority: 15 Application: SetAMAFlags AppData: billing Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: SetAMAFlags [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'MYID' is '202' [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: DB_RESULT Value: Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Function result is '' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'Set' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-dialout-base:16] Set("SIP/202-000000a0", "RECORD=") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: s Priority: 16 Application: Set AppData: RECORD= Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: RECORD Value: Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: Set [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'RECORD' is '' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Expression result is '1' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'GotoIf' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-dialout-base:17] GotoIf("SIP/202-000000a0", "1?done_checkrecord") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: s Priority: 17 Application: GotoIf AppData: 1?done_checkrecord Uniqueid: 1291215667.365 [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Goto (macro-tl-dialout-base,s,26) [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: GotoIf [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'RECORD' is '' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'NoOp' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-dialout-base:26] NoOp("SIP/202-000000a0", "RECORD=") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: s Priority: 26 Application: NoOp AppData: RECORD= Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: NoOp [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'TOUCH_MONITOR' is NULL [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'NoOp' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-dialout-base:27] NoOp("SIP/202-000000a0", "TOUCH_MONITOR=") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: s Priority: 27 Application: NoOp AppData: TOUCH_MONITOR= Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: NoOp [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'RECORD_OPTIONS' is NULL [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'NoOp' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-dialout-base:28] NoOp("SIP/202-000000a0", "RECORD_OPTIONS=") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: s Priority: 28 Application: NoOp AppData: RECORD_OPTIONS= Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: NoOp [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'RECORDING_FORMAT' is 'WAV' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'NoOp' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-dialout-base:29] NoOp("SIP/202-000000a0", "RECORDING_FORMAT=WAV") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: s Priority: 29 Application: NoOp AppData: RECORDING_FORMAT=WAV Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: NoOp [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'tenant' is '' [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: DB_RESULT Value: Erik Smith Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Function result is 'Erik Smith' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'Set' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-dialout-base:30] Set("SIP/202-000000a0", "CALLERID(name)=Erik Smith") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: s Priority: 30 Application: Set AppData: CALLERID(name)=Erik Smith Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: NewCallerid Privilege: call,all Channel: SIP/202-000000a0 CallerIDNum: 202 CallerIDName: Erik Smith Uniqueid: 1291215667.365 CID-CallingPres: 0 (Presentation Allowed, Not Screened) [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: Set [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'tenant' is '' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Expression result is '1' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'GotoIf' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-dialout-base:31] GotoIf("SIP/202-000000a0", "1?calleridallowed") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: s Priority: 31 Application: GotoIf AppData: 1?calleridallowed Uniqueid: 1291215667.365 [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Goto (macro-tl-dialout-base,s,39) [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: GotoIf [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'CLIMYID' is NULL [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'NoOp' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-dialout-base:39] NoOp("SIP/202-000000a0", "CLIMYID=") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: s Priority: 39 Application: NoOp AppData: CLIMYID= Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: NoOp [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'MYID' is '202' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'NoOp' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-dialout-base:40] NoOp("SIP/202-000000a0", "MYID=202") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: s Priority: 40 Application: NoOp AppData: MYID=202 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: NoOp [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'CLIMYID' is NULL [Dec 1 10:01:07] DEBUG[25126] db.c: Unable to find key '/callerid' in family 'TL' [Dec 1 10:01:07] DEBUG[25126] func_db.c: DB: TL//callerid not found in database. [Dec 1 10:01:07] DEBUG[25126] pbx.c: Function result is '' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'Set' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-dialout-base:41] Set("SIP/202-000000a0", "CLI=") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: s Priority: 41 Application: Set AppData: CLI= Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: CLI Value: Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: Set [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'CLI' is '' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Expression result is '0' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'GotoIf' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-dialout-base:42] GotoIf("SIP/202-000000a0", "0?chkcallfwd") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: s Priority: 42 Application: GotoIf AppData: 0?chkcallfwd Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Not taking any branch [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: GotoIf [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'MYID' is '202' [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: DB_RESULT Value: 5023152516 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Function result is '5023152516' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'Set' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-dialout-base:43] Set("SIP/202-000000a0", "CLI=5023152516") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: s Priority: 43 Application: Set AppData: CLI=5023152516 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: CLI Value: 5023152516 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: Set [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'CLI' is '5023152516' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Expression result is '1' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'GotoIf' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-dialout-base:44] GotoIf("SIP/202-000000a0", "1?chkcallfwd") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: s Priority: 44 Application: GotoIf AppData: 1?chkcallfwd Uniqueid: 1291215667.365 [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Goto (macro-tl-dialout-base,s,47) [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: GotoIf [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'MYID' is '202' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'NoOp' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-dialout-base:47] NoOp("SIP/202-000000a0", "MYID=202") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: s Priority: 47 Application: NoOp AppData: MYID=202 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: NoOp [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'INCOMINGCLI' is NULL [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'NoOp' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-dialout-base:48] NoOp("SIP/202-000000a0", "INCOMINGCLI=") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: s Priority: 48 Application: NoOp AppData: INCOMINGCLI= Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: NoOp [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'CALLFWD' is NULL [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'NoOp' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-dialout-base:49] NoOp("SIP/202-000000a0", "CALLFWD=") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: s Priority: 49 Application: NoOp AppData: CALLFWD= Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: NoOp [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'CALLFWD' is NULL [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'FOLLOWME' is NULL [Dec 1 10:01:07] DEBUG[25126] pbx.c: Expression result is '1' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'GotoIf' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-dialout-base:50] GotoIf("SIP/202-000000a0", "1?setcalleridasabove") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: s Priority: 50 Application: GotoIf AppData: 1?setcalleridasabove Uniqueid: 1291215667.365 [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Goto (macro-tl-dialout-base,s,58) [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: GotoIf [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'CLI' is '5023152516' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Expression result is '0' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'GotoIf' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-dialout-base:58] GotoIf("SIP/202-000000a0", "0?nocallerid") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: s Priority: 58 Application: GotoIf AppData: 0?nocallerid Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Not taking any branch [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: GotoIf [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'CLI' is '5023152516' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'Set' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-dialout-base:59] Set("SIP/202-000000a0", "CALLERID(num)=5023152516") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: s Priority: 59 Application: Set AppData: CALLERID(num)=5023152516 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: NewCallerid Privilege: call,all Channel: SIP/202-000000a0 CallerIDNum: 5023152516 CallerIDName: Erik Smith Uniqueid: 1291215667.365 CID-CallingPres: 0 (Presentation Allowed, Not Screened) [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: Set [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'MYID' is '202' [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: DB_RESULT Value: Erik Smith Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Function result is 'Erik Smith' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'Set' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-dialout-base:60] Set("SIP/202-000000a0", "temp=Erik Smith") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: s Priority: 60 Application: Set AppData: temp=Erik Smith Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: temp Value: Erik Smith Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: Set [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'temp' is 'Erik Smith' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Expression result is '0' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'GotoIf' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-dialout-base:61] GotoIf("SIP/202-000000a0", "0?onetrunk,1") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: s Priority: 61 Application: GotoIf AppData: 0?onetrunk,1 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Not taking any branch [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: GotoIf [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'temp' is 'Erik Smith' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'Set' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-dialout-base:62] Set("SIP/202-000000a0", "CALLERID(name)=Erik Smith") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: s Priority: 62 Application: Set AppData: CALLERID(name)=Erik Smith Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: Set [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'Goto' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [s@macro-tl-dialout-base:63] Goto("SIP/202-000000a0", "onetrunk,1") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: s Priority: 63 Application: Goto AppData: onetrunk,1 Uniqueid: 1291215667.365 [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Goto (macro-tl-dialout-base,onetrunk,1) [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: Goto [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'i' is '2' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'ARG2' is 'SIP/GW01EEMAN' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'Set' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [onetrunk@macro-tl-dialout-base:1] Set("SIP/202-000000a0", "FULLNAME=SIP/GW01EEMAN") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: onetrunk Priority: 1 Application: Set AppData: FULLNAME=SIP/GW01EEMAN Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: FULLNAME Value: SIP/GW01EEMAN Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: Set [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Evaluating 'FULLNAME' (from 'FULLNAME}' len 8) [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'FULLNAME' is 'SIP/GW01EEMAN' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Function result is 'GW01EEMAN' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'Set' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [onetrunk@macro-tl-dialout-base:2] Set("SIP/202-000000a0", "TRUNK=GW01EEMAN") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: onetrunk Priority: 2 Application: Set AppData: TRUNK=GW01EEMAN Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: TRUNK Value: GW01EEMAN Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: Set [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'TRUNK' is 'GW01EEMAN' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Function result is '9' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Expression result is '0' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'GotoIf' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [onetrunk@macro-tl-dialout-base:3] GotoIf("SIP/202-000000a0", "0?failed,1") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: onetrunk Priority: 3 Application: GotoIf AppData: 0?failed,1 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Not taking any branch [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: GotoIf [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'TRUNK' is 'GW01EEMAN' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'TRUNK_STATUS_GW01EEMAN' is '1' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'Set' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [onetrunk@macro-tl-dialout-base:4] Set("SIP/202-000000a0", "TRUNK_STATUS=1") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: onetrunk Priority: 4 Application: Set AppData: TRUNK_STATUS=1 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: TRUNK_STATUS Value: 1 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: Set [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'TRUNK_STATUS' is '1' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Expression result is '0' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'GotoIf' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [onetrunk@macro-tl-dialout-base:5] GotoIf("SIP/202-000000a0", "0?next,1") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: onetrunk Priority: 5 Application: GotoIf AppData: 0?next,1 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Not taking any branch [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: GotoIf [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'i' is '2' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Expression result is '3' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'ARG3' is '+' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'Set' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [onetrunk@macro-tl-dialout-base:6] Set("SIP/202-000000a0", "ROUTE_PREPEND=+") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: onetrunk Priority: 6 Application: Set AppData: ROUTE_PREPEND=+ Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: ROUTE_PREPEND Value: + Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: Set [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'i' is '2' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Expression result is '4' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'ARG4' is '0' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'Set' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [onetrunk@macro-tl-dialout-base:7] Set("SIP/202-000000a0", "ROUTE_STRIP=0") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: onetrunk Priority: 7 Application: Set AppData: ROUTE_STRIP=0 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: ROUTE_STRIP Value: 0 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: Set [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'i' is '2' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Expression result is '5' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'ARG5' is '' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'RECORD_OPTIONS' is NULL [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'Set' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [onetrunk@macro-tl-dialout-base:8] Set("SIP/202-000000a0", "ROUTE_OPTIONS=") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: onetrunk Priority: 8 Application: Set AppData: ROUTE_OPTIONS= Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: ROUTE_OPTIONS Value: Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: Set [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'ROUTE_PREPEND' is '+' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'ROUTE_STRIP' is '0' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'DIALED_NUMBER' is '18006262001' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'Set' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [onetrunk@macro-tl-dialout-base:9] Set("SIP/202-000000a0", "NUMBER_TO_DIAL=+18006262001") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: onetrunk Priority: 9 Application: Set AppData: NUMBER_TO_DIAL=+18006262001 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: NUMBER_TO_DIAL Value: +18006262001 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: Set [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'TRUNK' is 'GW01EEMAN' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'TRUNK_DIALSTRING_GW01EEMAN' is '' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'Set' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [onetrunk@macro-tl-dialout-base:10] Set("SIP/202-000000a0", "TRUNK_DIALSTRING=") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: onetrunk Priority: 10 Application: Set AppData: TRUNK_DIALSTRING= Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: TRUNK_DIALSTRING Value: Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: Set [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'TRUNK' is 'GW01EEMAN' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'TRUNK_NAME_GW01EEMAN' is 'GW01EEMAN' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'Set' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [onetrunk@macro-tl-dialout-base:11] Set("SIP/202-000000a0", "TRUNK_NAME=GW01EEMAN") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: onetrunk Priority: 11 Application: Set AppData: TRUNK_NAME=GW01EEMAN Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: TRUNK_NAME Value: GW01EEMAN Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: Set [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'TRUNK' is 'GW01EEMAN' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'TRUNK_PROTOCOL_GW01EEMAN' is 'SIP' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'Set' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [onetrunk@macro-tl-dialout-base:12] Set("SIP/202-000000a0", "TRUNK_PROTOCOL=SIP") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: onetrunk Priority: 12 Application: Set AppData: TRUNK_PROTOCOL=SIP Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: TRUNK_PROTOCOL Value: SIP Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: Set [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'TRUNK' is 'GW01EEMAN' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'TRUNK_STRIP_GW01EEMAN' is '0' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'Set' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [onetrunk@macro-tl-dialout-base:13] Set("SIP/202-000000a0", "TRUNK_STRIP=0") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: onetrunk Priority: 13 Application: Set AppData: TRUNK_STRIP=0 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: TRUNK_STRIP Value: 0 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: Set [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'TRUNK' is 'GW01EEMAN' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'TRUNK_PREPEND_GW01EEMAN' is '' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'Set' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [onetrunk@macro-tl-dialout-base:14] Set("SIP/202-000000a0", "TRUNK_PREPEND=") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: onetrunk Priority: 14 Application: Set AppData: TRUNK_PREPEND= Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: TRUNK_PREPEND Value: Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: Set [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'TRUNK' is 'GW01EEMAN' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'TRUNK_CLI_PREPEND_GW01EEMAN' is '' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'TRUNK' is 'GW01EEMAN' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'TRUNK_CLI_STRIP_GW01EEMAN' is '0' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Function result is '5023152516' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'Set' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [onetrunk@macro-tl-dialout-base:15] Set("SIP/202-000000a0", "CALLERID(num)=5023152516") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: onetrunk Priority: 15 Application: Set AppData: CALLERID(num)=5023152516 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: Set [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'TRUNK_DIALSTRING' is '' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Expression result is '0' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'GotoIf' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [onetrunk@macro-tl-dialout-base:16] GotoIf("SIP/202-000000a0", "0?dial-CUSTOM,1") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: onetrunk Priority: 16 Application: GotoIf AppData: 0?dial-CUSTOM,1 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Not taking any branch [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: GotoIf [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'TRUNK_PROTOCOL' is 'SIP' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'Goto' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [onetrunk@macro-tl-dialout-base:17] Goto("SIP/202-000000a0", "dial-SIP,1") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: onetrunk Priority: 17 Application: Goto AppData: dial-SIP,1 Uniqueid: 1291215667.365 [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Goto (macro-tl-dialout-base,dial-SIP,1) [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: Goto [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'Set' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [dial-SIP@macro-tl-dialout-base:1] Set("SIP/202-000000a0", "headernum=1") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: dial-SIP Priority: 1 Application: Set AppData: headernum=1 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: headernum Value: 1 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: Set [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'TRUNK' is 'GW01EEMAN' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'headernum' is '1' [Dec 1 10:01:07] DEBUG[25126] db.c: Unable to find key 'GW01EEMAN/headers/1' in family 'TL' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Function result is '0' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'GotoIf' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [dial-SIP@macro-tl-dialout-base:2] GotoIf("SIP/202-000000a0", "0?:routeoptions") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: dial-SIP Priority: 2 Application: GotoIf AppData: 0?:routeoptions Uniqueid: 1291215667.365 [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Goto (macro-tl-dialout-base,dial-SIP,7) [Dec 1 10:01:07] DEBUG[25126] app_macro.c: Executed application: GotoIf [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'TRUNK_PREPEND' is '' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'TRUNK_STRIP' is '0' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'NUMBER_TO_DIAL' is '+18006262001' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'TRUNK_NAME' is 'GW01EEMAN' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'ARG1' is '60' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Result of 'ROUTE_OPTIONS' is '' [Dec 1 10:01:07] DEBUG[25126] pbx.c: Launching 'Dial' [Dec 1 10:01:07] VERBOSE[25126] pbx.c: -- Executing [dial-SIP@macro-tl-dialout-base:7] Dial("SIP/202-000000a0", "SIP/+18006262001@GW01EEMAN,60,") in new stack [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: macro-tl-dialout-base Extension: dial-SIP Priority: 7 Application: Dial AppData: SIP/+18006262001@GW01EEMAN,60, Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: DIALSTATUS Value: Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: DIALEDPEERNUMBER Value: Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: DIALEDPEERNAME Value: Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: ANSWEREDTIME Value: Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: DIALEDTIME Value: Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25126] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw) [Dec 1 10:01:07] VERBOSE[25126] netsock.c: == Using UDPTL TOS bits 184 [Dec 1 10:01:07] VERBOSE[25126] netsock.c: == Using UDPTL CoS mark 5 [Dec 1 10:01:07] DEBUG[25126] chan_sip.c: Allocating new SIP dialog for 53e37dee250fca65192d73aa79b00577@216.135.89.226:0 - INVITE (No RTP) [Dec 1 10:01:07] DEBUG[25126] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x8e7f950' [Dec 1 10:01:07] DEBUG[25126] res_rtp_asterisk.c: Allocated port 10170 for RTP instance '0x8e7f950' [Dec 1 10:01:07] DEBUG[25126] rtp_engine.c: RTP instance '0x8e7f950' is setup and ready to go [Dec 1 10:01:07] DEBUG[25126] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x8e7f950' [Dec 1 10:01:07] VERBOSE[25126] netsock2.c: == Using SIP RTP TOS bits 184 [Dec 1 10:01:07] VERBOSE[25126] netsock2.c: == Using SIP RTP CoS mark 5 [Dec 1 10:01:07] DEBUG[25126] chan_sip.c: Setting NAT on RTP to Off [Dec 1 10:01:07] DEBUG[25126] chan_sip.c: Setting NAT on UDPTL to Off [Dec 1 10:01:07] DEBUG[25126] acl.c: For destination '69.64.11.6', our source address is '216.135.89.226'. [Dec 1 10:01:07] DEBUG[25126] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 216.135.89.226:5060 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Newchannel Privilege: call,all Channel: SIP/GW01EEMAN-000000a1 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: AccountCode: Exten: Context: from-outside Uniqueid: 1291215667.366 [Dec 1 10:01:07] DEBUG[25126] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Dec 1 10:01:07] DEBUG[25126] chan_sip.c: *** Joint capabilities are 0x4 (ulaw) [Dec 1 10:01:07] DEBUG[25126] chan_sip.c: *** Our capabilities are 0x4 (ulaw) [Dec 1 10:01:07] DEBUG[25126] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Dec 1 10:01:07] DEBUG[25126] chan_sip.c: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Dec 1 10:01:07] DEBUG[25126] chan_sip.c: This channel will not be able to handle video. [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/GW01EEMAN-000000a1 Variable: SIPCALLID Value: 67c9e9c63a04cdd82bf8fa3b52c15efb@216.135.89.226:5060 Uniqueid: 1291215667.366 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/GW01EEMAN-000000a1 Variable: DIALEDPEERNUMBER Value: +18006262001@GW01EEMAN Uniqueid: 1291215667.366 [Dec 1 10:01:07] DEBUG[25126] rtp_engine.c: Seeded SDP of 'SIP/GW01EEMAN-000000a1' with that of 'SIP/202-000000a0' [Dec 1 10:01:07] DEBUG[25126] channel.c: Not copying variable DIALEDTIME. [Dec 1 10:01:07] DEBUG[25126] channel.c: Not copying variable ANSWEREDTIME. [Dec 1 10:01:07] DEBUG[25126] channel.c: Not copying variable DIALEDPEERNAME. [Dec 1 10:01:07] DEBUG[25126] channel.c: Not copying variable DIALEDPEERNUMBER. [Dec 1 10:01:07] DEBUG[25126] channel.c: Not copying variable DIALSTATUS. [Dec 1 10:01:07] DEBUG[25126] channel.c: Not copying variable MACRO_DEPTH. [Dec 1 10:01:07] DEBUG[25126] channel.c: Not copying variable headernum. [Dec 1 10:01:07] DEBUG[25126] channel.c: Not copying variable TRUNK_PREPEND. [Dec 1 10:01:07] DEBUG[25126] channel.c: Not copying variable TRUNK_STRIP. [Dec 1 10:01:07] DEBUG[25126] channel.c: Not copying variable TRUNK_PROTOCOL. [Dec 1 10:01:07] DEBUG[25126] channel.c: Not copying variable TRUNK_NAME. [Dec 1 10:01:07] DEBUG[25126] channel.c: Not copying variable TRUNK_DIALSTRING. [Dec 1 10:01:07] DEBUG[25126] channel.c: Not copying variable NUMBER_TO_DIAL. [Dec 1 10:01:07] DEBUG[25126] channel.c: Not copying variable ROUTE_OPTIONS. [Dec 1 10:01:07] DEBUG[25126] channel.c: Not copying variable ROUTE_STRIP. [Dec 1 10:01:07] DEBUG[25126] channel.c: Not copying variable ROUTE_PREPEND. [Dec 1 10:01:07] DEBUG[25126] channel.c: Not copying variable TRUNK_STATUS. [Dec 1 10:01:07] DEBUG[25126] channel.c: Not copying variable TRUNK. [Dec 1 10:01:07] DEBUG[25126] channel.c: Not copying variable FULLNAME. [Dec 1 10:01:07] DEBUG[25126] channel.c: Not copying variable temp. [Dec 1 10:01:07] DEBUG[25126] channel.c: Not copying variable DB_RESULT. [Dec 1 10:01:07] DEBUG[25126] channel.c: Not copying variable CLI. [Dec 1 10:01:07] DEBUG[25126] channel.c: Not copying variable RECORD. [Dec 1 10:01:07] DEBUG[25126] channel.c: Not copying variable MACRO_PRIORITY. [Dec 1 10:01:07] DEBUG[25126] channel.c: Not copying variable MACRO_CONTEXT. [Dec 1 10:01:07] DEBUG[25126] channel.c: Not copying variable MACRO_EXTEN. [Dec 1 10:01:07] DEBUG[25126] channel.c: Copying hard-transferable variable MYID. [Dec 1 10:01:07] DEBUG[25126] channel.c: Copying hard-transferable variable MYEXTENSION. [Dec 1 10:01:07] DEBUG[25126] channel.c: Not copying variable local. [Dec 1 10:01:07] DEBUG[25126] channel.c: Not copying variable zap. [Dec 1 10:01:07] DEBUG[25126] channel.c: Not copying variable MY_CHAN. [Dec 1 10:01:07] DEBUG[25126] channel.c: Not copying variable i. [Dec 1 10:01:07] DEBUG[25126] channel.c: Not copying variable status. [Dec 1 10:01:07] DEBUG[25126] channel.c: Not copying variable ARG5. [Dec 1 10:01:07] DEBUG[25126] channel.c: Not copying variable ARG4. [Dec 1 10:01:07] DEBUG[25126] channel.c: Not copying variable ARG3. [Dec 1 10:01:07] DEBUG[25126] channel.c: Not copying variable ARG2. [Dec 1 10:01:07] DEBUG[25126] channel.c: Not copying variable ARG1. [Dec 1 10:01:07] DEBUG[25126] channel.c: Copying hard-transferable variable DIALED_NUMBER. [Dec 1 10:01:07] DEBUG[25126] channel.c: Copying hard-transferable variable MOH. [Dec 1 10:01:07] DEBUG[25126] channel.c: Copying hard-transferable variable FROM_INSIDE. [Dec 1 10:01:07] DEBUG[25126] channel.c: Copying hard-transferable variable tenant. [Dec 1 10:01:07] DEBUG[25126] channel.c: Not copying variable SIPCALLID. [Dec 1 10:01:07] DEBUG[25126] channel.c: Not copying variable SIPDOMAIN. [Dec 1 10:01:07] DEBUG[25126] channel.c: Not copying variable SIPURI. [Dec 1 10:01:07] DEBUG[25126] chan_sip.c: Outgoing Call for +18006262001 [Dec 1 10:01:07] DEBUG[25126] chan_sip.c: Updating call counter for outgoing call [Dec 1 10:01:07] DEBUG[25126] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: False Text flag: False [Dec 1 10:01:07] DEBUG[25126] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Dec 1 10:01:07] DEBUG[25126] chan_sip.c: -- Done with adding codecs to SDP [Dec 1 10:01:07] DEBUG[25126] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Dec 1 10:01:07] DEBUG[25126] chan_sip.c: Initializing initreq for method INVITE - callid 67c9e9c63a04cdd82bf8fa3b52c15efb@216.135.89.226:5060 [Dec 1 10:01:07] DEBUG[25126] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 69.64.11.6:5060 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: Dial Privilege: call,all SubEvent: Begin Channel: SIP/202-000000a0 Destination: SIP/GW01EEMAN-000000a1 CallerIDNum: 5023152516 CallerIDName: Erik Smith UniqueID: 1291215667.365 DestUniqueID: 1291215667.366 Dialstring: +18006262001@GW01EEMAN [Dec 1 10:01:07] VERBOSE[25126] app_dial.c: -- Called +18006262001@GW01EEMAN [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: NewCallerid Privilege: call,all Channel: SIP/GW01EEMAN-000000a1 CallerIDNum: 18006262001 CallerIDName: Uniqueid: 1291215667.366 CID-CallingPres: 0 (Presentation Allowed, Not Screened) [Dec 1 10:01:07] DEBUG[25506] manager.c: Running action 'Getvar' [Dec 1 10:01:07] DEBUG[25506] pbx.c: Result of 'AJ_TRACE_ID' is NULL [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: = Looking for Call ID: 67c9e9c63a04cdd82bf8fa3b52c15efb@216.135.89.226:5060 (Checking To) --From tag as6863221c --To-tag as0b533773 [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: Acked pending invite 102 [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: Stopping retransmission on '67c9e9c63a04cdd82bf8fa3b52c15efb@216.135.89.226:5060' of Request 102: Match Found [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: SIP response 401 to standard invite [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: Trying to put 'ACK sip:+18' onto UDP socket destined for 69.64.11.6:5060 [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: Auth attempt 1 on INVITE [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: False Text flag: False [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: -- Done with adding codecs to SDP [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 69.64.11.6:5060 [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: ~HASH~SIP_CAUSE~SIP/GW01EEMAN-000000a1~ Value: SIP 401 Unauthorized Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Running action 'Getvar' [Dec 1 10:01:07] DEBUG[25506] pbx.c: Result of 'XMLNamespaceAssistedTransferTrackerId' is NULL [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: = Looking for Call ID: 67c9e9c63a04cdd82bf8fa3b52c15efb@216.135.89.226:5060 (Checking To) --From tag as6863221c --To-tag [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '67c9e9c63a04cdd82bf8fa3b52c15efb@216.135.89.226:5060' Request 103: Found [Dec 1 10:01:07] DEBUG[25528] chan_sip.c: SIP response 100 to standard invite [Dec 1 10:01:07] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: ~HASH~SIP_CAUSE~SIP/GW01EEMAN-000000a1~ Value: SIP 100 Trying Uniqueid: 1291215667.365 [Dec 1 10:01:07] DEBUG[25506] manager.c: Running action 'Getvar' [Dec 1 10:01:07] DEBUG[25506] pbx.c: Result of 'AJ_TRACE_ID' is NULL [Dec 1 10:01:07] DEBUG[25506] manager.c: Running action 'Getvar' [Dec 1 10:01:07] DEBUG[25506] pbx.c: Result of 'XMLNamespaceAssistedTransferTrackerId' is NULL [Dec 1 10:01:07] DEBUG[25506] manager.c: Running action 'Getvar' [Dec 1 10:01:07] DEBUG[25506] pbx.c: Result of 'AJ_TRACE_ID' is NULL [Dec 1 10:01:07] DEBUG[25506] manager.c: Running action 'Getvar' [Dec 1 10:01:07] DEBUG[25506] pbx.c: Result of 'AJ_TRACE_ID' is NULL [Dec 1 10:01:08] DEBUG[25528] chan_sip.c: = Looking for Call ID: 527df662043cedb53efa3c1962455ce8@69.64.11.13 (Checking From) --From tag as4be9230d --To-tag [Dec 1 10:01:08] DEBUG[25528] acl.c: For destination '69.64.11.13', our source address is '216.135.89.226'. [Dec 1 10:01:08] DEBUG[25528] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 216.135.89.226:5060 [Dec 1 10:01:08] DEBUG[25528] chan_sip.c: Allocating new SIP dialog for 527df662043cedb53efa3c1962455ce8@69.64.11.13 - OPTIONS (No RTP) [Dec 1 10:01:08] DEBUG[25528] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Dec 1 10:01:08] DEBUG[25528] chan_sip.c: Trying to put 'SIP/2.0 404' onto UDP socket destined for 69.64.11.13:5060 [Dec 1 10:01:08] DEBUG[25528] chan_sip.c: SIP message could not be handled, bad request: 527df662043cedb53efa3c1962455ce8@69.64.11.13 [Dec 1 10:01:08] DEBUG[25528] chan_sip.c: Auto destroying SIP dialog '7a58ad0a416b9bfc4ed6731948a07b62@69.64.11.20' [Dec 1 10:01:08] DEBUG[25528] chan_sip.c: Destroying SIP dialog 7a58ad0a416b9bfc4ed6731948a07b62@69.64.11.20 [Dec 1 10:01:09] DEBUG[25528] chan_sip.c: = Looking for Call ID: 67c9e9c63a04cdd82bf8fa3b52c15efb@216.135.89.226:5060 (Checking To) --From tag as6863221c --To-tag as5ed9111c [Dec 1 10:01:09] DEBUG[25528] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '67c9e9c63a04cdd82bf8fa3b52c15efb@216.135.89.226:5060' Request 103: Found [Dec 1 10:01:09] DEBUG[25528] chan_sip.c: SIP response 183 to standard invite [Dec 1 10:01:09] DEBUG[25528] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Dec 1 10:01:09] DEBUG[25528] chan_sip.c: Processing session-level SDP o=root 1739111220 1739111220 IN IP4 69.64.11.6... UNSUPPORTED. [Dec 1 10:01:09] DEBUG[25528] chan_sip.c: Processing session-level SDP s=Asterisk PBX 1.6.2.14-rc1... UNSUPPORTED. [Dec 1 10:01:09] DEBUG[25528] netsock2.c: Splitting '69.64.11.6' gives... [Dec 1 10:01:09] DEBUG[25528] netsock2.c: ...host '69.64.11.6' and port '(null)'. [Dec 1 10:01:09] DEBUG[25528] chan_sip.c: Processing session-level SDP c=IN IP4 69.64.11.6... OK. [Dec 1 10:01:09] DEBUG[25528] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Dec 1 10:01:09] DEBUG[25528] rtp_engine.c: Setting payload 0 based on m type on 0xb7615160 [Dec 1 10:01:09] DEBUG[25528] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Dec 1 10:01:09] DEBUG[25528] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK. [Dec 1 10:01:09] DEBUG[25528] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Dec 1 10:01:09] DEBUG[25528] rtp_engine.c: Incorporating payload 0 on 0xb7615160 [Dec 1 10:01:09] DEBUG[25528] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x8e7f950' [Dec 1 10:01:09] DEBUG[25528] rtp_engine.c: Copying payload 0 from 0xb7615160 to 0x8e7fafc [Dec 1 10:01:09] DEBUG[25528] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Dec 1 10:01:09] DEBUG[25528] chan_sip.c: We have an owner, now see if we need to change this call [Dec 1 10:01:09] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: ~HASH~SIP_CAUSE~SIP/GW01EEMAN-000000a1~ Value: SIP 183 Session Progress Uniqueid: 1291215667.365 [Dec 1 10:01:09] VERBOSE[25126] app_dial.c: -- SIP/GW01EEMAN-000000a1 is making progress passing it to SIP/202-000000a0 [Dec 1 10:01:09] DEBUG[25126] rtp_engine.c: Setting early bridge SDP of 'SIP/202-000000a0' with that of 'SIP/GW01EEMAN-000000a1' [Dec 1 10:01:09] DEBUG[25126] chan_sip.c: Setting framing from config on incoming call [Dec 1 10:01:09] DEBUG[25126] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True [Dec 1 10:01:09] DEBUG[25126] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Dec 1 10:01:09] DEBUG[25126] chan_sip.c: -- Done with adding codecs to SDP [Dec 1 10:01:09] DEBUG[25126] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Dec 1 10:01:09] DEBUG[25126] chan_sip.c: Trying to put 'SIP/2.0 183' onto UDP socket destined for 172.16.100.186:5060 [Dec 1 10:01:09] DEBUG[25126] res_rtp_asterisk.c: Ooh, format changed from unknown to ulaw [Dec 1 10:01:09] DEBUG[25126] res_rtp_asterisk.c: Created smoother: format: ulaw ms: 20 len: 160 [Dec 1 10:01:09] DEBUG[25126] res_rtp_asterisk.c: Starting RTCP transmission on RTP instance '0xb6c1a9e8' [Dec 1 10:01:09] DEBUG[25126] res_rtp_asterisk.c: Ooh, format changed from unknown to ulaw [Dec 1 10:01:09] DEBUG[25126] res_rtp_asterisk.c: Created smoother: format: ulaw ms: 20 len: 160 [Dec 1 10:01:14] DEBUG[25506] manager.c: Examining event: Event: RTCPSent Privilege: reporting,all To 69.64.11.6:11013 OurSSRC: 1114562930 SentNTP: 1291215674.0214368256 SentRTP: 9811568 SentPackets: 248 SentOctets: 39680 ReportBlock: FractionLost: 2 CumulativeLoss: 2 IAJitter: 0.0012 TheirLastSR: 0 DLSR: 65510.0840 (sec) [Dec 1 10:01:14] DEBUG[25126] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Dec 1 10:01:14] DEBUG[25506] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From 69.64.11.6:11013 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 31280 SequenceNumberCycles: 0 IAJitter: 68 LastSR: 0.0000000000 DLSR: 65510.0680(sec) [Dec 1 10:01:14] DEBUG[25506] manager.c: Examining event: Event: RTCPSent Privilege: reporting,all To 172.16.100.186:16425 OurSSRC: 1665765199 SentNTP: 1291215674.0218570752 SentRTP: 39840 SentPackets: 248 SentOctets: 39680 ReportBlock: FractionLost: 0 CumulativeLoss: 0 IAJitter: 0.0004 TheirLastSR: 0 DLSR: 65510.0850 (sec) [Dec 1 10:01:15] DEBUG[25126] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 1 10:01:15] DEBUG[25126] res_rtp_asterisk.c: Sending dtmf: 49 (1), at 172.16.100.186:16424 [Dec 1 10:01:15] DTMF[25126] channel.c: DTMF begin '1' received on SIP/202-000000a0 [Dec 1 10:01:15] DTMF[25126] channel.c: DTMF begin passthrough '1' on SIP/202-000000a0 [Dec 1 10:01:15] DEBUG[25506] manager.c: Examining event: Event: DTMF Privilege: dtmf,all Channel: SIP/202-000000a0 Uniqueid: 1291215667.365 Digit: 1 Direction: Received Begin: Yes End: No [Dec 1 10:01:15] DEBUG[25506] manager.c: Examining event: Event: DTMF Privilege: dtmf,all Channel: SIP/GW01EEMAN-000000a1 Uniqueid: 1291215667.366 Digit: 1 Direction: Sent Begin: Yes End: No [Dec 1 10:01:15] DEBUG[25126] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 1 10:01:15] DEBUG[25126] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 1 10:01:15] DEBUG[25126] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 1 10:01:15] DEBUG[25126] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 1 10:01:15] DEBUG[25126] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 1 10:01:15] DEBUG[25126] res_rtp_asterisk.c: Sending dtmf: 49 (1), at 172.16.100.186:16424 [Dec 1 10:01:15] DTMF[25126] channel.c: DTMF end '1' received on SIP/202-000000a0, duration 120 ms [Dec 1 10:01:15] DEBUG[25506] manager.c: Examining event: Event: DTMF Privilege: dtmf,all Channel: SIP/202-000000a0 Uniqueid: 1291215667.365 Digit: 1 Direction: Received Begin: No End: Yes [Dec 1 10:01:15] DTMF[25126] channel.c: DTMF end accepted with begin '1' on SIP/202-000000a0 [Dec 1 10:01:15] DTMF[25126] channel.c: DTMF end '1' detected to have actual duration 50 on the wire, emulation will be triggered on SIP/202-000000a0 [Dec 1 10:01:15] DTMF[25126] channel.c: DTMF end '1' has duration 50 but want minimum 80, emulating on SIP/202-000000a0 [Dec 1 10:01:15] DEBUG[25126] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 1 10:01:15] DTMF[25126] channel.c: DTMF end emulation of '1' queued on SIP/202-000000a0 [Dec 1 10:01:15] DEBUG[25126] chan_sip.c: Trying to put 'INFO sip:+1' onto UDP socket destined for 69.64.11.6:5060 [Dec 1 10:01:15] DEBUG[25126] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [Dec 1 10:01:15] DEBUG[25506] manager.c: Examining event: Event: DTMF Privilege: dtmf,all Channel: SIP/GW01EEMAN-000000a1 Uniqueid: 1291215667.366 Digit: 1 Direction: Sent Begin: No End: Yes [Dec 1 10:01:15] DEBUG[25528] chan_sip.c: = Looking for Call ID: 67c9e9c63a04cdd82bf8fa3b52c15efb@216.135.89.226:5060 (Checking To) --From tag as6863221c --To-tag as5ed9111c [Dec 1 10:01:15] DEBUG[25528] chan_sip.c: Stopping retransmission on '67c9e9c63a04cdd82bf8fa3b52c15efb@216.135.89.226:5060' of Request 104: Match Found [Dec 1 10:01:15] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: ~HASH~SIP_CAUSE~SIP/GW01EEMAN-000000a1~ Value: SIP 200 OK Uniqueid: 1291215667.365 [Dec 1 10:01:19] DEBUG[25126] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Dec 1 10:01:19] DEBUG[25506] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From 69.64.11.6:11013 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 31522 SequenceNumberCycles: 0 IAJitter: 43 LastSR: 57786.1342177280 DLSR: 4.9870(sec) RTT: 11(sec) [Dec 1 10:01:19] DEBUG[25506] manager.c: Examining event: Event: RTCPSent Privilege: reporting,all To 69.64.11.6:11013 OurSSRC: 1114562930 SentNTP: 1291215679.0215834624 SentRTP: 9851808 SentPackets: 490 SentOctets: 78400 ReportBlock: FractionLost: 3 CumulativeLoss: 5 IAJitter: 0.0008 TheirLastSR: 3787393333 DLSR: 0.0010 (sec) [Dec 1 10:01:19] DEBUG[25506] manager.c: Examining event: Event: RTCPSent Privilege: reporting,all To 172.16.100.186:16425 OurSSRC: 1665765199 SentNTP: 1291215679.0216055808 SentRTP: 80000 SentPackets: 496 SentOctets: 79360 ReportBlock: FractionLost: 0 CumulativeLoss: 0 IAJitter: 0.0004 TheirLastSR: 0 DLSR: 65515.0840 (sec) [Dec 1 10:01:22] DEBUG[25517] chan_iax2.c: Determining if address 127.0.0.1 with username iaxmodem03 requires calltoken validation. Optional = 0 calltoken_required = 3 [Dec 1 10:01:22] DEBUG[25517] chan_iax2.c: ip callno count incremented to 5 for 127.0.0.1 [Dec 1 10:01:22] DEBUG[25496] devicestate.c: No provider found, checking channel drivers for IAX2 - iaxmodem03 [Dec 1 10:01:22] DEBUG[25496] chan_iax2.c: Checking device state for device iaxmodem03 [Dec 1 10:01:22] DEBUG[25496] chan_iax2.c: iax2_devicestate: Found peer. What's device state of iaxmodem03? addr=2130706433, defaddr=0 maxms=0, lastms=0 [Dec 1 10:01:22] DEBUG[25496] devicestate.c: Changing state for IAX2/iaxmodem03 - state 0 (Unknown) [Dec 1 10:01:22] DEBUG[25496] devicestate.c: device 'IAX2/iaxmodem03' state '0' [Dec 1 10:01:22] DEBUG[25542] app_queue.c: Device 'IAX2/iaxmodem03' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Dec 1 10:01:22] DEBUG[25496] devicestate.c: No provider found, checking channel drivers for IAX2 - iaxmodem03 [Dec 1 10:01:22] DEBUG[25496] chan_iax2.c: Checking device state for device iaxmodem03 [Dec 1 10:01:22] DEBUG[25496] chan_iax2.c: iax2_devicestate: Found peer. What's device state of iaxmodem03? addr=2130706433, defaddr=0 maxms=0, lastms=0 [Dec 1 10:01:22] DEBUG[25496] devicestate.c: Changing state for IAX2/iaxmodem03 - state 0 (Unknown) [Dec 1 10:01:22] DEBUG[25496] devicestate.c: device 'IAX2/iaxmodem03' state '0' [Dec 1 10:01:22] DEBUG[25542] app_queue.c: Device 'IAX2/iaxmodem03' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Dec 1 10:01:22] DEBUG[25516] chan_iax2.c: Determining if address 127.0.0.1 with username iaxmodem02 requires calltoken validation. Optional = 0 calltoken_required = 3 [Dec 1 10:01:22] DEBUG[25516] chan_iax2.c: ip callno count incremented to 6 for 127.0.0.1 [Dec 1 10:01:22] DEBUG[25517] chan_iax2.c: schedule decrement of callno used for 127.0.0.1 in 60 seconds [Dec 1 10:01:22] DEBUG[25521] chan_iax2.c: Determining if address 127.0.0.1 with username iaxmodem01 requires calltoken validation. Optional = 0 calltoken_required = 3 [Dec 1 10:01:22] DEBUG[25521] chan_iax2.c: ip callno count incremented to 7 for 127.0.0.1 [Dec 1 10:01:22] DEBUG[25496] devicestate.c: No provider found, checking channel drivers for IAX2 - iaxmodem01 [Dec 1 10:01:22] DEBUG[25496] chan_iax2.c: Checking device state for device iaxmodem01 [Dec 1 10:01:22] DEBUG[25496] chan_iax2.c: iax2_devicestate: Found peer. What's device state of iaxmodem01? addr=2130706433, defaddr=0 maxms=0, lastms=0 [Dec 1 10:01:22] DEBUG[25514] chan_iax2.c: Determining if address 127.0.0.1 with username iaxmodem00 requires calltoken validation. Optional = 0 calltoken_required = 3 [Dec 1 10:01:22] DEBUG[25496] devicestate.c: Changing state for IAX2/iaxmodem01 - state 0 (Unknown) [Dec 1 10:01:22] DEBUG[25496] devicestate.c: device 'IAX2/iaxmodem01' state '0' [Dec 1 10:01:22] DEBUG[25496] devicestate.c: No provider found, checking channel drivers for IAX2 - iaxmodem02 [Dec 1 10:01:22] DEBUG[25496] chan_iax2.c: Checking device state for device iaxmodem02 [Dec 1 10:01:22] DEBUG[25496] chan_iax2.c: iax2_devicestate: Found peer. What's device state of iaxmodem02? addr=2130706433, defaddr=0 maxms=0, lastms=0 [Dec 1 10:01:22] DEBUG[25496] devicestate.c: Changing state for IAX2/iaxmodem02 - state 0 (Unknown) [Dec 1 10:01:22] DEBUG[25496] devicestate.c: device 'IAX2/iaxmodem02' state '0' [Dec 1 10:01:22] DEBUG[25542] app_queue.c: Device 'IAX2/iaxmodem01' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Dec 1 10:01:22] DEBUG[25542] app_queue.c: Device 'IAX2/iaxmodem02' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Dec 1 10:01:22] DEBUG[25496] devicestate.c: No provider found, checking channel drivers for IAX2 - iaxmodem02 [Dec 1 10:01:22] DEBUG[25496] chan_iax2.c: Checking device state for device iaxmodem02 [Dec 1 10:01:22] DEBUG[25496] chan_iax2.c: iax2_devicestate: Found peer. What's device state of iaxmodem02? addr=2130706433, defaddr=0 maxms=0, lastms=0 [Dec 1 10:01:22] DEBUG[25496] devicestate.c: Changing state for IAX2/iaxmodem02 - state 0 (Unknown) [Dec 1 10:01:22] DEBUG[25496] devicestate.c: device 'IAX2/iaxmodem02' state '0' [Dec 1 10:01:22] DEBUG[25496] devicestate.c: No provider found, checking channel drivers for IAX2 - iaxmodem01 [Dec 1 10:01:22] DEBUG[25496] chan_iax2.c: Checking device state for device iaxmodem01 [Dec 1 10:01:22] DEBUG[25542] app_queue.c: Device 'IAX2/iaxmodem02' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Dec 1 10:01:22] DEBUG[25496] chan_iax2.c: iax2_devicestate: Found peer. What's device state of iaxmodem01? addr=2130706433, defaddr=0 maxms=0, lastms=0 [Dec 1 10:01:22] DEBUG[25496] devicestate.c: Changing state for IAX2/iaxmodem01 - state 0 (Unknown) [Dec 1 10:01:22] DEBUG[25496] devicestate.c: device 'IAX2/iaxmodem01' state '0' [Dec 1 10:01:22] DEBUG[25542] app_queue.c: Device 'IAX2/iaxmodem01' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Dec 1 10:01:22] DEBUG[25514] chan_iax2.c: ip callno count incremented to 8 for 127.0.0.1 [Dec 1 10:01:22] DEBUG[25519] chan_iax2.c: schedule decrement of callno used for 127.0.0.1 in 60 seconds [Dec 1 10:01:22] DEBUG[25520] chan_iax2.c: schedule decrement of callno used for 127.0.0.1 in 60 seconds [Dec 1 10:01:22] DEBUG[25496] devicestate.c: No provider found, checking channel drivers for IAX2 - iaxmodem00 [Dec 1 10:01:22] DEBUG[25496] chan_iax2.c: Checking device state for device iaxmodem00 [Dec 1 10:01:22] DEBUG[25496] chan_iax2.c: iax2_devicestate: Found peer. What's device state of iaxmodem00? addr=2130706433, defaddr=0 maxms=0, lastms=0 [Dec 1 10:01:22] DEBUG[25496] devicestate.c: Changing state for IAX2/iaxmodem00 - state 0 (Unknown) [Dec 1 10:01:22] DEBUG[25496] devicestate.c: device 'IAX2/iaxmodem00' state '0' [Dec 1 10:01:22] DEBUG[25542] app_queue.c: Device 'IAX2/iaxmodem00' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Dec 1 10:01:22] DEBUG[25496] devicestate.c: No provider found, checking channel drivers for IAX2 - iaxmodem00 [Dec 1 10:01:22] DEBUG[25496] chan_iax2.c: Checking device state for device iaxmodem00 [Dec 1 10:01:22] DEBUG[25496] chan_iax2.c: iax2_devicestate: Found peer. What's device state of iaxmodem00? addr=2130706433, defaddr=0 maxms=0, lastms=0 [Dec 1 10:01:22] DEBUG[25496] devicestate.c: Changing state for IAX2/iaxmodem00 - state 0 (Unknown) [Dec 1 10:01:22] DEBUG[25496] devicestate.c: device 'IAX2/iaxmodem00' state '0' [Dec 1 10:01:22] DEBUG[25542] app_queue.c: Device 'IAX2/iaxmodem00' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Dec 1 10:01:22] DEBUG[25515] chan_iax2.c: schedule decrement of callno used for 127.0.0.1 in 60 seconds [Dec 1 10:01:23] DEBUG[25126] res_rtp_asterisk.c: - RTP 2833 Event: 00000003 (len = 4) [Dec 1 10:01:23] DEBUG[25126] res_rtp_asterisk.c: Sending dtmf: 51 (3), at 172.16.100.186:16424 [Dec 1 10:01:23] DTMF[25126] channel.c: DTMF begin '3' received on SIP/202-000000a0 [Dec 1 10:01:23] DTMF[25126] channel.c: DTMF begin passthrough '3' on SIP/202-000000a0 [Dec 1 10:01:23] DEBUG[25506] manager.c: Examining event: Event: DTMF Privilege: dtmf,all Channel: SIP/202-000000a0 Uniqueid: 1291215667.365 Digit: 3 Direction: Received Begin: Yes End: No [Dec 1 10:01:23] DEBUG[25506] manager.c: Examining event: Event: DTMF Privilege: dtmf,all Channel: SIP/GW01EEMAN-000000a1 Uniqueid: 1291215667.366 Digit: 3 Direction: Sent Begin: Yes End: No [Dec 1 10:01:23] DEBUG[25126] res_rtp_asterisk.c: - RTP 2833 Event: 00000003 (len = 4) [Dec 1 10:01:23] DEBUG[25126] res_rtp_asterisk.c: - RTP 2833 Event: 00000003 (len = 4) [Dec 1 10:01:23] DEBUG[25126] res_rtp_asterisk.c: - RTP 2833 Event: 00000003 (len = 4) [Dec 1 10:01:23] DEBUG[25126] res_rtp_asterisk.c: - RTP 2833 Event: 00000003 (len = 4) [Dec 1 10:01:23] DEBUG[25126] res_rtp_asterisk.c: - RTP 2833 Event: 00000003 (len = 4) [Dec 1 10:01:23] DEBUG[25126] res_rtp_asterisk.c: Sending dtmf: 51 (3), at 172.16.100.186:16424 [Dec 1 10:01:23] DTMF[25126] channel.c: DTMF end '3' received on SIP/202-000000a0, duration 120 ms [Dec 1 10:01:23] DTMF[25126] channel.c: DTMF end accepted with begin '3' on SIP/202-000000a0 [Dec 1 10:01:23] DTMF[25126] channel.c: DTMF end '3' detected to have actual duration 49 on the wire, emulation will be triggered on SIP/202-000000a0 [Dec 1 10:01:23] DEBUG[25506] manager.c: Examining event: Event: DTMF Privilege: dtmf,all Channel: SIP/202-000000a0 Uniqueid: 1291215667.365 Digit: 3 Direction: Received Begin: No End: Yes [Dec 1 10:01:23] DTMF[25126] channel.c: DTMF end '3' has duration 49 but want minimum 80, emulating on SIP/202-000000a0 [Dec 1 10:01:23] DEBUG[25126] res_rtp_asterisk.c: - RTP 2833 Event: 00000003 (len = 4) [Dec 1 10:01:23] DTMF[25126] channel.c: DTMF end emulation of '3' queued on SIP/202-000000a0 [Dec 1 10:01:23] DEBUG[25506] manager.c: Examining event: Event: DTMF Privilege: dtmf,all Channel: SIP/GW01EEMAN-000000a1 Uniqueid: 1291215667.366 Digit: 3 Direction: Sent Begin: No End: Yes [Dec 1 10:01:23] DEBUG[25126] chan_sip.c: Trying to put 'INFO sip:+1' onto UDP socket destined for 69.64.11.6:5060 [Dec 1 10:01:23] DEBUG[25126] res_rtp_asterisk.c: - RTP 2833 Event: 00000003 (len = 4) [Dec 1 10:01:23] DEBUG[25528] chan_sip.c: = Looking for Call ID: 67c9e9c63a04cdd82bf8fa3b52c15efb@216.135.89.226:5060 (Checking To) --From tag as6863221c --To-tag as5ed9111c [Dec 1 10:01:23] DEBUG[25528] chan_sip.c: Stopping retransmission on '67c9e9c63a04cdd82bf8fa3b52c15efb@216.135.89.226:5060' of Request 105: Match Found [Dec 1 10:01:23] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: ~HASH~SIP_CAUSE~SIP/GW01EEMAN-000000a1~ Value: SIP 200 OK Uniqueid: 1291215667.365 [Dec 1 10:01:24] DEBUG[25126] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Dec 1 10:01:24] DEBUG[25506] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From 69.64.11.6:11013 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 31764 SequenceNumberCycles: 0 IAJitter: 73 LastSR: 57791.3489660928 DLSR: 4.9870(sec) RTT: 12(sec) [Dec 1 10:01:24] DEBUG[25506] manager.c: Examining event: Event: RTCPSent Privilege: reporting,all To 69.64.11.6:11013 OurSSRC: 1114562930 SentNTP: 1291215684.0217288704 SentRTP: 9891968 SentPackets: 731 SentOctets: 116960 ReportBlock: FractionLost: 5 CumulativeLoss: 10 IAJitter: 0.0012 TheirLastSR: 3787721013 DLSR: 0.0000 (sec) [Dec 1 10:01:24] DEBUG[25506] manager.c: Examining event: Event: RTCPSent Privilege: reporting,all To 172.16.100.186:16425 OurSSRC: 1665765199 SentNTP: 1291215684.0217489408 SentRTP: 119840 SentPackets: 740 SentOctets: 118400 ReportBlock: FractionLost: 0 CumulativeLoss: 0 IAJitter: 0.0010 TheirLastSR: 0 DLSR: 65520.0850 (sec) [Dec 1 10:01:27] DEBUG[25511] chan_iax2.c: ip callno count decremented to 7 for 127.0.0.1 [Dec 1 10:01:27] DEBUG[25511] chan_iax2.c: ip callno count decremented to 6 for 127.0.0.1 [Dec 1 10:01:27] DEBUG[25511] chan_iax2.c: ip callno count decremented to 5 for 127.0.0.1 [Dec 1 10:01:27] DEBUG[25511] chan_iax2.c: ip callno count decremented to 4 for 127.0.0.1 [Dec 1 10:01:27] DEBUG[25528] chan_sip.c: Auto destroying SIP dialog '204219c40ba4413d0a9de0370492c34e@69.64.11.6' [Dec 1 10:01:27] DEBUG[25528] chan_sip.c: Destroying SIP dialog 204219c40ba4413d0a9de0370492c34e@69.64.11.6 [Dec 1 10:01:29] DEBUG[25126] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Dec 1 10:01:29] DEBUG[25506] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From 69.64.11.6:11013 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 32014 SequenceNumberCycles: 0 IAJitter: 32 LastSR: 57796.1073741824 DLSR: 4.9870(sec) RTT: 11(sec) [Dec 1 10:01:29] DEBUG[25506] manager.c: Examining event: Event: RTCPSent Privilege: reporting,all To 69.64.11.6:11013 OurSSRC: 1114562930 SentNTP: 1291215689.0214646784 SentRTP: 9931968 SentPackets: 981 SentOctets: 156960 ReportBlock: FractionLost: 2 CumulativeLoss: 12 IAJitter: 0.0012 TheirLastSR: 3788048688 DLSR: 0.0000 (sec) [Dec 1 10:01:29] DEBUG[25506] manager.c: Examining event: Event: RTCPSent Privilege: reporting,all To 172.16.100.186:16425 OurSSRC: 1665765199 SentNTP: 1291215689.0218726400 SentRTP: 160000 SentPackets: 989 SentOctets: 158240 ReportBlock: FractionLost: 0 CumulativeLoss: 0 IAJitter: 0.0004 TheirLastSR: 0 DLSR: 65525.0850 (sec) [Dec 1 10:01:30] DEBUG[25528] chan_sip.c: = Looking for Call ID: 67c9e9c63a04cdd82bf8fa3b52c15efb@216.135.89.226:5060 (Checking To) --From tag as6863221c --To-tag as5ed9111c [Dec 1 10:01:30] DEBUG[25528] chan_sip.c: Acked pending invite 103 [Dec 1 10:01:30] DEBUG[25528] chan_sip.c: Stopping retransmission on '67c9e9c63a04cdd82bf8fa3b52c15efb@216.135.89.226:5060' of Request 103: Match Found [Dec 1 10:01:30] DEBUG[25528] chan_sip.c: SIP response 200 to standard invite [Dec 1 10:01:30] DEBUG[25528] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Dec 1 10:01:30] DEBUG[25528] chan_sip.c: Processing session-level SDP o=root 1739111220 1739111221 IN IP4 69.64.11.6... UNSUPPORTED. [Dec 1 10:01:30] DEBUG[25528] chan_sip.c: Processing session-level SDP s=Asterisk PBX 1.6.2.14-rc1... UNSUPPORTED. [Dec 1 10:01:30] DEBUG[25528] netsock2.c: Splitting '69.64.11.6' gives... [Dec 1 10:01:30] DEBUG[25528] netsock2.c: ...host '69.64.11.6' and port '(null)'. [Dec 1 10:01:30] DEBUG[25528] chan_sip.c: Processing session-level SDP c=IN IP4 69.64.11.6... OK. [Dec 1 10:01:30] DEBUG[25528] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Dec 1 10:01:30] DEBUG[25528] rtp_engine.c: Setting payload 0 based on m type on 0xb7615160 [Dec 1 10:01:30] DEBUG[25528] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Dec 1 10:01:30] DEBUG[25528] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK. [Dec 1 10:01:30] DEBUG[25528] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Dec 1 10:01:30] DEBUG[25528] rtp_engine.c: Incorporating payload 0 on 0xb7615160 [Dec 1 10:01:30] DEBUG[25528] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x8e7f950' [Dec 1 10:01:30] DEBUG[25528] rtp_engine.c: Copying payload 0 from 0xb7615160 to 0x8e7fafc [Dec 1 10:01:30] DEBUG[25528] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Dec 1 10:01:30] DEBUG[25528] chan_sip.c: We have an owner, now see if we need to change this call [Dec 1 10:01:30] DEBUG[25528] chan_sip.c: Updating call counter for outgoing call [Dec 1 10:01:30] WARNING[25528] chan_sip.c: Invalid contact uri (missing sip: or sips:), attempting to use anyway [Dec 1 10:01:30] DEBUG[25528] netsock2.c: Splitting '�� �' gives... [Dec 1 10:01:30] DEBUG[25528] netsock2.c: ...host '�� �' and port '(null)'. [Dec 1 10:01:30] ERROR[25528] netsock2.c: getaddrinfo("�� �", "(null)", ...): Name or service not known [Dec 1 10:01:30] WARNING[25528] chan_sip.c: Invalid host name in Contact: (can't resolve in DNS) : '�� �' [Dec 1 10:01:30] DEBUG[25528] chan_sip.c: Trying to put 'ACK sip:+18' onto UDP socket destined for 69.64.11.6:5060 [Dec 1 10:01:30] DEBUG[25528] channel.c: Soft-Hanging up channel 'SIP/GW01EEMAN-000000a1' [Dec 1 10:01:30] DEBUG[25528] chan_sip.c: Trying to put 'BYE sip:+18' onto UDP socket destined for 69.64.11.6:5060 [Dec 1 10:01:30] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: ~HASH~SIP_CAUSE~SIP/GW01EEMAN-000000a1~ Value: SIP 200 OK Uniqueid: 1291215667.365 [Dec 1 10:01:30] DEBUG[25506] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: SIP/GW01EEMAN-000000a1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 18006262001 CallerIDName: Uniqueid: 1291215667.366 [Dec 1 10:01:30] DEBUG[25496] devicestate.c: No provider found, checking channel drivers for SIP - GW01EEMAN [Dec 1 10:01:30] VERBOSE[25126] app_dial.c: -- SIP/GW01EEMAN-000000a1 answered SIP/202-000000a0 [Dec 1 10:01:30] DEBUG[25126] rtp_engine.c: Setting early bridge SDP of 'SIP/202-000000a0' with that of 'SIP/GW01EEMAN-000000a1' [Dec 1 10:01:30] DEBUG[25126] chan_sip.c: SIP answering channel: SIP/202-000000a0 [Dec 1 10:01:30] DEBUG[25126] res_rtp_asterisk.c: Setting the marker bit due to a source update [Dec 1 10:01:30] DEBUG[25126] chan_sip.c: Setting framing from config on incoming call [Dec 1 10:01:30] DEBUG[25126] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True [Dec 1 10:01:30] DEBUG[25126] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Dec 1 10:01:30] DEBUG[25126] chan_sip.c: -- Done with adding codecs to SDP [Dec 1 10:01:30] DEBUG[25126] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Dec 1 10:01:30] DEBUG[25126] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 172.16.100.186:5060 [Dec 1 10:01:30] DEBUG[25126] features.c: bridge answer set, chan answer set [Dec 1 10:01:30] DEBUG[25126] cdr_mysql.c: Inserting a CDR record. [Dec 1 10:01:30] DEBUG[25126] cdr_mysql.c: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,uniqueid) VALUES ('2010-12-01 10:01:07','\"Erik Smith\" <202>','202','18006262001','from-inside-redir','SIP/202-000000a0','SIP/GW01EEMAN-000000a1','Dial','SIP/+18006262001@GW01EEMAN,60,','23','0','ANSWERED','2','1291215667.365') [Dec 1 10:01:30] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: DIALSTATUS Value: ANSWER Uniqueid: 1291215667.365 [Dec 1 10:01:30] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: DIALEDPEERNAME Value: SIP/GW01EEMAN-000000a1 Uniqueid: 1291215667.365 [Dec 1 10:01:30] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: DIALEDPEERNUMBER Value: +18006262001@GW01EEMAN Uniqueid: 1291215667.365 [Dec 1 10:01:30] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: BRIDGEPEER Value: SIP/GW01EEMAN-000000a1 Uniqueid: 1291215667.365 [Dec 1 10:01:30] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/GW01EEMAN-000000a1 Variable: BRIDGEPEER Value: SIP/202-000000a0 Uniqueid: 1291215667.366 [Dec 1 10:01:30] DEBUG[25506] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: SIP/202-000000a0 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 5023152516 CallerIDName: Erik Smith Uniqueid: 1291215667.365 [Dec 1 10:01:30] DEBUG[25506] manager.c: Examining event: Event: NewAccountCode Privilege: call,all Channel: SIP/GW01EEMAN-000000a1 Uniqueid: 1291215667.366 AccountCode: OldAccountCode: [Dec 1 10:01:30] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: ANSWEREDTIME Value: 0 Uniqueid: 1291215667.365 [Dec 1 10:01:30] DEBUG[25496] chan_sip.c: Checking device state for peer GW01EEMAN [Dec 1 10:01:30] DEBUG[25496] devicestate.c: Changing state for SIP/GW01EEMAN - state 1 (Not in use) [Dec 1 10:01:30] DEBUG[25496] devicestate.c: device 'SIP/GW01EEMAN' state '1' [Dec 1 10:01:30] DEBUG[25496] devicestate.c: No provider found, checking channel drivers for SIP - 202 [Dec 1 10:01:30] DEBUG[25496] chan_sip.c: Checking device state for peer 202 [Dec 1 10:01:30] DEBUG[25496] devicestate.c: Changing state for SIP/202 - state 2 (In use) [Dec 1 10:01:30] DEBUG[25496] devicestate.c: device 'SIP/202' state '2' [Dec 1 10:01:30] DEBUG[25542] app_queue.c: Device 'SIP/GW01EEMAN' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Dec 1 10:01:30] DEBUG[25542] app_queue.c: Device 'SIP/202' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Dec 1 10:01:30] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: DIALEDTIME Value: 23 Uniqueid: 1291215667.365 [Dec 1 10:01:30] DEBUG[25506] manager.c: Running action 'Getvar' [Dec 1 10:01:30] DEBUG[25506] pbx.c: Result of 'XMLNamespaceVoiceMailMarkAsReadId' is NULL [Dec 1 10:01:30] DEBUG[25528] chan_sip.c: = Looking for Call ID: b176b300-269bca7b@172.16.100.186 (Checking From) --From tag d9d3a13c1d6b516fo0 --To-tag as1cc47242 [Dec 1 10:01:30] DEBUG[25528] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Dec 1 10:01:30] DEBUG[25528] chan_sip.c: Stopping retransmission on 'b176b300-269bca7b@172.16.100.186' of Response 102: Match Found [Dec 1 10:01:30] DEBUG[25126] channel.c: Hanging up channel 'SIP/GW01EEMAN-000000a1' [Dec 1 10:01:30] DEBUG[25126] chan_sip.c: Hangup call SIP/GW01EEMAN-000000a1, SIP callid 67c9e9c63a04cdd82bf8fa3b52c15efb@216.135.89.226:5060 [Dec 1 10:01:30] DEBUG[25126] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x8e7f950' [Dec 1 10:01:30] DEBUG[25126] chan_sip.c: Trying to put 'BYE sip:+18' onto UDP socket destined for 69.64.11.6:5060 [Dec 1 10:01:30] DEBUG[25126] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Dec 1 10:01:30] DEBUG[25126] app_macro.c: Spawn extension (macro-tl-dialout-base,dial-SIP,7) exited non-zero on 'SIP/202-000000a0' in macro 'tl-dialout-base' [Dec 1 10:01:30] VERBOSE[25126] app_macro.c: == Spawn extension (macro-tl-dialout-base, dial-SIP, 7) exited non-zero on 'SIP/202-000000a0' in macro 'tl-dialout-base' [Dec 1 10:01:30] DEBUG[25126] app_macro.c: Spawn extension (macro-tl-dialout-1-trunk,s,3) exited non-zero on 'SIP/202-000000a0' in macro 'tl-dialout-1-trunk' [Dec 1 10:01:30] VERBOSE[25126] app_macro.c: == Spawn extension (macro-tl-dialout-1-trunk, s, 3) exited non-zero on 'SIP/202-000000a0' in macro 'tl-dialout-1-trunk' [Dec 1 10:01:30] DEBUG[25126] pbx.c: Spawn extension (from-inside-redir,18006262001,1) exited non-zero on 'SIP/202-000000a0' [Dec 1 10:01:30] VERBOSE[25126] pbx.c: == Spawn extension (from-inside-redir, 18006262001, 1) exited non-zero on 'SIP/202-000000a0' [Dec 1 10:01:30] DEBUG[25126] channel.c: Soft-Hanging up channel 'SIP/202-000000a0' [Dec 1 10:01:30] DEBUG[25126] pbx.c: Launching 'Hangup' [Dec 1 10:01:30] VERBOSE[25126] pbx.c: -- Executing [h@from-inside-redir:1] Hangup("SIP/202-000000a0", "") in new stack [Dec 1 10:01:30] DEBUG[25126] pbx.c: Spawn extension (from-inside-redir,h,1) exited non-zero on 'SIP/202-000000a0' [Dec 1 10:01:30] VERBOSE[25126] pbx.c: == Spawn extension (from-inside-redir, h, 1) exited non-zero on 'SIP/202-000000a0' [Dec 1 10:01:30] DEBUG[25126] channel.c: Hanging up channel 'SIP/202-000000a0' [Dec 1 10:01:30] DEBUG[25126] chan_sip.c: Hangup call SIP/202-000000a0, SIP callid b176b300-269bca7b@172.16.100.186 [Dec 1 10:01:30] DEBUG[25126] chan_sip.c: Updating call counter for incoming call [Dec 1 10:01:30] DEBUG[25126] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb6c1a9e8' [Dec 1 10:01:30] DEBUG[25126] netsock2.c: Splitting '172.16.100.186:5060' gives... [Dec 1 10:01:30] DEBUG[25496] devicestate.c: No provider found, checking channel drivers for SIP - GW01EEMAN [Dec 1 10:01:30] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/GW01EEMAN-000000a1 Variable: RTPAUDIOQOS Value: ssrc=1114562930;themssrc=336255740;lp=12;rxjitter=0.001214;rxcount=1051;txjitter=0.000000;txcount=1044;rlp=0;rtt=0.011000 Uniqueid: 1291215667.366 [Dec 1 10:01:30] DEBUG[25496] chan_sip.c: Checking device state for peer GW01EEMAN [Dec 1 10:01:30] DEBUG[25496] devicestate.c: Changing state for SIP/GW01EEMAN - state 1 (Not in use) [Dec 1 10:01:30] DEBUG[25496] devicestate.c: device 'SIP/GW01EEMAN' state '1' [Dec 1 10:01:30] DEBUG[25496] devicestate.c: No provider found, checking channel drivers for SIP - 202 [Dec 1 10:01:30] DEBUG[25496] chan_sip.c: Checking device state for peer 202 [Dec 1 10:01:30] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/GW01EEMAN-000000a1 Variable: RTPAUDIOQOSJITTER Value: minrxjitter=0.000000;maxrxjitter=0.000000;avgrxjitter=0.000000;stdevrxjitter=0.000000;reported_minjitter=0.000000;reported_maxjitter=0.000000;reported_avgjitter=0.000000;reported_stdevjitter=0.000000; Uniqueid: 1291215667.366 [Dec 1 10:01:30] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/GW01EEMAN-000000a1 Variable: RTPAUDIOQOSLOSS Value: minrxlost=0.000000;maxrxlost=0.000000;avgrxlost=0.000000;stdevrxlost=0.000000;reported_minlost=0.000000;reported_maxlost=0.000000;reported_avglost=0.000000;reported_stdevlost=0.000000; Uniqueid: 1291215667.366 [Dec 1 10:01:30] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/GW01EEMAN-000000a1 Variable: RTPAUDIOQOSRTT Value: minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000; Uniqueid: 1291215667.366 [Dec 1 10:01:30] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/GW01EEMAN-000000a1 Variable: RTPAUDIOQOS Value: ssrc=1114562930;themssrc=336255740;lp=12;rxjitter=0.001214;rxcount=1051;txjitter=0.000000;txcount=1044;rlp=0;rtt=0.011000 Uniqueid: 1291215667.366 [Dec 1 10:01:30] DEBUG[25506] manager.c: Examining event: Event: Hangup Privilege: call,all Channel: SIP/GW01EEMAN-000000a1 Uniqueid: 1291215667.366 CallerIDNum: 18006262001 CallerIDName: Cause: 16 Cause-txt: Normal Clearing [Dec 1 10:01:30] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: DIALSTATUS Value: ANSWER Uniqueid: 1291215667.365 [Dec 1 10:01:30] DEBUG[25506] manager.c: Examining event: Event: Dial Privilege: call,all SubEvent: End Channel: SIP/202-000000a0 UniqueID: 1291215667.365 DialStatus: ANSWER [Dec 1 10:01:30] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1291215667.365 [Dec 1 10:01:30] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: ARG1 Value: 60 Uniqueid: 1291215667.365 [Dec 1 10:01:30] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: ARG2 Value: SIP/GW01EEMAN Uniqueid: 1291215667.365 [Dec 1 10:01:30] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: ARG3 Value: + Uniqueid: 1291215667.365 [Dec 1 10:01:30] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: ARG4 Value: 0 Uniqueid: 1291215667.365 [Dec 1 10:01:30] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_EXTEN Value: 18006262001 Uniqueid: 1291215667.365 [Dec 1 10:01:30] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_CONTEXT Value: from-inside-redir Uniqueid: 1291215667.365 [Dec 1 10:01:30] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_PRIORITY Value: 1 Uniqueid: 1291215667.365 [Dec 1 10:01:30] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: MACRO_DEPTH Value: 0 Uniqueid: 1291215667.365 [Dec 1 10:01:30] DEBUG[25506] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/202-000000a0 Context: from-inside-redir Extension: h Priority: 1 Application: Hangup AppData: Uniqueid: 1291215667.365 [Dec 1 10:01:30] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: RTPAUDIOQOS Value: ssrc=1665765199;themssrc=2321983192;lp=0;rxjitter=0.000380;rxcount=1060;txjitter=0.000000;txcount=1051;rlp=0;rtt=0.000000 Uniqueid: 1291215667.365 [Dec 1 10:01:30] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: RTPAUDIOQOSJITTER Value: minrxjitter=0.000000;maxrxjitter=0.000000;avgrxjitter=0.000000;stdevrxjitter=0.000000;reported_minjitter=0.000000;reported_maxjitter=0.000000;reported_avgjitter=0.000000;reported_stdevjitter=0.000000; Uniqueid: 1291215667.365 [Dec 1 10:01:30] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: RTPAUDIOQOSLOSS Value: minrxlost=0.000000;maxrxlost=0.000000;avgrxlost=0.000000;stdevrxlost=0.000000;reported_minlost=0.000000;reported_maxlost=0.000000;reported_avglost=0.000000;reported_stdevlost=0.000000; Uniqueid: 1291215667.365 [Dec 1 10:01:30] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: RTPAUDIOQOSRTT Value: minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000; Uniqueid: 1291215667.365 [Dec 1 10:01:30] DEBUG[25506] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/202-000000a0 Variable: RTPAUDIOQOS Value: ssrc=1665765199;themssrc=2321983192;lp=0;rxjitter=0.000380;rxcount=1060;txjitter=0.000000;txcount=1051;rlp=0;rtt=0.000000 Uniqueid: 1291215667.365 [Dec 1 10:01:30] DEBUG[25126] netsock2.c: ...host '172.16.100.186' and port '5060'. [Dec 1 10:01:30] DEBUG[25126] chan_sip.c: Trying to put 'BYE sip:202' onto UDP socket destined for 172.16.100.186:5060 [Dec 1 10:01:30] DEBUG[25506] manager.c: Examining event: Event: Hangup Privilege: call,all Channel: SIP/202-000000a0 Uniqueid: 1291215667.365 CallerIDNum: 5023152516 CallerIDName: Erik Smith Cause: 16 Cause-txt: Normal Clearing [Dec 1 10:01:30] DEBUG[25542] app_queue.c: Device 'SIP/GW01EEMAN' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Dec 1 10:01:30] DEBUG[25496] devicestate.c: Changing state for SIP/202 - state 1 (Not in use) [Dec 1 10:01:30] DEBUG[25496] devicestate.c: device 'SIP/202' state '1' [Dec 1 10:01:30] DEBUG[25496] devicestate.c: No provider found, checking channel drivers for SIP - 202 [Dec 1 10:01:30] DEBUG[25496] chan_sip.c: Checking device state for peer 202 [Dec 1 10:01:30] DEBUG[25496] devicestate.c: Changing state for SIP/202 - state 1 (Not in use) [Dec 1 10:01:30] DEBUG[25496] devicestate.c: device 'SIP/202' state '1' [Dec 1 10:01:30] DEBUG[25497] app_queue.c: Extension '202@local-extensions' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Dec 1 10:01:30] DEBUG[25542] app_queue.c: Device 'SIP/202' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Dec 1 10:01:30] DEBUG[25542] app_queue.c: Device 'SIP/202' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Dec 1 10:01:30] DEBUG[25506] manager.c: Examining event: Event: ExtensionStatus Privilege: call,all Exten: 202 Context: local-extensions Hint: SIP/202 Status: 0 [Dec 1 10:01:30] DEBUG[25528] chan_sip.c: = Looking for Call ID: 67c9e9c63a04cdd82bf8fa3b52c15efb@216.135.89.226:5060 (Checking To) --From tag as6863221c --To-tag as5ed9111c [Dec 1 10:01:30] DEBUG[25528] chan_sip.c: Stopping retransmission on '67c9e9c63a04cdd82bf8fa3b52c15efb@216.135.89.226:5060' of Request 106: Match Found [Dec 1 10:01:30] DEBUG[25528] chan_sip.c: = Looking for Call ID: b176b300-269bca7b@172.16.100.186 (Checking To) --From tag as1cc47242 --To-tag d9d3a13c1d6b516fo0 [Dec 1 10:01:30] DEBUG[25528] chan_sip.c: Stopping retransmission on 'b176b300-269bca7b@172.16.100.186' of Request 102: Match Found [Dec 1 10:01:30] DEBUG[25528] chan_sip.c: Destroying SIP dialog b176b300-269bca7b@172.16.100.186 [Dec 1 10:01:30] DEBUG[25528] rtp_engine.c: Destroyed RTP instance '0xb6c1a9e8' [Dec 1 10:01:30] DEBUG[25528] chan_sip.c: = Looking for Call ID: 67c9e9c63a04cdd82bf8fa3b52c15efb@216.135.89.226:5060 (Checking To) --From tag as6863221c --To-tag as5ed9111c [Dec 1 10:01:30] DEBUG[25528] chan_sip.c: Stopping retransmission on '67c9e9c63a04cdd82bf8fa3b52c15efb@216.135.89.226:5060' of Request 107: Match Found [Dec 1 10:01:30] DEBUG[25528] chan_sip.c: Destroying SIP dialog 67c9e9c63a04cdd82bf8fa3b52c15efb@216.135.89.226:5060 [Dec 1 10:01:30] DEBUG[25528] rtp_engine.c: Destroyed RTP instance '0x8e7f950' [Dec 1 10:01:36] DEBUG[25528] chan_sip.c: = Looking for Call ID: 2d1e99fc65aedb12219d36eb585ffc65@69.64.11.20 (Checking From) --From tag as1c49fa8b --To-tag [Dec 1 10:01:36] DEBUG[25528] acl.c: For destination '69.64.11.20', our source address is '216.135.89.226'. [Dec 1 10:01:36] DEBUG[25528] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 216.135.89.226:5060 [Dec 1 10:01:36] DEBUG[25528] chan_sip.c: Allocating new SIP dialog for 2d1e99fc65aedb12219d36eb585ffc65@69.64.11.20 - OPTIONS (No RTP) [Dec 1 10:01:36] DEBUG[25528] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Dec 1 10:01:36] DEBUG[25528] chan_sip.c: Trying to put 'SIP/2.0 404' onto UDP socket destined for 69.64.11.20:5060 [Dec 1 10:01:36] DEBUG[25528] chan_sip.c: SIP message could not be handled, bad request: 2d1e99fc65aedb12219d36eb585ffc65@69.64.11.20 [Dec 1 10:01:37] DEBUG[25528] chan_sip.c: Auto destroying SIP dialog 'fc80d54e-24baae26@172.16.100.186' [Dec 1 10:01:37] DEBUG[25528] chan_sip.c: Destroying SIP dialog fc80d54e-24baae26@172.16.100.186 [Dec 1 10:01:37] DEBUG[25528] chan_sip.c: Auto destroying SIP dialog '3c2c91c6-2d115c0e@172.16.100.186' [Dec 1 10:01:37] DEBUG[25528] chan_sip.c: Destroying SIP dialog 3c2c91c6-2d115c0e@172.16.100.186 [Dec 1 10:01:40] DEBUG[25528] chan_sip.c: Auto destroying SIP dialog '527df662043cedb53efa3c1962455ce8@69.64.11.13' [Dec 1 10:01:40] DEBUG[25528] chan_sip.c: Destroying SIP dialog 527df662043cedb53efa3c1962455ce8@69.64.11.13 [Dec 1 10:01:47] DEBUG[25511] chan_iax2.c: ip callno count decremented to 0 for 69.64.11.13 [Dec 1 10:01:47] DEBUG[25512] chan_iax2.c: ip callno count incremented to 1 for 69.64.11.13 [Dec 1 10:01:47] DEBUG[25515] chan_iax2.c: schedule decrement of callno used for 69.64.11.13 in 60 seconds [Dec 1 10:01:47] DEBUG[25515] chan_iax2.c: Peer routing_out: got pong, lastms 11, historicms 11, maxms 1000 [Dec 1 10:01:51] DEBUG[25528] chan_sip.c: Allocating new SIP dialog for 37bf66da0119edfe57eafc5a088a7fff@216.135.89.226:0 - OPTIONS (No RTP) [Dec 1 10:01:51] DEBUG[25528] acl.c: For destination '172.16.100.195', our source address is '172.16.100.1'. [Dec 1 10:01:51] DEBUG[25528] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 172.16.100.1:5060 [Dec 1 10:01:51] DEBUG[25528] chan_sip.c: Initializing initreq for method OPTIONS - callid 452778dd3ef02def71337b4d0347ce35@172.16.100.1:5060 [Dec 1 10:01:51] DEBUG[25528] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 172.16.100.195:5060 [Dec 1 10:01:51] DEBUG[25528] chan_sip.c: = Looking for Call ID: 452778dd3ef02def71337b4d0347ce35@172.16.100.1:5060 (Checking To) --From tag as4187cfc5 --To-tag 6CD405ED-1F828940 [Dec 1 10:01:51] DEBUG[25528] chan_sip.c: Stopping retransmission on '452778dd3ef02def71337b4d0347ce35@172.16.100.1:5060' of Request 102: Match Found [Dec 1 10:01:51] DEBUG[25528] chan_sip.c: Destroying SIP dialog 452778dd3ef02def71337b4d0347ce35@172.16.100.1:5060 [Dec 1 10:01:53] DEBUG[25528] chan_sip.c: Allocating new SIP dialog for 3f9b20d55eaa8d8462aec92c4e6b514e@216.135.89.226:0 - OPTIONS (No RTP) [Dec 1 10:01:53] DEBUG[25528] acl.c: For destination '69.64.11.6', our source address is '216.135.89.226'. [Dec 1 10:01:53] DEBUG[25528] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 216.135.89.226:5060 [Dec 1 10:01:53] DEBUG[25528] chan_sip.c: Initializing initreq for method OPTIONS - callid 0c59ae344cd103ce2accfc6910af9bb9@216.135.89.226:5060 [Dec 1 10:01:53] DEBUG[25528] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 69.64.11.6:5060 [Dec 1 10:01:53] DEBUG[25528] chan_sip.c: = Looking for Call ID: 0c59ae344cd103ce2accfc6910af9bb9@216.135.89.226:5060 (Checking To) --From tag as397d46b7 --To-tag as1da7c3a0 [Dec 1 10:01:53] DEBUG[25528] chan_sip.c: Stopping retransmission on '0c59ae344cd103ce2accfc6910af9bb9@216.135.89.226:5060' of Request 102: Match Found [Dec 1 10:01:53] DEBUG[25528] chan_sip.c: Destroying SIP dialog 0c59ae344cd103ce2accfc6910af9bb9@216.135.89.226:5060 [Dec 1 10:01:53] DEBUG[25528] chan_sip.c: Allocating new SIP dialog for 606632ba5dfb27ca0fba5cb070656841@216.135.89.226:0 - OPTIONS (No RTP) [Dec 1 10:01:53] DEBUG[25528] acl.c: For destination '69.64.11.13', our source address is '216.135.89.226'. [Dec 1 10:01:53] DEBUG[25528] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 216.135.89.226:5060 [Dec 1 10:01:53] DEBUG[25528] chan_sip.c: Initializing initreq for method OPTIONS - callid 1a5daebd39528a4f38f95dd539ec7a98@216.135.89.226:5060 [Dec 1 10:01:53] DEBUG[25528] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 69.64.11.13:5060 [Dec 1 10:01:53] DEBUG[25528] chan_sip.c: = Looking for Call ID: 1a5daebd39528a4f38f95dd539ec7a98@216.135.89.226:5060 (Checking To) --From tag as6f1dd319 --To-tag as7a899287 [Dec 1 10:01:53] DEBUG[25528] chan_sip.c: Stopping retransmission on '1a5daebd39528a4f38f95dd539ec7a98@216.135.89.226:5060' of Request 102: Match Found [Dec 1 10:01:53] DEBUG[25528] chan_sip.c: Destroying SIP dialog 1a5daebd39528a4f38f95dd539ec7a98@216.135.89.226:5060 [Dec 1 10:01:55] DEBUG[25528] chan_sip.c: = Looking for Call ID: 26107dea5bc6971043b5e6fd44c4d759@69.64.11.6 (Checking From) --From tag as3e1b8b3b --To-tag [Dec 1 10:01:55] DEBUG[25528] acl.c: For destination '69.64.11.6', our source address is '216.135.89.226'. [Dec 1 10:01:55] DEBUG[25528] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 216.135.89.226:5060 [Dec 1 10:01:55] DEBUG[25528] chan_sip.c: Allocating new SIP dialog for 26107dea5bc6971043b5e6fd44c4d759@69.64.11.6 - OPTIONS (No RTP) [Dec 1 10:01:55] DEBUG[25528] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Dec 1 10:01:55] DEBUG[25528] chan_sip.c: Trying to put 'SIP/2.0 404' onto UDP socket destined for 69.64.11.6:5060 [Dec 1 10:01:55] DEBUG[25528] chan_sip.c: SIP message could not be handled, bad request: 26107dea5bc6971043b5e6fd44c4d759@69.64.11.6 [Dec 1 10:01:57] DEBUG[25528] chan_sip.c: Allocating new SIP dialog for 5e5c182e6440a4ba449b4f9740654214@216.135.89.226:0 - OPTIONS (No RTP) [Dec 1 10:01:57] DEBUG[25528] acl.c: For destination '69.64.11.20', our source address is '216.135.89.226'. [Dec 1 10:01:57] DEBUG[25528] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 216.135.89.226:5060 [Dec 1 10:01:57] DEBUG[25528] chan_sip.c: Initializing initreq for method OPTIONS - callid 44e66e494a3dd4ec4292684c60e41a74@216.135.89.226:5060 [Dec 1 10:01:57] DEBUG[25528] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 69.64.11.20:5060 [Dec 1 10:01:57] DEBUG[25528] chan_sip.c: = Looking for Call ID: 44e66e494a3dd4ec4292684c60e41a74@216.135.89.226:5060 (Checking To) --From tag as41169bd7 --To-tag as6d2e3af9 [Dec 1 10:01:57] DEBUG[25528] chan_sip.c: Stopping retransmission on '44e66e494a3dd4ec4292684c60e41a74@216.135.89.226:5060' of Request 102: Match Found [Dec 1 10:01:57] DEBUG[25528] chan_sip.c: Destroying SIP dialog 44e66e494a3dd4ec4292684c60e41a74@216.135.89.226:5060 [Dec 1 10:02:01] VERBOSE[25090] asterisk.c: -- Remote UNIX connection disconnected [Dec 1 10:02:05] DEBUG[25528] chan_sip.c: Allocating new SIP dialog for 792ce7c81b23ce384c5c5ae86eb61f7c@216.135.89.226:0 - OPTIONS (No RTP) [Dec 1 10:02:05] DEBUG[25528] acl.c: For destination '172.16.100.186', our source address is '172.16.100.1'. [Dec 1 10:02:05] DEBUG[25528] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 172.16.100.1:5060 [Dec 1 10:02:05] DEBUG[25528] chan_sip.c: Initializing initreq for method OPTIONS - callid 294a7f88535ab7db46391c9872ca4f27@172.16.100.1:5060 [Dec 1 10:02:05] DEBUG[25528] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 172.16.100.186:5060 [Dec 1 10:02:05] DEBUG[25528] chan_sip.c: Allocating new SIP dialog for 78b694e946b99184450ef9e477a03876@216.135.89.226:0 - OPTIONS (No RTP) [Dec 1 10:02:05] DEBUG[25528] acl.c: For destination '172.16.100.186', our source address is '172.16.100.1'. [Dec 1 10:02:05] DEBUG[25528] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 172.16.100.1:5060 [Dec 1 10:02:05] DEBUG[25528] chan_sip.c: Initializing initreq for method OPTIONS - callid 1174a17e13f05335233240e80c3d169d@172.16.100.1:5060 [Dec 1 10:02:05] DEBUG[25528] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 172.16.100.186:5061 [Dec 1 10:02:05] DEBUG[25528] chan_sip.c: = Looking for Call ID: 294a7f88535ab7db46391c9872ca4f27@172.16.100.1:5060 (Checking To) --From tag as4a21263c --To-tag 221878ee710f5022i0 [Dec 1 10:02:05] DEBUG[25528] chan_sip.c: Stopping retransmission on '294a7f88535ab7db46391c9872ca4f27@172.16.100.1:5060' of Request 102: Match Found [Dec 1 10:02:05] DEBUG[25528] chan_sip.c: Destroying SIP dialog 294a7f88535ab7db46391c9872ca4f27@172.16.100.1:5060 [Dec 1 10:02:05] DEBUG[25528] chan_sip.c: = Looking for Call ID: 1174a17e13f05335233240e80c3d169d@172.16.100.1:5060 (Checking To) --From tag as4f640dac --To-tag b17f528e77ed4302i1 [Dec 1 10:02:05] DEBUG[25528] chan_sip.c: Stopping retransmission on '1174a17e13f05335233240e80c3d169d@172.16.100.1:5060' of Request 102: Match Found [Dec 1 10:02:05] DEBUG[25528] chan_sip.c: Destroying SIP dialog 1174a17e13f05335233240e80c3d169d@172.16.100.1:5060 [Dec 1 10:02:06] DEBUG[25528] chan_sip.c: Allocating new SIP dialog for 039c834b67fa90454e8ad73c11d2b97d@216.135.89.226:0 - OPTIONS (No RTP) [Dec 1 10:02:06] DEBUG[25528] acl.c: For destination '172.16.100.183', our source address is '172.16.100.1'. [Dec 1 10:02:06] DEBUG[25528] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 172.16.100.1:5060 [Dec 1 10:02:06] DEBUG[25528] chan_sip.c: Initializing initreq for method OPTIONS - callid 26c966374cceeb323a2427700b4a21a2@172.16.100.1:5060 [Dec 1 10:02:06] DEBUG[25528] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 172.16.100.183:5060 [Dec 1 10:02:06] DEBUG[25528] chan_sip.c: = Looking for Call ID: 26c966374cceeb323a2427700b4a21a2@172.16.100.1:5060 (Checking To) --From tag as19b8d18a --To-tag E43DA54A-FBE78357 [Dec 1 10:02:06] DEBUG[25528] chan_sip.c: Stopping retransmission on '26c966374cceeb323a2427700b4a21a2@172.16.100.1:5060' of Request 102: Match Found [Dec 1 10:02:06] DEBUG[25528] chan_sip.c: Destroying SIP dialog 26c966374cceeb323a2427700b4a21a2@172.16.100.1:5060 [Dec 1 10:02:08] DEBUG[25528] chan_sip.c: = Looking for Call ID: 1e1436da10a16ea00b2b0127661a1fd0@69.64.11.13 (Checking From) --From tag as743e052f --To-tag [Dec 1 10:02:08] DEBUG[25528] acl.c: For destination '69.64.11.13', our source address is '216.135.89.226'. [Dec 1 10:02:08] DEBUG[25528] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 216.135.89.226:5060 [Dec 1 10:02:08] DEBUG[25528] chan_sip.c: Allocating new SIP dialog for 1e1436da10a16ea00b2b0127661a1fd0@69.64.11.13 - OPTIONS (No RTP) [Dec 1 10:02:08] DEBUG[25528] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Dec 1 10:02:08] DEBUG[25528] chan_sip.c: Trying to put 'SIP/2.0 404' onto UDP socket destined for 69.64.11.13:5060 [Dec 1 10:02:08] DEBUG[25528] chan_sip.c: SIP message could not be handled, bad request: 1e1436da10a16ea00b2b0127661a1fd0@69.64.11.13 [Dec 1 10:02:08] DEBUG[25528] chan_sip.c: Auto destroying SIP dialog '2d1e99fc65aedb12219d36eb585ffc65@69.64.11.20' [Dec 1 10:02:08] DEBUG[25528] chan_sip.c: Destroying SIP dialog 2d1e99fc65aedb12219d36eb585ffc65@69.64.11.20 [Dec 1 10:02:10] VERBOSE[25492] asterisk.c: -- Remote UNIX connection