[Mar  8 18:43:01] DEBUG[27492]: chan_sip.c:7414 find_call: = Looking for  Call ID: YjEwYTY2YjExNThhMmM5OTc4MDA4OWE2NjRjNDUxZDk. (Checking From) --From tag 6b70fe68 --To-tag   
[Mar  8 18:43:01] DEBUG[27492]: acl.c:715 ast_ouraddrfor: For destination '10.7.0.90', our source address is '10.7.0.75'.
[Mar  8 18:43:01] DEBUG[27492]: chan_sip.c:3243 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 10.7.0.75:5060
[Mar  8 18:43:01] DEBUG[27492]: chan_sip.c:7215 sip_alloc: Allocating new SIP dialog for YjEwYTY2YjExNThhMmM5OTc4MDA4OWE2NjRjNDUxZDk. - INVITE (No RTP)
[Mar  8 18:43:01] DEBUG[27492]: chan_sip.c:23649 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE
[Mar  8 18:43:01] DEBUG[27492]: sip/reqresp_parser.c:1584 parse_sip_options: Begin: parsing SIP "Supported: replaces, norefersub, extended-refer, X-cisco-serviceuri"
[Mar  8 18:43:01] DEBUG[27492]: sip/reqresp_parser.c:1600 parse_sip_options: Found SIP option: -replaces-
[Mar  8 18:43:01] DEBUG[27492]: sip/reqresp_parser.c:1608 parse_sip_options: Matched SIP option: replaces
[Mar  8 18:43:01] DEBUG[27492]: sip/reqresp_parser.c:1600 parse_sip_options: Found SIP option: -norefersub-
[Mar  8 18:43:01] DEBUG[27492]: sip/reqresp_parser.c:1608 parse_sip_options: Matched SIP option: norefersub
[Mar  8 18:43:01] DEBUG[27492]: sip/reqresp_parser.c:1600 parse_sip_options: Found SIP option: -extended-refer-
[Mar  8 18:43:01] DEBUG[27492]: sip/reqresp_parser.c:1636 parse_sip_options: Found no match for SIP option: extended-refer (Please file bug report!)
[Mar  8 18:43:01] DEBUG[27492]: sip/reqresp_parser.c:1600 parse_sip_options: Found SIP option: -X-cisco-serviceuri-
[Mar  8 18:43:01] DEBUG[27492]: sip/reqresp_parser.c:1634 parse_sip_options: Found private SIP option, not supported: X-cisco-serviceuri
[Mar  8 18:43:01] DEBUG[27492]: netsock2.c:125 ast_sockaddr_split_hostport: Splitting '10.7.0.90' gives...
[Mar  8 18:43:01] DEBUG[27492]: netsock2.c:155 ast_sockaddr_split_hostport: ...host '10.7.0.90' and port '(null)'.
[Mar  8 18:43:01] DEBUG[27492]: res_config_odbc.c:88 custom_prepare: Skip: 0; SQL: SELECT * FROM ast_sipaccounts WHERE name = ? AND host = ?
[Mar  8 18:43:01] DEBUG[27492]: res_config_odbc.c:103 custom_prepare: Parameter 1 ('name') = 'MyTestSipAccount'
[Mar  8 18:43:01] DEBUG[27492]: res_config_odbc.c:103 custom_prepare: Parameter 2 ('host') = 'dynamic'
[Mar  8 18:43:01] DEBUG[27492]: res_odbc.c:1034 odbc_release_obj2: odbc_release_obj2(0x2aaaac47a368) called (obj->txf = (nil))
[Mar  8 18:43:01] DEBUG[27492]: res_config_odbc.c:88 custom_prepare: Skip: 0; SQL: SELECT * FROM ast_sipaccounts WHERE name = ?
[Mar  8 18:43:01] DEBUG[27492]: res_config_odbc.c:103 custom_prepare: Parameter 1 ('name') = 'MyTestSipAccount'
[Mar  8 18:43:01] DEBUG[27492]: res_odbc.c:1034 odbc_release_obj2: odbc_release_obj2(0x2aaaac47a368) called (obj->txf = (nil))
[Mar  8 18:43:01] DEBUG[27492]: chan_sip.c:25798 build_peer: -REALTIME- peer built. Name: MyTestSipAccount. Peer objects: 1
[Mar  8 18:43:01] DEBUG[27492]: netsock2.c:125 ast_sockaddr_split_hostport: Splitting 'registrar.voip.blueface.com:5060' gives...
[Mar  8 18:43:01] DEBUG[27492]: netsock2.c:155 ast_sockaddr_split_hostport: ...host 'registrar.voip.blueface.com' and port '5060'.
[Mar  8 18:43:01] DEBUG[27492]: chan_sip.c:28119 ast_sockaddr_resolve_first_af: Multiple addresses, using the first one only
[Mar  8 18:43:01] DEBUG[27492]: chan_sip.c:26347 build_peer: Not an IPv4 nor IPv6 address, cannot get port.
[Mar  8 18:43:01] DEBUG[27492]: chan_sip.c:26350 build_peer: Not an IPv4 nor IPv6 address, cannot set port.
[Mar  8 18:43:01] DEBUG[27492]: chan_sip.c:4557 realtime_peer: -REALTIME- loading peer from database to memory. Name: MyTestSipAccount. Peer objects: 1
[Mar  8 18:43:01] DEBUG[27492]: rtp_engine.c:344 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x1b665a58'
[Mar  8 18:43:01] DEBUG[27492]: res_rtp_asterisk.c:472 ast_rtp_new: Allocated port 14394 for RTP instance '0x1b665a58'
[Mar  8 18:43:01] DEBUG[27492]: rtp_engine.c:353 ast_rtp_instance_new: RTP instance '0x1b665a58' is setup and ready to go
[Mar  8 18:43:01] DEBUG[27492]: rtp_engine.c:344 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x1b770b08'
[Mar  8 18:43:01] DEBUG[27492]: res_rtp_asterisk.c:472 ast_rtp_new: Allocated port 15532 for RTP instance '0x1b770b08'
[Mar  8 18:43:01] DEBUG[27492]: rtp_engine.c:353 ast_rtp_instance_new: RTP instance '0x1b770b08' is setup and ready to go
[Mar  8 18:43:01] DEBUG[27492]: res_rtp_asterisk.c:2370 ast_rtp_prop_set: Setup RTCP on RTP instance '0x1b770b08'
[Mar  8 18:43:01] DEBUG[27492]: res_rtp_asterisk.c:2370 ast_rtp_prop_set: Setup RTCP on RTP instance '0x1b665a58'
  == Using SIP RTP TOS bits 184
  == Using SIP RTP CoS mark 5
[Mar  8 18:43:01] DEBUG[27492]: chan_sip.c:4683 do_setnat: Setting NAT on RTP to On
[Mar  8 18:43:01] DEBUG[27492]: chan_sip.c:4687 do_setnat: Setting NAT on VRTP to On
[Mar  8 18:43:01] DEBUG[27492]: chan_sip.c:8200 process_sdp: Processing session-level SDP v=0... UNSUPPORTED.
[Mar  8 18:43:01] DEBUG[27492]: chan_sip.c:8200 process_sdp: Processing session-level SDP o=ZoiperCommunicator_user 0 0 IN IP4 10.7.0.90... UNSUPPORTED.
[Mar  8 18:43:01] DEBUG[27492]: chan_sip.c:8200 process_sdp: Processing session-level SDP s=ZoiperCommunicator_session... UNSUPPORTED.
[Mar  8 18:43:01] DEBUG[27492]: netsock2.c:125 ast_sockaddr_split_hostport: Splitting '10.7.0.90' gives...
[Mar  8 18:43:01] DEBUG[27492]: netsock2.c:155 ast_sockaddr_split_hostport: ...host '10.7.0.90' and port '(null)'.
[Mar  8 18:43:01] DEBUG[27492]: chan_sip.c:8200 process_sdp: Processing session-level SDP c=IN IP4 10.7.0.90... OK.
[Mar  8 18:43:01] DEBUG[27492]: chan_sip.c:8200 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED.
[Mar  8 18:43:01] DEBUG[27492]: rtp_engine.c:535 ast_rtp_codecs_payloads_set_m_type: Setting payload 3 based on m type on 0x4157cd70
[Mar  8 18:43:01] DEBUG[27492]: rtp_engine.c:535 ast_rtp_codecs_payloads_set_m_type: Setting payload 110 based on m type on 0x4157cd70
[Mar  8 18:43:01] DEBUG[27492]: rtp_engine.c:535 ast_rtp_codecs_payloads_set_m_type: Setting payload 8 based on m type on 0x4157cd70
[Mar  8 18:43:01] DEBUG[27492]: rtp_engine.c:535 ast_rtp_codecs_payloads_set_m_type: Setting payload 0 based on m type on 0x4157cd70
[Mar  8 18:43:01] DEBUG[27492]: rtp_engine.c:535 ast_rtp_codecs_payloads_set_m_type: Setting payload 98 based on m type on 0x4157cd70
[Mar  8 18:43:01] DEBUG[27492]: rtp_engine.c:535 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0x4157cd70
[Mar  8 18:43:01] DEBUG[27492]: chan_sip.c:8387 process_sdp: Processing media-level (audio) SDP a=rtpmap:3 GSM/8000... OK.
[Mar  8 18:43:01] DEBUG[27492]: chan_sip.c:8387 process_sdp: Processing media-level (audio) SDP a=rtpmap:110 speex/8000... OK.
[Mar  8 18:43:01] DEBUG[27492]: chan_sip.c:8387 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[Mar  8 18:43:01] DEBUG[27492]: chan_sip.c:8387 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[Mar  8 18:43:01] DEBUG[27492]: chan_sip.c:8387 process_sdp: Processing media-level (audio) SDP a=rtpmap:98 iLBC/8000... OK.
[Mar  8 18:43:01] DEBUG[27492]: chan_sip.c:8387 process_sdp: Processing media-level (audio) SDP a=fmtp:98 mode=20... UNSUPPORTED.
[Mar  8 18:43:01] DEBUG[27492]: chan_sip.c:8387 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[Mar  8 18:43:01] DEBUG[27492]: chan_sip.c:8387 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED.
[Mar  8 18:43:01] DEBUG[27492]: chan_sip.c:8387 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK.
[Mar  8 18:43:01] DEBUG[27492]: chan_sip.c:8387 process_sdp: Processing media-level (audio) SDP a=nortpproxy:yes... UNSUPPORTED.
[Mar  8 18:43:01] DEBUG[27492]: rtp_engine.c:638 ast_rtp_codecs_payload_formats: Incorporating payload 0 on 0x4157cd70
[Mar  8 18:43:01] DEBUG[27492]: rtp_engine.c:638 ast_rtp_codecs_payload_formats: Incorporating payload 3 on 0x4157cd70
[Mar  8 18:43:01] DEBUG[27492]: rtp_engine.c:638 ast_rtp_codecs_payload_formats: Incorporating payload 8 on 0x4157cd70
[Mar  8 18:43:01] DEBUG[27492]: rtp_engine.c:638 ast_rtp_codecs_payload_formats: Incorporating payload 98 on 0x4157cd70
[Mar  8 18:43:01] DEBUG[27492]: rtp_engine.c:638 ast_rtp_codecs_payload_formats: Incorporating payload 101 on 0x4157cd70
[Mar  8 18:43:01] DEBUG[27492]: rtp_engine.c:638 ast_rtp_codecs_payload_formats: Incorporating payload 110 on 0x4157cd70
[Mar  8 18:43:01] DEBUG[27492]: res_rtp_asterisk.c:2391 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x1b665a58'
[Mar  8 18:43:01] DEBUG[27492]: rtp_engine.c:516 ast_rtp_codecs_payloads_copy: Copying payload 0 from 0x4157cd70 to 0x1b665c20
[Mar  8 18:43:01] DEBUG[27492]: rtp_engine.c:516 ast_rtp_codecs_payloads_copy: Copying payload 3 from 0x4157cd70 to 0x1b665c20
[Mar  8 18:43:01] DEBUG[27492]: rtp_engine.c:516 ast_rtp_codecs_payloads_copy: Copying payload 8 from 0x4157cd70 to 0x1b665c20
[Mar  8 18:43:01] DEBUG[27492]: rtp_engine.c:516 ast_rtp_codecs_payloads_copy: Copying payload 98 from 0x4157cd70 to 0x1b665c20
[Mar  8 18:43:01] DEBUG[27492]: rtp_engine.c:516 ast_rtp_codecs_payloads_copy: Copying payload 101 from 0x4157cd70 to 0x1b665c20
[Mar  8 18:43:01] DEBUG[27492]: rtp_engine.c:516 ast_rtp_codecs_payloads_copy: Copying payload 110 from 0x4157cd70 to 0x1b665c20
[Mar  8 18:43:01] DEBUG[27492]: res_rtp_asterisk.c:2391 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x1b770b08'
[Mar  8 18:43:01] DEBUG[27492]: chan_sip.c:8619 process_sdp: We're settling with these formats: 0x60e (gsm|ulaw|alaw|speex|ilbc)
[Mar  8 18:43:01] DEBUG[27492]: chan_sip.c:21320 handle_request_invite: Checking SIP call limits for device MyTestSipAccount
[Mar  8 18:43:01] DEBUG[27492]: chan_sip.c:5454 update_call_counter: Updating call counter for incoming call
[Mar  8 18:43:01] DEBUG[27480]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - MyTestSipAccount
[Mar  8 18:43:01] DEBUG[27480]: chan_sip.c:24969 sip_devicestate: Checking device state for peer MyTestSipAccount
[Mar  8 18:43:01] DEBUG[27480]: res_config_odbc.c:88 custom_prepare: Skip: 0; SQL: SELECT * FROM ast_sipaccounts WHERE name = ? AND host = ?
[Mar  8 18:43:01] DEBUG[27480]: res_config_odbc.c:103 custom_prepare: Parameter 1 ('name') = 'MyTestSipAccount'
[Mar  8 18:43:01] DEBUG[27480]: res_config_odbc.c:103 custom_prepare: Parameter 2 ('host') = 'dynamic'
[Mar  8 18:43:01] DEBUG[27492]: chan_sip.c:6557 sip_new: *** Our native formats are 0x8 (alaw) 
[Mar  8 18:43:01] DEBUG[27492]: chan_sip.c:6558 sip_new: *** Joint capabilities are 0x60e (gsm|ulaw|alaw|speex|ilbc) 
[Mar  8 18:43:01] DEBUG[27492]: chan_sip.c:6559 sip_new: *** Our capabilities are 0x8070e (gsm|ulaw|alaw|g729|speex|ilbc|h263) 
[Mar  8 18:43:01] DEBUG[27492]: chan_sip.c:6560 sip_new: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) 
[Mar  8 18:43:01] DEBUG[27492]: chan_sip.c:6588 sip_new: This channel can handle video! HOLLYWOOD next!
[Mar  8 18:43:01] DEBUG[27492]: chan_sip.c:13257 build_route: build_route: Record-Route hop: <sip:10.7.0.90;r2=on;lr=on;ftag=6b70fe68>
[Mar  8 18:43:01] DEBUG[27492]: chan_sip.c:13257 build_route: build_route: Record-Route hop: <sip:194.213.29.90;r2=on;lr=on;ftag=6b70fe68>
[Mar  8 18:43:01] DEBUG[27480]: res_odbc.c:1034 odbc_release_obj2: odbc_release_obj2(0x2aaaac47a368) called (obj->txf = (nil))
[Mar  8 18:43:01] DEBUG[27480]: res_config_odbc.c:88 custom_prepare: Skip: 0; SQL: SELECT * FROM ast_sipaccounts WHERE name = ?
[Mar  8 18:43:01] DEBUG[27480]: res_config_odbc.c:103 custom_prepare: Parameter 1 ('name') = 'MyTestSipAccount'
[Mar  8 18:43:01] DEBUG[27492]: chan_sip.c:21612 handle_request_invite: SIP/MyTestSipAccount-000000eb: New call is still down.... Trying... 
[Mar  8 18:43:01] DEBUG[27492]: chan_sip.c:3089 __sip_xmit: Trying to put 'SIP/2.0 100' onto UDP socket destined for 10.7.0.90:5060
[Mar  8 18:43:01] DEBUG[29549]: pbx.c:4067 pbx_extension_helper: Launching 'SetAMAFlags'
    -- Executing [012223333@base-out:1] SetAMAFlags("SIP/MyTestSipAccount-000000eb", "BILLING") in new stack
[Mar  8 18:43:01] DEBUG[29549]: pbx.c:3096 ast_str_retrieve_variable: Result of 'FastAGISrv' is '10.7.0.82:4573'
[Mar  8 18:43:01] DEBUG[29549]: pbx.c:4067 pbx_extension_helper: Launching 'AGI'
[Mar  8 18:43:01] DEBUG[27480]: res_odbc.c:1034 odbc_release_obj2: odbc_release_obj2(0x2aaaac47a368) called (obj->txf = (nil))
[Mar  8 18:43:01] DEBUG[27480]: chan_sip.c:25798 build_peer: -REALTIME- peer built. Name: MyTestSipAccount. Peer objects: 2
[Mar  8 18:43:01] DEBUG[27480]: netsock2.c:125 ast_sockaddr_split_hostport: Splitting 'registrar.voip.blueface.com:5060' gives...
[Mar  8 18:43:01] DEBUG[27480]: netsock2.c:155 ast_sockaddr_split_hostport: ...host 'registrar.voip.blueface.com' and port '5060'.
    -- Executing [012223333@base-out:2] AGI("SIP/MyTestSipAccount-000000eb", "agi://10.7.0.82:4573?app=loadusersettings") in new stack
[Mar  8 18:43:01] DEBUG[29549]: res_agi.c:1422 launch_netscript: Wow, connected!
[Mar  8 18:43:01] DEBUG[27480]: chan_sip.c:28119 ast_sockaddr_resolve_first_af: Multiple addresses, using the first one only
[Mar  8 18:43:01] DEBUG[27480]: chan_sip.c:26347 build_peer: Not an IPv4 nor IPv6 address, cannot get port.
[Mar  8 18:43:01] DEBUG[27480]: chan_sip.c:26350 build_peer: Not an IPv4 nor IPv6 address, cannot set port.
[Mar  8 18:43:01] DEBUG[27480]: chan_sip.c:4557 realtime_peer: -REALTIME- loading peer from database to memory. Name: MyTestSipAccount. Peer objects: 2
[Mar  8 18:43:01] DEBUG[27480]: chan_sip.c:4307 sip_destroy_peer: Destroying SIP peer MyTestSipAccount
[Mar  8 18:43:01] DEBUG[27480]: chan_sip.c:4336 sip_destroy_peer: -REALTIME- peer Destroyed. Name: MyTestSipAccount. Realtime Peer objects: 1
[Mar  8 18:43:01] DEBUG[27480]: devicestate.c:458 do_state_change: Changing state for SIP/MyTestSipAccount - state 1 (Not in use)
[Mar  8 18:43:01] DEBUG[27480]: devicestate.c:438 devstate_event: device 'SIP/MyTestSipAccount' state '1'
[Mar  8 18:43:01] DEBUG[27480]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - MyTestSipAccount
[Mar  8 18:43:01] DEBUG[27480]: chan_sip.c:24969 sip_devicestate: Checking device state for peer MyTestSipAccount
[Mar  8 18:43:01] DEBUG[27480]: res_config_odbc.c:88 custom_prepare: Skip: 0; SQL: SELECT * FROM ast_sipaccounts WHERE name = ? AND host = ?
[Mar  8 18:43:01] DEBUG[27480]: res_config_odbc.c:103 custom_prepare: Parameter 1 ('name') = 'MyTestSipAccount'
[Mar  8 18:43:01] DEBUG[27480]: res_config_odbc.c:103 custom_prepare: Parameter 2 ('host') = 'dynamic'
[Mar  8 18:43:01] DEBUG[27480]: res_odbc.c:1034 odbc_release_obj2: odbc_release_obj2(0x2aaaac47a368) called (obj->txf = (nil))
[Mar  8 18:43:01] DEBUG[27480]: res_config_odbc.c:88 custom_prepare: Skip: 0; SQL: SELECT * FROM ast_sipaccounts WHERE name = ?
[Mar  8 18:43:01] DEBUG[27480]: res_config_odbc.c:103 custom_prepare: Parameter 1 ('name') = 'MyTestSipAccount'
[Mar  8 18:43:01] DEBUG[27480]: res_odbc.c:1034 odbc_release_obj2: odbc_release_obj2(0x2aaaac47a368) called (obj->txf = (nil))
[Mar  8 18:43:01] DEBUG[27480]: chan_sip.c:25798 build_peer: -REALTIME- peer built. Name: MyTestSipAccount. Peer objects: 2
[Mar  8 18:43:01] DEBUG[27480]: netsock2.c:125 ast_sockaddr_split_hostport: Splitting 'registrar.voip.blueface.com:5060' gives...
[Mar  8 18:43:01] DEBUG[27480]: netsock2.c:155 ast_sockaddr_split_hostport: ...host 'registrar.voip.blueface.com' and port '5060'.
[Mar  8 18:43:01] DEBUG[27480]: chan_sip.c:28119 ast_sockaddr_resolve_first_af: Multiple addresses, using the first one only
[Mar  8 18:43:01] DEBUG[27480]: chan_sip.c:26347 build_peer: Not an IPv4 nor IPv6 address, cannot get port.
[Mar  8 18:43:01] DEBUG[27480]: chan_sip.c:26350 build_peer: Not an IPv4 nor IPv6 address, cannot set port.
[Mar  8 18:43:01] DEBUG[27480]: chan_sip.c:4557 realtime_peer: -REALTIME- loading peer from database to memory. Name: MyTestSipAccount. Peer objects: 2
[Mar  8 18:43:01] DEBUG[27480]: chan_sip.c:4307 sip_destroy_peer: Destroying SIP peer MyTestSipAccount
[Mar  8 18:43:01] DEBUG[27480]: chan_sip.c:4336 sip_destroy_peer: -REALTIME- peer Destroyed. Name: MyTestSipAccount. Realtime Peer objects: 1
[Mar  8 18:43:01] DEBUG[27480]: devicestate.c:458 do_state_change: Changing state for SIP/MyTestSipAccount - state 1 (Not in use)
[Mar  8 18:43:01] DEBUG[27480]: devicestate.c:438 devstate_event: device 'SIP/MyTestSipAccount' state '1'
    -- <SIP/MyTestSipAccount-000000eb>AGI Script agi://10.7.0.82:4573?app=loadusersettings completed, returning 0
[Mar  8 18:43:01] DEBUG[29549]: pbx.c:3096 ast_str_retrieve_variable: Result of 'FastAGISrv' is '10.7.0.82:4573'
[Mar  8 18:43:01] DEBUG[29549]: pbx.c:3096 ast_str_retrieve_variable: Result of 'EXTEN' is '012223333'
[Mar  8 18:43:01] DEBUG[29549]: pbx.c:3093 ast_str_retrieve_variable: Result of 'LocalCallPrefix' is NULL
[Mar  8 18:43:01] DEBUG[29549]: pbx.c:4067 pbx_extension_helper: Launching 'AGI'
    -- Executing [012223333@base-out:3] AGI("SIP/MyTestSipAccount-000000eb", "agi://10.7.0.82:4573?app=isLocalNumber&dst=012223333&prefix=") in new stack
[Mar  8 18:43:01] DEBUG[29549]: res_agi.c:1422 launch_netscript: Wow, connected!
    -- <SIP/MyTestSipAccount-000000eb>AGI Script agi://10.7.0.82:4573?app=isLocalNumber&dst=012223333&prefix= completed, returning 0
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3096 ast_str_retrieve_variable: Result of 'LocalNumber' is '35312223333'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3096 ast_str_retrieve_variable: Result of 'IsExtension' is 'False'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3096 ast_str_retrieve_variable: Result of 'IsVoxbone' is 'False'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:4067 pbx_extension_helper: Launching 'NoOp'
    -- Executing [012223333@base-out:4] NoOp("SIP/MyTestSipAccount-000000eb", "isLocalNumber: LocalNumber=35312223333, IsExtension=False, IsVoxbone=False") in new stack
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3895 pbx_substitute_variables_helper_full: Function result is '012223333'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3895 pbx_substitute_variables_helper_full: Function result is ''
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:4067 pbx_extension_helper: Launching 'NoOp'
    -- Executing [012223333@base-out:5] NoOp("SIP/MyTestSipAccount-000000eb", "CALLERID(dnid): 012223333 CALLERID(rdnis): ") in new stack
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3096 ast_str_retrieve_variable: Result of 'IsExtension' is 'False'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3963 pbx_substitute_variables_helper_full: Expression result is '0'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:4067 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [012223333@base-out:6] GotoIf("SIP/MyTestSipAccount-000000eb", "0?bfcid") in new stack
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:9733 pbx_builtin_gotoif: Not taking any branch
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3096 ast_str_retrieve_variable: Result of 'PSTNCallerId' is '0035315242051'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3895 pbx_substitute_variables_helper_full: Function result is '0035315242051'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3963 pbx_substitute_variables_helper_full: Expression result is '0'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3096 ast_str_retrieve_variable: Result of 'PSTNCallerId' is '0035315242051'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:4067 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [012223333@base-out:7] ExecIf("SIP/MyTestSipAccount-000000eb", "0?Set(CALLERID(all)=Unknown <0>):Set(CALLERID(num)=0035315242051)") in new stack
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:4067 pbx_extension_helper: Launching 'NoOp'
    -- Executing [012223333@base-out:8] NoOp("SIP/MyTestSipAccount-000000eb", "Placeholder to jump past blueface extension callerid settings") in new stack
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3096 ast_str_retrieve_variable: Result of 'LocalNumber' is '35312223333'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3963 pbx_substitute_variables_helper_full: Expression result is '1'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3096 ast_str_retrieve_variable: Result of 'LocalNumber' is '35312223333'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:4067 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [012223333@base-out:9] ExecIf("SIP/MyTestSipAccount-000000eb", "1?Goto(incoming,35312223333,1)") in new stack
    -- Goto (incoming,35312223333,1)
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3096 ast_str_retrieve_variable: Result of 'EXTEN' is '35312223333'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3895 pbx_substitute_variables_helper_full: Function result is '0035315242051'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:4067 pbx_extension_helper: Launching 'NoOp'
    -- Executing [35312223333@incoming:1] NoOp("SIP/MyTestSipAccount-000000eb", "Incoming call to number=35312223333 from=0035315242051") in new stack
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:4067 pbx_extension_helper: Launching 'SetAMAFlags'
    -- Executing [35312223333@incoming:2] SetAMAFlags("SIP/MyTestSipAccount-000000eb", "OMIT") in new stack
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3096 ast_str_retrieve_variable: Result of 'FastAGISrv' is '10.7.0.82:4573'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:4067 pbx_extension_helper: Launching 'AGI'
    -- Executing [35312223333@incoming:3] AGI("SIP/MyTestSipAccount-000000eb", "agi://10.7.0.82:4573?app=numcommandlookup") in new stack
[Mar  8 18:43:02] DEBUG[29549]: res_agi.c:1422 launch_netscript: Wow, connected!
    -- <SIP/MyTestSipAccount-000000eb>AGI Script agi://10.7.0.82:4573?app=numcommandlookup completed, returning 0
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3096 ast_str_retrieve_variable: Result of 'App' is 'Macro'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3096 ast_str_retrieve_variable: Result of 'Data' is 'in,SIP/eircomgw/353000000002&SIP/eircomgw/353000000001,,,3029,30,mytestaccountcode'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3093 ast_str_retrieve_variable: Result of 'Error' is NULL
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:4067 pbx_extension_helper: Launching 'NoOp'
    -- Executing [35312223333@incoming:4] NoOp("SIP/MyTestSipAccount-000000eb", "App=Macro, Data=in,SIP/eircomgw/353000000002&SIP/eircomgw/353000000001,,,3029,30,mytestaccountcode, ErrorCode=") in new stack
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3096 ast_str_retrieve_variable: Result of 'App' is 'Macro'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3963 pbx_substitute_variables_helper_full: Expression result is '1'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3096 ast_str_retrieve_variable: Result of 'App' is 'Macro'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:4067 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [35312223333@incoming:5] GotoIf("SIP/MyTestSipAccount-000000eb", "1?Macro") in new stack
    -- Goto (incoming,35312223333,8)
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3096 ast_str_retrieve_variable: Result of 'Data' is 'in,SIP/eircomgw/353000000002&SIP/eircomgw/353000000001,,,3029,30,mytestaccountcode'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:4067 pbx_extension_helper: Launching 'Macro'
    -- Executing [35312223333@incoming:8] Macro("SIP/MyTestSipAccount-000000eb", "in,SIP/eircomgw/353000000002&SIP/eircomgw/353000000001,,,3029,30,mytestaccountcode") in new stack
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3895 pbx_substitute_variables_helper_full: Function result is '0035315242051'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:4067 pbx_extension_helper: Launching 'NoOp'
    -- Executing [s@macro-in:1] NoOp("SIP/MyTestSipAccount-000000eb", "incoming call clid=0035315242051") in new stack
[Mar  8 18:43:02] DEBUG[29549]: app_macro.c:430 _macro_exec: Executed application: NoOp
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3895 pbx_substitute_variables_helper_full: Function result is '0035315242051'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3895 pbx_substitute_variables_helper_full: Function result is '13'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3963 pbx_substitute_variables_helper_full: Expression result is '0'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:4067 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-in:2] GotoIf("SIP/MyTestSipAccount-000000eb", "0?anonymise") in new stack
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:9733 pbx_builtin_gotoif: Not taking any branch
[Mar  8 18:43:02] DEBUG[29549]: app_macro.c:430 _macro_exec: Executed application: GotoIf
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3895 pbx_substitute_variables_helper_full: Function result is '0035315242051'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3963 pbx_substitute_variables_helper_full: Expression result is '0'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:4067 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-in:3] GotoIf("SIP/MyTestSipAccount-000000eb", "0?anonymise") in new stack
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:9733 pbx_builtin_gotoif: Not taking any branch
[Mar  8 18:43:02] DEBUG[29549]: app_macro.c:430 _macro_exec: Executed application: GotoIf
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3895 pbx_substitute_variables_helper_full: Function result is '0035315242051'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3963 pbx_substitute_variables_helper_full: Expression result is '0'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:4067 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-in:4] GotoIf("SIP/MyTestSipAccount-000000eb", "0?anonymise") in new stack
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:9733 pbx_builtin_gotoif: Not taking any branch
[Mar  8 18:43:02] DEBUG[29549]: app_macro.c:430 _macro_exec: Executed application: GotoIf
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3895 pbx_substitute_variables_helper_full: Function result is '0035315242051'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3963 pbx_substitute_variables_helper_full: Expression result is '0'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:4067 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-in:5] GotoIf("SIP/MyTestSipAccount-000000eb", "0?hangup") in new stack
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:9733 pbx_builtin_gotoif: Not taking any branch
[Mar  8 18:43:02] DEBUG[29549]: app_macro.c:430 _macro_exec: Executed application: GotoIf
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3895 pbx_substitute_variables_helper_full: Function result is '0035315242051'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3963 pbx_substitute_variables_helper_full: Expression result is '0'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:4067 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-in:6] GotoIf("SIP/MyTestSipAccount-000000eb", "0?hangup") in new stack
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:9733 pbx_builtin_gotoif: Not taking any branch
[Mar  8 18:43:02] DEBUG[29549]: app_macro.c:430 _macro_exec: Executed application: GotoIf
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3895 pbx_substitute_variables_helper_full: Function result is '0035315242051'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3963 pbx_substitute_variables_helper_full: Expression result is '0'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:4067 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-in:7] GotoIf("SIP/MyTestSipAccount-000000eb", "0?hangup") in new stack
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:9733 pbx_builtin_gotoif: Not taking any branch
[Mar  8 18:43:02] DEBUG[29549]: app_macro.c:430 _macro_exec: Executed application: GotoIf
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3895 pbx_substitute_variables_helper_full: Function result is '0035315242051'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3963 pbx_substitute_variables_helper_full: Expression result is '0'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:4067 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-in:8] GotoIf("SIP/MyTestSipAccount-000000eb", "0?hangup") in new stack
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:9733 pbx_builtin_gotoif: Not taking any branch
[Mar  8 18:43:02] DEBUG[29549]: app_macro.c:430 _macro_exec: Executed application: GotoIf
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:4067 pbx_extension_helper: Launching 'Goto'
    -- Executing [s@macro-in:9] Goto("SIP/MyTestSipAccount-000000eb", "start") in new stack
    -- Goto (macro-in,s,12)
[Mar  8 18:43:02] DEBUG[29549]: app_macro.c:430 _macro_exec: Executed application: Goto
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3096 ast_str_retrieve_variable: Result of 'ARG6' is 'mytestaccountcode'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3895 pbx_substitute_variables_helper_full: Function result is '19'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3963 pbx_substitute_variables_helper_full: Expression result is '0'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:4067 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-in:12] GotoIf("SIP/MyTestSipAccount-000000eb", "0?vmtimeout") in new stack
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:9733 pbx_builtin_gotoif: Not taking any branch
[Mar  8 18:43:02] DEBUG[29549]: app_macro.c:430 _macro_exec: Executed application: GotoIf
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3096 ast_str_retrieve_variable: Result of 'ARG6' is 'mytestaccountcode'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:4067 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-in:13] Set("SIP/MyTestSipAccount-000000eb", "CDR(accountcode)=mytestaccountcode") in new stack
[Mar  8 18:43:02] DEBUG[29549]: app_macro.c:430 _macro_exec: Executed application: Set
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3096 ast_str_retrieve_variable: Result of 'ARG5' is '30'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3963 pbx_substitute_variables_helper_full: Expression result is '0'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:4067 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-in:14] GotoIf("SIP/MyTestSipAccount-000000eb", "0?vm") in new stack
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:9733 pbx_builtin_gotoif: Not taking any branch
[Mar  8 18:43:02] DEBUG[29549]: app_macro.c:430 _macro_exec: Executed application: GotoIf
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3096 ast_str_retrieve_variable: Result of 'ARG5' is '30'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3963 pbx_substitute_variables_helper_full: Expression result is '0'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:4067 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-in:15] GotoIf("SIP/MyTestSipAccount-000000eb", "0?setmoh") in new stack
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:9733 pbx_builtin_gotoif: Not taking any branch
[Mar  8 18:43:02] DEBUG[29549]: app_macro.c:430 _macro_exec: Executed application: GotoIf
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3096 ast_str_retrieve_variable: Result of 'ARG5' is '30'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:4067 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-in:16] Set("SIP/MyTestSipAccount-000000eb", "vmtimeout=30") in new stack
[Mar  8 18:43:02] DEBUG[29549]: app_macro.c:430 _macro_exec: Executed application: Set
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3093 ast_str_retrieve_variable: Result of 'ARG7' is NULL
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3963 pbx_substitute_variables_helper_full: Expression result is '1'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:4067 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-in:17] GotoIf("SIP/MyTestSipAccount-000000eb", "1?startcall") in new stack
    -- Goto (macro-in,s,19)
[Mar  8 18:43:02] DEBUG[29549]: app_macro.c:430 _macro_exec: Executed application: GotoIf
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3096 ast_str_retrieve_variable: Result of 'ARG1' is 'SIP/eircomgw/353000000002&SIP/eircomgw/353000000001'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:3096 ast_str_retrieve_variable: Result of 'vmtimeout' is '30'
[Mar  8 18:43:02] DEBUG[29549]: pbx.c:4067 pbx_extension_helper: Launching 'Dial'
    -- Executing [s@macro-in:19] Dial("SIP/MyTestSipAccount-000000eb", "SIP/eircomgw/353000000002&SIP/eircomgw/353000000001,30,ti") in new stack
[Mar  8 18:43:02] DEBUG[29549]: chan_sip.c:25071 sip_request_call: Asked to create a SIP channel with formats: 0x8 (alaw)
[Mar  8 18:43:02] DEBUG[29549]: chan_sip.c:7215 sip_alloc: Allocating new SIP dialog for 5686230a3fc132b0338b344305dd8374@blueface.eu - INVITE (No RTP)
[Mar  8 18:43:02] DEBUG[29549]: rtp_engine.c:344 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x2b412433e4f8'
[Mar  8 18:43:02] DEBUG[29549]: res_rtp_asterisk.c:472 ast_rtp_new: Allocated port 11348 for RTP instance '0x2b412433e4f8'
[Mar  8 18:43:02] DEBUG[29549]: rtp_engine.c:353 ast_rtp_instance_new: RTP instance '0x2b412433e4f8' is setup and ready to go
[Mar  8 18:43:02] DEBUG[29549]: res_rtp_asterisk.c:2370 ast_rtp_prop_set: Setup RTCP on RTP instance '0x2b412433e4f8'
  == Using SIP RTP TOS bits 184
  == Using SIP RTP CoS mark 5
[Mar  8 18:43:02] DEBUG[29549]: chan_sip.c:4683 do_setnat: Setting NAT on RTP to Off
[Mar  8 18:43:02] DEBUG[29549]: acl.c:715 ast_ouraddrfor: For destination '87.238.74.170', our source address is '10.7.0.75'.
[Mar  8 18:43:02] DEBUG[29549]: chan_sip.c:3243 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 10.7.0.75:5060
[Mar  8 18:43:02] DEBUG[29549]: chan_sip.c:6557 sip_new: *** Our native formats are 0x8 (alaw) 
[Mar  8 18:43:02] DEBUG[29549]: chan_sip.c:6558 sip_new: *** Joint capabilities are 0x8 (alaw) 
[Mar  8 18:43:02] DEBUG[29549]: chan_sip.c:6559 sip_new: *** Our capabilities are 0x10c (ulaw|alaw|g729) 
[Mar  8 18:43:02] DEBUG[29549]: chan_sip.c:6560 sip_new: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) 
[Mar  8 18:43:02] DEBUG[29549]: chan_sip.c:6562 sip_new: *** Our preferred formats from the incoming channel are 0x8 (alaw) 
[Mar  8 18:43:02] DEBUG[29549]: chan_sip.c:6590 sip_new: This channel will not be able to handle video.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable DIALEDTIME.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable DIALSTATUS.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable vmtimeout.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable ARG6.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable ARG5.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable ARG4.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable ARG3.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable ARG2.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable ARG1.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable AGISTATUS.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable AccountCode.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable WhiteLabelId.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable Data.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable App.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable IsVoxbone.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable IsExtension.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable LocalNumber.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable isSubscriber.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable WhitelabelId.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable DialPlan.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable PSTNCallerId.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable Username.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable SIPDOMAIN.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable SIPURI.
[Mar  8 18:43:02] DEBUG[29549]: chan_sip.c:5212 sip_call: Outgoing Call for 353000000002
[Mar  8 18:43:02] DEBUG[29549]: chan_sip.c:5454 update_call_counter: Updating call counter for outgoing call
[Mar  8 18:43:02] DEBUG[27480]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - eircomgw
[Mar  8 18:43:02] DEBUG[27480]: chan_sip.c:24969 sip_devicestate: Checking device state for peer eircomgw
[Mar  8 18:43:02] DEBUG[27480]: devicestate.c:458 do_state_change: Changing state for SIP/eircomgw - state 6 (Ringing)
[Mar  8 18:43:02] DEBUG[27480]: devicestate.c:438 devstate_event: device 'SIP/eircomgw' state '6'
[Mar  8 18:43:02] DEBUG[29549]: chan_sip.c:10570 add_sdp: ** Our capability: 0x10c (ulaw|alaw|g729) Video flag: False Text flag: False
[Mar  8 18:43:02] DEBUG[29549]: chan_sip.c:10571 add_sdp: ** Our prefcodec: 0x8 (alaw) 
[Mar  8 18:43:02] DEBUG[29549]: chan_sip.c:10680 add_sdp: -- Done with adding codecs to SDP
[Mar  8 18:43:02] DEBUG[29549]: chan_sip.c:10819 add_sdp: Done building SDP. Settling with this capability: 0x10c (ulaw|alaw|g729)
[Mar  8 18:43:02] DEBUG[29549]: chan_sip.c:2823 initialize_initreq: Initializing initreq for method INVITE - callid 5a58b15404ae3856365ee01d05458162@blueface.eu
[Mar  8 18:43:02] DEBUG[29549]: chan_sip.c:3089 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 10.7.0.89:5060
    -- Called eircomgw/353000000002
[Mar  8 18:43:02] DEBUG[29549]: chan_sip.c:25071 sip_request_call: Asked to create a SIP channel with formats: 0x8 (alaw)
[Mar  8 18:43:02] DEBUG[29549]: chan_sip.c:7215 sip_alloc: Allocating new SIP dialog for 4242ef66068e4cb06ffea59729b9dc0e@blueface.eu - INVITE (No RTP)
[Mar  8 18:43:02] DEBUG[29549]: rtp_engine.c:344 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x2b4124208a08'
[Mar  8 18:43:02] DEBUG[29549]: res_rtp_asterisk.c:472 ast_rtp_new: Allocated port 12352 for RTP instance '0x2b4124208a08'
[Mar  8 18:43:02] DEBUG[29549]: rtp_engine.c:353 ast_rtp_instance_new: RTP instance '0x2b4124208a08' is setup and ready to go
[Mar  8 18:43:02] DEBUG[29549]: res_rtp_asterisk.c:2370 ast_rtp_prop_set: Setup RTCP on RTP instance '0x2b4124208a08'
  == Using SIP RTP TOS bits 184
  == Using SIP RTP CoS mark 5
[Mar  8 18:43:02] DEBUG[29549]: chan_sip.c:4683 do_setnat: Setting NAT on RTP to Off
[Mar  8 18:43:02] DEBUG[29549]: acl.c:715 ast_ouraddrfor: For destination '87.238.74.170', our source address is '10.7.0.75'.
[Mar  8 18:43:02] DEBUG[29549]: chan_sip.c:3243 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 10.7.0.75:5060
[Mar  8 18:43:02] DEBUG[29549]: chan_sip.c:6557 sip_new: *** Our native formats are 0x8 (alaw) 
[Mar  8 18:43:02] DEBUG[29549]: chan_sip.c:6558 sip_new: *** Joint capabilities are 0x8 (alaw) 
[Mar  8 18:43:02] DEBUG[29549]: chan_sip.c:6559 sip_new: *** Our capabilities are 0x10c (ulaw|alaw|g729) 
[Mar  8 18:43:02] DEBUG[29549]: chan_sip.c:6560 sip_new: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) 
[Mar  8 18:43:02] DEBUG[29549]: chan_sip.c:6562 sip_new: *** Our preferred formats from the incoming channel are 0x8 (alaw) 
[Mar  8 18:43:02] DEBUG[29549]: chan_sip.c:6590 sip_new: This channel will not be able to handle video.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable DIALEDTIME.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable DIALSTATUS.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable vmtimeout.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable ARG6.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable ARG5.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable ARG4.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable ARG3.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable ARG2.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable ARG1.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable AGISTATUS.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable AccountCode.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable WhiteLabelId.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable Data.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable App.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable IsVoxbone.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable IsExtension.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable LocalNumber.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable isSubscriber.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable WhitelabelId.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable DialPlan.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable PSTNCallerId.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable Username.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable SIPDOMAIN.
[Mar  8 18:43:02] DEBUG[29549]: channel.c:5900 ast_channel_inherit_variables: Not copying variable SIPURI.
[Mar  8 18:43:02] DEBUG[29549]: chan_sip.c:5212 sip_call: Outgoing Call for 353000000001
[Mar  8 18:43:02] DEBUG[29549]: chan_sip.c:5454 update_call_counter: Updating call counter for outgoing call
[Mar  8 18:43:02] DEBUG[27480]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - eircomgw
[Mar  8 18:43:02] DEBUG[27480]: chan_sip.c:24969 sip_devicestate: Checking device state for peer eircomgw
[Mar  8 18:43:02] DEBUG[27480]: devicestate.c:458 do_state_change: Changing state for SIP/eircomgw - state 6 (Ringing)
[Mar  8 18:43:02] DEBUG[27480]: devicestate.c:438 devstate_event: device 'SIP/eircomgw' state '6'
[Mar  8 18:43:02] DEBUG[29549]: chan_sip.c:10570 add_sdp: ** Our capability: 0x10c (ulaw|alaw|g729) Video flag: False Text flag: False
[Mar  8 18:43:02] DEBUG[29549]: chan_sip.c:10571 add_sdp: ** Our prefcodec: 0x8 (alaw) 
[Mar  8 18:43:02] DEBUG[27492]: chan_sip.c:7414 find_call: = Looking for  Call ID: 5a58b15404ae3856365ee01d05458162@blueface.eu (Checking To) --From tag as3abcfb6e --To-tag   
[Mar  8 18:43:02] DEBUG[29549]: chan_sip.c:10680 add_sdp: -- Done with adding codecs to SDP
[Mar  8 18:43:02] DEBUG[29549]: chan_sip.c:10819 add_sdp: Done building SDP. Settling with this capability: 0x10c (ulaw|alaw|g729)
[Mar  8 18:43:02] DEBUG[27492]: chan_sip.c:3821 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '5a58b15404ae3856365ee01d05458162@blueface.eu' Request 102: Found
[Mar  8 18:43:02] DEBUG[29549]: chan_sip.c:2823 initialize_initreq: Initializing initreq for method INVITE - callid 68e742c218b1472c4caee64257c3883d@blueface.eu
[Mar  8 18:43:02] DEBUG[29549]: chan_sip.c:3089 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 10.7.0.89:5060
    -- Called eircomgw/353000000001
[Mar  8 18:43:02] DEBUG[27492]: chan_sip.c:18794 handle_response_invite: SIP response 100 to standard invite
[Mar  8 18:43:02] DEBUG[27492]: chan_sip.c:7414 find_call: = Looking for  Call ID: 68e742c218b1472c4caee64257c3883d@blueface.eu (Checking To) --From tag as4ef57eaf --To-tag   
[Mar  8 18:43:02] DEBUG[27492]: chan_sip.c:3821 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '68e742c218b1472c4caee64257c3883d@blueface.eu' Request 102: Found
[Mar  8 18:43:02] DEBUG[27492]: chan_sip.c:18794 handle_response_invite: SIP response 100 to standard invite
[Mar  8 18:43:02] DEBUG[27492]: chan_sip.c:7414 find_call: = Looking for  Call ID: 5a58b15404ae3856365ee01d05458162@blueface.eu (Checking To) --From tag as3abcfb6e --To-tag 8CDBA854-1429  
[Mar  8 18:43:02] DEBUG[27492]: chan_sip.c:3821 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '5a58b15404ae3856365ee01d05458162@blueface.eu' Request 102: Found
[Mar  8 18:43:02] DEBUG[27492]: chan_sip.c:18794 handle_response_invite: SIP response 183 to standard invite
[Mar  8 18:43:02] DEBUG[27492]: chan_sip.c:8200 process_sdp: Processing session-level SDP v=0... UNSUPPORTED.
[Mar  8 18:43:02] DEBUG[27492]: chan_sip.c:8200 process_sdp: Processing session-level SDP o=CiscoSystemsSIP-GW-UserAgent 6 6086 IN IP4 10.7.0.89... UNSUPPORTED.
[Mar  8 18:43:02] DEBUG[27492]: chan_sip.c:8200 process_sdp: Processing session-level SDP s=SIP Call... UNSUPPORTED.
[Mar  8 18:43:02] DEBUG[27492]: netsock2.c:125 ast_sockaddr_split_hostport: Splitting '10.7.0.89' gives...
[Mar  8 18:43:02] DEBUG[27492]: netsock2.c:155 ast_sockaddr_split_hostport: ...host '10.7.0.89' and port '(null)'.
[Mar  8 18:43:02] DEBUG[27492]: chan_sip.c:8200 process_sdp: Processing session-level SDP c=IN IP4 10.7.0.89... OK.
[Mar  8 18:43:02] DEBUG[27492]: chan_sip.c:8200 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED.
[Mar  8 18:43:02] DEBUG[27492]: rtp_engine.c:535 ast_rtp_codecs_payloads_set_m_type: Setting payload 8 based on m type on 0x4157c430
[Mar  8 18:43:02] DEBUG[27492]: rtp_engine.c:535 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0x4157c430
[Mar  8 18:43:02] DEBUG[27492]: netsock2.c:125 ast_sockaddr_split_hostport: Splitting '10.7.0.89' gives...
[Mar  8 18:43:02] DEBUG[27492]: netsock2.c:155 ast_sockaddr_split_hostport: ...host '10.7.0.89' and port '(null)'.
[Mar  8 18:43:02] DEBUG[27492]: chan_sip.c:8387 process_sdp: Processing media-level (audio) SDP c=IN IP4 10.7.0.89... OK.
[Mar  8 18:43:02] DEBUG[27492]: chan_sip.c:8387 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[Mar  8 18:43:02] DEBUG[27492]: chan_sip.c:8387 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[Mar  8 18:43:02] DEBUG[27492]: chan_sip.c:8387 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED.
[Mar  8 18:43:02] DEBUG[27492]: chan_sip.c:8387 process_sdp: Processing media-level (audio) SDP a=ptime:20... OK.
[Mar  8 18:43:02] DEBUG[27492]: chan_sip.c:8387 process_sdp: Processing media-level (audio) SDP a=nortpproxy:yes... UNSUPPORTED.
[Mar  8 18:43:02] DEBUG[27492]: rtp_engine.c:638 ast_rtp_codecs_payload_formats: Incorporating payload 8 on 0x4157c430
[Mar  8 18:43:02] DEBUG[27492]: rtp_engine.c:638 ast_rtp_codecs_payload_formats: Incorporating payload 101 on 0x4157c430
[Mar  8 18:43:02] DEBUG[27492]: res_rtp_asterisk.c:2391 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x2b412433e4f8'
[Mar  8 18:43:02] DEBUG[27492]: rtp_engine.c:516 ast_rtp_codecs_payloads_copy: Copying payload 8 from 0x4157c430 to 0x2b412433e6c0
[Mar  8 18:43:02] DEBUG[27492]: rtp_engine.c:516 ast_rtp_codecs_payloads_copy: Copying payload 101 from 0x4157c430 to 0x2b412433e6c0
[Mar  8 18:43:02] DEBUG[27492]: chan_sip.c:8619 process_sdp: We're settling with these formats: 0x8 (alaw)
[Mar  8 18:43:02] DEBUG[27492]: chan_sip.c:8624 process_sdp: We have an owner, now see if we need to change this call
    -- SIP/eircomgw-000000ec is making progress passing it to SIP/MyTestSipAccount-000000eb
[Mar  8 18:43:02] DEBUG[29549]: chan_sip.c:10924 transmit_response_with_sdp: Setting framing from config on incoming call
[Mar  8 18:43:02] DEBUG[29549]: chan_sip.c:10570 add_sdp: ** Our capability: 0x60e (gsm|ulaw|alaw|speex|ilbc) Video flag: True Text flag: True
[Mar  8 18:43:02] DEBUG[29549]: chan_sip.c:10571 add_sdp: ** Our prefcodec: 0x0 (nothing) 
[Mar  8 18:43:02] DEBUG[29549]: chan_sip.c:10680 add_sdp: -- Done with adding codecs to SDP
[Mar  8 18:43:02] DEBUG[29549]: chan_sip.c:10819 add_sdp: Done building SDP. Settling with this capability: 0x60e (gsm|ulaw|alaw|speex|ilbc)
[Mar  8 18:43:02] DEBUG[29549]: chan_sip.c:3089 __sip_xmit: Trying to put 'SIP/2.0 183' onto UDP socket destined for 10.7.0.90:5060
[Mar  8 18:43:02] DEBUG[27492]: chan_sip.c:7414 find_call: = Looking for  Call ID: 68e742c218b1472c4caee64257c3883d@blueface.eu (Checking To) --From tag as4ef57eaf --To-tag 78AC1534-1A10  
[Mar  8 18:43:02] DEBUG[27492]: chan_sip.c:3821 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '68e742c218b1472c4caee64257c3883d@blueface.eu' Request 102: Found
[Mar  8 18:43:02] DEBUG[27492]: chan_sip.c:18794 handle_response_invite: SIP response 183 to standard invite
[Mar  8 18:43:02] DEBUG[27492]: chan_sip.c:8200 process_sdp: Processing session-level SDP v=0... UNSUPPORTED.
[Mar  8 18:43:02] DEBUG[27492]: chan_sip.c:8200 process_sdp: Processing session-level SDP o=CiscoSystemsSIP-GW-UserAgent 6013 6427 IN IP4 10.7.0.89... UNSUPPORTED.
[Mar  8 18:43:02] DEBUG[27492]: chan_sip.c:8200 process_sdp: Processing session-level SDP s=SIP Call... UNSUPPORTED.
[Mar  8 18:43:02] DEBUG[27492]: netsock2.c:125 ast_sockaddr_split_hostport: Splitting '10.7.0.89' gives...
[Mar  8 18:43:02] DEBUG[27492]: netsock2.c:155 ast_sockaddr_split_hostport: ...host '10.7.0.89' and port '(null)'.
[Mar  8 18:43:02] DEBUG[27492]: chan_sip.c:8200 process_sdp: Processing session-level SDP c=IN IP4 10.7.0.89... OK.
[Mar  8 18:43:02] DEBUG[27492]: chan_sip.c:8200 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED.
[Mar  8 18:43:02] DEBUG[27492]: rtp_engine.c:535 ast_rtp_codecs_payloads_set_m_type: Setting payload 8 based on m type on 0x4157c430
[Mar  8 18:43:02] DEBUG[27492]: rtp_engine.c:535 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0x4157c430
[Mar  8 18:43:02] DEBUG[27492]: netsock2.c:125 ast_sockaddr_split_hostport: Splitting '10.7.0.89' gives...
[Mar  8 18:43:02] DEBUG[27492]: netsock2.c:155 ast_sockaddr_split_hostport: ...host '10.7.0.89' and port '(null)'.
[Mar  8 18:43:02] DEBUG[27492]: chan_sip.c:8387 process_sdp: Processing media-level (audio) SDP c=IN IP4 10.7.0.89... OK.
[Mar  8 18:43:02] DEBUG[27492]: chan_sip.c:8387 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[Mar  8 18:43:02] DEBUG[27492]: chan_sip.c:8387 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[Mar  8 18:43:02] DEBUG[27492]: chan_sip.c:8387 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED.
[Mar  8 18:43:02] DEBUG[27492]: chan_sip.c:8387 process_sdp: Processing media-level (audio) SDP a=ptime:20... OK.
[Mar  8 18:43:02] DEBUG[27492]: chan_sip.c:8387 process_sdp: Processing media-level (audio) SDP a=nortpproxy:yes... UNSUPPORTED.
[Mar  8 18:43:02] DEBUG[27492]: rtp_engine.c:638 ast_rtp_codecs_payload_formats: Incorporating payload 8 on 0x4157c430
[Mar  8 18:43:02] DEBUG[27492]: rtp_engine.c:638 ast_rtp_codecs_payload_formats: Incorporating payload 101 on 0x4157c430
[Mar  8 18:43:02] DEBUG[27492]: res_rtp_asterisk.c:2391 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x2b4124208a08'
[Mar  8 18:43:02] DEBUG[27492]: rtp_engine.c:516 ast_rtp_codecs_payloads_copy: Copying payload 8 from 0x4157c430 to 0x2b4124208bd0
[Mar  8 18:43:02] DEBUG[27492]: rtp_engine.c:516 ast_rtp_codecs_payloads_copy: Copying payload 101 from 0x4157c430 to 0x2b4124208bd0
[Mar  8 18:43:02] DEBUG[27492]: chan_sip.c:8619 process_sdp: We're settling with these formats: 0x8 (alaw)
[Mar  8 18:43:02] DEBUG[27492]: chan_sip.c:8624 process_sdp: We have an owner, now see if we need to change this call
    -- SIP/eircomgw-000000ed is making progress passing it to SIP/MyTestSipAccount-000000eb
[Mar  8 18:43:03] DEBUG[29549]: res_rtp_asterisk.c:1422 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Mar  8 18:43:03] DEBUG[29549]: res_rtp_asterisk.c:1378 create_dtmf_frame: Sending dtmf: 48 (0), at 10.7.0.89:41892
[Mar  8 18:43:03] DEBUG[29549]: res_rtp_asterisk.c:1422 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Mar  8 18:43:03] DEBUG[29549]: res_rtp_asterisk.c:1422 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Mar  8 18:43:03] DEBUG[29549]: res_rtp_asterisk.c:1422 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Mar  8 18:43:03] DEBUG[29549]: res_rtp_asterisk.c:1378 create_dtmf_frame: Sending dtmf: 48 (0), at 10.7.0.89:51070
[Mar  8 18:43:03] DEBUG[29549]: res_rtp_asterisk.c:1422 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Mar  8 18:43:03] DEBUG[29549]: res_rtp_asterisk.c:1422 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Mar  8 18:43:03] DEBUG[29549]: res_rtp_asterisk.c:1422 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Mar  8 18:43:03] DEBUG[29549]: res_rtp_asterisk.c:1378 create_dtmf_frame: Sending dtmf: 48 (0), at 10.7.0.89:41892
[Mar  8 18:43:03] DEBUG[29549]: res_rtp_asterisk.c:1422 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Mar  8 18:43:03] DEBUG[29549]: res_rtp_asterisk.c:1422 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Mar  8 18:43:03] DEBUG[29549]: res_rtp_asterisk.c:1422 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Mar  8 18:43:03] DEBUG[29549]: res_rtp_asterisk.c:1378 create_dtmf_frame: Sending dtmf: 48 (0), at 10.7.0.89:51070
[Mar  8 18:43:03] DEBUG[29549]: res_rtp_asterisk.c:1422 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Mar  8 18:43:03] DEBUG[29549]: res_rtp_asterisk.c:1422 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Mar  8 18:43:04] DEBUG[29549]: res_rtp_asterisk.c:1673 ast_rtcp_read: Got RTCP report of 88 bytes
[Mar  8 18:43:05] DEBUG[29549]: res_rtp_asterisk.c:1673 ast_rtcp_read: Got RTCP report of 64 bytes
[Mar  8 18:43:05] DEBUG[29549]: res_rtp_asterisk.c:1673 ast_rtcp_read: Got RTCP report of 88 bytes
[Mar  8 18:43:05] DEBUG[29549]: res_rtp_asterisk.c:1673 ast_rtcp_read: Got RTCP report of 88 bytes
[Mar  8 18:43:09] DEBUG[29549]: res_rtp_asterisk.c:1673 ast_rtcp_read: Got RTCP report of 88 bytes
[Mar  8 18:43:09] DEBUG[29549]: res_rtp_asterisk.c:1673 ast_rtcp_read: Got RTCP report of 64 bytes
[Mar  8 18:43:11] DEBUG[29549]: res_rtp_asterisk.c:1673 ast_rtcp_read: Got RTCP report of 88 bytes
[Mar  8 18:43:13] DEBUG[29549]: res_rtp_asterisk.c:1673 ast_rtcp_read: Got RTCP report of 88 bytes
[Mar  8 18:43:15] DEBUG[29549]: res_rtp_asterisk.c:1673 ast_rtcp_read: Got RTCP report of 64 bytes
[Mar  8 18:43:16] DEBUG[27492]: chan_sip.c:7414 find_call: = Looking for  Call ID: YjEwYTY2YjExNThhMmM5OTc4MDA4OWE2NjRjNDUxZDk. (Checking From) --From tag 6b70fe68 --To-tag   
[Mar  8 18:43:16] DEBUG[27492]: chan_sip.c:23649 handle_incoming: **** Received CANCEL (14) - Command in SIP CANCEL
[Mar  8 18:43:16] DEBUG[27492]: netsock2.c:125 ast_sockaddr_split_hostport: Splitting '10.7.0.90' gives...
[Mar  8 18:43:16] DEBUG[27492]: netsock2.c:155 ast_sockaddr_split_hostport: ...host '10.7.0.90' and port '(null)'.
[Mar  8 18:43:16] DEBUG[27492]: chan_sip.c:2836 sip_alreadygone: Setting SIP_ALREADYGONE on dialog YjEwYTY2YjExNThhMmM5OTc4MDA4OWE2NjRjNDUxZDk.
[Mar  8 18:43:16] DEBUG[27492]: chan_sip.c:5454 update_call_counter: Updating call counter for incoming call
[Mar  8 18:43:16] DEBUG[27492]: res_rtp_asterisk.c:2391 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x1b665a58'
[Mar  8 18:43:16] DEBUG[27492]: res_rtp_asterisk.c:2391 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x1b770b08'
[Mar  8 18:43:16] DEBUG[27492]: chan_sip.c:3089 __sip_xmit: Trying to put 'SIP/2.0 487' onto UDP socket destined for 10.7.0.90:5060
[Mar  8 18:43:16] DEBUG[27492]: chan_sip.c:3089 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.7.0.90:5060
[Mar  8 18:43:16] DEBUG[27480]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - MyTestSipAccount
[Mar  8 18:43:16] DEBUG[27480]: chan_sip.c:24969 sip_devicestate: Checking device state for peer MyTestSipAccount
[Mar  8 18:43:16] DEBUG[27480]: res_config_odbc.c:88 custom_prepare: Skip: 0; SQL: SELECT * FROM ast_sipaccounts WHERE name = ? AND host = ?
[Mar  8 18:43:16] DEBUG[27480]: res_config_odbc.c:103 custom_prepare: Parameter 1 ('name') = 'MyTestSipAccount'
[Mar  8 18:43:16] DEBUG[27480]: res_config_odbc.c:103 custom_prepare: Parameter 2 ('host') = 'dynamic'
[Mar  8 18:43:16] DEBUG[29549]: channel.c:2733 ast_hangup: Hanging up channel 'SIP/eircomgw-000000ed'
[Mar  8 18:43:16] DEBUG[29549]: chan_sip.c:5827 sip_hangup: Hangup call SIP/eircomgw-000000ed, SIP callid 68e742c218b1472c4caee64257c3883d@blueface.eu
[Mar  8 18:43:16] DEBUG[29549]: chan_sip.c:5454 update_call_counter: Updating call counter for outgoing call
[Mar  8 18:43:16] DEBUG[29549]: chan_sip.c:5846 sip_hangup: Hanging up channel in state Down (not UP)
[Mar  8 18:43:16] DEBUG[29549]: res_rtp_asterisk.c:2391 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x2b4124208a08'
[Mar  8 18:43:16] DEBUG[29549]: chan_sip.c:3821 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '68e742c218b1472c4caee64257c3883d@blueface.eu' Request 102: Found
[Mar  8 18:43:16] DEBUG[29549]: chan_sip.c:3089 __sip_xmit: Trying to put 'CANCEL sip:' onto UDP socket destined for 10.7.0.89:5060
[Mar  8 18:43:16] DEBUG[27492]: chan_sip.c:7414 find_call: = Looking for  Call ID: YjEwYTY2YjExNThhMmM5OTc4MDA4OWE2NjRjNDUxZDk. (Checking From) --From tag 6b70fe68 --To-tag as64f8972a  
[Mar  8 18:43:16] DEBUG[27492]: chan_sip.c:23649 handle_incoming: **** Received ACK (6) - Command in SIP ACK
[Mar  8 18:43:16] DEBUG[29549]: channel.c:2733 ast_hangup: Hanging up channel 'SIP/eircomgw-000000ec'
[Mar  8 18:43:16] DEBUG[29549]: chan_sip.c:5827 sip_hangup: Hangup call SIP/eircomgw-000000ec, SIP callid 5a58b15404ae3856365ee01d05458162@blueface.eu
[Mar  8 18:43:16] DEBUG[29549]: chan_sip.c:5454 update_call_counter: Updating call counter for outgoing call
[Mar  8 18:43:16] DEBUG[27492]: chan_sip.c:3780 __sip_ack: Stopping retransmission on 'YjEwYTY2YjExNThhMmM5OTc4MDA4OWE2NjRjNDUxZDk.' of Response 2: Match Found
[Mar  8 18:43:16] DEBUG[29549]: chan_sip.c:5846 sip_hangup: Hanging up channel in state Down (not UP)
[Mar  8 18:43:16] DEBUG[29549]: res_rtp_asterisk.c:2391 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x2b412433e4f8'
[Mar  8 18:43:16] DEBUG[29549]: chan_sip.c:3821 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '5a58b15404ae3856365ee01d05458162@blueface.eu' Request 102: Found
[Mar  8 18:43:16] DEBUG[29549]: chan_sip.c:3089 __sip_xmit: Trying to put 'CANCEL sip:' onto UDP socket destined for 10.7.0.89:5060
[Mar  8 18:43:16] DEBUG[29549]: app_dial.c:2713 dial_exec_full: Exiting with DIALSTATUS=CANCEL.
[Mar  8 18:43:16] DEBUG[29549]: app_macro.c:424 _macro_exec: Spawn extension (macro-in,s,19) exited non-zero on 'SIP/MyTestSipAccount-000000eb' in macro 'in'
[Mar  8 18:43:16] DEBUG[27492]: chan_sip.c:7414 find_call: = Looking for  Call ID: 68e742c218b1472c4caee64257c3883d@blueface.eu (Checking To) --From tag as4ef57eaf --To-tag a6a1c5f60faecf035a1ae5b6e96e979a-830f  
[Mar  8 18:43:16] DEBUG[27492]: chan_sip.c:3742 __sip_ack: Acked pending invite 102
[Mar  8 18:43:16] DEBUG[27492]: chan_sip.c:3780 __sip_ack: Stopping retransmission on '68e742c218b1472c4caee64257c3883d@blueface.eu' of Request 102: Match Found
[Mar  8 18:43:16] DEBUG[27480]: res_odbc.c:1034 odbc_release_obj2: odbc_release_obj2(0x2aaaac47a368) called (obj->txf = (nil))
[Mar  8 18:43:16] DEBUG[27480]: res_config_odbc.c:88 custom_prepare: Skip: 0; SQL: SELECT * FROM ast_sipaccounts WHERE name = ?
[Mar  8 18:43:16] DEBUG[27480]: res_config_odbc.c:103 custom_prepare: Parameter 1 ('name') = 'MyTestSipAccount'
  == Spawn extension (macro-in, s, 19) exited non-zero on 'SIP/MyTestSipAccount-000000eb' in macro 'in'
[Mar  8 18:43:16] DEBUG[29549]: pbx.c:4752 __ast_pbx_run: Spawn extension (incoming,35312223333,8) exited non-zero on 'SIP/MyTestSipAccount-000000eb'
  == Spawn extension (incoming, 35312223333, 8) exited non-zero on 'SIP/MyTestSipAccount-000000eb'
[Mar  8 18:43:16] DEBUG[29549]: channel.c:2605 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/MyTestSipAccount-000000eb'
[Mar  8 18:43:16] DEBUG[29549]: pbx.c:3096 ast_str_retrieve_variable: Result of 'DIALEDPEERNUMBER' is ''
[Mar  8 18:43:16] DEBUG[27492]: chan_sip.c:7414 find_call: = Looking for  Call ID: 5a58b15404ae3856365ee01d05458162@blueface.eu (Checking To) --From tag as3abcfb6e --To-tag a6a1c5f60faecf035a1ae5b6e96e979a-b2b3  
[Mar  8 18:43:16] DEBUG[29549]: pbx.c:4067 pbx_extension_helper: Launching 'NoOp'
    -- Executing [h@incoming:1] NoOp("SIP/MyTestSipAccount-000000eb", "Set UserField=") in new stack
[Mar  8 18:43:16] DEBUG[27492]: chan_sip.c:3742 __sip_ack: Acked pending invite 102
[Mar  8 18:43:16] DEBUG[27492]: chan_sip.c:3780 __sip_ack: Stopping retransmission on '5a58b15404ae3856365ee01d05458162@blueface.eu' of Request 102: Match Found
[Mar  8 18:43:16] DEBUG[29549]: pbx.c:3096 ast_str_retrieve_variable: Result of 'DIALEDPEERNUMBER' is ''
[Mar  8 18:43:16] DEBUG[29549]: pbx.c:4067 pbx_extension_helper: Launching 'Set'
    -- Executing [h@incoming:2] Set("SIP/MyTestSipAccount-000000eb", "CDR(userfield)=") in new stack
[Mar  8 18:43:16] DEBUG[29549]: channel.c:2733 ast_hangup: Hanging up channel 'SIP/MyTestSipAccount-000000eb'
[Mar  8 18:43:16] DEBUG[27480]: res_odbc.c:1034 odbc_release_obj2: odbc_release_obj2(0x2aaaac47a368) called (obj->txf = (nil))
[Mar  8 18:43:16] DEBUG[27480]: chan_sip.c:25798 build_peer: -REALTIME- peer built. Name: MyTestSipAccount. Peer objects: 2
[Mar  8 18:43:16] DEBUG[27480]: netsock2.c:125 ast_sockaddr_split_hostport: Splitting 'registrar.voip.blueface.com:5060' gives...
[Mar  8 18:43:16] DEBUG[27480]: netsock2.c:155 ast_sockaddr_split_hostport: ...host 'registrar.voip.blueface.com' and port '5060'.
[Mar  8 18:43:16] DEBUG[29549]: chan_sip.c:5827 sip_hangup: Hangup call SIP/MyTestSipAccount-000000eb, SIP callid YjEwYTY2YjExNThhMmM5OTc4MDA4OWE2NjRjNDUxZDk.
[Mar  8 18:43:16] DEBUG[29549]: res_rtp_asterisk.c:2391 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x1b665a58'
[Mar  8 18:43:16] DEBUG[29549]: res_rtp_asterisk.c:2391 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x1b770b08'
[Mar  8 18:43:16] DEBUG[27480]: chan_sip.c:28119 ast_sockaddr_resolve_first_af: Multiple addresses, using the first one only
[Mar  8 18:43:16] DEBUG[27480]: chan_sip.c:26347 build_peer: Not an IPv4 nor IPv6 address, cannot get port.
[Mar  8 18:43:16] DEBUG[27480]: chan_sip.c:26350 build_peer: Not an IPv4 nor IPv6 address, cannot set port.
[Mar  8 18:43:16] DEBUG[27480]: chan_sip.c:4557 realtime_peer: -REALTIME- loading peer from database to memory. Name: MyTestSipAccount. Peer objects: 2
[Mar  8 18:43:16] DEBUG[27480]: chan_sip.c:4307 sip_destroy_peer: Destroying SIP peer MyTestSipAccount
[Mar  8 18:43:16] DEBUG[27480]: chan_sip.c:4336 sip_destroy_peer: -REALTIME- peer Destroyed. Name: MyTestSipAccount. Realtime Peer objects: 1
[Mar  8 18:43:16] DEBUG[27480]: devicestate.c:458 do_state_change: Changing state for SIP/MyTestSipAccount - state 1 (Not in use)
[Mar  8 18:43:16] DEBUG[27480]: devicestate.c:438 devstate_event: device 'SIP/MyTestSipAccount' state '1'
[Mar  8 18:43:16] DEBUG[27480]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - eircomgw
[Mar  8 18:43:16] DEBUG[27480]: chan_sip.c:24969 sip_devicestate: Checking device state for peer eircomgw
[Mar  8 18:43:16] DEBUG[27480]: devicestate.c:458 do_state_change: Changing state for SIP/eircomgw - state 1 (Not in use)
[Mar  8 18:43:16] DEBUG[27480]: devicestate.c:438 devstate_event: device 'SIP/eircomgw' state '1'
[Mar  8 18:43:16] DEBUG[27480]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - eircomgw
[Mar  8 18:43:16] DEBUG[27480]: chan_sip.c:24969 sip_devicestate: Checking device state for peer eircomgw
[Mar  8 18:43:16] DEBUG[27480]: devicestate.c:458 do_state_change: Changing state for SIP/eircomgw - state 1 (Not in use)
[Mar  8 18:43:16] DEBUG[27480]: devicestate.c:438 devstate_event: device 'SIP/eircomgw' state '1'
[Mar  8 18:43:16] DEBUG[27480]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - eircomgw
[Mar  8 18:43:16] DEBUG[27480]: chan_sip.c:24969 sip_devicestate: Checking device state for peer eircomgw
[Mar  8 18:43:16] DEBUG[27480]: devicestate.c:458 do_state_change: Changing state for SIP/eircomgw - state 1 (Not in use)
[Mar  8 18:43:16] DEBUG[27480]: devicestate.c:438 devstate_event: device 'SIP/eircomgw' state '1'
[Mar  8 18:43:16] DEBUG[27480]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - eircomgw
[Mar  8 18:43:16] DEBUG[27480]: chan_sip.c:24969 sip_devicestate: Checking device state for peer eircomgw
[Mar  8 18:43:16] DEBUG[27480]: devicestate.c:458 do_state_change: Changing state for SIP/eircomgw - state 1 (Not in use)
[Mar  8 18:43:16] DEBUG[27480]: devicestate.c:438 devstate_event: device 'SIP/eircomgw' state '1'
[Mar  8 18:43:16] DEBUG[29549]: res_odbc.c:1034 odbc_release_obj2: odbc_release_obj2(0x2aaaac4bc938) called (obj->txf = (nil))
[Mar  8 18:43:16] DEBUG[27480]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - MyTestSipAccount
[Mar  8 18:43:16] DEBUG[27480]: chan_sip.c:24969 sip_devicestate: Checking device state for peer MyTestSipAccount
[Mar  8 18:43:16] DEBUG[27480]: res_config_odbc.c:88 custom_prepare: Skip: 0; SQL: SELECT * FROM ast_sipaccounts WHERE name = ? AND host = ?
[Mar  8 18:43:16] DEBUG[27480]: res_config_odbc.c:103 custom_prepare: Parameter 1 ('name') = 'MyTestSipAccount'
[Mar  8 18:43:16] DEBUG[27480]: res_config_odbc.c:103 custom_prepare: Parameter 2 ('host') = 'dynamic'
[Mar  8 18:43:16] DEBUG[27492]: chan_sip.c:7414 find_call: = Looking for  Call ID: 5a58b15404ae3856365ee01d05458162@blueface.eu (Checking To) --From tag as3abcfb6e --To-tag 8CDBA854-1429  
[Mar  8 18:43:16] DEBUG[27492]: chan_sip.c:3780 __sip_ack: Stopping retransmission on '5a58b15404ae3856365ee01d05458162@blueface.eu' of Request 102: Match Found
[Mar  8 18:43:16] DEBUG[27492]: chan_sip.c:18794 handle_response_invite: SIP response 487 to standard invite
[Mar  8 18:43:16] DEBUG[27492]: chan_sip.c:3089 __sip_xmit: Trying to put 'ACK sip:353' onto UDP socket destined for 10.7.0.89:5060
[Mar  8 18:43:16] DEBUG[27492]: chan_sip.c:5454 update_call_counter: Updating call counter for outgoing call
[Mar  8 18:43:16] DEBUG[27480]: res_odbc.c:1034 odbc_release_obj2: odbc_release_obj2(0x2aaaac47a368) called (obj->txf = (nil))
[Mar  8 18:43:16] DEBUG[27492]: chan_sip.c:2836 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 5a58b15404ae3856365ee01d05458162@blueface.eu
[Mar  8 18:43:16] DEBUG[27480]: res_config_odbc.c:88 custom_prepare: Skip: 0; SQL: SELECT * FROM ast_sipaccounts WHERE name = ?
[Mar  8 18:43:16] DEBUG[27492]: chan_sip.c:5602 sip_destroy: Destroying SIP dialog 5a58b15404ae3856365ee01d05458162@blueface.eu
[Mar  8 18:43:16] DEBUG[27480]: res_config_odbc.c:103 custom_prepare: Parameter 1 ('name') = 'MyTestSipAccount'
[Mar  8 18:43:16] DEBUG[27492]: rtp_engine.c:292 instance_destructor: Destroyed RTP instance '0x2b412433e4f8'
[Mar  8 18:43:16] DEBUG[27492]: chan_sip.c:5602 sip_destroy: Destroying SIP dialog YjEwYTY2YjExNThhMmM5OTc4MDA4OWE2NjRjNDUxZDk.
[Mar  8 18:43:16] DEBUG[27492]: chan_sip.c:4307 sip_destroy_peer: Destroying SIP peer MyTestSipAccount
[Mar  8 18:43:16] DEBUG[27492]: chan_sip.c:4336 sip_destroy_peer: -REALTIME- peer Destroyed. Name: MyTestSipAccount. Realtime Peer objects: 0
[Mar  8 18:43:16] DEBUG[27492]: rtp_engine.c:292 instance_destructor: Destroyed RTP instance '0x1b665a58'
[Mar  8 18:43:16] DEBUG[27492]: rtp_engine.c:292 instance_destructor: Destroyed RTP instance '0x1b770b08'
[Mar  8 18:43:16] DEBUG[27480]: res_odbc.c:1034 odbc_release_obj2: odbc_release_obj2(0x2aaaac47a368) called (obj->txf = (nil))
[Mar  8 18:43:16] DEBUG[27480]: chan_sip.c:25798 build_peer: -REALTIME- peer built. Name: MyTestSipAccount. Peer objects: 1
[Mar  8 18:43:16] DEBUG[27480]: netsock2.c:125 ast_sockaddr_split_hostport: Splitting 'registrar.voip.blueface.com:5060' gives...
[Mar  8 18:43:16] DEBUG[27480]: netsock2.c:155 ast_sockaddr_split_hostport: ...host 'registrar.voip.blueface.com' and port '5060'.
[Mar  8 18:43:16] DEBUG[27480]: chan_sip.c:28119 ast_sockaddr_resolve_first_af: Multiple addresses, using the first one only
[Mar  8 18:43:16] DEBUG[27480]: chan_sip.c:26347 build_peer: Not an IPv4 nor IPv6 address, cannot get port.
[Mar  8 18:43:16] DEBUG[27480]: chan_sip.c:26350 build_peer: Not an IPv4 nor IPv6 address, cannot set port.
[Mar  8 18:43:16] DEBUG[27480]: chan_sip.c:4557 realtime_peer: -REALTIME- loading peer from database to memory. Name: MyTestSipAccount. Peer objects: 1
[Mar  8 18:43:16] DEBUG[27480]: chan_sip.c:4307 sip_destroy_peer: Destroying SIP peer MyTestSipAccount
[Mar  8 18:43:16] DEBUG[27480]: chan_sip.c:4336 sip_destroy_peer: -REALTIME- peer Destroyed. Name: MyTestSipAccount. Realtime Peer objects: 0
[Mar  8 18:43:16] DEBUG[27480]: devicestate.c:458 do_state_change: Changing state for SIP/MyTestSipAccount - state 1 (Not in use)
[Mar  8 18:43:16] DEBUG[27480]: devicestate.c:438 devstate_event: device 'SIP/MyTestSipAccount' state '1'
[Mar  8 18:43:16] DEBUG[27480]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - eircomgw
[Mar  8 18:43:16] DEBUG[27480]: chan_sip.c:24969 sip_devicestate: Checking device state for peer eircomgw
[Mar  8 18:43:16] DEBUG[27480]: devicestate.c:458 do_state_change: Changing state for SIP/eircomgw - state 1 (Not in use)
[Mar  8 18:43:16] DEBUG[27480]: devicestate.c:438 devstate_event: device 'SIP/eircomgw' state '1'
[Mar  8 18:43:16] DEBUG[27492]: chan_sip.c:7414 find_call: = Looking for  Call ID: 68e742c218b1472c4caee64257c3883d@blueface.eu (Checking To) --From tag as4ef57eaf --To-tag 78AC1534-1A10  
[Mar  8 18:43:16] DEBUG[27492]: chan_sip.c:3780 __sip_ack: Stopping retransmission on '68e742c218b1472c4caee64257c3883d@blueface.eu' of Request 102: Match Found
[Mar  8 18:43:16] DEBUG[27492]: chan_sip.c:18794 handle_response_invite: SIP response 487 to standard invite
[Mar  8 18:43:16] DEBUG[27492]: chan_sip.c:3089 __sip_xmit: Trying to put 'ACK sip:353' onto UDP socket destined for 10.7.0.89:5060
[Mar  8 18:43:16] DEBUG[27492]: chan_sip.c:5454 update_call_counter: Updating call counter for outgoing call
[Mar  8 18:43:16] DEBUG[27492]: chan_sip.c:2836 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 68e742c218b1472c4caee64257c3883d@blueface.eu
[Mar  8 18:43:16] DEBUG[27492]: chan_sip.c:5602 sip_destroy: Destroying SIP dialog 68e742c218b1472c4caee64257c3883d@blueface.eu
[Mar  8 18:43:16] DEBUG[27492]: rtp_engine.c:292 instance_destructor: Destroyed RTP instance '0x2b4124208a08'
[Mar  8 18:43:16] DEBUG[27480]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - eircomgw
[Mar  8 18:43:16] DEBUG[27480]: chan_sip.c:24969 sip_devicestate: Checking device state for peer eircomgw
[Mar  8 18:43:16] DEBUG[27480]: devicestate.c:458 do_state_change: Changing state for SIP/eircomgw - state 1 (Not in use)
[Mar  8 18:43:16] DEBUG[27480]: devicestate.c:438 devstate_event: device 'SIP/eircomgw' state '1'