[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:8515 find_call: = Looking for  Call ID: ef9ce4dc-4892-1231-3b9b-fe38fc8f3ce1 (Checking From) --From tag UraQZSH8SSy7N --To-tag   
[Jun  5 16:56:25] DEBUG[16221]: acl.c:736 ast_ouraddrfor: For destination '1.1.1.1', our source address is '2.2.2.2'.
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:3836 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 2.2.2.2:5060
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:8195 sip_alloc: Allocating new SIP dialog for ef9ce4dc-4892-1231-3b9b-fe38fc8f3ce1 - INVITE (No RTP)
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:25813 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE
[Jun  5 16:56:25] DEBUG[16221]: sip/reqresp_parser.c:1603 parse_sip_options: Begin: parsing SIP "Supported: timer, precondition, path, replaces"
[Jun  5 16:56:25] DEBUG[16221]: sip/reqresp_parser.c:1619 parse_sip_options: Found SIP option: -timer-
[Jun  5 16:56:25] DEBUG[16221]: sip/reqresp_parser.c:1627 parse_sip_options: Matched SIP option: timer
[Jun  5 16:56:25] DEBUG[16221]: sip/reqresp_parser.c:1619 parse_sip_options: Found SIP option: -precondition-
[Jun  5 16:56:25] DEBUG[16221]: sip/reqresp_parser.c:1627 parse_sip_options: Matched SIP option: precondition
[Jun  5 16:56:25] DEBUG[16221]: sip/reqresp_parser.c:1619 parse_sip_options: Found SIP option: -path-
[Jun  5 16:56:25] DEBUG[16221]: sip/reqresp_parser.c:1627 parse_sip_options: Matched SIP option: path
[Jun  5 16:56:25] DEBUG[16221]: sip/reqresp_parser.c:1619 parse_sip_options: Found SIP option: -replaces-
[Jun  5 16:56:25] DEBUG[16221]: sip/reqresp_parser.c:1627 parse_sip_options: Matched SIP option: replaces
[Jun  5 16:56:25] DEBUG[16221]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '1.1.1.1' into...
[Jun  5 16:56:25] DEBUG[16221]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '1.1.1.1' and port ''.
[Jun  5 16:56:25] DEBUG[16221]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '1.1.1.1' into...
[Jun  5 16:56:25] DEBUG[16221]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '1.1.1.1' and port ''.
[Jun  5 16:56:25] DEBUG[16221]: rtp_engine.c:350 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x1907098'
[Jun  5 16:56:25] DEBUG[16221]: res_rtp_asterisk.c:558 ast_rtp_new: Allocated port 11638 for RTP instance '0x1907098'
[Jun  5 16:56:25] DEBUG[16221]: rtp_engine.c:359 ast_rtp_instance_new: RTP instance '0x1907098' is setup and ready to go
[Jun  5 16:56:25] DEBUG[16221]: res_rtp_asterisk.c:2541 ast_rtp_prop_set: Setup RTCP on RTP instance '0x1907098'
  == Using SIP RTP CoS mark 5
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:5471 do_setnat: Setting NAT on RTP to On
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:9313 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED.
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:9313 process_sdp: Processing session-level SDP o=FreeSWITCH 1370422795 1370422796 IN IP4 1.1.1.1... OK.
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:9313 process_sdp: Processing session-level SDP s=FreeSWITCH... UNSUPPORTED OR FAILED.
[Jun  5 16:56:25] DEBUG[16221]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '1.1.1.1' into...
[Jun  5 16:56:25] DEBUG[16221]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '1.1.1.1' and port ''.
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:9313 process_sdp: Processing session-level SDP c=IN IP4 1.1.1.1... OK.
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:9313 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED.
[Jun  5 16:56:25] DEBUG[16221]: rtp_engine.c:541 ast_rtp_codecs_payloads_set_m_type: Setting payload 8 based on m type on 0x7f6023f8c070
[Jun  5 16:56:25] DEBUG[16221]: rtp_engine.c:541 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0x7f6023f8c070
[Jun  5 16:56:25] DEBUG[16221]: rtp_engine.c:541 ast_rtp_codecs_payloads_set_m_type: Setting payload 13 based on m type on 0x7f6023f8c070
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:9585 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:9585 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED OR FAILED.
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:9585 process_sdp: Processing media-level (audio) SDP a=ptime:20... OK.
[Jun  5 16:56:25] DEBUG[16221]: rtp_engine.c:644 ast_rtp_codecs_payload_formats: Incorporating payload 8 on 0x7f6023f8c070
[Jun  5 16:56:25] DEBUG[16221]: rtp_engine.c:644 ast_rtp_codecs_payload_formats: Incorporating payload 13 on 0x7f6023f8c070
[Jun  5 16:56:25] DEBUG[16221]: rtp_engine.c:644 ast_rtp_codecs_payload_formats: Incorporating payload 101 on 0x7f6023f8c070
[Jun  5 16:56:25] DEBUG[16221]: res_rtp_asterisk.c:2581 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x1907098'
[Jun  5 16:56:25] DEBUG[16221]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 8 from 0x7f6023f8c070 to 0x1907260
[Jun  5 16:56:25] DEBUG[16221]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 13 from 0x7f6023f8c070 to 0x1907260
[Jun  5 16:56:25] DEBUG[16221]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 101 from 0x7f6023f8c070 to 0x1907260
[Jun  5 16:56:25] DEBUG[16221]: res_rtp_asterisk.c:2507 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x1907098'
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:9839 process_sdp: We're settling with these formats: 0x8 (alaw)
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:23330 handle_request_invite: Checking SIP call limits for device 
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:6297 update_call_counter: Updating call counter for incoming call
[Jun  5 16:56:25] DEBUG[16221]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting 'tdev04.tdev.example.com' into...
[Jun  5 16:56:25] DEBUG[16221]: netsock2.c:192 ast_sockaddr_split_hostport: ...host 'tdev04.tdev.example.com' and port ''.
[Jun  5 16:56:25] DEBUG[16221]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '1.1.1.1' into...
[Jun  5 16:56:25] DEBUG[16221]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '1.1.1.1' and port ''.
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:7483 sip_new: *** Our native formats are 0x8 (alaw) 
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:7484 sip_new: *** Joint capabilities are 0x8 (alaw) 
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:7485 sip_new: *** Our capabilities are 0x8 (alaw) 
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:7486 sip_new: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) 
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:7516 sip_new: This channel will not be able to handle video.
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:14805 build_route: build_route: Contact hop: <sip:mod_sofia@1.1.1.1:5060>
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:23445 handle_request_invite: Incoming INVITE with 'timer' option supported
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:23454 handle_request_invite: INVITE also has "Session-Expires" header.
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:26797 parse_session_expires: Session-Expires: 1800
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:26810 parse_session_expires: Refresher: UAC
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:23471 handle_request_invite: INVITE also has "Min-SE" header.
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:26767 parse_minse: Received Min-SE: 120
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:26676 start_session_timer: Session timer started: 169 - ef9ce4dc-4892-1231-3b9b-fe38fc8f3ce1
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:23639 handle_request_invite: SIP/1.1.1.1-0000001c: New call is still down.... Trying... 
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:3684 __sip_xmit: Trying to put 'SIP/2.0 100' onto UDP socket destined for 1.1.1.1:5060
[Jun  5 16:56:25] DEBUG[16197]: devicestate.c:344 _ast_device_state: No provider found, checking channel drivers for SIP - 1.1.1.1
[Jun  5 16:56:25] DEBUG[16197]: chan_sip.c:27119 sip_devicestate: Checking device state for peer 1.1.1.1
[Jun  5 16:56:25] DEBUG[16197]: devicestate.c:467 do_state_change: Changing state for SIP/1.1.1.1 - state 4 (Invalid)
[Jun  5 16:56:25] DEBUG[16197]: devicestate.c:442 devstate_event: device 'SIP/1.1.1.1' state '4'
[Jun  5 16:56:25] DEBUG[18430]: pbx.c:4470 pbx_extension_helper: Launching 'SIPAddHeader'
    -- Executing [1000@default:1] SIPAddHeader("SIP/1.1.1.1-0000001c", "X-Asterisk-CONFERENCE: K9999-0001,USER,K9999CALLGEN,en") in new stack
[Jun  5 16:56:25] DEBUG[18430]: pbx.c:4470 pbx_extension_helper: Launching 'SIPAddHeader'
    -- Executing [1000@default:2] SIPAddHeader("SIP/1.1.1.1-0000001c", "X-Asterisk-CUSTOMER: K9999") in new stack
[Jun  5 16:56:25] DEBUG[18430]: pbx.c:4470 pbx_extension_helper: Launching 'SIPAddHeader'
    -- Executing [1000@default:3] SIPAddHeader("SIP/1.1.1.1-0000001c", "X-Asterisk-CUSTOMER_ID: 7") in new stack
[Jun  5 16:56:25] DEBUG[18430]: pbx.c:4470 pbx_extension_helper: Launching 'Dial'
    -- Executing [1000@default:4] Dial("SIP/1.1.1.1-0000001c", "SIP/*780001@CONF02-PILOT,,t") in new stack
[Jun  5 16:56:25] DEBUG[18430]: chan_sip.c:27223 sip_request_call: Asked to create a SIP channel with formats: 0x8 (alaw)
[Jun  5 16:56:25] DEBUG[18430]: chan_sip.c:8195 sip_alloc: Allocating new SIP dialog for 62020dcd5f18bb191deb05b013b898fb@2.2.2.2:5060 - INVITE (No RTP)
[Jun  5 16:56:25] DEBUG[18430]: rtp_engine.c:350 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x1896e28'
[Jun  5 16:56:25] DEBUG[18430]: res_rtp_asterisk.c:558 ast_rtp_new: Allocated port 13884 for RTP instance '0x1896e28'
[Jun  5 16:56:25] DEBUG[18430]: rtp_engine.c:359 ast_rtp_instance_new: RTP instance '0x1896e28' is setup and ready to go
[Jun  5 16:56:25] DEBUG[18430]: res_rtp_asterisk.c:2541 ast_rtp_prop_set: Setup RTCP on RTP instance '0x1896e28'
  == Using SIP RTP CoS mark 5
[Jun  5 16:56:25] DEBUG[18430]: chan_sip.c:5471 do_setnat: Setting NAT on RTP to On
[Jun  5 16:56:25] DEBUG[18430]: acl.c:736 ast_ouraddrfor: For destination '3.3.3.3', our source address is '2.2.2.2'.
[Jun  5 16:56:25] DEBUG[18430]: chan_sip.c:3836 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 2.2.2.2:5060
[Jun  5 16:56:25] DEBUG[18430]: chan_sip.c:8021 change_callid_pvt: SIP call-id changed from '62020dcd5f18bb191deb05b013b898fb@2.2.2.2:5060' to '4e26979371737ed82e99e378241ec665@2.2.2.2:5060'
[Jun  5 16:56:25] DEBUG[18430]: chan_sip.c:7483 sip_new: *** Our native formats are 0x8 (alaw) 
[Jun  5 16:56:25] DEBUG[18430]: chan_sip.c:7484 sip_new: *** Joint capabilities are 0x8 (alaw) 
[Jun  5 16:56:25] DEBUG[18430]: chan_sip.c:7485 sip_new: *** Our capabilities are 0x8 (alaw) 
[Jun  5 16:56:25] DEBUG[18430]: chan_sip.c:7486 sip_new: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) 
[Jun  5 16:56:25] DEBUG[18430]: chan_sip.c:7488 sip_new: *** Our preferred formats from the incoming channel are 0x8 (alaw) 
[Jun  5 16:56:25] DEBUG[18430]: chan_sip.c:7516 sip_new: This channel will not be able to handle video.
[Jun  5 16:56:25] DEBUG[18430]: rtp_engine.c:1494 ast_rtp_instance_early_bridge_make_compatible: Seeded SDP of 'SIP/CONF02-PILOT-0000001d' with that of 'SIP/1.1.1.1-0000001c'
[Jun  5 16:56:25] DEBUG[18430]: channel.c:6232 ast_channel_inherit_variables: Not copying variable DIALEDTIME.
[Jun  5 16:56:25] DEBUG[18430]: channel.c:6232 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME.
[Jun  5 16:56:25] DEBUG[18430]: channel.c:6232 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME.
[Jun  5 16:56:25] DEBUG[18430]: channel.c:6232 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER.
[Jun  5 16:56:25] DEBUG[18430]: channel.c:6232 ast_channel_inherit_variables: Not copying variable DIALSTATUS.
[Jun  5 16:56:25] DEBUG[18430]: channel.c:6228 ast_channel_inherit_variables: Copying hard-transferable variable SIPADDHEADER03.
[Jun  5 16:56:25] DEBUG[18430]: channel.c:6228 ast_channel_inherit_variables: Copying hard-transferable variable SIPADDHEADER02.
[Jun  5 16:56:25] DEBUG[18430]: channel.c:6228 ast_channel_inherit_variables: Copying hard-transferable variable SIPADDHEADER01.
[Jun  5 16:56:25] DEBUG[18430]: channel.c:6232 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[Jun  5 16:56:25] DEBUG[18430]: channel.c:6232 ast_channel_inherit_variables: Not copying variable SIPDOMAIN.
[Jun  5 16:56:25] DEBUG[18430]: channel.c:6232 ast_channel_inherit_variables: Not copying variable SIPURI.
[Jun  5 16:56:25] DEBUG[18430]: chan_sip.c:6014 sip_call: Outgoing Call for *780001
[Jun  5 16:56:25] DEBUG[18430]: chan_sip.c:6297 update_call_counter: Updating call counter for outgoing call
[Jun  5 16:56:25] DEBUG[18430]: chan_sip.c:11852 add_sdp: ** Our capability: 0x8 (alaw) Video flag: False Text flag: False
[Jun  5 16:56:25] DEBUG[18430]: chan_sip.c:11853 add_sdp: ** Our prefcodec: 0x8 (alaw) 
[Jun  5 16:56:25] DEBUG[18430]: chan_sip.c:11962 add_sdp: -- Done with adding codecs to SDP
[Jun  5 16:56:25] DEBUG[18430]: chan_sip.c:12148 add_sdp: Done building SDP. Settling with this capability: 0x8 (alaw)
[Jun  5 16:56:25] DEBUG[18430]: chan_sip.c:3360 initialize_initreq: Initializing initreq for method INVITE - callid 4e26979371737ed82e99e378241ec665@2.2.2.2:5060
[Jun  5 16:56:25] DEBUG[18430]: chan_sip.c:3684 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 3.3.3.3:5060
    -- Called SIP/*780001@CONF02-PILOT
[Jun  5 16:56:25] DEBUG[16231]: app_queue.c:1544 handle_statechange: Device 'SIP/1.1.1.1' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:8515 find_call: = Looking for  Call ID: 4e26979371737ed82e99e378241ec665@2.2.2.2:5060 (Checking To) --From tag as63d0280d --To-tag   
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:4409 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '4e26979371737ed82e99e378241ec665@2.2.2.2:5060' Request 102: Found
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:20653 handle_response_invite: SIP response 100 to standard invite
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:8515 find_call: = Looking for  Call ID: 4e26979371737ed82e99e378241ec665@2.2.2.2:5060 (Checking To) --From tag as63d0280d --To-tag p8cZav87XHXZQ  
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:4330 __sip_ack: Acked pending invite 102
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:4368 __sip_ack: Stopping retransmission on '4e26979371737ed82e99e378241ec665@2.2.2.2:5060' of Request 102: Match Found
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:20653 handle_response_invite: SIP response 407 to standard invite
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:3684 __sip_xmit: Trying to put 'ACK sip:*78' onto UDP socket destined for 3.3.3.3:5060
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:19790 do_proxy_auth: Auth attempt 1 on INVITE
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:11852 add_sdp: ** Our capability: 0x8 (alaw) Video flag: False Text flag: False
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:11853 add_sdp: ** Our prefcodec: 0x8 (alaw) 
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:11962 add_sdp: -- Done with adding codecs to SDP
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:12148 add_sdp: Done building SDP. Settling with this capability: 0x8 (alaw)
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:3684 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 3.3.3.3:5060
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:8515 find_call: = Looking for  Call ID: 4e26979371737ed82e99e378241ec665@2.2.2.2:5060 (Checking To) --From tag as63d0280d --To-tag   
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:4409 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '4e26979371737ed82e99e378241ec665@2.2.2.2:5060' Request 103: Found
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:20653 handle_response_invite: SIP response 100 to standard invite
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:8515 find_call: = Looking for  Call ID: 4e26979371737ed82e99e378241ec665@2.2.2.2:5060 (Checking To) --From tag as63d0280d --To-tag QH6QcQSBUtKjK  
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:4330 __sip_ack: Acked pending invite 103
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:4368 __sip_ack: Stopping retransmission on '4e26979371737ed82e99e378241ec665@2.2.2.2:5060' of Request 103: Match Found
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:20653 handle_response_invite: SIP response 200 to standard invite
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:9313 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED.
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:9313 process_sdp: Processing session-level SDP o=FreeSWITCH 1370421849 1370421850 IN IP4 3.3.3.3... OK.
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:9313 process_sdp: Processing session-level SDP s=FreeSWITCH... UNSUPPORTED OR FAILED.
[Jun  5 16:56:25] DEBUG[16221]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '3.3.3.3' into...
[Jun  5 16:56:25] DEBUG[16221]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '3.3.3.3' and port ''.
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:9313 process_sdp: Processing session-level SDP c=IN IP4 3.3.3.3... OK.
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:9313 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED.
[Jun  5 16:56:25] DEBUG[16221]: rtp_engine.c:541 ast_rtp_codecs_payloads_set_m_type: Setting payload 8 based on m type on 0x7f6023f8cad0
[Jun  5 16:56:25] DEBUG[16221]: rtp_engine.c:541 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0x7f6023f8cad0
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:9585 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:9585 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:9585 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED OR FAILED.
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:9585 process_sdp: Processing media-level (audio) SDP a=silenceSupp:off - - - -... UNSUPPORTED OR FAILED.
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:9585 process_sdp: Processing media-level (audio) SDP a=ptime:20... OK.
[Jun  5 16:56:25] DEBUG[16221]: rtp_engine.c:644 ast_rtp_codecs_payload_formats: Incorporating payload 8 on 0x7f6023f8cad0
[Jun  5 16:56:25] DEBUG[16221]: rtp_engine.c:644 ast_rtp_codecs_payload_formats: Incorporating payload 101 on 0x7f6023f8cad0
[Jun  5 16:56:25] DEBUG[16221]: res_rtp_asterisk.c:2581 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x1896e28'
[Jun  5 16:56:25] DEBUG[16221]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 8 from 0x7f6023f8cad0 to 0x1896ff0
[Jun  5 16:56:25] DEBUG[16221]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 101 from 0x7f6023f8cad0 to 0x1896ff0
[Jun  5 16:56:25] DEBUG[16221]: res_rtp_asterisk.c:2507 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x1896e28'
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:9839 process_sdp: We're settling with these formats: 0x8 (alaw)
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:9844 process_sdp: We have an owner, now see if we need to change this call
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:6297 update_call_counter: Updating call counter for outgoing call
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:14805 build_route: build_route: Contact hop: <sip:*780001@3.3.3.3:5060;transport=udp>
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:26797 parse_session_expires: Session-Expires: 1800
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:26810 parse_session_expires: Refresher: UAC
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:26676 start_session_timer: Session timer started: 174 - 4e26979371737ed82e99e378241ec665@2.2.2.2:5060
[Jun  5 16:56:25] DEBUG[16221]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '3.3.3.3:5060' into...
[Jun  5 16:56:25] DEBUG[16221]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '3.3.3.3' and port '5060'.
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:3684 __sip_xmit: Trying to put 'ACK sip:*78' onto UDP socket destined for 3.3.3.3:5060
    -- SIP/CONF02-PILOT-0000001d answered SIP/1.1.1.1-0000001c
[Jun  5 16:56:25] DEBUG[18430]: chan_sip.c:6884 sip_answer: SIP answering channel: SIP/1.1.1.1-0000001c
[Jun  5 16:56:25] DEBUG[18430]: res_rtp_asterisk.c:832 ast_rtp_update_source: Setting the marker bit due to a source update
[Jun  5 16:56:25] DEBUG[18430]: chan_sip.c:12255 transmit_response_with_sdp: Setting framing from config on incoming call
[Jun  5 16:56:25] DEBUG[18430]: chan_sip.c:11852 add_sdp: ** Our capability: 0x8 (alaw) Video flag: True Text flag: True
[Jun  5 16:56:25] DEBUG[18430]: chan_sip.c:11853 add_sdp: ** Our prefcodec: 0x0 (nothing) 
[Jun  5 16:56:25] DEBUG[18430]: chan_sip.c:11962 add_sdp: -- Done with adding codecs to SDP
[Jun  5 16:56:25] DEBUG[18430]: chan_sip.c:12148 add_sdp: Done building SDP. Settling with this capability: 0x8 (alaw)
[Jun  5 16:56:25] DEBUG[18430]: chan_sip.c:3684 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 1.1.1.1:5060
[Jun  5 16:56:25] DEBUG[18430]: features.c:4075 ast_bridge_call: bridge answer set, chan answer set
[Jun  5 16:56:25] DEBUG[18430]: features.c:3896 clear_dialed_interfaces: Removing dialed interfaces datastore on SIP/CONF02-PILOT-0000001d since we're bridging
[Jun  5 16:56:25] DEBUG[18430]: res_rtp_asterisk.c:832 ast_rtp_update_source: Setting the marker bit due to a source update
[Jun  5 16:56:25] DEBUG[18430]: res_rtp_asterisk.c:832 ast_rtp_update_source: Setting the marker bit due to a source update
[Jun  5 16:56:25] DEBUG[16197]: devicestate.c:344 _ast_device_state: No provider found, checking channel drivers for SIP - CONF02-PILOT
[Jun  5 16:56:25] DEBUG[16197]: chan_sip.c:27119 sip_devicestate: Checking device state for peer CONF02-PILOT
[Jun  5 16:56:25] DEBUG[16197]: devicestate.c:467 do_state_change: Changing state for SIP/CONF02-PILOT - state 1 (Not in use)
[Jun  5 16:56:25] DEBUG[16197]: devicestate.c:442 devstate_event: device 'SIP/CONF02-PILOT' state '1'
[Jun  5 16:56:25] DEBUG[16197]: devicestate.c:344 _ast_device_state: No provider found, checking channel drivers for SIP - 1.1.1.1
[Jun  5 16:56:25] DEBUG[16197]: chan_sip.c:27119 sip_devicestate: Checking device state for peer 1.1.1.1
[Jun  5 16:56:25] DEBUG[16197]: devicestate.c:467 do_state_change: Changing state for SIP/1.1.1.1 - state 4 (Invalid)
[Jun  5 16:56:25] DEBUG[16197]: devicestate.c:442 devstate_event: device 'SIP/1.1.1.1' state '4'
[Jun  5 16:56:25] DEBUG[16231]: app_queue.c:1544 handle_statechange: Device 'SIP/CONF02-PILOT' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jun  5 16:56:25] DEBUG[16231]: app_queue.c:1544 handle_statechange: Device 'SIP/1.1.1.1' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:8515 find_call: = Looking for  Call ID: ef9ce4dc-4892-1231-3b9b-fe38fc8f3ce1 (Checking From) --From tag UraQZSH8SSy7N --To-tag as43d9d9c6  
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:25813 handle_incoming: **** Received ACK (6) - Command in SIP ACK
[Jun  5 16:56:25] DEBUG[16221]: chan_sip.c:4368 __sip_ack: Stopping retransmission on 'ef9ce4dc-4892-1231-3b9b-fe38fc8f3ce1' of Response 44886028: Match Found
[Jun  5 16:56:25] DEBUG[18430]: res_rtp_asterisk.c:2190 ast_rtp_read: 0x189d310 -- start learning mode pass with addr = 3.3.3.3:22336
[Jun  5 16:56:25] DEBUG[18430]: res_rtp_asterisk.c:502 rtp_learning_rtp_seq_update: 0x189d310 -- probation = 4, seq = 45340
[Jun  5 16:56:25] DEBUG[18430]: res_rtp_asterisk.c:2196 ast_rtp_read: 0x189d310 -- Condition for learning hasn't exited, so reject the frame.
[Jun  5 16:56:25] DEBUG[18430]: res_rtp_asterisk.c:2190 ast_rtp_read: 0x189d310 -- start learning mode pass with addr = 3.3.3.3:22336
[Jun  5 16:56:25] DEBUG[18430]: res_rtp_asterisk.c:502 rtp_learning_rtp_seq_update: 0x189d310 -- probation = 3, seq = 45341
[Jun  5 16:56:25] DEBUG[18430]: res_rtp_asterisk.c:2196 ast_rtp_read: 0x189d310 -- Condition for learning hasn't exited, so reject the frame.
[Jun  5 16:56:25] DEBUG[18430]: res_rtp_asterisk.c:2190 ast_rtp_read: 0x1903930 -- start learning mode pass with addr = 1.1.1.1:21390
[Jun  5 16:56:25] DEBUG[18430]: res_rtp_asterisk.c:502 rtp_learning_rtp_seq_update: 0x1903930 -- probation = 4, seq = 43132
[Jun  5 16:56:25] DEBUG[18430]: res_rtp_asterisk.c:2196 ast_rtp_read: 0x1903930 -- Condition for learning hasn't exited, so reject the frame.
[Jun  5 16:56:25] DEBUG[18430]: res_rtp_asterisk.c:2190 ast_rtp_read: 0x1903930 -- start learning mode pass with addr = 1.1.1.1:21390
[Jun  5 16:56:25] DEBUG[18430]: res_rtp_asterisk.c:502 rtp_learning_rtp_seq_update: 0x1903930 -- probation = 3, seq = 43133
[Jun  5 16:56:25] DEBUG[18430]: res_rtp_asterisk.c:2196 ast_rtp_read: 0x1903930 -- Condition for learning hasn't exited, so reject the frame.
[Jun  5 16:56:25] DEBUG[18430]: res_rtp_asterisk.c:2190 ast_rtp_read: 0x189d310 -- start learning mode pass with addr = 3.3.3.3:22336
[Jun  5 16:56:25] DEBUG[18430]: res_rtp_asterisk.c:502 rtp_learning_rtp_seq_update: 0x189d310 -- probation = 2, seq = 45342
[Jun  5 16:56:25] DEBUG[18430]: res_rtp_asterisk.c:2196 ast_rtp_read: 0x189d310 -- Condition for learning hasn't exited, so reject the frame.
[Jun  5 16:56:25] DEBUG[18430]: res_rtp_asterisk.c:2190 ast_rtp_read: 0x1903930 -- start learning mode pass with addr = 1.1.1.1:21390
[Jun  5 16:56:25] DEBUG[18430]: res_rtp_asterisk.c:502 rtp_learning_rtp_seq_update: 0x1903930 -- probation = 2, seq = 43134
[Jun  5 16:56:25] DEBUG[18430]: res_rtp_asterisk.c:2196 ast_rtp_read: 0x1903930 -- Condition for learning hasn't exited, so reject the frame.
[Jun  5 16:56:25] DEBUG[18430]: res_rtp_asterisk.c:2190 ast_rtp_read: 0x189d310 -- start learning mode pass with addr = 3.3.3.3:22336
[Jun  5 16:56:25] DEBUG[18430]: res_rtp_asterisk.c:502 rtp_learning_rtp_seq_update: 0x189d310 -- probation = 1, seq = 45343
[Jun  5 16:56:25] DEBUG[18430]: res_rtp_asterisk.c:2200 ast_rtp_read: 0x189d310 -- Probation Ended. Set strict_rtp_state to STRICT_RTP_CLOSED with address 3.3.3.3:22336
[Jun  5 16:56:25] DEBUG[18430]: res_rtp_asterisk.c:1363 ast_rtp_write: Ooh, format changed from unknown to alaw
[Jun  5 16:56:25] DEBUG[18430]: res_rtp_asterisk.c:1394 ast_rtp_write: Created smoother: format: alaw ms: 20 len: 160
[Jun  5 16:56:25] DEBUG[18430]: res_rtp_asterisk.c:1259 ast_rtp_raw_write: Starting RTCP transmission on RTP instance '0x1907098'
[Jun  5 16:56:25] DEBUG[18430]: res_rtp_asterisk.c:2190 ast_rtp_read: 0x1903930 -- start learning mode pass with addr = 1.1.1.1:21390
[Jun  5 16:56:25] DEBUG[18430]: res_rtp_asterisk.c:502 rtp_learning_rtp_seq_update: 0x1903930 -- probation = 1, seq = 43135
[Jun  5 16:56:25] DEBUG[18430]: res_rtp_asterisk.c:2200 ast_rtp_read: 0x1903930 -- Probation Ended. Set strict_rtp_state to STRICT_RTP_CLOSED with address 1.1.1.1:21390
[Jun  5 16:56:25] DEBUG[18430]: res_rtp_asterisk.c:1363 ast_rtp_write: Ooh, format changed from unknown to alaw
[Jun  5 16:56:25] DEBUG[18430]: res_rtp_asterisk.c:1394 ast_rtp_write: Created smoother: format: alaw ms: 20 len: 160
[Jun  5 16:56:32] DEBUG[16221]: chan_sip.c:4224 __sip_autodestruct: Auto destroying SIP dialog '179ec65452ee5fbd69c712ef7aab5aec@2.2.2.2:5060'
[Jun  5 16:56:32] DEBUG[16221]: chan_sip.c:6445 sip_destroy: Destroying SIP dialog 179ec65452ee5fbd69c712ef7aab5aec@2.2.2.2:5060
[Jun  5 16:56:32] DEBUG[16221]: rtp_engine.c:298 instance_destructor: Destroyed RTP instance '0x18d66c8'
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:8515 find_call: = Looking for  Call ID: fbc8d639-4892-1231-3b9b-fe38fc8f3ce1 (Checking From) --From tag v13F1m2BQ2mtH --To-tag   
[Jun  5 16:56:46] DEBUG[16221]: acl.c:736 ast_ouraddrfor: For destination '1.1.1.1', our source address is '2.2.2.2'.
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:3836 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 2.2.2.2:5060
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:8195 sip_alloc: Allocating new SIP dialog for fbc8d639-4892-1231-3b9b-fe38fc8f3ce1 - INVITE (No RTP)
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:25813 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE
[Jun  5 16:56:46] DEBUG[16221]: sip/reqresp_parser.c:1603 parse_sip_options: Begin: parsing SIP "Supported: timer, precondition, path, replaces"
[Jun  5 16:56:46] DEBUG[16221]: sip/reqresp_parser.c:1619 parse_sip_options: Found SIP option: -timer-
[Jun  5 16:56:46] DEBUG[16221]: sip/reqresp_parser.c:1627 parse_sip_options: Matched SIP option: timer
[Jun  5 16:56:46] DEBUG[16221]: sip/reqresp_parser.c:1619 parse_sip_options: Found SIP option: -precondition-
[Jun  5 16:56:46] DEBUG[16221]: sip/reqresp_parser.c:1627 parse_sip_options: Matched SIP option: precondition
[Jun  5 16:56:46] DEBUG[16221]: sip/reqresp_parser.c:1619 parse_sip_options: Found SIP option: -path-
[Jun  5 16:56:46] DEBUG[16221]: sip/reqresp_parser.c:1627 parse_sip_options: Matched SIP option: path
[Jun  5 16:56:46] DEBUG[16221]: sip/reqresp_parser.c:1619 parse_sip_options: Found SIP option: -replaces-
[Jun  5 16:56:46] DEBUG[16221]: sip/reqresp_parser.c:1627 parse_sip_options: Matched SIP option: replaces
[Jun  5 16:56:46] DEBUG[16221]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '1.1.1.1' into...
[Jun  5 16:56:46] DEBUG[16221]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '1.1.1.1' and port ''.
[Jun  5 16:56:46] DEBUG[16221]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '1.1.1.1' into...
[Jun  5 16:56:46] DEBUG[16221]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '1.1.1.1' and port ''.
[Jun  5 16:56:46] DEBUG[16221]: rtp_engine.c:350 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x18e6738'
[Jun  5 16:56:46] DEBUG[16221]: res_rtp_asterisk.c:558 ast_rtp_new: Allocated port 19672 for RTP instance '0x18e6738'
[Jun  5 16:56:46] DEBUG[16221]: rtp_engine.c:359 ast_rtp_instance_new: RTP instance '0x18e6738' is setup and ready to go
[Jun  5 16:56:46] DEBUG[16221]: res_rtp_asterisk.c:2541 ast_rtp_prop_set: Setup RTCP on RTP instance '0x18e6738'
  == Using SIP RTP CoS mark 5
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:5471 do_setnat: Setting NAT on RTP to On
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:9313 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED.
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:9313 process_sdp: Processing session-level SDP o=FreeSWITCH 1370421436 1370421437 IN IP4 1.1.1.1... OK.
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:9313 process_sdp: Processing session-level SDP s=FreeSWITCH... UNSUPPORTED OR FAILED.
[Jun  5 16:56:46] DEBUG[16221]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '1.1.1.1' into...
[Jun  5 16:56:46] DEBUG[16221]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '1.1.1.1' and port ''.
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:9313 process_sdp: Processing session-level SDP c=IN IP4 1.1.1.1... OK.
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:9313 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED.
[Jun  5 16:56:46] DEBUG[16221]: rtp_engine.c:541 ast_rtp_codecs_payloads_set_m_type: Setting payload 8 based on m type on 0x7f6023f8c070
[Jun  5 16:56:46] DEBUG[16221]: rtp_engine.c:541 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0x7f6023f8c070
[Jun  5 16:56:46] DEBUG[16221]: rtp_engine.c:541 ast_rtp_codecs_payloads_set_m_type: Setting payload 13 based on m type on 0x7f6023f8c070
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:9585 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:9585 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED OR FAILED.
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:9585 process_sdp: Processing media-level (audio) SDP a=ptime:20... OK.
[Jun  5 16:56:46] DEBUG[16221]: rtp_engine.c:644 ast_rtp_codecs_payload_formats: Incorporating payload 8 on 0x7f6023f8c070
[Jun  5 16:56:46] DEBUG[16221]: rtp_engine.c:644 ast_rtp_codecs_payload_formats: Incorporating payload 13 on 0x7f6023f8c070
[Jun  5 16:56:46] DEBUG[16221]: rtp_engine.c:644 ast_rtp_codecs_payload_formats: Incorporating payload 101 on 0x7f6023f8c070
[Jun  5 16:56:46] DEBUG[16221]: res_rtp_asterisk.c:2581 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x18e6738'
[Jun  5 16:56:46] DEBUG[16221]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 8 from 0x7f6023f8c070 to 0x18e6900
[Jun  5 16:56:46] DEBUG[16221]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 13 from 0x7f6023f8c070 to 0x18e6900
[Jun  5 16:56:46] DEBUG[16221]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 101 from 0x7f6023f8c070 to 0x18e6900
[Jun  5 16:56:46] DEBUG[16221]: res_rtp_asterisk.c:2507 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x18e6738'
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:9839 process_sdp: We're settling with these formats: 0x8 (alaw)
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:23330 handle_request_invite: Checking SIP call limits for device 
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:6297 update_call_counter: Updating call counter for incoming call
[Jun  5 16:56:46] DEBUG[16221]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting 'tdev04.tdev.example.com' into...
[Jun  5 16:56:46] DEBUG[16221]: netsock2.c:192 ast_sockaddr_split_hostport: ...host 'tdev04.tdev.example.com' and port ''.
[Jun  5 16:56:46] DEBUG[16221]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '1.1.1.1' into...
[Jun  5 16:56:46] DEBUG[16221]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '1.1.1.1' and port ''.
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:7483 sip_new: *** Our native formats are 0x8 (alaw) 
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:7484 sip_new: *** Joint capabilities are 0x8 (alaw) 
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:7485 sip_new: *** Our capabilities are 0x8 (alaw) 
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:7486 sip_new: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) 
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:7516 sip_new: This channel will not be able to handle video.
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:14805 build_route: build_route: Contact hop: <sip:mod_sofia@1.1.1.1:5060>
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:23445 handle_request_invite: Incoming INVITE with 'timer' option supported
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:23454 handle_request_invite: INVITE also has "Session-Expires" header.
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:26797 parse_session_expires: Session-Expires: 1800
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:26810 parse_session_expires: Refresher: UAC
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:23471 handle_request_invite: INVITE also has "Min-SE" header.
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:26767 parse_minse: Received Min-SE: 120
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:26676 start_session_timer: Session timer started: 178 - fbc8d639-4892-1231-3b9b-fe38fc8f3ce1
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:23639 handle_request_invite: SIP/1.1.1.1-0000001e: New call is still down.... Trying... 
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:3684 __sip_xmit: Trying to put 'SIP/2.0 100' onto UDP socket destined for 1.1.1.1:5060
[Jun  5 16:56:46] DEBUG[16197]: devicestate.c:344 _ast_device_state: No provider found, checking channel drivers for SIP - 1.1.1.1
[Jun  5 16:56:46] DEBUG[16197]: chan_sip.c:27119 sip_devicestate: Checking device state for peer 1.1.1.1
[Jun  5 16:56:46] DEBUG[16197]: devicestate.c:467 do_state_change: Changing state for SIP/1.1.1.1 - state 4 (Invalid)
[Jun  5 16:56:46] DEBUG[16197]: devicestate.c:442 devstate_event: device 'SIP/1.1.1.1' state '4'
[Jun  5 16:56:46] DEBUG[18469]: pbx.c:4470 pbx_extension_helper: Launching 'SIPAddHeader'
    -- Executing [2000@default:1] SIPAddHeader("SIP/1.1.1.1-0000001e", "X-Asterisk-CONFERENCE: K9999-0001,USER,K9999CALLGEN,en") in new stack
[Jun  5 16:56:46] DEBUG[18469]: pbx.c:4470 pbx_extension_helper: Launching 'SIPAddHeader'
    -- Executing [2000@default:2] SIPAddHeader("SIP/1.1.1.1-0000001e", "X-Asterisk-CUSTOMER: K9999") in new stack
[Jun  5 16:56:46] DEBUG[18469]: pbx.c:4470 pbx_extension_helper: Launching 'SIPAddHeader'
    -- Executing [2000@default:3] SIPAddHeader("SIP/1.1.1.1-0000001e", "X-Asterisk-CUSTOMER_ID: 7") in new stack
[Jun  5 16:56:46] DEBUG[18469]: pbx.c:4470 pbx_extension_helper: Launching 'Dial'
    -- Executing [2000@default:4] Dial("SIP/1.1.1.1-0000001e", "SIP/*780001@CONF02-PILOT,,t") in new stack
[Jun  5 16:56:46] DEBUG[18469]: chan_sip.c:27223 sip_request_call: Asked to create a SIP channel with formats: 0x8 (alaw)
[Jun  5 16:56:46] DEBUG[18469]: chan_sip.c:8195 sip_alloc: Allocating new SIP dialog for 5e438f8d79cf4a5a02285d2b5e1f9553@2.2.2.2:5060 - INVITE (No RTP)
[Jun  5 16:56:46] DEBUG[18469]: rtp_engine.c:350 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x18bd528'
[Jun  5 16:56:46] DEBUG[18469]: res_rtp_asterisk.c:558 ast_rtp_new: Allocated port 16072 for RTP instance '0x18bd528'
[Jun  5 16:56:46] DEBUG[18469]: rtp_engine.c:359 ast_rtp_instance_new: RTP instance '0x18bd528' is setup and ready to go
[Jun  5 16:56:46] DEBUG[18469]: res_rtp_asterisk.c:2541 ast_rtp_prop_set: Setup RTCP on RTP instance '0x18bd528'
  == Using SIP RTP CoS mark 5
[Jun  5 16:56:46] DEBUG[18469]: chan_sip.c:5471 do_setnat: Setting NAT on RTP to On
[Jun  5 16:56:46] DEBUG[18469]: acl.c:736 ast_ouraddrfor: For destination '3.3.3.3', our source address is '2.2.2.2'.
[Jun  5 16:56:46] DEBUG[18469]: chan_sip.c:3836 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 2.2.2.2:5060
[Jun  5 16:56:46] DEBUG[18469]: chan_sip.c:8021 change_callid_pvt: SIP call-id changed from '5e438f8d79cf4a5a02285d2b5e1f9553@2.2.2.2:5060' to '62124ba076dbbeb2696f02420563bb7c@2.2.2.2:5060'
[Jun  5 16:56:46] DEBUG[18469]: chan_sip.c:7483 sip_new: *** Our native formats are 0x8 (alaw) 
[Jun  5 16:56:46] DEBUG[18469]: chan_sip.c:7484 sip_new: *** Joint capabilities are 0x8 (alaw) 
[Jun  5 16:56:46] DEBUG[18469]: chan_sip.c:7485 sip_new: *** Our capabilities are 0x8 (alaw) 
[Jun  5 16:56:46] DEBUG[18469]: chan_sip.c:7486 sip_new: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) 
[Jun  5 16:56:46] DEBUG[18469]: chan_sip.c:7488 sip_new: *** Our preferred formats from the incoming channel are 0x8 (alaw) 
[Jun  5 16:56:46] DEBUG[18469]: chan_sip.c:7516 sip_new: This channel will not be able to handle video.
[Jun  5 16:56:46] DEBUG[18469]: rtp_engine.c:1494 ast_rtp_instance_early_bridge_make_compatible: Seeded SDP of 'SIP/CONF02-PILOT-0000001f' with that of 'SIP/1.1.1.1-0000001e'
[Jun  5 16:56:46] DEBUG[18469]: channel.c:6232 ast_channel_inherit_variables: Not copying variable DIALEDTIME.
[Jun  5 16:56:46] DEBUG[18469]: channel.c:6232 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME.
[Jun  5 16:56:46] DEBUG[18469]: channel.c:6232 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME.
[Jun  5 16:56:46] DEBUG[18469]: channel.c:6232 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER.
[Jun  5 16:56:46] DEBUG[18469]: channel.c:6232 ast_channel_inherit_variables: Not copying variable DIALSTATUS.
[Jun  5 16:56:46] DEBUG[18469]: channel.c:6228 ast_channel_inherit_variables: Copying hard-transferable variable SIPADDHEADER03.
[Jun  5 16:56:46] DEBUG[18469]: channel.c:6228 ast_channel_inherit_variables: Copying hard-transferable variable SIPADDHEADER02.
[Jun  5 16:56:46] DEBUG[18469]: channel.c:6228 ast_channel_inherit_variables: Copying hard-transferable variable SIPADDHEADER01.
[Jun  5 16:56:46] DEBUG[18469]: channel.c:6232 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[Jun  5 16:56:46] DEBUG[18469]: channel.c:6232 ast_channel_inherit_variables: Not copying variable SIPDOMAIN.
[Jun  5 16:56:46] DEBUG[18469]: channel.c:6232 ast_channel_inherit_variables: Not copying variable SIPURI.
[Jun  5 16:56:46] DEBUG[18469]: chan_sip.c:6014 sip_call: Outgoing Call for *780001
[Jun  5 16:56:46] DEBUG[18469]: chan_sip.c:6297 update_call_counter: Updating call counter for outgoing call
[Jun  5 16:56:46] DEBUG[18469]: chan_sip.c:11852 add_sdp: ** Our capability: 0x8 (alaw) Video flag: False Text flag: False
[Jun  5 16:56:46] DEBUG[18469]: chan_sip.c:11853 add_sdp: ** Our prefcodec: 0x8 (alaw) 
[Jun  5 16:56:46] DEBUG[18469]: chan_sip.c:11962 add_sdp: -- Done with adding codecs to SDP
[Jun  5 16:56:46] DEBUG[18469]: chan_sip.c:12148 add_sdp: Done building SDP. Settling with this capability: 0x8 (alaw)
[Jun  5 16:56:46] DEBUG[18469]: chan_sip.c:3360 initialize_initreq: Initializing initreq for method INVITE - callid 62124ba076dbbeb2696f02420563bb7c@2.2.2.2:5060
[Jun  5 16:56:46] DEBUG[18469]: chan_sip.c:3684 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 3.3.3.3:5060
    -- Called SIP/*780001@CONF02-PILOT
[Jun  5 16:56:46] DEBUG[16231]: app_queue.c:1544 handle_statechange: Device 'SIP/1.1.1.1' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:8515 find_call: = Looking for  Call ID: 62124ba076dbbeb2696f02420563bb7c@2.2.2.2:5060 (Checking To) --From tag as665299cd --To-tag   
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:4409 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '62124ba076dbbeb2696f02420563bb7c@2.2.2.2:5060' Request 102: Found
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:20653 handle_response_invite: SIP response 100 to standard invite
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:8515 find_call: = Looking for  Call ID: 62124ba076dbbeb2696f02420563bb7c@2.2.2.2:5060 (Checking To) --From tag as665299cd --To-tag rtZgejaFr394e  
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:4330 __sip_ack: Acked pending invite 102
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:4368 __sip_ack: Stopping retransmission on '62124ba076dbbeb2696f02420563bb7c@2.2.2.2:5060' of Request 102: Match Found
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:20653 handle_response_invite: SIP response 407 to standard invite
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:3684 __sip_xmit: Trying to put 'ACK sip:*78' onto UDP socket destined for 3.3.3.3:5060
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:19790 do_proxy_auth: Auth attempt 1 on INVITE
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:11852 add_sdp: ** Our capability: 0x8 (alaw) Video flag: False Text flag: False
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:11853 add_sdp: ** Our prefcodec: 0x8 (alaw) 
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:11962 add_sdp: -- Done with adding codecs to SDP
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:12148 add_sdp: Done building SDP. Settling with this capability: 0x8 (alaw)
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:3684 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 3.3.3.3:5060
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:8515 find_call: = Looking for  Call ID: 62124ba076dbbeb2696f02420563bb7c@2.2.2.2:5060 (Checking To) --From tag as665299cd --To-tag   
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:4409 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '62124ba076dbbeb2696f02420563bb7c@2.2.2.2:5060' Request 103: Found
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:20653 handle_response_invite: SIP response 100 to standard invite
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:8515 find_call: = Looking for  Call ID: 62124ba076dbbeb2696f02420563bb7c@2.2.2.2:5060 (Checking To) --From tag as665299cd --To-tag S3r9FDUjNc0Qa  
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:4330 __sip_ack: Acked pending invite 103
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:4368 __sip_ack: Stopping retransmission on '62124ba076dbbeb2696f02420563bb7c@2.2.2.2:5060' of Request 103: Match Found
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:20653 handle_response_invite: SIP response 200 to standard invite
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:9313 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED.
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:9313 process_sdp: Processing session-level SDP o=FreeSWITCH 1370423684 1370423685 IN IP4 3.3.3.3... OK.
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:9313 process_sdp: Processing session-level SDP s=FreeSWITCH... UNSUPPORTED OR FAILED.
[Jun  5 16:56:46] DEBUG[16221]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '3.3.3.3' into...
[Jun  5 16:56:46] DEBUG[16221]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '3.3.3.3' and port ''.
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:9313 process_sdp: Processing session-level SDP c=IN IP4 3.3.3.3... OK.
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:9313 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED.
[Jun  5 16:56:46] DEBUG[16221]: rtp_engine.c:541 ast_rtp_codecs_payloads_set_m_type: Setting payload 8 based on m type on 0x7f6023f8cad0
[Jun  5 16:56:46] DEBUG[16221]: rtp_engine.c:541 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0x7f6023f8cad0
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:9585 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:9585 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:9585 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED OR FAILED.
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:9585 process_sdp: Processing media-level (audio) SDP a=silenceSupp:off - - - -... UNSUPPORTED OR FAILED.
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:9585 process_sdp: Processing media-level (audio) SDP a=ptime:20... OK.
[Jun  5 16:56:46] DEBUG[16221]: rtp_engine.c:644 ast_rtp_codecs_payload_formats: Incorporating payload 8 on 0x7f6023f8cad0
[Jun  5 16:56:46] DEBUG[16221]: rtp_engine.c:644 ast_rtp_codecs_payload_formats: Incorporating payload 101 on 0x7f6023f8cad0
[Jun  5 16:56:46] DEBUG[16221]: res_rtp_asterisk.c:2581 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x18bd528'
[Jun  5 16:56:46] DEBUG[16221]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 8 from 0x7f6023f8cad0 to 0x18bd6f0
[Jun  5 16:56:46] DEBUG[16221]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 101 from 0x7f6023f8cad0 to 0x18bd6f0
[Jun  5 16:56:46] DEBUG[16221]: res_rtp_asterisk.c:2507 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x18bd528'
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:9839 process_sdp: We're settling with these formats: 0x8 (alaw)
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:9844 process_sdp: We have an owner, now see if we need to change this call
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:6297 update_call_counter: Updating call counter for outgoing call
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:14805 build_route: build_route: Contact hop: <sip:*780001@3.3.3.3:5060;transport=udp>
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:26797 parse_session_expires: Session-Expires: 1800
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:26810 parse_session_expires: Refresher: UAC
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:26676 start_session_timer: Session timer started: 183 - 62124ba076dbbeb2696f02420563bb7c@2.2.2.2:5060
[Jun  5 16:56:46] DEBUG[16221]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '3.3.3.3:5060' into...
[Jun  5 16:56:46] DEBUG[16221]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '3.3.3.3' and port '5060'.
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:3684 __sip_xmit: Trying to put 'ACK sip:*78' onto UDP socket destined for 3.3.3.3:5060
    -- SIP/CONF02-PILOT-0000001f answered SIP/1.1.1.1-0000001e
[Jun  5 16:56:46] DEBUG[18469]: chan_sip.c:6884 sip_answer: SIP answering channel: SIP/1.1.1.1-0000001e
[Jun  5 16:56:46] DEBUG[18469]: res_rtp_asterisk.c:832 ast_rtp_update_source: Setting the marker bit due to a source update
[Jun  5 16:56:46] DEBUG[18469]: chan_sip.c:12255 transmit_response_with_sdp: Setting framing from config on incoming call
[Jun  5 16:56:46] DEBUG[18469]: chan_sip.c:11852 add_sdp: ** Our capability: 0x8 (alaw) Video flag: True Text flag: True
[Jun  5 16:56:46] DEBUG[18469]: chan_sip.c:11853 add_sdp: ** Our prefcodec: 0x0 (nothing) 
[Jun  5 16:56:46] DEBUG[18469]: chan_sip.c:11962 add_sdp: -- Done with adding codecs to SDP
[Jun  5 16:56:46] DEBUG[18469]: chan_sip.c:12148 add_sdp: Done building SDP. Settling with this capability: 0x8 (alaw)
[Jun  5 16:56:46] DEBUG[18469]: chan_sip.c:3684 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 1.1.1.1:5060
[Jun  5 16:56:46] DEBUG[18469]: features.c:4075 ast_bridge_call: bridge answer set, chan answer set
[Jun  5 16:56:46] DEBUG[18469]: features.c:3896 clear_dialed_interfaces: Removing dialed interfaces datastore on SIP/CONF02-PILOT-0000001f since we're bridging
[Jun  5 16:56:46] DEBUG[18469]: res_rtp_asterisk.c:832 ast_rtp_update_source: Setting the marker bit due to a source update
[Jun  5 16:56:46] DEBUG[18469]: res_rtp_asterisk.c:832 ast_rtp_update_source: Setting the marker bit due to a source update
[Jun  5 16:56:46] DEBUG[16197]: devicestate.c:344 _ast_device_state: No provider found, checking channel drivers for SIP - CONF02-PILOT
[Jun  5 16:56:46] DEBUG[16197]: chan_sip.c:27119 sip_devicestate: Checking device state for peer CONF02-PILOT
[Jun  5 16:56:46] DEBUG[16197]: devicestate.c:467 do_state_change: Changing state for SIP/CONF02-PILOT - state 1 (Not in use)
[Jun  5 16:56:46] DEBUG[16197]: devicestate.c:442 devstate_event: device 'SIP/CONF02-PILOT' state '1'
[Jun  5 16:56:46] DEBUG[16197]: devicestate.c:344 _ast_device_state: No provider found, checking channel drivers for SIP - 1.1.1.1
[Jun  5 16:56:46] DEBUG[16197]: chan_sip.c:27119 sip_devicestate: Checking device state for peer 1.1.1.1
[Jun  5 16:56:46] DEBUG[16197]: devicestate.c:467 do_state_change: Changing state for SIP/1.1.1.1 - state 4 (Invalid)
[Jun  5 16:56:46] DEBUG[16197]: devicestate.c:442 devstate_event: device 'SIP/1.1.1.1' state '4'
[Jun  5 16:56:46] DEBUG[16231]: app_queue.c:1544 handle_statechange: Device 'SIP/CONF02-PILOT' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jun  5 16:56:46] DEBUG[16231]: app_queue.c:1544 handle_statechange: Device 'SIP/1.1.1.1' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:8515 find_call: = Looking for  Call ID: fbc8d639-4892-1231-3b9b-fe38fc8f3ce1 (Checking From) --From tag v13F1m2BQ2mtH --To-tag as4cb21dcd  
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:25813 handle_incoming: **** Received ACK (6) - Command in SIP ACK
[Jun  5 16:56:46] DEBUG[16221]: chan_sip.c:4368 __sip_ack: Stopping retransmission on 'fbc8d639-4892-1231-3b9b-fe38fc8f3ce1' of Response 44886039: Match Found
[Jun  5 16:56:46] DEBUG[18469]: res_rtp_asterisk.c:2190 ast_rtp_read: 0x18ff9b0 -- start learning mode pass with addr = 3.3.3.3:20522
[Jun  5 16:56:46] DEBUG[18469]: res_rtp_asterisk.c:502 rtp_learning_rtp_seq_update: 0x18ff9b0 -- probation = 4, seq = 62838
[Jun  5 16:56:46] DEBUG[18469]: res_rtp_asterisk.c:2196 ast_rtp_read: 0x18ff9b0 -- Condition for learning hasn't exited, so reject the frame.
[Jun  5 16:56:46] DEBUG[18469]: res_rtp_asterisk.c:2190 ast_rtp_read: 0x18ff9b0 -- start learning mode pass with addr = 3.3.3.3:20522
[Jun  5 16:56:46] DEBUG[18469]: res_rtp_asterisk.c:502 rtp_learning_rtp_seq_update: 0x18ff9b0 -- probation = 3, seq = 62839
[Jun  5 16:56:46] DEBUG[18469]: res_rtp_asterisk.c:2196 ast_rtp_read: 0x18ff9b0 -- Condition for learning hasn't exited, so reject the frame.
[Jun  5 16:56:46] DEBUG[18469]: res_rtp_asterisk.c:2190 ast_rtp_read: 0x18ff9b0 -- start learning mode pass with addr = 3.3.3.3:20522
[Jun  5 16:56:46] DEBUG[18469]: res_rtp_asterisk.c:502 rtp_learning_rtp_seq_update: 0x18ff9b0 -- probation = 2, seq = 62840
[Jun  5 16:56:46] DEBUG[18469]: res_rtp_asterisk.c:2196 ast_rtp_read: 0x18ff9b0 -- Condition for learning hasn't exited, so reject the frame.
[Jun  5 16:56:46] DEBUG[18469]: res_rtp_asterisk.c:2190 ast_rtp_read: 0x18ff9b0 -- start learning mode pass with addr = 3.3.3.3:20522
[Jun  5 16:56:46] DEBUG[18469]: res_rtp_asterisk.c:502 rtp_learning_rtp_seq_update: 0x18ff9b0 -- probation = 1, seq = 62841
[Jun  5 16:56:46] DEBUG[18469]: res_rtp_asterisk.c:2200 ast_rtp_read: 0x18ff9b0 -- Probation Ended. Set strict_rtp_state to STRICT_RTP_CLOSED with address 3.3.3.3:20522
[Jun  5 16:56:46] DEBUG[18469]: res_rtp_asterisk.c:1363 ast_rtp_write: Ooh, format changed from unknown to alaw
[Jun  5 16:56:46] DEBUG[18469]: res_rtp_asterisk.c:1394 ast_rtp_write: Created smoother: format: alaw ms: 20 len: 160
[Jun  5 16:56:46] DEBUG[18469]: res_rtp_asterisk.c:1259 ast_rtp_raw_write: Starting RTCP transmission on RTP instance '0x18e6738'
[Jun  5 16:56:46] DEBUG[18469]: res_rtp_asterisk.c:2190 ast_rtp_read: 0x18ebb50 -- start learning mode pass with addr = 1.1.1.1:22770
[Jun  5 16:56:46] DEBUG[18469]: res_rtp_asterisk.c:502 rtp_learning_rtp_seq_update: 0x18ebb50 -- probation = 4, seq = 61304
[Jun  5 16:56:46] DEBUG[18469]: res_rtp_asterisk.c:2196 ast_rtp_read: 0x18ebb50 -- Condition for learning hasn't exited, so reject the frame.
[Jun  5 16:56:46] DEBUG[18469]: res_rtp_asterisk.c:2190 ast_rtp_read: 0x18ebb50 -- start learning mode pass with addr = 1.1.1.1:22770
[Jun  5 16:56:46] DEBUG[18469]: res_rtp_asterisk.c:502 rtp_learning_rtp_seq_update: 0x18ebb50 -- probation = 3, seq = 61305
[Jun  5 16:56:46] DEBUG[18469]: res_rtp_asterisk.c:2196 ast_rtp_read: 0x18ebb50 -- Condition for learning hasn't exited, so reject the frame.
[Jun  5 16:56:46] DEBUG[18469]: res_rtp_asterisk.c:2190 ast_rtp_read: 0x18ebb50 -- start learning mode pass with addr = 1.1.1.1:22770
[Jun  5 16:56:46] DEBUG[18469]: res_rtp_asterisk.c:502 rtp_learning_rtp_seq_update: 0x18ebb50 -- probation = 2, seq = 61306
[Jun  5 16:56:46] DEBUG[18469]: res_rtp_asterisk.c:2196 ast_rtp_read: 0x18ebb50 -- Condition for learning hasn't exited, so reject the frame.
[Jun  5 16:56:46] DEBUG[18469]: res_rtp_asterisk.c:2190 ast_rtp_read: 0x18ebb50 -- start learning mode pass with addr = 1.1.1.1:22770
[Jun  5 16:56:46] DEBUG[18469]: res_rtp_asterisk.c:502 rtp_learning_rtp_seq_update: 0x18ebb50 -- probation = 1, seq = 61307
[Jun  5 16:56:46] DEBUG[18469]: res_rtp_asterisk.c:2200 ast_rtp_read: 0x18ebb50 -- Probation Ended. Set strict_rtp_state to STRICT_RTP_CLOSED with address 1.1.1.1:22770
[Jun  5 16:56:46] DEBUG[18469]: res_rtp_asterisk.c:1363 ast_rtp_write: Ooh, format changed from unknown to alaw
[Jun  5 16:56:46] DEBUG[18469]: res_rtp_asterisk.c:1394 ast_rtp_write: Created smoother: format: alaw ms: 20 len: 160
[Jun  5 16:56:48] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:48] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating BEGIN DTMF Frame: 49 (1), at 1.1.1.1:22770
[Jun  5 16:56:48] DTMF[18469]: channel.c:4151 __ast_read: DTMF begin '1' received on SIP/1.1.1.1-0000001e
[Jun  5 16:56:48] DTMF[18469]: channel.c:4161 __ast_read: DTMF begin passthrough '1' on SIP/1.1.1.1-0000001e
[Jun  5 16:56:48] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:48] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:48] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:48] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:48] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:48] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:48] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:48] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:48] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:48] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:48] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:48] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:48] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating END DTMF Frame: 49 (1), at 1.1.1.1:22770
[Jun  5 16:56:48] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '1' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:48] DTMF[18469]: channel.c:4106 __ast_read: DTMF end accepted with begin '1' on SIP/1.1.1.1-0000001e
[Jun  5 16:56:48] DTMF[18469]: channel.c:4135 __ast_read: DTMF end passthrough '1' on SIP/1.1.1.1-0000001e
[Jun  5 16:56:48] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:48] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:48] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:48] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating BEGIN DTMF Frame: 50 (2), at 1.1.1.1:22770
[Jun  5 16:56:48] DTMF[18469]: channel.c:4151 __ast_read: DTMF begin '2' received on SIP/1.1.1.1-0000001e
[Jun  5 16:56:48] DTMF[18469]: channel.c:4155 __ast_read: DTMF begin ignored '2' on SIP/1.1.1.1-0000001e
[Jun  5 16:56:48] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:48] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:48] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:48] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:48] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:48] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:48] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:48] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:48] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:48] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:48] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:48] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:48] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating END DTMF Frame: 50 (2), at 1.1.1.1:22770
[Jun  5 16:56:48] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '2' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:48] DTMF[18469]: channel.c:4092 __ast_read: DTMF begin emulation of '2' with duration 260 queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:48] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:48] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:48] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:48] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating BEGIN DTMF Frame: 51 (3), at 1.1.1.1:22770
[Jun  5 16:56:48] DTMF[18469]: channel.c:4151 __ast_read: DTMF begin '3' received on SIP/1.1.1.1-0000001e
[Jun  5 16:56:48] DTMF[18469]: channel.c:4155 __ast_read: DTMF begin ignored '3' on SIP/1.1.1.1-0000001e
[Jun  5 16:56:48] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:48] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:49] DTMF[18469]: channel.c:4184 __ast_read: DTMF end emulation of '2' queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating END DTMF Frame: 51 (3), at 1.1.1.1:22770
[Jun  5 16:56:49] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '3' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:49] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '3' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:49] DTMF[18469]: channel.c:4092 __ast_read: DTMF begin emulation of '3' with duration 260 queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating BEGIN DTMF Frame: 52 (4), at 1.1.1.1:22770
[Jun  5 16:56:49] DTMF[18469]: channel.c:4151 __ast_read: DTMF begin '4' received on SIP/1.1.1.1-0000001e
[Jun  5 16:56:49] DTMF[18469]: channel.c:4155 __ast_read: DTMF begin ignored '4' on SIP/1.1.1.1-0000001e
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating END DTMF Frame: 52 (4), at 1.1.1.1:22770
[Jun  5 16:56:49] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '4' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:49] DTMF[18469]: channel.c:4184 __ast_read: DTMF end emulation of '3' queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:49] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '4' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:49] DTMF[18469]: channel.c:4092 __ast_read: DTMF begin emulation of '4' with duration 260 queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating BEGIN DTMF Frame: 53 (5), at 1.1.1.1:22770
[Jun  5 16:56:49] DTMF[18469]: channel.c:4151 __ast_read: DTMF begin '5' received on SIP/1.1.1.1-0000001e
[Jun  5 16:56:49] DTMF[18469]: channel.c:4155 __ast_read: DTMF begin ignored '5' on SIP/1.1.1.1-0000001e
[Jun  5 16:56:49] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 2 instead
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating END DTMF Frame: 53 (5), at 1.1.1.1:22770
[Jun  5 16:56:49] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '5' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:49] DTMF[18469]: channel.c:4184 __ast_read: DTMF end emulation of '4' queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:49] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '5' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:49] DTMF[18469]: channel.c:4092 __ast_read: DTMF begin emulation of '5' with duration 260 queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating BEGIN DTMF Frame: 54 (6), at 1.1.1.1:22770
[Jun  5 16:56:49] DTMF[18469]: channel.c:4151 __ast_read: DTMF begin '6' received on SIP/1.1.1.1-0000001e
[Jun  5 16:56:49] DTMF[18469]: channel.c:4155 __ast_read: DTMF begin ignored '6' on SIP/1.1.1.1-0000001e
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:49] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 4 instead
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:49] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating END DTMF Frame: 54 (6), at 1.1.1.1:22770
[Jun  5 16:56:50] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '6' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:50] DTMF[18469]: channel.c:4184 __ast_read: DTMF end emulation of '5' queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:50] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '6' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:50] DTMF[18469]: channel.c:4092 __ast_read: DTMF begin emulation of '6' with duration 260 queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating BEGIN DTMF Frame: 55 (7), at 1.1.1.1:22770
[Jun  5 16:56:50] DTMF[18469]: channel.c:4151 __ast_read: DTMF begin '7' received on SIP/1.1.1.1-0000001e
[Jun  5 16:56:50] DTMF[18469]: channel.c:4155 __ast_read: DTMF begin ignored '7' on SIP/1.1.1.1-0000001e
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:50] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating END DTMF Frame: 55 (7), at 1.1.1.1:22770
[Jun  5 16:56:50] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '7' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:50] DTMF[18469]: channel.c:4184 __ast_read: DTMF end emulation of '6' queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:50] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '7' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:50] DTMF[18469]: channel.c:4092 __ast_read: DTMF begin emulation of '7' with duration 260 queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating BEGIN DTMF Frame: 56 (8), at 1.1.1.1:22770
[Jun  5 16:56:50] DTMF[18469]: channel.c:4151 __ast_read: DTMF begin '8' received on SIP/1.1.1.1-0000001e
[Jun  5 16:56:50] DTMF[18469]: channel.c:4155 __ast_read: DTMF begin ignored '8' on SIP/1.1.1.1-0000001e
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:50] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 6 instead
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating END DTMF Frame: 56 (8), at 1.1.1.1:22770
[Jun  5 16:56:50] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '8' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:50] DTMF[18469]: channel.c:4184 __ast_read: DTMF end emulation of '7' queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:50] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '8' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:50] DTMF[18469]: channel.c:4092 __ast_read: DTMF begin emulation of '8' with duration 260 queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating BEGIN DTMF Frame: 57 (9), at 1.1.1.1:22770
[Jun  5 16:56:50] DTMF[18469]: channel.c:4151 __ast_read: DTMF begin '9' received on SIP/1.1.1.1-0000001e
[Jun  5 16:56:50] DTMF[18469]: channel.c:4155 __ast_read: DTMF begin ignored '9' on SIP/1.1.1.1-0000001e
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:50] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 7 instead
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:50] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating END DTMF Frame: 57 (9), at 1.1.1.1:22770
[Jun  5 16:56:50] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '9' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:50] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:50] DTMF[18469]: channel.c:4184 __ast_read: DTMF end emulation of '8' queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:51] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '9' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:51] DTMF[18469]: channel.c:4092 __ast_read: DTMF begin emulation of '9' with duration 260 queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating BEGIN DTMF Frame: 48 (0), at 1.1.1.1:22770
[Jun  5 16:56:51] DTMF[18469]: channel.c:4151 __ast_read: DTMF begin '0' received on SIP/1.1.1.1-0000001e
[Jun  5 16:56:51] DTMF[18469]: channel.c:4155 __ast_read: DTMF begin ignored '0' on SIP/1.1.1.1-0000001e
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:51] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 4 instead
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating END DTMF Frame: 48 (0), at 1.1.1.1:22770
[Jun  5 16:56:51] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '0' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:51] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:51] DTMF[18469]: channel.c:4184 __ast_read: DTMF end emulation of '9' queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:51] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '0' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:51] DTMF[18469]: channel.c:4092 __ast_read: DTMF begin emulation of '0' with duration 260 queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating BEGIN DTMF Frame: 49 (1), at 1.1.1.1:22770
[Jun  5 16:56:51] DTMF[18469]: channel.c:4151 __ast_read: DTMF begin '1' received on SIP/1.1.1.1-0000001e
[Jun  5 16:56:51] DTMF[18469]: channel.c:4155 __ast_read: DTMF begin ignored '1' on SIP/1.1.1.1-0000001e
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:51] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 4 instead
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating END DTMF Frame: 49 (1), at 1.1.1.1:22770
[Jun  5 16:56:51] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '1' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:51] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:51] DTMF[18469]: channel.c:4184 __ast_read: DTMF end emulation of '0' queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:51] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:51] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '1' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:51] DTMF[18469]: channel.c:4092 __ast_read: DTMF begin emulation of '1' with duration 260 queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating BEGIN DTMF Frame: 50 (2), at 1.1.1.1:22770
[Jun  5 16:56:51] DTMF[18469]: channel.c:4151 __ast_read: DTMF begin '2' received on SIP/1.1.1.1-0000001e
[Jun  5 16:56:51] DTMF[18469]: channel.c:4155 __ast_read: DTMF begin ignored '2' on SIP/1.1.1.1-0000001e
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating END DTMF Frame: 50 (2), at 1.1.1.1:22770
[Jun  5 16:56:51] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '2' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:51] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:51] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:51] DTMF[18469]: channel.c:4184 __ast_read: DTMF end emulation of '1' queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:51] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '2' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:51] DTMF[18469]: channel.c:4092 __ast_read: DTMF begin emulation of '2' with duration 260 queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating BEGIN DTMF Frame: 51 (3), at 1.1.1.1:22770
[Jun  5 16:56:51] DTMF[18469]: channel.c:4151 __ast_read: DTMF begin '3' received on SIP/1.1.1.1-0000001e
[Jun  5 16:56:51] DTMF[18469]: channel.c:4155 __ast_read: DTMF begin ignored '3' on SIP/1.1.1.1-0000001e
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:51] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 2 instead
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:51] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating END DTMF Frame: 51 (3), at 1.1.1.1:22770
[Jun  5 16:56:51] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '3' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:52] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 2 instead
[Jun  5 16:56:52] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:52] DTMF[18469]: channel.c:4184 __ast_read: DTMF end emulation of '2' queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:52] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:52] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '3' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:52] DTMF[18469]: channel.c:4092 __ast_read: DTMF begin emulation of '3' with duration 260 queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating BEGIN DTMF Frame: 52 (4), at 1.1.1.1:22770
[Jun  5 16:56:52] DTMF[18469]: channel.c:4151 __ast_read: DTMF begin '4' received on SIP/1.1.1.1-0000001e
[Jun  5 16:56:52] DTMF[18469]: channel.c:4155 __ast_read: DTMF begin ignored '4' on SIP/1.1.1.1-0000001e
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:52] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 2 instead
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating END DTMF Frame: 52 (4), at 1.1.1.1:22770
[Jun  5 16:56:52] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '4' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:52] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 3 instead
[Jun  5 16:56:52] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:52] DTMF[18469]: channel.c:4184 __ast_read: DTMF end emulation of '3' queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:52] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:52] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '4' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:52] DTMF[18469]: channel.c:4092 __ast_read: DTMF begin emulation of '4' with duration 260 queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating BEGIN DTMF Frame: 53 (5), at 1.1.1.1:22770
[Jun  5 16:56:52] DTMF[18469]: channel.c:4151 __ast_read: DTMF begin '5' received on SIP/1.1.1.1-0000001e
[Jun  5 16:56:52] DTMF[18469]: channel.c:4155 __ast_read: DTMF begin ignored '5' on SIP/1.1.1.1-0000001e
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating END DTMF Frame: 53 (5), at 1.1.1.1:22770
[Jun  5 16:56:52] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '5' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:52] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:52] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:52] DTMF[18469]: channel.c:4184 __ast_read: DTMF end emulation of '4' queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:52] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:52] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '5' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:52] DTMF[18469]: channel.c:4092 __ast_read: DTMF begin emulation of '5' with duration 260 queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating BEGIN DTMF Frame: 54 (6), at 1.1.1.1:22770
[Jun  5 16:56:52] DTMF[18469]: channel.c:4151 __ast_read: DTMF begin '6' received on SIP/1.1.1.1-0000001e
[Jun  5 16:56:52] DTMF[18469]: channel.c:4155 __ast_read: DTMF begin ignored '6' on SIP/1.1.1.1-0000001e
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:52] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating END DTMF Frame: 54 (6), at 1.1.1.1:22770
[Jun  5 16:56:52] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '6' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:52] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 6 instead
[Jun  5 16:56:53] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:53] DTMF[18469]: channel.c:4184 __ast_read: DTMF end emulation of '5' queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:53] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:53] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '6' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:53] DTMF[18469]: channel.c:4092 __ast_read: DTMF begin emulation of '6' with duration 260 queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating BEGIN DTMF Frame: 55 (7), at 1.1.1.1:22770
[Jun  5 16:56:53] DTMF[18469]: channel.c:4151 __ast_read: DTMF begin '7' received on SIP/1.1.1.1-0000001e
[Jun  5 16:56:53] DTMF[18469]: channel.c:4155 __ast_read: DTMF begin ignored '7' on SIP/1.1.1.1-0000001e
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating END DTMF Frame: 55 (7), at 1.1.1.1:22770
[Jun  5 16:56:53] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '7' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:53] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:53] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:53] DTMF[18469]: channel.c:4184 __ast_read: DTMF end emulation of '6' queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:53] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:53] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '7' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:53] DTMF[18469]: channel.c:4092 __ast_read: DTMF begin emulation of '7' with duration 260 queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating BEGIN DTMF Frame: 56 (8), at 1.1.1.1:22770
[Jun  5 16:56:53] DTMF[18469]: channel.c:4151 __ast_read: DTMF begin '8' received on SIP/1.1.1.1-0000001e
[Jun  5 16:56:53] DTMF[18469]: channel.c:4155 __ast_read: DTMF begin ignored '8' on SIP/1.1.1.1-0000001e
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating END DTMF Frame: 56 (8), at 1.1.1.1:22770
[Jun  5 16:56:53] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '8' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:53] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:53] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:53] DTMF[18469]: channel.c:4184 __ast_read: DTMF end emulation of '7' queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:53] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:53] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '8' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:53] DTMF[18469]: channel.c:4092 __ast_read: DTMF begin emulation of '8' with duration 260 queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating BEGIN DTMF Frame: 57 (9), at 1.1.1.1:22770
[Jun  5 16:56:53] DTMF[18469]: channel.c:4151 __ast_read: DTMF begin '9' received on SIP/1.1.1.1-0000001e
[Jun  5 16:56:53] DTMF[18469]: channel.c:4155 __ast_read: DTMF begin ignored '9' on SIP/1.1.1.1-0000001e
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:53] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating END DTMF Frame: 57 (9), at 1.1.1.1:22770
[Jun  5 16:56:53] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '9' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:53] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 8 instead
[Jun  5 16:56:54] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:54] DTMF[18469]: channel.c:4184 __ast_read: DTMF end emulation of '8' queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:54] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '9' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:54] DTMF[18469]: channel.c:4092 __ast_read: DTMF begin emulation of '9' with duration 260 queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating BEGIN DTMF Frame: 48 (0), at 1.1.1.1:22770
[Jun  5 16:56:54] DTMF[18469]: channel.c:4151 __ast_read: DTMF begin '0' received on SIP/1.1.1.1-0000001e
[Jun  5 16:56:54] DTMF[18469]: channel.c:4155 __ast_read: DTMF begin ignored '0' on SIP/1.1.1.1-0000001e
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating END DTMF Frame: 48 (0), at 1.1.1.1:22770
[Jun  5 16:56:54] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '0' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:54] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:54] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:54] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:54] DTMF[18469]: channel.c:4184 __ast_read: DTMF end emulation of '9' queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:54] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:54] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '0' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:54] DTMF[18469]: channel.c:4092 __ast_read: DTMF begin emulation of '0' with duration 260 queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating BEGIN DTMF Frame: 49 (1), at 1.1.1.1:22770
[Jun  5 16:56:54] DTMF[18469]: channel.c:4151 __ast_read: DTMF begin '1' received on SIP/1.1.1.1-0000001e
[Jun  5 16:56:54] DTMF[18469]: channel.c:4155 __ast_read: DTMF begin ignored '1' on SIP/1.1.1.1-0000001e
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating END DTMF Frame: 49 (1), at 1.1.1.1:22770
[Jun  5 16:56:54] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '1' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:54] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:54] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:54] DTMF[18469]: channel.c:4184 __ast_read: DTMF end emulation of '0' queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:54] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:54] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '1' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:54] DTMF[18469]: channel.c:4092 __ast_read: DTMF begin emulation of '1' with duration 260 queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating BEGIN DTMF Frame: 50 (2), at 1.1.1.1:22770
[Jun  5 16:56:54] DTMF[18469]: channel.c:4151 __ast_read: DTMF begin '2' received on SIP/1.1.1.1-0000001e
[Jun  5 16:56:54] DTMF[18469]: channel.c:4155 __ast_read: DTMF begin ignored '2' on SIP/1.1.1.1-0000001e
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:54] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating END DTMF Frame: 50 (2), at 1.1.1.1:22770
[Jun  5 16:56:54] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '2' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:54] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:54] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 7 instead
[Jun  5 16:56:54] DTMF[18469]: channel.c:4184 __ast_read: DTMF end emulation of '1' queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:55] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '2' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:55] DTMF[18469]: channel.c:4092 __ast_read: DTMF begin emulation of '2' with duration 260 queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating BEGIN DTMF Frame: 51 (3), at 1.1.1.1:22770
[Jun  5 16:56:55] DTMF[18469]: channel.c:4151 __ast_read: DTMF begin '3' received on SIP/1.1.1.1-0000001e
[Jun  5 16:56:55] DTMF[18469]: channel.c:4155 __ast_read: DTMF begin ignored '3' on SIP/1.1.1.1-0000001e
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating END DTMF Frame: 51 (3), at 1.1.1.1:22770
[Jun  5 16:56:55] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '3' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:55] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:55] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:55] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:55] DTMF[18469]: channel.c:4184 __ast_read: DTMF end emulation of '2' queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:55] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '3' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:55] DTMF[18469]: channel.c:4092 __ast_read: DTMF begin emulation of '3' with duration 260 queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating BEGIN DTMF Frame: 52 (4), at 1.1.1.1:22770
[Jun  5 16:56:55] DTMF[18469]: channel.c:4151 __ast_read: DTMF begin '4' received on SIP/1.1.1.1-0000001e
[Jun  5 16:56:55] DTMF[18469]: channel.c:4155 __ast_read: DTMF begin ignored '4' on SIP/1.1.1.1-0000001e
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating END DTMF Frame: 52 (4), at 1.1.1.1:22770
[Jun  5 16:56:55] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '4' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:55] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:55] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:55] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:55] DTMF[18469]: channel.c:4184 __ast_read: DTMF end emulation of '3' queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:55] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '4' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:55] DTMF[18469]: channel.c:4092 __ast_read: DTMF begin emulation of '4' with duration 260 queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating BEGIN DTMF Frame: 53 (5), at 1.1.1.1:22770
[Jun  5 16:56:55] DTMF[18469]: channel.c:4151 __ast_read: DTMF begin '5' received on SIP/1.1.1.1-0000001e
[Jun  5 16:56:55] DTMF[18469]: channel.c:4155 __ast_read: DTMF begin ignored '5' on SIP/1.1.1.1-0000001e
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating END DTMF Frame: 53 (5), at 1.1.1.1:22770
[Jun  5 16:56:55] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '5' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:55] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:55] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:55] DTMF[18469]: channel.c:4184 __ast_read: DTMF end emulation of '4' queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:55] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 8 instead
[Jun  5 16:56:55] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '5' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:55] DTMF[18469]: channel.c:4092 __ast_read: DTMF begin emulation of '5' with duration 260 queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating BEGIN DTMF Frame: 54 (6), at 1.1.1.1:22770
[Jun  5 16:56:55] DTMF[18469]: channel.c:4151 __ast_read: DTMF begin '6' received on SIP/1.1.1.1-0000001e
[Jun  5 16:56:55] DTMF[18469]: channel.c:4155 __ast_read: DTMF begin ignored '6' on SIP/1.1.1.1-0000001e
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:55] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating END DTMF Frame: 54 (6), at 1.1.1.1:22770
[Jun  5 16:56:55] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '6' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:56] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:56] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:56] DTMF[18469]: channel.c:4184 __ast_read: DTMF end emulation of '5' queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:56] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:56] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '6' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:56] DTMF[18469]: channel.c:4092 __ast_read: DTMF begin emulation of '6' with duration 260 queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating BEGIN DTMF Frame: 55 (7), at 1.1.1.1:22770
[Jun  5 16:56:56] DTMF[18469]: channel.c:4151 __ast_read: DTMF begin '7' received on SIP/1.1.1.1-0000001e
[Jun  5 16:56:56] DTMF[18469]: channel.c:4155 __ast_read: DTMF begin ignored '7' on SIP/1.1.1.1-0000001e
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating END DTMF Frame: 55 (7), at 1.1.1.1:22770
[Jun  5 16:56:56] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '7' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:56] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:56] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:56] DTMF[18469]: channel.c:4184 __ast_read: DTMF end emulation of '6' queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:56] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:56] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '7' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:56] DTMF[18469]: channel.c:4092 __ast_read: DTMF begin emulation of '7' with duration 260 queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating BEGIN DTMF Frame: 56 (8), at 1.1.1.1:22770
[Jun  5 16:56:56] DTMF[18469]: channel.c:4151 __ast_read: DTMF begin '8' received on SIP/1.1.1.1-0000001e
[Jun  5 16:56:56] DTMF[18469]: channel.c:4155 __ast_read: DTMF begin ignored '8' on SIP/1.1.1.1-0000001e
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating END DTMF Frame: 56 (8), at 1.1.1.1:22770
[Jun  5 16:56:56] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '8' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:56] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:56] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:56] DTMF[18469]: channel.c:4184 __ast_read: DTMF end emulation of '7' queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:56] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:56] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '8' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:56] DTMF[18469]: channel.c:4092 __ast_read: DTMF begin emulation of '8' with duration 260 queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating BEGIN DTMF Frame: 57 (9), at 1.1.1.1:22770
[Jun  5 16:56:56] DTMF[18469]: channel.c:4151 __ast_read: DTMF begin '9' received on SIP/1.1.1.1-0000001e
[Jun  5 16:56:56] DTMF[18469]: channel.c:4155 __ast_read: DTMF begin ignored '9' on SIP/1.1.1.1-0000001e
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:56] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating END DTMF Frame: 57 (9), at 1.1.1.1:22770
[Jun  5 16:56:56] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '9' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:56] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 7 instead
[Jun  5 16:56:57] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:57] DTMF[18469]: channel.c:4184 __ast_read: DTMF end emulation of '8' queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:57] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:57] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '9' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:57] DTMF[18469]: channel.c:4092 __ast_read: DTMF begin emulation of '9' with duration 260 queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating BEGIN DTMF Frame: 48 (0), at 1.1.1.1:22770
[Jun  5 16:56:57] DTMF[18469]: channel.c:4151 __ast_read: DTMF begin '0' received on SIP/1.1.1.1-0000001e
[Jun  5 16:56:57] DTMF[18469]: channel.c:4155 __ast_read: DTMF begin ignored '0' on SIP/1.1.1.1-0000001e
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating END DTMF Frame: 48 (0), at 1.1.1.1:22770
[Jun  5 16:56:57] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '0' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:57] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:57] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:57] DTMF[18469]: channel.c:4184 __ast_read: DTMF end emulation of '9' queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:57] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:57] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '0' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:57] DTMF[18469]: channel.c:4092 __ast_read: DTMF begin emulation of '0' with duration 260 queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating BEGIN DTMF Frame: 49 (1), at 1.1.1.1:22770
[Jun  5 16:56:57] DTMF[18469]: channel.c:4151 __ast_read: DTMF begin '1' received on SIP/1.1.1.1-0000001e
[Jun  5 16:56:57] DTMF[18469]: channel.c:4155 __ast_read: DTMF begin ignored '1' on SIP/1.1.1.1-0000001e
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating END DTMF Frame: 49 (1), at 1.1.1.1:22770
[Jun  5 16:56:57] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '1' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:57] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:57] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:57] DTMF[18469]: channel.c:4184 __ast_read: DTMF end emulation of '0' queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:57] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:57] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '1' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:57] DTMF[18469]: channel.c:4092 __ast_read: DTMF begin emulation of '1' with duration 260 queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating BEGIN DTMF Frame: 50 (2), at 1.1.1.1:22770
[Jun  5 16:56:57] DTMF[18469]: channel.c:4151 __ast_read: DTMF begin '2' received on SIP/1.1.1.1-0000001e
[Jun  5 16:56:57] DTMF[18469]: channel.c:4155 __ast_read: DTMF begin ignored '2' on SIP/1.1.1.1-0000001e
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:57] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating END DTMF Frame: 50 (2), at 1.1.1.1:22770
[Jun  5 16:56:57] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '2' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:57] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 8 instead
[Jun  5 16:56:58] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:58] DTMF[18469]: channel.c:4184 __ast_read: DTMF end emulation of '1' queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:58] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '2' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:58] DTMF[18469]: channel.c:4092 __ast_read: DTMF begin emulation of '2' with duration 260 queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating BEGIN DTMF Frame: 51 (3), at 1.1.1.1:22770
[Jun  5 16:56:58] DTMF[18469]: channel.c:4151 __ast_read: DTMF begin '3' received on SIP/1.1.1.1-0000001e
[Jun  5 16:56:58] DTMF[18469]: channel.c:4155 __ast_read: DTMF begin ignored '3' on SIP/1.1.1.1-0000001e
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating END DTMF Frame: 51 (3), at 1.1.1.1:22770
[Jun  5 16:56:58] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '3' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:58] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:58] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:58] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:58] DTMF[18469]: channel.c:4184 __ast_read: DTMF end emulation of '2' queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:58] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:58] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '3' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:58] DTMF[18469]: channel.c:4092 __ast_read: DTMF begin emulation of '3' with duration 260 queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating BEGIN DTMF Frame: 52 (4), at 1.1.1.1:22770
[Jun  5 16:56:58] DTMF[18469]: channel.c:4151 __ast_read: DTMF begin '4' received on SIP/1.1.1.1-0000001e
[Jun  5 16:56:58] DTMF[18469]: channel.c:4155 __ast_read: DTMF begin ignored '4' on SIP/1.1.1.1-0000001e
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating END DTMF Frame: 52 (4), at 1.1.1.1:22770
[Jun  5 16:56:58] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '4' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:58] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:58] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:58] DTMF[18469]: channel.c:4184 __ast_read: DTMF end emulation of '3' queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:58] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:58] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '4' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:58] DTMF[18469]: channel.c:4092 __ast_read: DTMF begin emulation of '4' with duration 260 queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating BEGIN DTMF Frame: 53 (5), at 1.1.1.1:22770
[Jun  5 16:56:58] DTMF[18469]: channel.c:4151 __ast_read: DTMF begin '5' received on SIP/1.1.1.1-0000001e
[Jun  5 16:56:58] DTMF[18469]: channel.c:4155 __ast_read: DTMF begin ignored '5' on SIP/1.1.1.1-0000001e
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:58] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating END DTMF Frame: 53 (5), at 1.1.1.1:22770
[Jun  5 16:56:58] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '5' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:58] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:58] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 7 instead
[Jun  5 16:56:58] DTMF[18469]: channel.c:4184 __ast_read: DTMF end emulation of '4' queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:59] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '5' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:59] DTMF[18469]: channel.c:4092 __ast_read: DTMF begin emulation of '5' with duration 260 queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating BEGIN DTMF Frame: 54 (6), at 1.1.1.1:22770
[Jun  5 16:56:59] DTMF[18469]: channel.c:4151 __ast_read: DTMF begin '6' received on SIP/1.1.1.1-0000001e
[Jun  5 16:56:59] DTMF[18469]: channel.c:4155 __ast_read: DTMF begin ignored '6' on SIP/1.1.1.1-0000001e
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating END DTMF Frame: 54 (6), at 1.1.1.1:22770
[Jun  5 16:56:59] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '6' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:59] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:59] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:59] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:59] DTMF[18469]: channel.c:4184 __ast_read: DTMF end emulation of '5' queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:59] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '6' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:59] DTMF[18469]: channel.c:4092 __ast_read: DTMF begin emulation of '6' with duration 260 queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating BEGIN DTMF Frame: 55 (7), at 1.1.1.1:22770
[Jun  5 16:56:59] DTMF[18469]: channel.c:4151 __ast_read: DTMF begin '7' received on SIP/1.1.1.1-0000001e
[Jun  5 16:56:59] DTMF[18469]: channel.c:4155 __ast_read: DTMF begin ignored '7' on SIP/1.1.1.1-0000001e
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating END DTMF Frame: 55 (7), at 1.1.1.1:22770
[Jun  5 16:56:59] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '7' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:59] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:59] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:59] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:59] DTMF[18469]: channel.c:4184 __ast_read: DTMF end emulation of '6' queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:59] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '7' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:59] DTMF[18469]: channel.c:4092 __ast_read: DTMF begin emulation of '7' with duration 260 queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating BEGIN DTMF Frame: 56 (8), at 1.1.1.1:22770
[Jun  5 16:56:59] DTMF[18469]: channel.c:4151 __ast_read: DTMF begin '8' received on SIP/1.1.1.1-0000001e
[Jun  5 16:56:59] DTMF[18469]: channel.c:4155 __ast_read: DTMF begin ignored '8' on SIP/1.1.1.1-0000001e
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating END DTMF Frame: 56 (8), at 1.1.1.1:22770
[Jun  5 16:56:59] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '8' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:59] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:59] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:56:59] DTMF[18469]: channel.c:4184 __ast_read: DTMF end emulation of '7' queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:59] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 8 instead
[Jun  5 16:56:59] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '8' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:56:59] DTMF[18469]: channel.c:4092 __ast_read: DTMF begin emulation of '8' with duration 260 queued on SIP/1.1.1.1-0000001e
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating BEGIN DTMF Frame: 57 (9), at 1.1.1.1:22770
[Jun  5 16:56:59] DTMF[18469]: channel.c:4151 __ast_read: DTMF begin '9' received on SIP/1.1.1.1-0000001e
[Jun  5 16:56:59] DTMF[18469]: channel.c:4155 __ast_read: DTMF begin ignored '9' on SIP/1.1.1.1-0000001e
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:56:59] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating END DTMF Frame: 57 (9), at 1.1.1.1:22770
[Jun  5 16:56:59] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '9' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:57:00] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:57:00] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:57:00] DTMF[18469]: channel.c:4184 __ast_read: DTMF end emulation of '8' queued on SIP/1.1.1.1-0000001e
[Jun  5 16:57:00] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:57:00] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '9' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:57:00] DTMF[18469]: channel.c:4092 __ast_read: DTMF begin emulation of '9' with duration 260 queued on SIP/1.1.1.1-0000001e
[Jun  5 16:57:00] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:57:00] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4)
[Jun  5 16:57:00] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:57:00] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating BEGIN DTMF Frame: 48 (0), at 1.1.1.1:22770
[Jun  5 16:57:00] DTMF[18469]: channel.c:4151 __ast_read: DTMF begin '0' received on SIP/1.1.1.1-0000001e
[Jun  5 16:57:00] DTMF[18469]: channel.c:4155 __ast_read: DTMF begin ignored '0' on SIP/1.1.1.1-0000001e
[Jun  5 16:57:00] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:57:00] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:57:00] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:57:00] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:57:00] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:57:00] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:57:00] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:57:00] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:57:00] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:57:00] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:57:00] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:57:00] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:57:00] DEBUG[18469]: res_rtp_asterisk.c:1504 create_dtmf_frame: Creating END DTMF Frame: 48 (0), at 1.1.1.1:22770
[Jun  5 16:57:00] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '0' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:57:00] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:57:00] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:57:00] DTMF[18469]: channel.c:4184 __ast_read: DTMF end emulation of '9' queued on SIP/1.1.1.1-0000001e
[Jun  5 16:57:00] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
[Jun  5 16:57:00] DTMF[18469]: channel.c:4066 __ast_read: DTMF end '0' received on SIP/1.1.1.1-0000001e, duration 260 ms
[Jun  5 16:57:00] DTMF[18469]: channel.c:4092 __ast_read: DTMF begin emulation of '0' with duration 260 queued on SIP/1.1.1.1-0000001e
[Jun  5 16:57:00] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:57:00] DEBUG[18469]: res_rtp_asterisk.c:1548 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jun  5 16:57:00] DEBUG[16218]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 2 instead
[Jun  5 16:57:00] DTMF[18469]: channel.c:4228 __ast_read: DTMF end emulation of '0' queued on SIP/1.1.1.1-0000001e
[Jun  5 16:57:22] DEBUG[16221]: chan_sip.c:8515 find_call: = Looking for  Call ID: 62124ba076dbbeb2696f02420563bb7c@2.2.2.2:5060 (Checking From) --From tag S3r9FDUjNc0Qa --To-tag as665299cd  
[Jun  5 16:57:22] DEBUG[16221]: chan_sip.c:25813 handle_incoming: **** Received BYE (8) - Command in SIP BYE
[Jun  5 16:57:22] DEBUG[16221]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '3.3.3.3' into...
[Jun  5 16:57:22] DEBUG[16221]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '3.3.3.3' and port ''.
[Jun  5 16:57:22] DEBUG[16221]: chan_sip.c:3373 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 62124ba076dbbeb2696f02420563bb7c@2.2.2.2:5060
[Jun  5 16:57:22] DEBUG[16221]: res_rtp_asterisk.c:2581 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x18bd528'
[Jun  5 16:57:22] DEBUG[16221]: chan_sip.c:26647 stop_session_timer: Session timer stopped: 183 - 62124ba076dbbeb2696f02420563bb7c@2.2.2.2:5060
[Jun  5 16:57:22] DEBUG[16221]: chan_sip.c:24622 handle_request_bye: Received bye, issuing owner hangup
[Jun  5 16:57:22] DEBUG[16221]: chan_sip.c:3684 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 3.3.3.3:5060
[Jun  5 16:57:22] DEBUG[18469]: channel.c:7238 ast_generic_bridge: Didn't get a frame from channel: SIP/CONF02-PILOT-0000001f
[Jun  5 16:57:22] DEBUG[18469]: res_rtp_asterisk.c:832 ast_rtp_update_source: Setting the marker bit due to a source update
[Jun  5 16:57:22] DEBUG[18469]: channel.c:7710 ast_channel_bridge: Bridge stops bridging channels SIP/1.1.1.1-0000001e and SIP/CONF02-PILOT-0000001f
[Jun  5 16:57:22] DEBUG[18469]: channel.c:2884 ast_hangup: Hanging up channel 'SIP/CONF02-PILOT-0000001f'
[Jun  5 16:57:22] DEBUG[18469]: chan_sip.c:6679 sip_hangup: Hangup call SIP/CONF02-PILOT-0000001f, SIP callid 62124ba076dbbeb2696f02420563bb7c@2.2.2.2:5060
[Jun  5 16:57:22] DEBUG[18469]: res_rtp_asterisk.c:2581 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x18bd528'
[Jun  5 16:57:22] DEBUG[18469]: app_dial.c:3029 dial_exec_full: Exiting with DIALSTATUS=ANSWER.
[Jun  5 16:57:22] DEBUG[18469]: pbx.c:5290 __ast_pbx_run: Spawn extension (default,2000,4) exited non-zero on 'SIP/1.1.1.1-0000001e'
  == Spawn extension (default, 2000, 4) exited non-zero on 'SIP/1.1.1.1-0000001e'
[Jun  5 16:57:22] DEBUG[18469]: channel.c:2735 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/1.1.1.1-0000001e'
[Jun  5 16:57:22] DEBUG[18469]: channel.c:2884 ast_hangup: Hanging up channel 'SIP/1.1.1.1-0000001e'
[Jun  5 16:57:22] DEBUG[18469]: chan_sip.c:6679 sip_hangup: Hangup call SIP/1.1.1.1-0000001e, SIP callid fbc8d639-4892-1231-3b9b-fe38fc8f3ce1
[Jun  5 16:57:22] DEBUG[18469]: res_rtp_asterisk.c:2581 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x18e6738'
[Jun  5 16:57:22] DEBUG[18469]: chan_sip.c:26647 stop_session_timer: Session timer stopped: 178 - fbc8d639-4892-1231-3b9b-fe38fc8f3ce1
[Jun  5 16:57:22] DEBUG[18469]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '1.1.1.1:5060' into...
[Jun  5 16:57:22] DEBUG[18469]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '1.1.1.1' and port '5060'.
[Jun  5 16:57:22] DEBUG[18469]: chan_sip.c:3684 __sip_xmit: Trying to put 'BYE sip:mod' onto UDP socket destined for 1.1.1.1:5060
[Jun  5 16:57:22] DEBUG[16197]: devicestate.c:344 _ast_device_state: No provider found, checking channel drivers for SIP - CONF02-PILOT
[Jun  5 16:57:22] DEBUG[16197]: chan_sip.c:27119 sip_devicestate: Checking device state for peer CONF02-PILOT
[Jun  5 16:57:22] DEBUG[16197]: devicestate.c:467 do_state_change: Changing state for SIP/CONF02-PILOT - state 1 (Not in use)
[Jun  5 16:57:22] DEBUG[16197]: devicestate.c:442 devstate_event: device 'SIP/CONF02-PILOT' state '1'
[Jun  5 16:57:22] DEBUG[16197]: devicestate.c:344 _ast_device_state: No provider found, checking channel drivers for SIP - 1.1.1.1
[Jun  5 16:57:22] DEBUG[16197]: chan_sip.c:27119 sip_devicestate: Checking device state for peer 1.1.1.1
[Jun  5 16:57:22] DEBUG[16197]: devicestate.c:467 do_state_change: Changing state for SIP/1.1.1.1 - state 4 (Invalid)
[Jun  5 16:57:22] DEBUG[16197]: devicestate.c:442 devstate_event: device 'SIP/1.1.1.1' state '4'
[Jun  5 16:57:22] DEBUG[16231]: app_queue.c:1544 handle_statechange: Device 'SIP/CONF02-PILOT' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jun  5 16:57:22] DEBUG[16231]: app_queue.c:1544 handle_statechange: Device 'SIP/1.1.1.1' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
[Jun  5 16:57:22] DEBUG[16221]: chan_sip.c:8515 find_call: = Looking for  Call ID: fbc8d639-4892-1231-3b9b-fe38fc8f3ce1 (Checking To) --From tag as4cb21dcd --To-tag v13F1m2BQ2mtH  
[Jun  5 16:57:22] DEBUG[16221]: chan_sip.c:4368 __sip_ack: Stopping retransmission on 'fbc8d639-4892-1231-3b9b-fe38fc8f3ce1' of Request 102: Match Found
[Jun  5 16:57:22] DEBUG[16221]: chan_sip.c:6445 sip_destroy: Destroying SIP dialog fbc8d639-4892-1231-3b9b-fe38fc8f3ce1
[Jun  5 16:57:22] DEBUG[16221]: rtp_engine.c:298 instance_destructor: Destroyed RTP instance '0x18e6738'
[Jun  5 16:57:23] DEBUG[16221]: chan_sip.c:8515 find_call: = Looking for  Call ID: 4e26979371737ed82e99e378241ec665@2.2.2.2:5060 (Checking From) --From tag QH6QcQSBUtKjK --To-tag as63d0280d  
[Jun  5 16:57:23] DEBUG[16221]: chan_sip.c:25813 handle_incoming: **** Received BYE (8) - Command in SIP BYE
[Jun  5 16:57:23] DEBUG[16221]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '3.3.3.3' into...
[Jun  5 16:57:23] DEBUG[16221]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '3.3.3.3' and port ''.
[Jun  5 16:57:23] DEBUG[16221]: chan_sip.c:3373 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 4e26979371737ed82e99e378241ec665@2.2.2.2:5060
[Jun  5 16:57:23] DEBUG[16221]: res_rtp_asterisk.c:2581 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x1896e28'
[Jun  5 16:57:23] DEBUG[16221]: chan_sip.c:26647 stop_session_timer: Session timer stopped: 174 - 4e26979371737ed82e99e378241ec665@2.2.2.2:5060
[Jun  5 16:57:23] DEBUG[16221]: chan_sip.c:24622 handle_request_bye: Received bye, issuing owner hangup
[Jun  5 16:57:23] DEBUG[16221]: chan_sip.c:3684 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 3.3.3.3:5060
[Jun  5 16:57:23] DEBUG[18430]: channel.c:7238 ast_generic_bridge: Didn't get a frame from channel: SIP/CONF02-PILOT-0000001d
[Jun  5 16:57:23] DEBUG[18430]: res_rtp_asterisk.c:832 ast_rtp_update_source: Setting the marker bit due to a source update
[Jun  5 16:57:23] DEBUG[18430]: channel.c:7710 ast_channel_bridge: Bridge stops bridging channels SIP/1.1.1.1-0000001c and SIP/CONF02-PILOT-0000001d
[Jun  5 16:57:23] DEBUG[18430]: channel.c:2884 ast_hangup: Hanging up channel 'SIP/CONF02-PILOT-0000001d'
[Jun  5 16:57:23] DEBUG[18430]: chan_sip.c:6679 sip_hangup: Hangup call SIP/CONF02-PILOT-0000001d, SIP callid 4e26979371737ed82e99e378241ec665@2.2.2.2:5060
[Jun  5 16:57:23] DEBUG[18430]: res_rtp_asterisk.c:2581 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x1896e28'
[Jun  5 16:57:23] DEBUG[18430]: app_dial.c:3029 dial_exec_full: Exiting with DIALSTATUS=ANSWER.
[Jun  5 16:57:23] DEBUG[18430]: pbx.c:5290 __ast_pbx_run: Spawn extension (default,1000,4) exited non-zero on 'SIP/1.1.1.1-0000001c'
  == Spawn extension (default, 1000, 4) exited non-zero on 'SIP/1.1.1.1-0000001c'
[Jun  5 16:57:23] DEBUG[18430]: channel.c:2735 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/1.1.1.1-0000001c'
[Jun  5 16:57:23] DEBUG[18430]: channel.c:2884 ast_hangup: Hanging up channel 'SIP/1.1.1.1-0000001c'
[Jun  5 16:57:23] DEBUG[18430]: chan_sip.c:6679 sip_hangup: Hangup call SIP/1.1.1.1-0000001c, SIP callid ef9ce4dc-4892-1231-3b9b-fe38fc8f3ce1
[Jun  5 16:57:23] DEBUG[18430]: res_rtp_asterisk.c:2581 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x1907098'
[Jun  5 16:57:23] DEBUG[18430]: chan_sip.c:26647 stop_session_timer: Session timer stopped: 169 - ef9ce4dc-4892-1231-3b9b-fe38fc8f3ce1
[Jun  5 16:57:23] DEBUG[18430]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '1.1.1.1:5060' into...
[Jun  5 16:57:23] DEBUG[18430]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '1.1.1.1' and port '5060'.
[Jun  5 16:57:23] DEBUG[18430]: chan_sip.c:3684 __sip_xmit: Trying to put 'BYE sip:mod' onto UDP socket destined for 1.1.1.1:5060
[Jun  5 16:57:23] DEBUG[16197]: devicestate.c:344 _ast_device_state: No provider found, checking channel drivers for SIP - CONF02-PILOT
[Jun  5 16:57:23] DEBUG[16197]: chan_sip.c:27119 sip_devicestate: Checking device state for peer CONF02-PILOT
[Jun  5 16:57:23] DEBUG[16197]: devicestate.c:467 do_state_change: Changing state for SIP/CONF02-PILOT - state 1 (Not in use)
[Jun  5 16:57:23] DEBUG[16197]: devicestate.c:442 devstate_event: device 'SIP/CONF02-PILOT' state '1'
[Jun  5 16:57:23] DEBUG[16197]: devicestate.c:344 _ast_device_state: No provider found, checking channel drivers for SIP - 1.1.1.1
[Jun  5 16:57:23] DEBUG[16197]: chan_sip.c:27119 sip_devicestate: Checking device state for peer 1.1.1.1
[Jun  5 16:57:23] DEBUG[16197]: devicestate.c:467 do_state_change: Changing state for SIP/1.1.1.1 - state 4 (Invalid)
[Jun  5 16:57:23] DEBUG[16197]: devicestate.c:442 devstate_event: device 'SIP/1.1.1.1' state '4'
[Jun  5 16:57:23] DEBUG[16231]: app_queue.c:1544 handle_statechange: Device 'SIP/CONF02-PILOT' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jun  5 16:57:23] DEBUG[16231]: app_queue.c:1544 handle_statechange: Device 'SIP/1.1.1.1' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
[Jun  5 16:57:23] DEBUG[16221]: chan_sip.c:8515 find_call: = Looking for  Call ID: ef9ce4dc-4892-1231-3b9b-fe38fc8f3ce1 (Checking To) --From tag as43d9d9c6 --To-tag UraQZSH8SSy7N  
[Jun  5 16:57:23] DEBUG[16221]: chan_sip.c:4368 __sip_ack: Stopping retransmission on 'ef9ce4dc-4892-1231-3b9b-fe38fc8f3ce1' of Request 102: Match Found
[Jun  5 16:57:23] DEBUG[16221]: chan_sip.c:6445 sip_destroy: Destroying SIP dialog ef9ce4dc-4892-1231-3b9b-fe38fc8f3ce1
[Jun  5 16:57:23] DEBUG[16221]: rtp_engine.c:298 instance_destructor: Destroyed RTP instance '0x1907098'
[Jun  5 16:57:54] DEBUG[16221]: chan_sip.c:4224 __sip_autodestruct: Auto destroying SIP dialog '62124ba076dbbeb2696f02420563bb7c@2.2.2.2:5060'
[Jun  5 16:57:54] DEBUG[16221]: chan_sip.c:6445 sip_destroy: Destroying SIP dialog 62124ba076dbbeb2696f02420563bb7c@2.2.2.2:5060
[Jun  5 16:57:54] DEBUG[16221]: rtp_engine.c:298 instance_destructor: Destroyed RTP instance '0x18bd528'
[Jun  5 16:57:55] DEBUG[16221]: chan_sip.c:4224 __sip_autodestruct: Auto destroying SIP dialog '4e26979371737ed82e99e378241ec665@2.2.2.2:5060'
[Jun  5 16:57:55] DEBUG[16221]: chan_sip.c:6445 sip_destroy: Destroying SIP dialog 4e26979371737ed82e99e378241ec665@2.2.2.2:5060
[Jun  5 16:57:55] DEBUG[16221]: rtp_engine.c:298 instance_destructor: Destroyed RTP instance '0x1896e28'