*CLI> Nov  6 09:48:25 DEBUG[17382]: chan_sip.c:3168 sip_alloc: Allocating new SIP dialog for 70D7D48D65CE361ED5BCC79C8D8F8FE2@asterisk.vodacomm.ca - REGISTER (No RTP)
Nov  6 09:48:25 DEBUG[17382]: chan_sip.c:3168 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
    -- Registered SIP 'stephen' at 10.130.1.10 port 5060 expires 1800
Nov  6 09:48:25 DEBUG[17388]: app_queue.c:500 changethread: Device 'SIP/stephen' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
Nov  6 09:48:25 DEBUG[17382]: chan_sip.c:1412 __sip_ack: Stopping retransmission on '1ab1e34011df37805c21b275665e4efa@10.130.1.65' of Request 102: Match Found
Nov  6 09:48:25 DEBUG[17389]: app_queue.c:500 changethread: Device 'SIP/stephen' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
Nov  6 09:48:29 DEBUG[17382]: chan_sip.c:3168 sip_alloc: Allocating new SIP dialog for 3aa02c91-be5d85e3-36b32868@10.130.1.100 - INVITE (With RTP)
Nov  6 09:48:29 DEBUG[17382]: chan_sip.c:1044 parse_sip_options: * SIP extension value: 2 for call 3aa02c91-be5d85e3-36b32868@10.130.1.100
Nov  6 09:48:29 DEBUG[17382]: chan_sip.c:7215 check_user_full: Setting NAT on RTP to 0
Nov  6 09:48:29 DEBUG[17382]: chan_sip.c:1412 __sip_ack: Stopping retransmission on '3aa02c91-be5d85e3-36b32868@10.130.1.100' of Response 1: Match Found
Nov  6 09:48:29 DEBUG[17382]: chan_sip.c:7215 check_user_full: Setting NAT on RTP to 0
Nov  6 09:48:29 DEBUG[17382]: chan_sip.c:10571 handle_request_invite: Checking SIP call limits for device polycom
Nov  6 09:48:29 DEBUG[17382]: chan_sip.c:6194 build_route: build_route: Contact hop: <sip:polycom@10.130.1.100>
Nov  6 09:48:29 DEBUG[17390]: pbx.c:1677 pbx_extension_helper: Launching 'Answer'
    -- Executing Answer("SIP/polycom-0817f388", "") in new stack
Nov  6 09:48:29 DEBUG[17390]: chan_sip.c:2557 sip_answer: sip_answer(SIP/polycom-0817f388)
Nov  6 09:48:29 DEBUG[17390]: pbx.c:1677 pbx_extension_helper: Launching 'Wait'
    -- Executing Wait("SIP/polycom-0817f388", "1") in new stack
Nov  6 09:48:29 DEBUG[17391]: app_queue.c:500 changethread: Device 'SIP/polycom' changed to state '2' (In use) but we don't care because they're not a member of any queue.
Nov  6 09:48:29 DEBUG[17392]: app_queue.c:500 changethread: Device 'SIP/polycom' changed to state '2' (In use) but we don't care because they're not a member of any queue.
Nov  6 09:48:30 DEBUG[17382]: chan_sip.c:1412 __sip_ack: Stopping retransmission on '3aa02c91-be5d85e3-36b32868@10.130.1.100' of Response 2: Match Found
Nov  6 09:48:30 DEBUG[17390]: pbx.c:1677 pbx_extension_helper: Launching 'Dial'
    -- Executing Dial("SIP/polycom-0817f388", "SIP/stephen||M(page)") in new stack
Nov  6 09:48:30 DEBUG[17390]: chan_sip.c:3168 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
Nov  6 09:48:30 DEBUG[17390]: chan_sip.c:1885 create_addr_from_peer: Setting NAT on RTP to 0
Nov  6 09:48:30 DEBUG[17390]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-internal-123-3.
Nov  6 09:48:30 DEBUG[17390]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-internal-123-2.
Nov  6 09:48:30 DEBUG[17390]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-internal-123-1.
Nov  6 09:48:30 DEBUG[17390]: channel.c:2902 ast_channel_inherit_variables: Not copying variable SIPCALLID.
Nov  6 09:48:30 DEBUG[17390]: channel.c:2902 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT.
Nov  6 09:48:30 DEBUG[17390]: channel.c:2902 ast_channel_inherit_variables: Not copying variable SIPDOMAIN.
Nov  6 09:48:30 DEBUG[17390]: channel.c:2902 ast_channel_inherit_variables: Not copying variable SIPURI.
Nov  6 09:48:30 DEBUG[17390]: chan_sip.c:2079 sip_call: Outgoing Call for stephen
    -- Called stephen
Nov  6 09:48:30 DEBUG[17382]: chan_sip.c:1465 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '29708a052cd6a322211f41dc1a73fe5f@10.130.1.65' Request 102: Found
Nov  6 09:48:30 DEBUG[17382]: chan_sip.c:1465 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '29708a052cd6a322211f41dc1a73fe5f@10.130.1.65' Request 102: Found
    -- SIP/stephen-081848c8 is ringing
Nov  6 09:48:30 DEBUG[17390]: channel.c:2088 ast_indicate: Driver for channel 'SIP/polycom-0817f388' does not support indication 3, emulating it
Nov  6 09:48:30 DEBUG[17390]: channel.c:2409 set_format: Set channel SIP/polycom-0817f388 to write format slin
Nov  6 09:48:30 DEBUG[17393]: app_queue.c:500 changethread: Device 'SIP/stephen' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
Nov  6 09:48:30 DEBUG[17390]: rtp.c:1359 ast_rtp_write: Ooh, format changed from unknown to ulaw
Nov  6 09:48:33 DEBUG[17382]: chan_sip.c:1390 __sip_ack: Acked pending invite 102
Nov  6 09:48:33 DEBUG[17382]: chan_sip.c:1412 __sip_ack: Stopping retransmission on '29708a052cd6a322211f41dc1a73fe5f@10.130.1.65' of Request 102: Match Found
Nov  6 09:48:33 DEBUG[17382]: chan_sip.c:6194 build_route: build_route: Contact hop: <sip:stephen@10.130.1.10:5060>
    -- SIP/stephen-081848c8 answered SIP/polycom-0817f388
Nov  6 09:48:33 DEBUG[17390]: pbx.c:1677 pbx_extension_helper: Launching 'Wait'
    -- Executing Wait("SIP/stephen-081848c8", "1") in new stack
Nov  6 09:48:33 DEBUG[17395]: app_queue.c:500 changethread: Device 'SIP/stephen' changed to state '2' (In use) but we don't care because they're not a member of any queue.
Nov  6 09:48:33 DEBUG[17390]: rtp.c:411 ast_rtcp_read: Got RTCP report of 84 bytes
Nov  6 09:48:33 DEBUG[17390]: rtp.c:411 ast_rtcp_read: Got RTCP report of 114 bytes
Nov  6 09:48:34 DEBUG[17390]: pbx.c:1677 pbx_extension_helper: Launching 'SendDTMF'
    -- Executing SendDTMF("SIP/stephen-081848c8", "234|100") in new stack
Nov  6 09:48:34 DEBUG[17390]: channel.c:2409 set_format: Set channel SIP/stephen-081848c8 to write format slin
Nov  6 09:48:34 DTMF[17390]: channel.c:2345 ast_write: SIP/stephen-081848c8 : 2
Nov  6 09:48:35 DEBUG[17390]: pbx.c:1677 pbx_extension_helper: Launching 'Wait'
    -- Executing Wait("SIP/stephen-081848c8", "1") in new stack
Nov  6 09:48:36 DEBUG[17390]: pbx.c:1677 pbx_extension_helper: Launching 'SendDTMF'
    -- Executing SendDTMF("SIP/stephen-081848c8", "6|250") in new stack
Nov  6 09:48:36 DEBUG[17390]: pbx.c:1677 pbx_extension_helper: Launching 'Wait'
    -- Executing Wait("SIP/stephen-081848c8", "1") in new stack
Nov  6 09:48:36 DEBUG[17394]: rtp.c:411 ast_rtcp_read: Got RTCP report of 88 bytes
Nov  6 09:48:37 DEBUG[17390]: pbx.c:1677 pbx_extension_helper: Launching 'SendDTMF'
    -- Executing SendDTMF("SIP/stephen-081848c8", "1") in new stack
Nov  6 09:48:37 DEBUG[17390]: pbx.c:1677 pbx_extension_helper: Launching 'Wait'
    -- Executing Wait("SIP/stephen-081848c8", "1") in new stack
Nov  6 09:48:38 DEBUG[17390]: rtp.c:411 ast_rtcp_read: Got RTCP report of 84 bytes
Nov  6 09:48:38 DEBUG[17390]: pbx.c:1677 pbx_extension_helper: Launching 'SendDTMF'
    -- Executing SendDTMF("SIP/stephen-081848c8", "3") in new stack
Nov  6 09:48:39 DEBUG[17390]: pbx.c:1677 pbx_extension_helper: Launching 'Wait'
    -- Executing Wait("SIP/stephen-081848c8", "1") in new stack
Nov  6 09:48:40 DEBUG[17390]: pbx.c:1677 pbx_extension_helper: Launching 'SendDTMF'
    -- Executing SendDTMF("SIP/stephen-081848c8", "6") in new stack
Nov  6 09:48:40 DEBUG[17390]: pbx.c:1677 pbx_extension_helper: Launching 'Wait'
    -- Executing Wait("SIP/stephen-081848c8", "10") in new stack
Nov  6 09:48:40 DEBUG[17382]: chan_sip.c:1334 __sip_autodestruct: Auto destroying call '70D7D48D65CE361ED5BCC79C8D8F8FE2@asterisk.vodacomm.ca'
Nov  6 09:48:43 DEBUG[17390]: rtp.c:411 ast_rtcp_read: Got RTCP report of 84 bytes
Nov  6 09:48:46 DEBUG[17394]: rtp.c:411 ast_rtcp_read: Got RTCP report of 88 bytes
Nov  6 09:48:47 DEBUG[17390]: rtp.c:411 ast_rtcp_read: Got RTCP report of 114 bytes
Nov  6 09:48:48 DEBUG[17390]: rtp.c:502 ast_rtp_read: Forcing Marker bit, because SSRC has changed
Nov  6 09:48:48 NOTICE[17390]: rtp.c:331 process_rfc3389: Comfort noise support incomplete in Asterisk (RFC 3389). Please turn off on client if possible. Client IP: 10.130.1.10
Nov  6 09:48:48 DEBUG[17390]: rtp.c:411 ast_rtcp_read: Got RTCP report of 84 bytes
Nov  6 09:48:50 DEBUG[17381]: chan_iax2.c:7751 iax2_do_register: Allocate call number
Nov  6 09:48:50 DEBUG[17381]: chan_iax2.c:7757 iax2_do_register: Registration created on call 5
Nov  6 09:48:50 DEBUG[17381]: chan_iax2.c:7751 iax2_do_register: Allocate call number
Nov  6 09:48:50 DEBUG[17381]: chan_iax2.c:7757 iax2_do_register: Registration created on call 6
Nov  6 09:48:50 DEBUG[17390]: pbx.c:1677 pbx_extension_helper: Launching 'Set'
    -- Executing Set("SIP/stephen-081848c8", "MACRO_RESULT=CONTINUE") in new stack
Nov  6 09:48:50 DEBUG[17390]: app_dial.c:1489 dial_exec_full: Macro exited with status 0
Nov  6 09:48:50 DEBUG[17390]: channel.c:2409 set_format: Set channel SIP/stephen-081848c8 to write format ulaw
Nov  6 09:48:50 DEBUG[17390]: channel.c:1373 ast_hangup: Hanging up channel 'SIP/stephen-081848c8'
Nov  6 09:48:50 DEBUG[17390]: chan_sip.c:2427 sip_hangup: Hangup call SIP/stephen-081848c8, SIP callid 29708a052cd6a322211f41dc1a73fe5f@10.130.1.65)
Nov  6 09:48:50 DEBUG[17390]: chan_sip.c:2435 sip_hangup: update_call_counter(stephen) - decrement call limit counter
Nov  6 09:48:50 DEBUG[17390]: channel.c:2409 set_format: Set channel SIP/polycom-0817f388 to write format ulaw
Nov  6 09:48:50 DEBUG[17390]: app_dial.c:1635 dial_exec_full: Exiting with DIALSTATUS=ANSWER.
Nov  6 09:48:50 DEBUG[17390]: pbx.c:1677 pbx_extension_helper: Launching 'Hangup'
    -- Executing Hangup("SIP/polycom-0817f388", "") in new stack
Nov  6 09:48:50 DEBUG[17390]: pbx.c:2316 __ast_pbx_run: Spawn extension (internal,123,4) exited non-zero on 'SIP/polycom-0817f388'
  == Spawn extension (internal, 123, 4) exited non-zero on 'SIP/polycom-0817f388'
Nov  6 09:48:50 DEBUG[17390]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '"polycom" <polycom>'
Nov  6 09:48:50 DEBUG[17390]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'polycom'
Nov  6 09:48:50 DEBUG[17390]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '123'
Nov  6 09:48:50 DEBUG[17390]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'internal'
Nov  6 09:48:50 DEBUG[17390]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'SIP/polycom-0817f388'
Nov  6 09:48:50 DEBUG[17390]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'SIP/stephen-081848c8'
Nov  6 09:48:50 DEBUG[17390]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'Hangup'
Nov  6 09:48:50 DEBUG[17390]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)'
Nov  6 09:48:50 DEBUG[17390]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-11-06 09:48:29'
Nov  6 09:48:50 DEBUG[17390]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-11-06 09:48:29'
Nov  6 09:48:50 DEBUG[17390]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-11-06 09:48:50'
Nov  6 09:48:50 DEBUG[17390]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '21'
Nov  6 09:48:50 DEBUG[17390]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '21'
Nov  6 09:48:50 DEBUG[17390]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'ANSWERED'
Nov  6 09:48:50 DEBUG[17390]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION'
Nov  6 09:48:50 DEBUG[17390]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)'
Nov  6 09:48:50 DEBUG[17390]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '1162831709.1'
Nov  6 09:48:50 DEBUG[17390]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)'
Nov  6 09:48:50 DEBUG[17390]: channel.c:1373 ast_hangup: Hanging up channel 'SIP/polycom-0817f388'
Nov  6 09:48:50 DEBUG[17390]: chan_sip.c:2427 sip_hangup: Hangup call SIP/polycom-0817f388, SIP callid 3aa02c91-be5d85e3-36b32868@10.130.1.100)
Nov  6 09:48:50 DEBUG[17390]: chan_sip.c:2435 sip_hangup: update_call_counter(polycom) - decrement call limit counter
Nov  6 09:48:50 DEBUG[17396]: app_queue.c:500 changethread: Device 'SIP/stephen' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
Nov  6 09:48:50 DEBUG[17397]: app_queue.c:500 changethread: Device 'SIP/polycom' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
Nov  6 09:48:50 DEBUG[17382]: chan_sip.c:1412 __sip_ack: Stopping retransmission on '29708a052cd6a322211f41dc1a73fe5f@10.130.1.65' of Request 103: Match Found
Nov  6 09:48:50 DEBUG[17382]: chan_sip.c:1412 __sip_ack: Stopping retransmission on '3aa02c91-be5d85e3-36b32868@10.130.1.100' of Request 102: Match Found
Nov  6 09:48:59 DEBUG[17382]: chan_sip.c:3168 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
Nov  6 09:49:00 DEBUG[17381]: chan_iax2.c:7257 socket_read: Peer lastms 70, historicms 70, maxms 2000
Nov  6 09:49:00 DEBUG[17382]: chan_sip.c:1412 __sip_ack: Stopping retransmission on '5b3a08486c97d07a3e4b4e3b2d13aaee@10.130.1.65' of Request 102: Match Found
Nov  6 09:49:00 DEBUG[17381]: chan_iax2.c:7257 socket_read: Peer lastms 72, historicms 72, maxms 2000