[Apr 8 16:05:11] Asterisk SVN-branch-12-r411945 built by root @ newtonr-laptop on a x86_64 running Linux on 2014-04-08 19:29:04 UTC [Apr 8 16:05:11] DEBUG[20233] config.c: Parsing /etc/asterisk/logger.conf [Apr 8 16:05:11] VERBOSE[20233] config.c: == Parsing '/etc/asterisk/logger.conf': Found [Apr 8 16:05:11] VERBOSE[20233] logger.c: Asterisk Queue Logger restarted [Apr 8 16:05:15] DEBUG[19931] chan_sip.c: = Looking for Call ID: owjDwcyDEaN8UH-hVGSG7IKtfnFO-DFO (Checking From) --From tag eaRpRZwRc5WDYyFQCkdyR1wI9nzZZ2Ty --To-tag [Apr 8 16:05:15] DEBUG[19931] acl.c: For destination '10.24.18.16', our source address is '10.24.18.124'. [Apr 8 16:05:15] DEBUG[19931] chan_sip.c: Setting AST_TRANSPORT_UDP with address 10.24.18.124:5060 [Apr 8 16:05:15] DEBUG[19931] netsock2.c: Splitting '10.24.18.16:5060' into... [Apr 8 16:05:15] DEBUG[19931] netsock2.c: ...host '10.24.18.16' and port '5060'. [Apr 8 16:05:15] DEBUG[19931] chan_sip.c: Allocating new SIP dialog for owjDwcyDEaN8UH-hVGSG7IKtfnFO-DFO - SUBSCRIBE (No RTP) [Apr 8 16:05:15] DEBUG[19931] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Apr 8 16:05:15] DEBUG[19931] netsock2.c: Splitting '10.24.18.16:5060' into... [Apr 8 16:05:15] DEBUG[19931] netsock2.c: ...host '10.24.18.16' and port '5060'. [Apr 8 16:05:15] DEBUG[19931] chan_sip.c: build_route: Contact hop: "RustyONE" [Apr 8 16:05:15] DEBUG[19931] netsock2.c: Splitting '10.24.18.124' into... [Apr 8 16:05:15] DEBUG[19931] netsock2.c: ...host '10.24.18.124' and port ''. [Apr 8 16:05:15] DEBUG[19931] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 10.24.18.16:5060 [Apr 8 16:05:15] DEBUG[19931] chan_sip.c: = Looking for Call ID: owjDwcyDEaN8UH-hVGSG7IKtfnFO-DFO (Checking From) --From tag eaRpRZwRc5WDYyFQCkdyR1wI9nzZZ2Ty --To-tag [Apr 8 16:05:15] DEBUG[19931] netsock2.c: Splitting '10.24.18.124:5060' into... [Apr 8 16:05:15] DEBUG[19931] netsock2.c: ...host '10.24.18.124' and port '5060'. [Apr 8 16:05:15] DEBUG[19931] netsock2.c: Splitting '10.24.18.124:5060' into... [Apr 8 16:05:15] DEBUG[19931] netsock2.c: ...host '10.24.18.124' and port '5060'. [Apr 8 16:05:15] DEBUG[19931] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Apr 8 16:05:15] DEBUG[19931] netsock2.c: Splitting '10.24.18.16:5060' into... [Apr 8 16:05:15] DEBUG[19931] netsock2.c: ...host '10.24.18.16' and port '5060'. [Apr 8 16:05:15] DEBUG[19931] chan_sip.c: build_route: Retaining previous route: [Apr 8 16:05:15] DEBUG[19931] netsock2.c: Splitting '10.24.18.124' into... [Apr 8 16:05:15] DEBUG[19931] netsock2.c: ...host '10.24.18.124' and port ''. [Apr 8 16:05:15] DEBUG[19931] netsock2.c: Splitting '10.24.18.124:5060' into... [Apr 8 16:05:15] DEBUG[19931] netsock2.c: ...host '10.24.18.124' and port ''. [Apr 8 16:05:15] DEBUG[19931] netsock2.c: Splitting '10.24.18.124' into... [Apr 8 16:05:15] DEBUG[19931] netsock2.c: ...host '10.24.18.124' and port ''. [Apr 8 16:05:15] DEBUG[19931] chan_sip.c: Trying to put 'SIP/2.0 404' onto UDP socket destined for 10.24.18.16:5060 [Apr 8 16:05:15] DEBUG[19931] chan_sip.c: Destroying SIP dialog owjDwcyDEaN8UH-hVGSG7IKtfnFO-DFO [Apr 8 16:05:16] DEBUG[19931] chan_sip.c: = Looking for Call ID: KGlMtfIl-KgrUYwasot8XUZdVQydmlVO (Checking From) --From tag zm8Y7r0zbR8Q575x4STWMxDuQZLaYZQ8 --To-tag [Apr 8 16:05:16] DEBUG[19931] acl.c: For destination '10.24.18.16', our source address is '10.24.18.124'. [Apr 8 16:05:16] DEBUG[19931] chan_sip.c: Setting AST_TRANSPORT_UDP with address 10.24.18.124:5060 [Apr 8 16:05:16] DEBUG[19931] netsock2.c: Splitting '10.24.18.16:5060' into... [Apr 8 16:05:16] DEBUG[19931] netsock2.c: ...host '10.24.18.16' and port '5060'. [Apr 8 16:05:16] DEBUG[19931] chan_sip.c: Allocating new SIP dialog for KGlMtfIl-KgrUYwasot8XUZdVQydmlVO - INVITE (No RTP) [Apr 8 16:05:16] DEBUG[19931][C-00000009] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Apr 8 16:05:16] DEBUG[19931][C-00000009] sip/reqresp_parser.c: Begin: parsing SIP "Supported: replaces, 100rel, timer, norefersub" [Apr 8 16:05:16] DEBUG[19931][C-00000009] sip/reqresp_parser.c: Found SIP option: -replaces- [Apr 8 16:05:16] DEBUG[19931][C-00000009] sip/reqresp_parser.c: Matched SIP option: replaces [Apr 8 16:05:16] DEBUG[19931][C-00000009] sip/reqresp_parser.c: Found SIP option: -100rel- [Apr 8 16:05:16] DEBUG[19931][C-00000009] sip/reqresp_parser.c: Matched SIP option: 100rel [Apr 8 16:05:16] DEBUG[19931][C-00000009] sip/reqresp_parser.c: Found SIP option: -timer- [Apr 8 16:05:16] DEBUG[19931][C-00000009] sip/reqresp_parser.c: Matched SIP option: timer [Apr 8 16:05:16] DEBUG[19931][C-00000009] sip/reqresp_parser.c: Found SIP option: -norefersub- [Apr 8 16:05:16] DEBUG[19931][C-00000009] sip/reqresp_parser.c: Matched SIP option: norefersub [Apr 8 16:05:16] DEBUG[19931][C-00000009] netsock2.c: Splitting '10.24.18.16:5060' into... [Apr 8 16:05:16] DEBUG[19931][C-00000009] netsock2.c: ...host '10.24.18.16' and port '5060'. [Apr 8 16:05:16] DEBUG[19931][C-00000009] netsock2.c: Splitting '10.24.18.124' into... [Apr 8 16:05:16] DEBUG[19931][C-00000009] netsock2.c: ...host '10.24.18.124' and port ''. [Apr 8 16:05:16] DEBUG[19931][C-00000009] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 10.24.18.16:5060 [Apr 8 16:05:16] DEBUG[19931] chan_sip.c: = Looking for Call ID: KGlMtfIl-KgrUYwasot8XUZdVQydmlVO (Checking From) --From tag zm8Y7r0zbR8Q575x4STWMxDuQZLaYZQ8 --To-tag as7a64000d [Apr 8 16:05:16] DEBUG[19931][C-00000009] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Apr 8 16:05:16] DEBUG[19931][C-00000009] chan_sip.c: Stopping retransmission on 'KGlMtfIl-KgrUYwasot8XUZdVQydmlVO' of Response 17270: Match Found [Apr 8 16:05:16] DEBUG[19931] chan_sip.c: = Looking for Call ID: KGlMtfIl-KgrUYwasot8XUZdVQydmlVO (Checking From) --From tag zm8Y7r0zbR8Q575x4STWMxDuQZLaYZQ8 --To-tag [Apr 8 16:05:16] DEBUG[19931] netsock2.c: Splitting '10.24.18.124' into... [Apr 8 16:05:16] DEBUG[19931] netsock2.c: ...host '10.24.18.124' and port ''. [Apr 8 16:05:16] DEBUG[19931] netsock2.c: Splitting '10.24.18.124' into... [Apr 8 16:05:16] DEBUG[19931] netsock2.c: ...host '10.24.18.124' and port ''. [Apr 8 16:05:16] DEBUG[19931][C-00000009] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Apr 8 16:05:16] DEBUG[19931][C-00000009] netsock2.c: Splitting '10.24.18.16:5060' into... [Apr 8 16:05:16] DEBUG[19931][C-00000009] netsock2.c: ...host '10.24.18.16' and port '5060'. [Apr 8 16:05:16] DEBUG[19931][C-00000009] netsock2.c: Splitting '10.24.18.124' into... [Apr 8 16:05:16] DEBUG[19931][C-00000009] netsock2.c: ...host '10.24.18.124' and port ''. [Apr 8 16:05:16] DEBUG[19931][C-00000009] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f717002bb28' [Apr 8 16:05:16] DEBUG[19931][C-00000009] res_rtp_asterisk.c: Allocated port 12388 for RTP instance '0x7f717002bb28' [Apr 8 16:05:16] DEBUG[19931][C-00000009] netsock2.c: Splitting '10.24.18.124' into... [Apr 8 16:05:16] DEBUG[19931][C-00000009] netsock2.c: ...host '10.24.18.124' and port ''. [Apr 8 16:05:16] DEBUG[19931][C-00000009] rtp_engine.c: RTP instance '0x7f717002bb28' is setup and ready to go [Apr 8 16:05:16] DEBUG[19931][C-00000009] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f717002bb28' [Apr 8 16:05:16] VERBOSE[19931][C-00000009] netsock2.c: == Using SIP RTP CoS mark 5 [Apr 8 16:05:16] DEBUG[19931][C-00000009] chan_sip.c: Setting NAT on RTP to Off [Apr 8 16:05:16] DEBUG[19931][C-00000009] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Apr 8 16:05:16] DEBUG[19931][C-00000009] chan_sip.c: Processing session-level SDP o=- 92362407 92362407 IN IP4 10.24.18.16... OK. [Apr 8 16:05:16] DEBUG[19931][C-00000009] chan_sip.c: Processing session-level SDP s=digphn... UNSUPPORTED OR FAILED. [Apr 8 16:05:16] DEBUG[19931][C-00000009] netsock2.c: Splitting '10.24.18.16' into... [Apr 8 16:05:16] DEBUG[19931][C-00000009] netsock2.c: ...host '10.24.18.16' and port ''. [Apr 8 16:05:16] DEBUG[19931][C-00000009] chan_sip.c: Processing session-level SDP c=IN IP4 10.24.18.16... OK. [Apr 8 16:05:16] DEBUG[19931][C-00000009] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Apr 8 16:05:16] DEBUG[19931][C-00000009] chan_sip.c: Processing session-level SDP a=X-nat:0... UNSUPPORTED OR FAILED. [Apr 8 16:05:16] DEBUG[19931][C-00000009] rtp_engine.c: Setting payload 0 based on m type on 0x7f7147a9bf40 [Apr 8 16:05:16] DEBUG[19931][C-00000009] rtp_engine.c: Setting payload 8 based on m type on 0x7f7147a9bf40 [Apr 8 16:05:16] DEBUG[19931][C-00000009] rtp_engine.c: Setting payload 9 based on m type on 0x7f7147a9bf40 [Apr 8 16:05:16] DEBUG[19931][C-00000009] rtp_engine.c: Setting payload 96 based on m type on 0x7f7147a9bf40 [Apr 8 16:05:16] DEBUG[19931][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=rtcp:4021 IN IP4 10.24.18.16... UNSUPPORTED OR FAILED. [Apr 8 16:05:16] DEBUG[19931][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Apr 8 16:05:16] DEBUG[19931][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Apr 8 16:05:16] DEBUG[19931][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK. [Apr 8 16:05:16] DEBUG[19931][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Apr 8 16:05:16] DEBUG[19931][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:96 telephone-event/8000... OK. [Apr 8 16:05:16] DEBUG[19931][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=fmtp:96 0-15... UNSUPPORTED OR FAILED. [Apr 8 16:05:16] DEBUG[19931][C-00000009] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f717002bb28' [Apr 8 16:05:16] DEBUG[19931][C-00000009] rtp_engine.c: Copying payload 0 from 0x7f7147a9bf40 to 0x7f717002bc68 [Apr 8 16:05:16] DEBUG[19931][C-00000009] rtp_engine.c: Copying payload 8 from 0x7f7147a9bf40 to 0x7f717002bc68 [Apr 8 16:05:16] DEBUG[19931][C-00000009] rtp_engine.c: Copying payload 9 from 0x7f7147a9bf40 to 0x7f717002bc68 [Apr 8 16:05:16] DEBUG[19931][C-00000009] rtp_engine.c: Copying payload 96 from 0x7f7147a9bf40 to 0x7f717002bc68 [Apr 8 16:05:16] DEBUG[19931][C-00000009] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f717002bb28' [Apr 8 16:05:16] DEBUG[19931][C-00000009] chan_sip.c: We're settling with these formats: (ulaw) [Apr 8 16:05:16] DEBUG[19931][C-00000009] chan_sip.c: Checking SIP call limits for device 6001 [Apr 8 16:05:16] DEBUG[19931][C-00000009] chan_sip.c: Updating call counter for incoming call [Apr 8 16:05:16] DEBUG[19931][C-00000009] netsock2.c: Splitting '10.24.18.124' into... [Apr 8 16:05:16] DEBUG[19931][C-00000009] netsock2.c: ...host '10.24.18.124' and port ''. [Apr 8 16:05:16] DEBUG[19931][C-00000009] netsock2.c: Splitting '10.24.18.124' into... [Apr 8 16:05:16] DEBUG[19931][C-00000009] netsock2.c: ...host '10.24.18.124' and port ''. [Apr 8 16:05:16] DEBUG[19931][C-00000009] chan_sip.c: Incoming INVITE with 'timer' option supported [Apr 8 16:05:16] DEBUG[19931][C-00000009] chan_sip.c: INVITE also has "Session-Expires" header. [Apr 8 16:05:16] DEBUG[19931][C-00000009] chan_sip.c: Session-Expires: 1800 [Apr 8 16:05:16] DEBUG[19931][C-00000009] chan_sip.c: INVITE also has "Min-SE" header. [Apr 8 16:05:16] DEBUG[19931][C-00000009] chan_sip.c: Received Min-SE: 90 [Apr 8 16:05:16] DEBUG[19931][C-00000009] chan_sip.c: *** Our native formats are (ulaw) [Apr 8 16:05:16] DEBUG[19931][C-00000009] chan_sip.c: *** Joint capabilities are (ulaw) [Apr 8 16:05:16] DEBUG[19931][C-00000009] chan_sip.c: *** Our capabilities are (ulaw) [Apr 8 16:05:16] DEBUG[19931][C-00000009] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw [Apr 8 16:05:16] DEBUG[19931][C-00000009] chan_sip.c: This channel will not be able to handle video. [Apr 8 16:05:16] DEBUG[19931][C-00000009] chan_sip.c: build_route: Contact hop: "RustyONE" [Apr 8 16:05:16] DEBUG[19931][C-00000009] chan_sip.c: Session timer started: 717 - KGlMtfIl-KgrUYwasot8XUZdVQydmlVO 900000ms [Apr 8 16:05:16] DEBUG[19931][C-00000009] chan_sip.c: SIP/6001-0000001b: New call is still down.... Trying... [Apr 8 16:05:16] DEBUG[19931][C-00000009] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 10.24.18.16:5060 [Apr 8 16:05:16] DEBUG[19894] devicestate.c: No provider found, checking channel drivers for SIP - 6001 [Apr 8 16:05:16] DEBUG[19894] chan_sip.c: Checking device state for peer 6001 [Apr 8 16:05:16] DEBUG[19894] devicestate.c: Changing state for SIP/6001 - state 1 (Not in use) [Apr 8 16:05:16] DEBUG[20234][C-00000009] pbx.c: Launching 'AGI' [Apr 8 16:05:16] VERBOSE[20234][C-00000009] pbx.c: -- Executing [1@agi-test-context:1] AGI("SIP/6001-0000001b", "/root/asterisk.sh") in new stack [Apr 8 16:05:16] VERBOSE[20234][C-00000009] res_agi.c: -- Launched AGI Script /root/asterisk.sh [Apr 8 16:05:16] VERBOSE[20234][C-00000009] res_agi.c: AGI Tx >> agi_request: /root/asterisk.sh [Apr 8 16:05:16] VERBOSE[20234][C-00000009] res_agi.c: AGI Tx >> agi_channel: SIP/6001-0000001b [Apr 8 16:05:16] VERBOSE[20234][C-00000009] res_agi.c: AGI Tx >> agi_language: en [Apr 8 16:05:16] VERBOSE[20234][C-00000009] res_agi.c: AGI Tx >> agi_type: SIP [Apr 8 16:05:16] VERBOSE[20234][C-00000009] res_agi.c: AGI Tx >> agi_uniqueid: 1396991116.45 [Apr 8 16:05:16] VERBOSE[20234][C-00000009] res_agi.c: AGI Tx >> agi_version: SVN-branch-12-r411945 [Apr 8 16:05:16] VERBOSE[20234][C-00000009] res_agi.c: AGI Tx >> agi_callerid: 6001 [Apr 8 16:05:16] VERBOSE[20234][C-00000009] res_agi.c: AGI Tx >> agi_calleridname: Alice [Apr 8 16:05:16] VERBOSE[20234][C-00000009] res_agi.c: AGI Tx >> agi_callingpres: 0 [Apr 8 16:05:16] VERBOSE[20234][C-00000009] res_agi.c: AGI Tx >> agi_callingani2: 0 [Apr 8 16:05:16] VERBOSE[20234][C-00000009] res_agi.c: AGI Tx >> agi_callington: 0 [Apr 8 16:05:16] VERBOSE[20234][C-00000009] res_agi.c: AGI Tx >> agi_callingtns: 0 [Apr 8 16:05:16] VERBOSE[20234][C-00000009] res_agi.c: AGI Tx >> agi_dnid: 1 [Apr 8 16:05:16] VERBOSE[20234][C-00000009] res_agi.c: AGI Tx >> agi_rdnis: unknown [Apr 8 16:05:16] VERBOSE[20234][C-00000009] res_agi.c: AGI Tx >> agi_context: agi-test-context [Apr 8 16:05:16] VERBOSE[20234][C-00000009] res_agi.c: AGI Tx >> agi_extension: 1 [Apr 8 16:05:16] VERBOSE[20234][C-00000009] res_agi.c: AGI Tx >> agi_priority: 1 [Apr 8 16:05:16] VERBOSE[20234][C-00000009] res_agi.c: AGI Tx >> agi_enhanced: 0.0 [Apr 8 16:05:16] VERBOSE[20234][C-00000009] res_agi.c: AGI Tx >> agi_accountcode: [Apr 8 16:05:16] VERBOSE[20234][C-00000009] res_agi.c: AGI Tx >> agi_threadid: 140124501767936 [Apr 8 16:05:16] VERBOSE[20234][C-00000009] res_agi.c: AGI Tx >> [Apr 8 16:05:16] VERBOSE[20234][C-00000009] res_agi.c: AGI Rx << ANSWER [Apr 8 16:05:16] DEBUG[19894] devicestate.c: No provider found, checking channel drivers for SIP - 6001 [Apr 8 16:05:16] DEBUG[19894] chan_sip.c: Checking device state for peer 6001 [Apr 8 16:05:16] DEBUG[19894] devicestate.c: Changing state for SIP/6001 - state 1 (Not in use) [Apr 8 16:05:16] DEBUG[20234][C-00000009] chan_sip.c: SIP answering channel: SIP/6001-0000001b [Apr 8 16:05:16] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Setting the marker bit due to a source update [Apr 8 16:05:16] DEBUG[20234][C-00000009] chan_sip.c: Setting framing from config on incoming call [Apr 8 16:05:16] DEBUG[20234][C-00000009] chan_sip.c: ** Our capability: (ulaw) Video flag: True Text flag: True [Apr 8 16:05:16] DEBUG[20234][C-00000009] chan_sip.c: ** Our prefcodec: (nothing) [Apr 8 16:05:16] DEBUG[20234][C-00000009] chan_sip.c: -- Done with adding codecs to SDP [Apr 8 16:05:16] DEBUG[20234][C-00000009] chan_sip.c: Done building SDP. Settling with this capability: (ulaw) [Apr 8 16:05:16] DEBUG[20234][C-00000009] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.24.18.16:5060 [Apr 8 16:05:16] DEBUG[20234][C-00000009] res_rtp_asterisk.c: 0x7f7170021d10 -- Probation learning mode pass with source address 10.24.18.16:4020 [Apr 8 16:05:16] VERBOSE[20234][C-00000009] res_rtp_asterisk.c: > 0x7f7170021d10 -- Probation passed - setting RTP source address to 10.24.18.16:4020 [Apr 8 16:05:16] VERBOSE[20234][C-00000009] res_agi.c: AGI Tx >> 200 result=0 [Apr 8 16:05:16] VERBOSE[20234][C-00000009] res_agi.c: AGI Rx << EXEC Dial SIP/6004 [Apr 8 16:05:16] VERBOSE[20234][C-00000009] res_agi.c: -- AGI Script Executing Application: (Dial) Options: (SIP/6004) [Apr 8 16:05:16] DEBUG[20234][C-00000009] chan_sip.c: Asked to create a SIP channel with formats: (ulaw) [Apr 8 16:05:16] DEBUG[20234][C-00000009] chan_sip.c: Allocating new SIP dialog for 5f86de4661e95566257a2adc51029315@127.0.1.1:5060 - INVITE (No RTP) [Apr 8 16:05:16] DEBUG[20234][C-00000009] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f71d4009a18' [Apr 8 16:05:16] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Allocated port 17158 for RTP instance '0x7f71d4009a18' [Apr 8 16:05:16] DEBUG[20234][C-00000009] netsock2.c: Splitting '10.24.18.124' into... [Apr 8 16:05:16] DEBUG[20234][C-00000009] netsock2.c: ...host '10.24.18.124' and port ''. [Apr 8 16:05:16] DEBUG[20234][C-00000009] rtp_engine.c: RTP instance '0x7f71d4009a18' is setup and ready to go [Apr 8 16:05:16] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f71d4009a18' [Apr 8 16:05:16] VERBOSE[20234][C-00000009] netsock2.c: == Using SIP RTP CoS mark 5 [Apr 8 16:05:16] DEBUG[20234][C-00000009] chan_sip.c: Setting NAT on RTP to Off [Apr 8 16:05:16] DEBUG[20234][C-00000009] acl.c: For destination '10.24.18.166', our source address is '10.24.18.124'. [Apr 8 16:05:16] DEBUG[20234][C-00000009] chan_sip.c: Setting AST_TRANSPORT_UDP with address 10.24.18.124:5060 [Apr 8 16:05:16] DEBUG[20234][C-00000009] chan_sip.c: Setting NAT on RTP to Off [Apr 8 16:05:16] DEBUG[20234][C-00000009] chan_sip.c: SIP call-id changed from '5f86de4661e95566257a2adc51029315@127.0.1.1:5060' to '17ec2f31558556e17e92e5fc13412e2e@10.24.18.124:5060' [Apr 8 16:05:16] DEBUG[20234][C-00000009] chan_sip.c: *** Our native formats are (ulaw) [Apr 8 16:05:16] DEBUG[20234][C-00000009] chan_sip.c: *** Joint capabilities are (ulaw) [Apr 8 16:05:16] DEBUG[20234][C-00000009] chan_sip.c: *** Our capabilities are (ulaw) [Apr 8 16:05:16] DEBUG[20234][C-00000009] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw [Apr 8 16:05:16] DEBUG[20234][C-00000009] chan_sip.c: *** Our preferred formats from the incoming channel are (ulaw) [Apr 8 16:05:16] DEBUG[20234][C-00000009] chan_sip.c: This channel will not be able to handle video. [Apr 8 16:05:16] DEBUG[20234][C-00000009] channel_internal_api.c: Channel Call ID changing from [C-00000009] to [C-00000009] [Apr 8 16:05:16] DEBUG[20234][C-00000009] chan_sip.c: Outgoing Call for 6004 [Apr 8 16:05:16] DEBUG[20234][C-00000009] chan_sip.c: Updating call counter for outgoing call [Apr 8 16:05:16] DEBUG[20234][C-00000009] chan_sip.c: ** Our capability: (ulaw) Video flag: False Text flag: False [Apr 8 16:05:16] DEBUG[20234][C-00000009] chan_sip.c: ** Our prefcodec: (ulaw) [Apr 8 16:05:16] DEBUG[20234][C-00000009] chan_sip.c: -- Done with adding codecs to SDP [Apr 8 16:05:16] DEBUG[20234][C-00000009] chan_sip.c: Done building SDP. Settling with this capability: (ulaw) [Apr 8 16:05:16] DEBUG[20234][C-00000009] chan_sip.c: Initializing initreq for method INVITE - callid 17ec2f31558556e17e92e5fc13412e2e@10.24.18.124:5060 [Apr 8 16:05:16] DEBUG[20234][C-00000009] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 10.24.18.166:5060 [Apr 8 16:05:16] VERBOSE[20234][C-00000009] app_dial.c: -- Called SIP/6004 [Apr 8 16:05:16] DEBUG[20234][C-00000009] channel.c: SIP/6001-0000001b: Dropping redundant connected line update "David" <6004>. [Apr 8 16:05:16] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:16] DEBUG[19931] chan_sip.c: = Looking for Call ID: 17ec2f31558556e17e92e5fc13412e2e@10.24.18.124:5060 (Checking To) --From tag as0f0ed517 --To-tag [Apr 8 16:05:16] DEBUG[19931][C-00000009] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '17ec2f31558556e17e92e5fc13412e2e@10.24.18.124:5060' Request 102: Found [Apr 8 16:05:16] DEBUG[19931][C-00000009] chan_sip.c: SIP response 100 to standard invite [Apr 8 16:05:16] DEBUG[19931] chan_sip.c: = Looking for Call ID: 17ec2f31558556e17e92e5fc13412e2e@10.24.18.124:5060 (Checking To) --From tag as0f0ed517 --To-tag 1095016331 [Apr 8 16:05:16] DEBUG[19931][C-00000009] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '17ec2f31558556e17e92e5fc13412e2e@10.24.18.124:5060' Request 102: Found [Apr 8 16:05:16] DEBUG[19931][C-00000009] chan_sip.c: SIP response 180 to standard invite [Apr 8 16:05:16] DEBUG[19931][C-00000009] chan_sip.c: build_route: Contact hop: [Apr 8 16:05:16] DEBUG[19894] devicestate.c: No provider found, checking channel drivers for SIP - 6004 [Apr 8 16:05:16] DEBUG[19894] chan_sip.c: Checking device state for peer 6004 [Apr 8 16:05:16] DEBUG[19894] devicestate.c: Changing state for SIP/6004 - state 1 (Not in use) [Apr 8 16:05:16] VERBOSE[20234][C-00000009] app_dial.c: -- SIP/6004-0000001c is ringing [Apr 8 16:05:16] DEBUG[20234][C-00000009] rtp_engine.c: Setting early bridge SDP of 'SIP/6001-0000001b' with that of 'SIP/6004-0000001c' [Apr 8 16:05:16] DEBUG[20234][C-00000009] channel.c: Driver for channel 'SIP/6001-0000001b' does not support indication 3, emulating it [Apr 8 16:05:16] DEBUG[20234][C-00000009] channel.c: Set channel SIP/6001-0000001b to write format slin [Apr 8 16:05:16] DEBUG[20234][C-00000009] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Apr 8 16:05:16] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:16] DEBUG[19931] chan_sip.c: = Looking for Call ID: KGlMtfIl-KgrUYwasot8XUZdVQydmlVO (Checking From) --From tag zm8Y7r0zbR8Q575x4STWMxDuQZLaYZQ8 --To-tag as7c85b754 [Apr 8 16:05:16] DEBUG[19931][C-00000009] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Apr 8 16:05:16] DEBUG[19931][C-00000009] chan_sip.c: Stopping retransmission on 'KGlMtfIl-KgrUYwasot8XUZdVQydmlVO' of Response 17271: Match Found [Apr 8 16:05:16] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Ooh, format changed from unknown to ulaw [Apr 8 16:05:16] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Created smoother: format: ulaw ms: 20 len: 160 [Apr 8 16:05:16] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:17] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:18] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:18] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:18] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:18] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:18] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:18] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:18] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:18] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:18] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:18] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:18] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:18] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:18] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:18] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:18] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:18] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:18] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:18] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:18] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:18] DEBUG[20234][C-00000009] res_rtp_asterisk.c: No remote address on RTP instance '0x7f71d4009a18' so dropping frame [Apr 8 16:05:18] DEBUG[19931] chan_sip.c: = Looking for Call ID: 17ec2f31558556e17e92e5fc13412e2e@10.24.18.124:5060 (Checking To) --From tag as0f0ed517 --To-tag 1095016331 [Apr 8 16:05:18] DEBUG[19931][C-00000009] chan_sip.c: Acked pending invite 102 [Apr 8 16:05:18] DEBUG[19931][C-00000009] chan_sip.c: Stopping retransmission on '17ec2f31558556e17e92e5fc13412e2e@10.24.18.124:5060' of Request 102: Match Found [Apr 8 16:05:18] DEBUG[19931][C-00000009] chan_sip.c: SIP response 200 to standard invite [Apr 8 16:05:18] DEBUG[19931][C-00000009] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Apr 8 16:05:18] DEBUG[19931][C-00000009] chan_sip.c: Processing session-level SDP o=6004 24183147 19338273 IN IP4 10.24.18.166... OK. [Apr 8 16:05:18] DEBUG[19931][C-00000009] chan_sip.c: Processing session-level SDP s=A conversation... UNSUPPORTED OR FAILED. [Apr 8 16:05:18] DEBUG[19931][C-00000009] netsock2.c: Splitting '10.24.18.166' into... [Apr 8 16:05:18] DEBUG[19931][C-00000009] netsock2.c: ...host '10.24.18.166' and port ''. [Apr 8 16:05:18] DEBUG[19931][C-00000009] chan_sip.c: Processing session-level SDP c=IN IP4 10.24.18.166... OK. [Apr 8 16:05:18] DEBUG[19931][C-00000009] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Apr 8 16:05:18] DEBUG[19931][C-00000009] rtp_engine.c: Setting payload 0 based on m type on 0x7f7147a9bdc0 [Apr 8 16:05:18] DEBUG[19931][C-00000009] rtp_engine.c: Setting payload 101 based on m type on 0x7f7147a9bdc0 [Apr 8 16:05:18] DEBUG[19931][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Apr 8 16:05:18] DEBUG[19931][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Apr 8 16:05:18] DEBUG[19931][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED OR FAILED. [Apr 8 16:05:18] DEBUG[19931][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Apr 8 16:05:18] DEBUG[19931][C-00000009] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f71d4009a18' [Apr 8 16:05:18] DEBUG[19931][C-00000009] rtp_engine.c: Copying payload 0 from 0x7f7147a9bdc0 to 0x7f71d4009b58 [Apr 8 16:05:18] DEBUG[19931][C-00000009] rtp_engine.c: Copying payload 101 from 0x7f7147a9bdc0 to 0x7f71d4009b58 [Apr 8 16:05:18] DEBUG[19931][C-00000009] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f71d4009a18' [Apr 8 16:05:18] DEBUG[19931][C-00000009] chan_sip.c: We're settling with these formats: (ulaw) [Apr 8 16:05:18] DEBUG[19931][C-00000009] chan_sip.c: We have an owner, now see if we need to change this call [Apr 8 16:05:18] DEBUG[19931][C-00000009] chan_sip.c: Updating call counter for outgoing call [Apr 8 16:05:18] DEBUG[19931][C-00000009] chan_sip.c: build_route: Contact hop: [Apr 8 16:05:18] DEBUG[19931][C-00000009] netsock2.c: Splitting '10.24.18.166:5060' into... [Apr 8 16:05:18] DEBUG[19931][C-00000009] netsock2.c: ...host '10.24.18.166' and port '5060'. [Apr 8 16:05:18] DEBUG[19931][C-00000009] netsock2.c: Splitting '10.24.18.166:5060' into... [Apr 8 16:05:18] DEBUG[19931][C-00000009] netsock2.c: ...host '10.24.18.166' and port '5060'. [Apr 8 16:05:18] DEBUG[19931][C-00000009] chan_sip.c: Trying to put 'ACK sip:600' onto UDP socket destined for 10.24.18.166:5060 [Apr 8 16:05:18] DEBUG[20234][C-00000009] channel.c: SIP/6001-0000001b: Dropping redundant connected line update "David" <6004>. [Apr 8 16:05:18] VERBOSE[20234][C-00000009] app_dial.c: -- SIP/6004-0000001c answered SIP/6001-0000001b [Apr 8 16:05:18] DEBUG[19894] devicestate.c: No provider found, checking channel drivers for SIP - 6004 [Apr 8 16:05:18] DEBUG[20234][C-00000009] rtp_engine.c: Setting early bridge SDP of 'SIP/6001-0000001b' with that of 'SIP/6004-0000001c' [Apr 8 16:05:18] DEBUG[19894] chan_sip.c: Checking device state for peer 6004 [Apr 8 16:05:18] DEBUG[19894] devicestate.c: Changing state for SIP/6004 - state 1 (Not in use) [Apr 8 16:05:18] DEBUG[20234][C-00000009] channel.c: Set channel SIP/6001-0000001b to write format ulaw [Apr 8 16:05:18] DEBUG[20234][C-00000009] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Apr 8 16:05:18] DEBUG[20234][C-00000009] features.c: Removing dialed interfaces datastore on SIP/6004-0000001c since we're bridging [Apr 8 16:05:18] DEBUG[20234][C-00000009] bridge_native_rtp.c: Bridge 'd2e652ed-2565-4201-a479-7a0c356d9bbf' can not use native RTP bridge as two channels are required [Apr 8 16:05:18] DEBUG[20234][C-00000009] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Apr 8 16:05:18] DEBUG[20234][C-00000009] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Apr 8 16:05:18] DEBUG[20234][C-00000009] bridge.c: Chose bridge technology simple_bridge [Apr 8 16:05:18] DEBUG[20234][C-00000009] bridge.c: Bridge d2e652ed-2565-4201-a479-7a0c356d9bbf: calling simple_bridge technology constructor [Apr 8 16:05:18] DEBUG[20234][C-00000009] bridge.c: Bridge d2e652ed-2565-4201-a479-7a0c356d9bbf: calling simple_bridge technology start [Apr 8 16:05:18] DEBUG[20234][C-00000009] bridge_channel.c: Bridge d2e652ed-2565-4201-a479-7a0c356d9bbf: 0x7f71d4030748(SIP/6001-0000001b) is joining [Apr 8 16:05:18] DEBUG[20236][C-00000009] bridge_channel.c: Bridge d2e652ed-2565-4201-a479-7a0c356d9bbf: 0x7f71d40103c8(SIP/6004-0000001c) is joining [Apr 8 16:05:18] DEBUG[20234][C-00000009] bridge_channel.c: Bridge d2e652ed-2565-4201-a479-7a0c356d9bbf: pushing 0x7f71d4030748(SIP/6001-0000001b) [Apr 8 16:05:18] VERBOSE[20234][C-00000009] bridge_channel.c: -- Channel SIP/6001-0000001b joined 'simple_bridge' basic-bridge [Apr 8 16:05:18] DEBUG[20234][C-00000009] bridge_native_rtp.c: Bridge 'd2e652ed-2565-4201-a479-7a0c356d9bbf' can not use native RTP bridge as two channels are required [Apr 8 16:05:18] DEBUG[20234][C-00000009] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Apr 8 16:05:18] DEBUG[20234][C-00000009] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Apr 8 16:05:18] DEBUG[20234][C-00000009] bridge.c: Bridge technology softmix does not have any capabilities we want. [Apr 8 16:05:18] DEBUG[20234][C-00000009] bridge.c: Chose bridge technology simple_bridge [Apr 8 16:05:18] DEBUG[20234][C-00000009] bridge.c: Bridge d2e652ed-2565-4201-a479-7a0c356d9bbf is already using the new technology. [Apr 8 16:05:18] DEBUG[20234][C-00000009] bridge.c: Bridge d2e652ed-2565-4201-a479-7a0c356d9bbf is happy that channel SIP/6001-0000001b already has read format ulaw [Apr 8 16:05:18] DEBUG[20234][C-00000009] bridge.c: Bridge d2e652ed-2565-4201-a479-7a0c356d9bbf is happy that channel SIP/6001-0000001b already has write format ulaw [Apr 8 16:05:18] DEBUG[20234][C-00000009] bridge.c: Bridge d2e652ed-2565-4201-a479-7a0c356d9bbf: 0x7f71d4030748(SIP/6001-0000001b) is joining simple_bridge technology [Apr 8 16:05:18] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Changing ssrc from 1864944973 to 1724357764 due to a source change [Apr 8 16:05:18] DEBUG[20236][C-00000009] bridge_channel.c: Bridge d2e652ed-2565-4201-a479-7a0c356d9bbf: pushing 0x7f71d40103c8(SIP/6004-0000001c) [Apr 8 16:05:18] VERBOSE[20236][C-00000009] bridge_channel.c: -- Channel SIP/6004-0000001c joined 'simple_bridge' basic-bridge [Apr 8 16:05:18] DEBUG[19896] cdr.c: Finalized CDR for SIP/6004-0000001c - start 1396991116.939719 answer 1396991118.418457 end 1396991118.420237 dispo ANSWERED [Apr 8 16:05:18] DEBUG[20236][C-00000009] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Apr 8 16:05:18] DEBUG[20236][C-00000009] bridge.c: Bridge technology softmix does not have any capabilities we want. [Apr 8 16:05:18] DEBUG[20236][C-00000009] bridge.c: Bridge technology simple_bridge has less preference than native_rtp (50 <= 90). Skipping. [Apr 8 16:05:18] DEBUG[20236][C-00000009] bridge.c: Chose bridge technology native_rtp [Apr 8 16:05:18] VERBOSE[20236][C-00000009] bridge.c: > Bridge d2e652ed-2565-4201-a479-7a0c356d9bbf: switching from simple_bridge technology to native_rtp [Apr 8 16:05:18] DEBUG[20236][C-00000009] bridge.c: Bridge d2e652ed-2565-4201-a479-7a0c356d9bbf: calling native_rtp technology constructor [Apr 8 16:05:18] DEBUG[20236][C-00000009] bridge.c: Bridge d2e652ed-2565-4201-a479-7a0c356d9bbf: calling simple_bridge technology stop [Apr 8 16:05:18] DEBUG[20236][C-00000009] bridge.c: Bridge d2e652ed-2565-4201-a479-7a0c356d9bbf: 0x7f71d4030748(SIP/6001-0000001b) is leaving simple_bridge technology (dummy) [Apr 8 16:05:18] DEBUG[20236][C-00000009] bridge.c: Bridge d2e652ed-2565-4201-a479-7a0c356d9bbf is happy that channel SIP/6001-0000001b already has read format ulaw [Apr 8 16:05:18] DEBUG[20236][C-00000009] bridge.c: Bridge d2e652ed-2565-4201-a479-7a0c356d9bbf is happy that channel SIP/6001-0000001b already has write format ulaw [Apr 8 16:05:18] DEBUG[20236][C-00000009] bridge.c: Bridge d2e652ed-2565-4201-a479-7a0c356d9bbf: 0x7f71d4030748(SIP/6001-0000001b) is joining native_rtp technology [Apr 8 16:05:18] DEBUG[20236][C-00000009] bridge_native_rtp.c: Locally RTP bridged 'SIP/6001-0000001b' and 'SIP/6004-0000001c' in stack [Apr 8 16:05:18] DEBUG[20236][C-00000009] bridge.c: Bridge d2e652ed-2565-4201-a479-7a0c356d9bbf is happy that channel SIP/6004-0000001c already has read format ulaw [Apr 8 16:05:18] DEBUG[20236][C-00000009] bridge.c: Bridge d2e652ed-2565-4201-a479-7a0c356d9bbf is happy that channel SIP/6004-0000001c already has write format ulaw [Apr 8 16:05:18] DEBUG[20236][C-00000009] bridge.c: Bridge d2e652ed-2565-4201-a479-7a0c356d9bbf: 0x7f71d40103c8(SIP/6004-0000001c) is joining native_rtp technology [Apr 8 16:05:18] DEBUG[20236][C-00000009] bridge_native_rtp.c: Locally RTP bridged 'SIP/6001-0000001b' and 'SIP/6004-0000001c' in stack [Apr 8 16:05:18] DEBUG[20236][C-00000009] bridge.c: Bridge d2e652ed-2565-4201-a479-7a0c356d9bbf: calling native_rtp technology start [Apr 8 16:05:18] DEBUG[20236][C-00000009] bridge.c: Bridge d2e652ed-2565-4201-a479-7a0c356d9bbf: calling simple_bridge technology destructor [Apr 8 16:05:18] DEBUG[20236][C-00000009] res_rtp_asterisk.c: Not changing SSRC since we haven't sent any RTP yet [Apr 8 16:05:18] DEBUG[20236][C-00000009] res_rtp_asterisk.c: 0x7f71d4013b60 -- Probation learning mode pass with source address 10.24.18.166:10020 [Apr 8 16:05:18] VERBOSE[20236][C-00000009] res_rtp_asterisk.c: > 0x7f71d4013b60 -- Probation passed - setting RTP source address to 10.24.18.166:10020 [Apr 8 16:05:19] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Apr 8 16:05:20] DEBUG[19931] chan_sip.c: = Looking for Call ID: 17ec2f31558556e17e92e5fc13412e2e@10.24.18.124:5060 (Checking From) --From tag 1095016331 --To-tag as0f0ed517 [Apr 8 16:05:20] DEBUG[19931][C-00000009] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Apr 8 16:05:20] DEBUG[19931][C-00000009] sip/reqresp_parser.c: Begin: parsing SIP "Supported: replaces, join, path" [Apr 8 16:05:20] DEBUG[19931][C-00000009] sip/reqresp_parser.c: Found SIP option: -replaces- [Apr 8 16:05:20] DEBUG[19931][C-00000009] sip/reqresp_parser.c: Matched SIP option: replaces [Apr 8 16:05:20] DEBUG[19931][C-00000009] sip/reqresp_parser.c: Found SIP option: -join- [Apr 8 16:05:20] DEBUG[19931][C-00000009] sip/reqresp_parser.c: Matched SIP option: join [Apr 8 16:05:20] DEBUG[19931][C-00000009] sip/reqresp_parser.c: Found SIP option: -path- [Apr 8 16:05:20] DEBUG[19931][C-00000009] sip/reqresp_parser.c: Matched SIP option: path [Apr 8 16:05:20] DEBUG[19931][C-00000009] netsock2.c: Splitting '10.24.18.166:5060' into... [Apr 8 16:05:20] DEBUG[19931][C-00000009] netsock2.c: ...host '10.24.18.166' and port '5060'. [Apr 8 16:05:20] DEBUG[19931][C-00000009] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Apr 8 16:05:20] DEBUG[19931][C-00000009] chan_sip.c: Processing session-level SDP o=6004 24183147 19338274 IN IP4 10.24.18.166... OK. [Apr 8 16:05:20] DEBUG[19931][C-00000009] chan_sip.c: Processing session-level SDP s=A conversation... UNSUPPORTED OR FAILED. [Apr 8 16:05:20] DEBUG[19931][C-00000009] netsock2.c: Splitting '0.0.0.0' into... [Apr 8 16:05:20] DEBUG[19931][C-00000009] netsock2.c: ...host '0.0.0.0' and port ''. [Apr 8 16:05:20] DEBUG[19931][C-00000009] chan_sip.c: Processing session-level SDP c=IN IP4 0.0.0.0... OK. [Apr 8 16:05:20] DEBUG[19931][C-00000009] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Apr 8 16:05:20] DEBUG[19931][C-00000009] rtp_engine.c: Setting payload 0 based on m type on 0x7f7147a9bf40 [Apr 8 16:05:20] DEBUG[19931][C-00000009] rtp_engine.c: Setting payload 101 based on m type on 0x7f7147a9bf40 [Apr 8 16:05:20] DEBUG[19931][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Apr 8 16:05:20] DEBUG[19931][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Apr 8 16:05:20] DEBUG[19931][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED OR FAILED. [Apr 8 16:05:20] DEBUG[19931][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=sendonly... OK. [Apr 8 16:05:20] DEBUG[19931][C-00000009] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f71d4009a18' [Apr 8 16:05:20] DEBUG[19931][C-00000009] rtp_engine.c: Copying payload 0 from 0x7f7147a9bf40 to 0x7f71d4009b58 [Apr 8 16:05:20] DEBUG[19931][C-00000009] rtp_engine.c: Copying payload 101 from 0x7f7147a9bf40 to 0x7f71d4009b58 [Apr 8 16:05:20] DEBUG[19931][C-00000009] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f71d4009a18' [Apr 8 16:05:20] DEBUG[19931][C-00000009] chan_sip.c: We're settling with these formats: (ulaw) [Apr 8 16:05:20] DEBUG[19931][C-00000009] chan_sip.c: We have an owner, now see if we need to change this call [Apr 8 16:05:20] DEBUG[19931][C-00000009] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f71d4009a18' [Apr 8 16:05:20] DEBUG[19931][C-00000009] chan_sip.c: SIP/6004-0000001c: This call is UP.... [Apr 8 16:05:20] DEBUG[19931][C-00000009] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 10.24.18.166:5060 [Apr 8 16:05:20] DEBUG[19931][C-00000009] chan_sip.c: Setting framing from config on incoming call [Apr 8 16:05:20] DEBUG[19931][C-00000009] chan_sip.c: ** Our capability: (ulaw) Video flag: True Text flag: True [Apr 8 16:05:20] DEBUG[19931][C-00000009] chan_sip.c: ** Our prefcodec: (ulaw) [Apr 8 16:05:20] DEBUG[19931][C-00000009] chan_sip.c: -- Done with adding codecs to SDP [Apr 8 16:05:20] DEBUG[19931][C-00000009] chan_sip.c: Done building SDP. Settling with this capability: (ulaw) [Apr 8 16:05:20] DEBUG[19931][C-00000009] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.24.18.166:5060 [Apr 8 16:05:20] DEBUG[20234][C-00000009] bridge_native_rtp.c: Discontinued RTP bridging of 'SIP/6001-0000001b' and 'SIP/6004-0000001c' - media will flow through Asterisk core [Apr 8 16:05:20] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Setting the marker bit due to a source update [Apr 8 16:05:20] VERBOSE[20234][C-00000009] res_musiconhold.c: -- Started music on hold, class 'default', on channel 'SIP/6001-0000001b' [Apr 8 16:05:20] DEBUG[20234][C-00000009] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Apr 8 16:05:20] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Setting the marker bit due to a source update [Apr 8 16:05:20] DEBUG[20234][C-00000009] bridge_native_rtp.c: Locally RTP bridged 'SIP/6001-0000001b' and 'SIP/6004-0000001c' in stack [Apr 8 16:05:20] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:20] DEBUG[19931] chan_sip.c: = Looking for Call ID: 17ec2f31558556e17e92e5fc13412e2e@10.24.18.124:5060 (Checking From) --From tag 1095016331 --To-tag as0f0ed517 [Apr 8 16:05:20] DEBUG[19931][C-00000009] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Apr 8 16:05:20] DEBUG[19931][C-00000009] chan_sip.c: Stopping retransmission on '17ec2f31558556e17e92e5fc13412e2e@10.24.18.124:5060' of Response 1: Match Found [Apr 8 16:05:20] DEBUG[20236][C-00000009] res_rtp_asterisk.c: 0x7f71d4013b60 -- Probation learning mode pass with source address 10.24.18.166:10020 [Apr 8 16:05:20] VERBOSE[20236][C-00000009] res_rtp_asterisk.c: > 0x7f71d4013b60 -- Probation passed - setting RTP source address to 10.24.18.166:10020 [Apr 8 16:05:20] DEBUG[20234][C-00000009] channel.c: Set channel SIP/6001-0000001b to write format slin [Apr 8 16:05:20] DEBUG[20234][C-00000009] res_musiconhold.c: SIP/6001-0000001b Opened file 0 '/var/lib/asterisk/moh/macroform-cold_day' [Apr 8 16:05:20] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Difference is 19696, ms is 2482 [Apr 8 16:05:20] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:20] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:20] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:20] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:20] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:20] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:21] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:22] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:23] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:24] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:25] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:26] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:27] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:27] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:27] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:27] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:27] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:27] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:27] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Remote address is null, most likely RTP has been stopped [Apr 8 16:05:27] DEBUG[19931] chan_sip.c: = Looking for Call ID: 17ec2f31558556e17e92e5fc13412e2e@10.24.18.124:5060 (Checking From) --From tag 1095016331 --To-tag as0f0ed517 [Apr 8 16:05:27] DEBUG[19931][C-00000009] chan_sip.c: **** Received REFER (9) - Command in SIP REFER [Apr 8 16:05:27] DEBUG[19931][C-00000009] chan_sip.c: Trying to put 'SIP/2.0 202' onto UDP socket destined for 10.24.18.166:5060 [Apr 8 16:05:27] DEBUG[19931][C-00000009] parking/parking_bridge_features.c: Checking if 12@agi-test-context is a parking exten [Apr 8 16:05:27] DEBUG[20234][C-00000009] bridge_native_rtp.c: Locally RTP bridged 'SIP/6001-0000001b' and 'SIP/6004-0000001c' in stack [Apr 8 16:05:27] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Setting the marker bit due to a source update [Apr 8 16:05:27] VERBOSE[20234][C-00000009] res_musiconhold.c: -- Stopped music on hold on SIP/6001-0000001b [Apr 8 16:05:27] DEBUG[20234][C-00000009] channel.c: Set channel SIP/6001-0000001b to write format ulaw [Apr 8 16:05:27] DEBUG[20234][C-00000009] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Apr 8 16:05:27] DEBUG[19931][C-00000009] bridge_channel.c: Setting 0x7f71d40103c8(SIP/6004-0000001c) state from:0 to:2 [Apr 8 16:05:27] DEBUG[20234][C-00000009] channel.c: Soft-Hanging up channel 'SIP/6001-0000001b' [Apr 8 16:05:27] DEBUG[20234][C-00000009] bridge_channel.c: Setting 0x7f71d4030748(SIP/6001-0000001b) state from:0 to:1 [Apr 8 16:05:27] DEBUG[20234][C-00000009] bridge_channel.c: Bridge d2e652ed-2565-4201-a479-7a0c356d9bbf: pulling 0x7f71d4030748(SIP/6001-0000001b) [Apr 8 16:05:27] VERBOSE[20234][C-00000009] bridge_channel.c: -- Channel SIP/6001-0000001b left 'native_rtp' basic-bridge [Apr 8 16:05:27] DEBUG[20234][C-00000009] bridge_channel.c: Bridge d2e652ed-2565-4201-a479-7a0c356d9bbf: 0x7f71d4030748(SIP/6001-0000001b) is leaving native_rtp technology [Apr 8 16:05:27] DEBUG[19931][C-00000009] netsock2.c: Splitting '10.24.18.166:5060' into... [Apr 8 16:05:27] DEBUG[19931][C-00000009] netsock2.c: ...host '10.24.18.166' and port '5060'. [Apr 8 16:05:27] DEBUG[19931][C-00000009] chan_sip.c: Trying to put 'NOTIFY sip:' onto UDP socket destined for 10.24.18.166:5060 [Apr 8 16:05:27] DEBUG[20234][C-00000009] bridge_native_rtp.c: Discontinued RTP bridging of 'SIP/6001-0000001b' and 'SIP/6004-0000001c' - media will flow through Asterisk core [Apr 8 16:05:27] DEBUG[20234][C-00000009] bridge.c: Bridge d2e652ed-2565-4201-a479-7a0c356d9bbf: dissolving bridge with cause 16(Normal Clearing) [Apr 8 16:05:27] DEBUG[20234][C-00000009] bridge.c: Bridge d2e652ed-2565-4201-a479-7a0c356d9bbf: queueing action type:13 sub:1001 [Apr 8 16:05:27] DEBUG[20234][C-00000009] bridge.c: Bridge d2e652ed-2565-4201-a479-7a0c356d9bbf is dissolved, not performing smart bridge operation. [Apr 8 16:05:27] DEBUG[19896] cdr.c: Finalized CDR for SIP/6001-0000001b - start 1396991116.662914 answer 1396991116.674951 end 1396991127.153761 dispo ANSWERED [Apr 8 16:05:27] DEBUG[20236][C-00000009] bridge_channel.c: Bridge d2e652ed-2565-4201-a479-7a0c356d9bbf: pulling 0x7f71d40103c8(SIP/6004-0000001c) [Apr 8 16:05:27] VERBOSE[20236][C-00000009] bridge_channel.c: -- Channel SIP/6004-0000001c left 'native_rtp' basic-bridge [Apr 8 16:05:27] DEBUG[20236][C-00000009] bridge_channel.c: Bridge d2e652ed-2565-4201-a479-7a0c356d9bbf: 0x7f71d40103c8(SIP/6004-0000001c) is leaving native_rtp technology [Apr 8 16:05:27] DEBUG[20236][C-00000009] bridge.c: Bridge d2e652ed-2565-4201-a479-7a0c356d9bbf is dissolved, not performing smart bridge operation. [Apr 8 16:05:27] DEBUG[20236][C-00000009] res_rtp_asterisk.c: Not changing SSRC since we haven't sent any RTP yet [Apr 8 16:05:27] DEBUG[20236][C-00000009] channel.c: Hanging up channel 'SIP/6004-0000001c' [Apr 8 16:05:27] DEBUG[20236][C-00000009] chan_sip.c: Updating call counter for outgoing call [Apr 8 16:05:27] DEBUG[20236][C-00000009] chan_sip.c: SIP Transfer: Not hanging up right now... Rescheduling hangup for 17ec2f31558556e17e92e5fc13412e2e@10.24.18.124:5060. [Apr 8 16:05:27] DEBUG[20234][C-00000009] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Apr 8 16:05:27] VERBOSE[20234][C-00000009] res_agi.c: AGI Tx >> 200 result=0 [Apr 8 16:05:27] DEBUG[19894] devicestate.c: No provider found, checking channel drivers for SIP - 6004 [Apr 8 16:05:27] DEBUG[19894] chan_sip.c: Checking device state for peer 6004 [Apr 8 16:05:27] DEBUG[19894] devicestate.c: Changing state for SIP/6004 - state 1 (Not in use) [Apr 8 16:05:27] DEBUG[19894] devicestate.c: No provider found, checking channel drivers for SIP - 6004 [Apr 8 16:05:27] DEBUG[19894] chan_sip.c: Checking device state for peer 6004 [Apr 8 16:05:27] DEBUG[19894] devicestate.c: Changing state for SIP/6004 - state 1 (Not in use) [Apr 8 16:05:27] DEBUG[19893][C-00000009] bridge.c: Bridge d2e652ed-2565-4201-a479-7a0c356d9bbf: actually destroying basic bridge, nobody wants it anymore [Apr 8 16:05:27] DEBUG[19893][C-00000009] bridge.c: Bridge d2e652ed-2565-4201-a479-7a0c356d9bbf: calling basic bridge destructor [Apr 8 16:05:27] DEBUG[20234][C-00000009] res_agi.c: SIP/6001-0000001b hungup [Apr 8 16:05:27] DEBUG[19893][C-00000009] bridge.c: Bridge d2e652ed-2565-4201-a479-7a0c356d9bbf: calling native_rtp technology stop [Apr 8 16:05:27] DEBUG[19893][C-00000009] bridge.c: Bridge d2e652ed-2565-4201-a479-7a0c356d9bbf: calling native_rtp technology destructor [Apr 8 16:05:27] DEBUG[19896] cdr.c: CDR for SIP/6004-0000001c is dialed and has no Party B; discarding [Apr 8 16:05:27] VERBOSE[20234][C-00000009] res_agi.c: AGI Rx << EXEC Hangup [Apr 8 16:05:27] VERBOSE[20234][C-00000009] res_agi.c: -- AGI Script Executing Application: (Hangup) Options: () [Apr 8 16:05:27] DEBUG[20234][C-00000009] channel.c: Soft-Hanging up channel 'SIP/6001-0000001b' [Apr 8 16:05:27] VERBOSE[20234][C-00000009] res_agi.c: AGI Tx >> 200 result=-1 [Apr 8 16:05:27] ERROR[20234][C-00000009] utils.c: write() returned error: Broken pipe [Apr 8 16:05:27] VERBOSE[20234][C-00000009] res_agi.c: -- AGI Script /root/asterisk.sh completed, returning 4 [Apr 8 16:05:27] DEBUG[20234][C-00000009] pbx.c: Spawn extension (agi-test-context,12,1) exited non-zero on 'SIP/6001-0000001b' [Apr 8 16:05:27] VERBOSE[20234][C-00000009] pbx.c: == Spawn extension (agi-test-context, 12, 1) exited non-zero on 'SIP/6001-0000001b' [Apr 8 16:05:27] DEBUG[20234][C-00000009] pbx.c: Launching 'Dial' [Apr 8 16:05:27] VERBOSE[20234][C-00000009] pbx.c: -- Executing [12@agi-test-context:1] Dial("SIP/6001-0000001b", "SIP/6002,45,Tt") in new stack [Apr 8 16:05:27] DEBUG[20234][C-00000009] chan_sip.c: Asked to create a SIP channel with formats: (ulaw) [Apr 8 16:05:27] DEBUG[20234][C-00000009] chan_sip.c: Allocating new SIP dialog for 2570aba9579ecd642e5613a0501f052e@127.0.1.1:5060 - INVITE (No RTP) [Apr 8 16:05:27] DEBUG[20234][C-00000009] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f71d401bc88' [Apr 8 16:05:27] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Allocated port 18190 for RTP instance '0x7f71d401bc88' [Apr 8 16:05:27] DEBUG[20234][C-00000009] netsock2.c: Splitting '10.24.18.124' into... [Apr 8 16:05:27] DEBUG[20234][C-00000009] netsock2.c: ...host '10.24.18.124' and port ''. [Apr 8 16:05:27] DEBUG[20234][C-00000009] rtp_engine.c: RTP instance '0x7f71d401bc88' is setup and ready to go [Apr 8 16:05:27] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f71d401bc88' [Apr 8 16:05:27] VERBOSE[20234][C-00000009] netsock2.c: == Using SIP RTP CoS mark 5 [Apr 8 16:05:27] DEBUG[20234][C-00000009] chan_sip.c: Setting NAT on RTP to Off [Apr 8 16:05:27] DEBUG[20234][C-00000009] acl.c: For destination '10.24.18.138', our source address is '10.24.18.124'. [Apr 8 16:05:27] DEBUG[20234][C-00000009] chan_sip.c: Setting AST_TRANSPORT_UDP with address 10.24.18.124:5060 [Apr 8 16:05:27] DEBUG[20234][C-00000009] chan_sip.c: Setting NAT on RTP to Off [Apr 8 16:05:27] DEBUG[20234][C-00000009] chan_sip.c: SIP call-id changed from '2570aba9579ecd642e5613a0501f052e@127.0.1.1:5060' to '06fc799c41afcbe357c9708226ca6e8a@10.24.18.124:5060' [Apr 8 16:05:27] DEBUG[20234][C-00000009] chan_sip.c: *** Our native formats are (ulaw) [Apr 8 16:05:27] DEBUG[20234][C-00000009] chan_sip.c: *** Joint capabilities are (ulaw) [Apr 8 16:05:27] DEBUG[20234][C-00000009] chan_sip.c: *** Our capabilities are (ulaw) [Apr 8 16:05:27] DEBUG[20234][C-00000009] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw [Apr 8 16:05:27] DEBUG[20234][C-00000009] chan_sip.c: *** Our preferred formats from the incoming channel are (ulaw) [Apr 8 16:05:27] DEBUG[20234][C-00000009] chan_sip.c: This channel will not be able to handle video. [Apr 8 16:05:27] DEBUG[20234][C-00000009] channel_internal_api.c: Channel Call ID changing from [C-00000009] to [C-00000009] [Apr 8 16:05:27] DEBUG[20234][C-00000009] chan_sip.c: Outgoing Call for 6002 [Apr 8 16:05:27] DEBUG[20234][C-00000009] chan_sip.c: Updating call counter for outgoing call [Apr 8 16:05:27] DEBUG[20234][C-00000009] chan_sip.c: ** Our capability: (ulaw) Video flag: False Text flag: False [Apr 8 16:05:27] DEBUG[20234][C-00000009] chan_sip.c: ** Our prefcodec: (ulaw) [Apr 8 16:05:27] DEBUG[20234][C-00000009] chan_sip.c: -- Done with adding codecs to SDP [Apr 8 16:05:27] DEBUG[20234][C-00000009] chan_sip.c: Done building SDP. Settling with this capability: (ulaw) [Apr 8 16:05:27] DEBUG[20234][C-00000009] chan_sip.c: Initializing initreq for method INVITE - callid 06fc799c41afcbe357c9708226ca6e8a@10.24.18.124:5060 [Apr 8 16:05:27] DEBUG[20234][C-00000009] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 10.24.18.138:5060 [Apr 8 16:05:27] VERBOSE[20234][C-00000009] app_dial.c: -- Called SIP/6002 [Apr 8 16:05:27] DEBUG[19896] cdr.c: Finalized CDR for SIP/6001-0000001b - start 1396991127.157148 answer 1396991127.157148 end 1396991127.157249 dispo NO ANSWER [Apr 8 16:05:27] DEBUG[20234][C-00000009] channel.c: Hanging up channel 'SIP/6002-0000001d' [Apr 8 16:05:27] DEBUG[20234][C-00000009] chan_sip.c: Hangup call SIP/6002-0000001d, SIP callid 06fc799c41afcbe357c9708226ca6e8a@10.24.18.124:5060 [Apr 8 16:05:27] DEBUG[20234][C-00000009] chan_sip.c: Hanging up channel in state Down (not UP) [Apr 8 16:05:27] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f71d401bc88' [Apr 8 16:05:27] DEBUG[19896] cdr.c: Finalized CDR for SIP/6002-0000001d - start 1396991127.156579 answer 0.000000 end 1396991127.157306 dispo FAILED [Apr 8 16:05:27] DEBUG[19896] cdr.c: CDR for SIP/6002-0000001d is dialed and has no Party B; discarding [Apr 8 16:05:27] DEBUG[19894] devicestate.c: No provider found, checking channel drivers for SIP - 6002 [Apr 8 16:05:27] DEBUG[19894] chan_sip.c: Checking device state for peer 6002 [Apr 8 16:05:27] DEBUG[19894] devicestate.c: Changing state for SIP/6002 - state 1 (Not in use) [Apr 8 16:05:27] DEBUG[20234][C-00000009] app_dial.c: Exiting with DIALSTATUS=CANCEL. [Apr 8 16:05:27] DEBUG[20234][C-00000009] pbx.c: Spawn extension (agi-test-context,12,1) exited non-zero on 'SIP/6001-0000001b' [Apr 8 16:05:27] VERBOSE[20234][C-00000009] pbx.c: == Spawn extension (agi-test-context, 12, 1) exited non-zero on 'SIP/6001-0000001b' [Apr 8 16:05:27] DEBUG[20234][C-00000009] channel.c: Soft-Hanging up channel 'SIP/6001-0000001b' [Apr 8 16:05:27] DEBUG[20234][C-00000009] channel.c: Soft-Hanging up channel 'SIP/6001-0000001b' [Apr 8 16:05:27] DEBUG[20234][C-00000009] pbx.c: Result of 'EXTEN' is 'h' [Apr 8 16:05:27] DEBUG[20234][C-00000009] pbx.c: Result of 'ORGDEST' is NULL [Apr 8 16:05:27] DEBUG[20234][C-00000009] pbx.c: Launching 'NoOp' [Apr 8 16:05:27] VERBOSE[20234][C-00000009] pbx.c: -- Executing [h@agi-test-context:1] NoOp("SIP/6001-0000001b", ""po AGI ===================="h" """) in new stack [Apr 8 16:05:27] DEBUG[20234][C-00000009] pbx.c: Launching 'Hangup' [Apr 8 16:05:27] VERBOSE[20234][C-00000009] pbx.c: -- Executing [h@agi-test-context:2] Hangup("SIP/6001-0000001b", "") in new stack [Apr 8 16:05:27] DEBUG[20234][C-00000009] channel.c: Soft-Hanging up channel 'SIP/6001-0000001b' [Apr 8 16:05:27] DEBUG[20234][C-00000009] pbx.c: Spawn extension (agi-test-context,h,2) exited non-zero on 'SIP/6001-0000001b' [Apr 8 16:05:27] VERBOSE[20234][C-00000009] pbx.c: == Spawn extension (agi-test-context, h, 2) exited non-zero on 'SIP/6001-0000001b' [Apr 8 16:05:27] DEBUG[20234][C-00000009] channel.c: Hanging up channel 'SIP/6001-0000001b' [Apr 8 16:05:27] DEBUG[20234][C-00000009] chan_sip.c: Hangup call SIP/6001-0000001b, SIP callid KGlMtfIl-KgrUYwasot8XUZdVQydmlVO [Apr 8 16:05:27] DEBUG[20234][C-00000009] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f717002bb28' [Apr 8 16:05:27] DEBUG[20234][C-00000009] chan_sip.c: Session timer stopped: 717 - KGlMtfIl-KgrUYwasot8XUZdVQydmlVO [Apr 8 16:05:27] DEBUG[20234][C-00000009] netsock2.c: Splitting '10.24.18.16:5060' into... [Apr 8 16:05:27] DEBUG[20234][C-00000009] netsock2.c: ...host '10.24.18.16' and port '5060'. [Apr 8 16:05:27] DEBUG[20234][C-00000009] chan_sip.c: Trying to put 'BYE sip:600' onto UDP socket destined for 10.24.18.16:5060 [Apr 8 16:05:27] DEBUG[19894] devicestate.c: No provider found, checking channel drivers for SIP - 6001 [Apr 8 16:05:27] DEBUG[19894] chan_sip.c: Checking device state for peer 6001 [Apr 8 16:05:27] DEBUG[19894] devicestate.c: Changing state for SIP/6001 - state 1 (Not in use) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CSV_QUOTE(${CDR(src)})' (from 'CSV_QUOTE(${CDR(src)})},"Destination":${CSV_QUOTE(${CDR(dst)})},"Context":${CSV_QUOTE(${CDR(dcontext)})},"SourceChannel":${CSV_QUOTE(${CDR(channel)})},"DestinationChannel":${CSV_QUOTE(${CDR(dstchannel)})},"LastAPP":${CSV_QUOTE(${CDR(lastapp)})},"LastData":${CSV_QUOTE(${CDR(lastdata)})},"Start":${CSV_QUOTE(${CDR(start)})},"Answer":${CSV_QUOTE(${CDR(answer)})},"End":${CSV_QUOTE(${CDR(end)})},"Duration":${CSV_QUOTE(${CDR(duration,f)})},"BillSec":${CSV_QUOTE(${CDR(billsec,f)})},"Disposition":${CSV_QUOTE(${CDR(disposition)})},"amaFlags":${CSV_QUOTE(${CDR(amaflags)})},"AccountCode":${CSV_QUOTE(${CDR(accountcode)})},"UniqueID":${CSV_QUOTE(${CDR(uniqueid)})},"UserField":${CSV_QUOTE(${CDR(userfield)})},"Sequence":${CDR(sequence)},"acustomfield1":${CSV_QUOTE(${CDR(acustomfield1)})},"acustomfield2":${CSV_QUOTE(${CDR(acustomfield2)})}} ' len 22) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CDR(src)' (from 'CDR(src)})' len 8) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CDR(src) result is '6001' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CSV_QUOTE(6001) result is '"6001"' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CSV_QUOTE(${CDR(dst)})' (from 'CSV_QUOTE(${CDR(dst)})},"Context":${CSV_QUOTE(${CDR(dcontext)})},"SourceChannel":${CSV_QUOTE(${CDR(channel)})},"DestinationChannel":${CSV_QUOTE(${CDR(dstchannel)})},"LastAPP":${CSV_QUOTE(${CDR(lastapp)})},"LastData":${CSV_QUOTE(${CDR(lastdata)})},"Start":${CSV_QUOTE(${CDR(start)})},"Answer":${CSV_QUOTE(${CDR(answer)})},"End":${CSV_QUOTE(${CDR(end)})},"Duration":${CSV_QUOTE(${CDR(duration,f)})},"BillSec":${CSV_QUOTE(${CDR(billsec,f)})},"Disposition":${CSV_QUOTE(${CDR(disposition)})},"amaFlags":${CSV_QUOTE(${CDR(amaflags)})},"AccountCode":${CSV_QUOTE(${CDR(accountcode)})},"UniqueID":${CSV_QUOTE(${CDR(uniqueid)})},"UserField":${CSV_QUOTE(${CDR(userfield)})},"Sequence":${CDR(sequence)},"acustomfield1":${CSV_QUOTE(${CDR(acustomfield1)})},"acustomfield2":${CSV_QUOTE(${CDR(acustomfield2)})}} ' len 22) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CDR(dst)' (from 'CDR(dst)})' len 8) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CDR(dst) result is '1' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CSV_QUOTE(1) result is '"1"' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CSV_QUOTE(${CDR(dcontext)})' (from 'CSV_QUOTE(${CDR(dcontext)})},"SourceChannel":${CSV_QUOTE(${CDR(channel)})},"DestinationChannel":${CSV_QUOTE(${CDR(dstchannel)})},"LastAPP":${CSV_QUOTE(${CDR(lastapp)})},"LastData":${CSV_QUOTE(${CDR(lastdata)})},"Start":${CSV_QUOTE(${CDR(start)})},"Answer":${CSV_QUOTE(${CDR(answer)})},"End":${CSV_QUOTE(${CDR(end)})},"Duration":${CSV_QUOTE(${CDR(duration,f)})},"BillSec":${CSV_QUOTE(${CDR(billsec,f)})},"Disposition":${CSV_QUOTE(${CDR(disposition)})},"amaFlags":${CSV_QUOTE(${CDR(amaflags)})},"AccountCode":${CSV_QUOTE(${CDR(accountcode)})},"UniqueID":${CSV_QUOTE(${CDR(uniqueid)})},"UserField":${CSV_QUOTE(${CDR(userfield)})},"Sequence":${CDR(sequence)},"acustomfield1":${CSV_QUOTE(${CDR(acustomfield1)})},"acustomfield2":${CSV_QUOTE(${CDR(acustomfield2)})}} ' len 27) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CDR(dcontext)' (from 'CDR(dcontext)})' len 13) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CDR(dcontext) result is 'agi-test-context' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CSV_QUOTE(agi-test-context) result is '"agi-test-context"' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CSV_QUOTE(${CDR(channel)})' (from 'CSV_QUOTE(${CDR(channel)})},"DestinationChannel":${CSV_QUOTE(${CDR(dstchannel)})},"LastAPP":${CSV_QUOTE(${CDR(lastapp)})},"LastData":${CSV_QUOTE(${CDR(lastdata)})},"Start":${CSV_QUOTE(${CDR(start)})},"Answer":${CSV_QUOTE(${CDR(answer)})},"End":${CSV_QUOTE(${CDR(end)})},"Duration":${CSV_QUOTE(${CDR(duration,f)})},"BillSec":${CSV_QUOTE(${CDR(billsec,f)})},"Disposition":${CSV_QUOTE(${CDR(disposition)})},"amaFlags":${CSV_QUOTE(${CDR(amaflags)})},"AccountCode":${CSV_QUOTE(${CDR(accountcode)})},"UniqueID":${CSV_QUOTE(${CDR(uniqueid)})},"UserField":${CSV_QUOTE(${CDR(userfield)})},"Sequence":${CDR(sequence)},"acustomfield1":${CSV_QUOTE(${CDR(acustomfield1)})},"acustomfield2":${CSV_QUOTE(${CDR(acustomfield2)})}} ' len 26) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CDR(channel)' (from 'CDR(channel)})' len 12) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CDR(channel) result is 'SIP/6001-0000001b' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CSV_QUOTE(SIP/6001-0000001b) result is '"SIP/6001-0000001b"' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CSV_QUOTE(${CDR(dstchannel)})' (from 'CSV_QUOTE(${CDR(dstchannel)})},"LastAPP":${CSV_QUOTE(${CDR(lastapp)})},"LastData":${CSV_QUOTE(${CDR(lastdata)})},"Start":${CSV_QUOTE(${CDR(start)})},"Answer":${CSV_QUOTE(${CDR(answer)})},"End":${CSV_QUOTE(${CDR(end)})},"Duration":${CSV_QUOTE(${CDR(duration,f)})},"BillSec":${CSV_QUOTE(${CDR(billsec,f)})},"Disposition":${CSV_QUOTE(${CDR(disposition)})},"amaFlags":${CSV_QUOTE(${CDR(amaflags)})},"AccountCode":${CSV_QUOTE(${CDR(accountcode)})},"UniqueID":${CSV_QUOTE(${CDR(uniqueid)})},"UserField":${CSV_QUOTE(${CDR(userfield)})},"Sequence":${CDR(sequence)},"acustomfield1":${CSV_QUOTE(${CDR(acustomfield1)})},"acustomfield2":${CSV_QUOTE(${CDR(acustomfield2)})}} ' len 29) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CDR(dstchannel)' (from 'CDR(dstchannel)})' len 15) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CDR(dstchannel) result is 'SIP/6004-0000001c' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CSV_QUOTE(SIP/6004-0000001c) result is '"SIP/6004-0000001c"' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CSV_QUOTE(${CDR(lastapp)})' (from 'CSV_QUOTE(${CDR(lastapp)})},"LastData":${CSV_QUOTE(${CDR(lastdata)})},"Start":${CSV_QUOTE(${CDR(start)})},"Answer":${CSV_QUOTE(${CDR(answer)})},"End":${CSV_QUOTE(${CDR(end)})},"Duration":${CSV_QUOTE(${CDR(duration,f)})},"BillSec":${CSV_QUOTE(${CDR(billsec,f)})},"Disposition":${CSV_QUOTE(${CDR(disposition)})},"amaFlags":${CSV_QUOTE(${CDR(amaflags)})},"AccountCode":${CSV_QUOTE(${CDR(accountcode)})},"UniqueID":${CSV_QUOTE(${CDR(uniqueid)})},"UserField":${CSV_QUOTE(${CDR(userfield)})},"Sequence":${CDR(sequence)},"acustomfield1":${CSV_QUOTE(${CDR(acustomfield1)})},"acustomfield2":${CSV_QUOTE(${CDR(acustomfield2)})}} ' len 26) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CDR(lastapp)' (from 'CDR(lastapp)})' len 12) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CDR(lastapp) result is 'Dial' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CSV_QUOTE(Dial) result is '"Dial"' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CSV_QUOTE(${CDR(lastdata)})' (from 'CSV_QUOTE(${CDR(lastdata)})},"Start":${CSV_QUOTE(${CDR(start)})},"Answer":${CSV_QUOTE(${CDR(answer)})},"End":${CSV_QUOTE(${CDR(end)})},"Duration":${CSV_QUOTE(${CDR(duration,f)})},"BillSec":${CSV_QUOTE(${CDR(billsec,f)})},"Disposition":${CSV_QUOTE(${CDR(disposition)})},"amaFlags":${CSV_QUOTE(${CDR(amaflags)})},"AccountCode":${CSV_QUOTE(${CDR(accountcode)})},"UniqueID":${CSV_QUOTE(${CDR(uniqueid)})},"UserField":${CSV_QUOTE(${CDR(userfield)})},"Sequence":${CDR(sequence)},"acustomfield1":${CSV_QUOTE(${CDR(acustomfield1)})},"acustomfield2":${CSV_QUOTE(${CDR(acustomfield2)})}} ' len 27) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CDR(lastdata)' (from 'CDR(lastdata)})' len 13) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CDR(lastdata) result is 'SIP/6004' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CSV_QUOTE(SIP/6004) result is '"SIP/6004"' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CSV_QUOTE(${CDR(start)})' (from 'CSV_QUOTE(${CDR(start)})},"Answer":${CSV_QUOTE(${CDR(answer)})},"End":${CSV_QUOTE(${CDR(end)})},"Duration":${CSV_QUOTE(${CDR(duration,f)})},"BillSec":${CSV_QUOTE(${CDR(billsec,f)})},"Disposition":${CSV_QUOTE(${CDR(disposition)})},"amaFlags":${CSV_QUOTE(${CDR(amaflags)})},"AccountCode":${CSV_QUOTE(${CDR(accountcode)})},"UniqueID":${CSV_QUOTE(${CDR(uniqueid)})},"UserField":${CSV_QUOTE(${CDR(userfield)})},"Sequence":${CDR(sequence)},"acustomfield1":${CSV_QUOTE(${CDR(acustomfield1)})},"acustomfield2":${CSV_QUOTE(${CDR(acustomfield2)})}} ' len 24) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CDR(start)' (from 'CDR(start)})' len 10) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CDR(start) result is '2014-04-08 16:05:16' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CSV_QUOTE(2014-04-08 16:05:16) result is '"2014-04-08 16:05:16"' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CSV_QUOTE(${CDR(answer)})' (from 'CSV_QUOTE(${CDR(answer)})},"End":${CSV_QUOTE(${CDR(end)})},"Duration":${CSV_QUOTE(${CDR(duration,f)})},"BillSec":${CSV_QUOTE(${CDR(billsec,f)})},"Disposition":${CSV_QUOTE(${CDR(disposition)})},"amaFlags":${CSV_QUOTE(${CDR(amaflags)})},"AccountCode":${CSV_QUOTE(${CDR(accountcode)})},"UniqueID":${CSV_QUOTE(${CDR(uniqueid)})},"UserField":${CSV_QUOTE(${CDR(userfield)})},"Sequence":${CDR(sequence)},"acustomfield1":${CSV_QUOTE(${CDR(acustomfield1)})},"acustomfield2":${CSV_QUOTE(${CDR(acustomfield2)})}} ' len 25) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CDR(answer)' (from 'CDR(answer)})' len 11) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CDR(answer) result is '2014-04-08 16:05:16' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CSV_QUOTE(2014-04-08 16:05:16) result is '"2014-04-08 16:05:16"' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CSV_QUOTE(${CDR(end)})' (from 'CSV_QUOTE(${CDR(end)})},"Duration":${CSV_QUOTE(${CDR(duration,f)})},"BillSec":${CSV_QUOTE(${CDR(billsec,f)})},"Disposition":${CSV_QUOTE(${CDR(disposition)})},"amaFlags":${CSV_QUOTE(${CDR(amaflags)})},"AccountCode":${CSV_QUOTE(${CDR(accountcode)})},"UniqueID":${CSV_QUOTE(${CDR(uniqueid)})},"UserField":${CSV_QUOTE(${CDR(userfield)})},"Sequence":${CDR(sequence)},"acustomfield1":${CSV_QUOTE(${CDR(acustomfield1)})},"acustomfield2":${CSV_QUOTE(${CDR(acustomfield2)})}} ' len 22) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CDR(end)' (from 'CDR(end)})' len 8) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CDR(end) result is '2014-04-08 16:05:27' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CSV_QUOTE(2014-04-08 16:05:27) result is '"2014-04-08 16:05:27"' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CSV_QUOTE(${CDR(duration,f)})' (from 'CSV_QUOTE(${CDR(duration,f)})},"BillSec":${CSV_QUOTE(${CDR(billsec,f)})},"Disposition":${CSV_QUOTE(${CDR(disposition)})},"amaFlags":${CSV_QUOTE(${CDR(amaflags)})},"AccountCode":${CSV_QUOTE(${CDR(accountcode)})},"UniqueID":${CSV_QUOTE(${CDR(uniqueid)})},"UserField":${CSV_QUOTE(${CDR(userfield)})},"Sequence":${CDR(sequence)},"acustomfield1":${CSV_QUOTE(${CDR(acustomfield1)})},"acustomfield2":${CSV_QUOTE(${CDR(acustomfield2)})}} ' len 29) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CDR(duration,f)' (from 'CDR(duration,f)})' len 15) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CDR(duration,f) result is '0.010000' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CSV_QUOTE(0.010000) result is '"0.010000"' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CSV_QUOTE(${CDR(billsec,f)})' (from 'CSV_QUOTE(${CDR(billsec,f)})},"Disposition":${CSV_QUOTE(${CDR(disposition)})},"amaFlags":${CSV_QUOTE(${CDR(amaflags)})},"AccountCode":${CSV_QUOTE(${CDR(accountcode)})},"UniqueID":${CSV_QUOTE(${CDR(uniqueid)})},"UserField":${CSV_QUOTE(${CDR(userfield)})},"Sequence":${CDR(sequence)},"acustomfield1":${CSV_QUOTE(${CDR(acustomfield1)})},"acustomfield2":${CSV_QUOTE(${CDR(acustomfield2)})}} ' len 28) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CDR(billsec,f)' (from 'CDR(billsec,f)})' len 14) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CDR(billsec,f) result is '0.010000' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CSV_QUOTE(0.010000) result is '"0.010000"' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CSV_QUOTE(${CDR(disposition)})' (from 'CSV_QUOTE(${CDR(disposition)})},"amaFlags":${CSV_QUOTE(${CDR(amaflags)})},"AccountCode":${CSV_QUOTE(${CDR(accountcode)})},"UniqueID":${CSV_QUOTE(${CDR(uniqueid)})},"UserField":${CSV_QUOTE(${CDR(userfield)})},"Sequence":${CDR(sequence)},"acustomfield1":${CSV_QUOTE(${CDR(acustomfield1)})},"acustomfield2":${CSV_QUOTE(${CDR(acustomfield2)})}} ' len 30) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CDR(disposition)' (from 'CDR(disposition)})' len 16) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CDR(disposition) result is 'ANSWERED' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CSV_QUOTE(ANSWERED) result is '"ANSWERED"' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CSV_QUOTE(${CDR(amaflags)})' (from 'CSV_QUOTE(${CDR(amaflags)})},"AccountCode":${CSV_QUOTE(${CDR(accountcode)})},"UniqueID":${CSV_QUOTE(${CDR(uniqueid)})},"UserField":${CSV_QUOTE(${CDR(userfield)})},"Sequence":${CDR(sequence)},"acustomfield1":${CSV_QUOTE(${CDR(acustomfield1)})},"acustomfield2":${CSV_QUOTE(${CDR(acustomfield2)})}} ' len 27) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CDR(amaflags)' (from 'CDR(amaflags)})' len 13) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CDR(amaflags) result is 'DOCUMENTATION' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CSV_QUOTE(DOCUMENTATION) result is '"DOCUMENTATION"' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CSV_QUOTE(${CDR(accountcode)})' (from 'CSV_QUOTE(${CDR(accountcode)})},"UniqueID":${CSV_QUOTE(${CDR(uniqueid)})},"UserField":${CSV_QUOTE(${CDR(userfield)})},"Sequence":${CDR(sequence)},"acustomfield1":${CSV_QUOTE(${CDR(acustomfield1)})},"acustomfield2":${CSV_QUOTE(${CDR(acustomfield2)})}} ' len 30) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CDR(accountcode)' (from 'CDR(accountcode)})' len 16) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CDR(accountcode) result is '' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CSV_QUOTE() result is '""' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CSV_QUOTE(${CDR(uniqueid)})' (from 'CSV_QUOTE(${CDR(uniqueid)})},"UserField":${CSV_QUOTE(${CDR(userfield)})},"Sequence":${CDR(sequence)},"acustomfield1":${CSV_QUOTE(${CDR(acustomfield1)})},"acustomfield2":${CSV_QUOTE(${CDR(acustomfield2)})}} ' len 27) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CDR(uniqueid)' (from 'CDR(uniqueid)})' len 13) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CDR(uniqueid) result is '1396991116.45' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CSV_QUOTE(1396991116.45) result is '"1396991116.45"' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CSV_QUOTE(${CDR(userfield)})' (from 'CSV_QUOTE(${CDR(userfield)})},"Sequence":${CDR(sequence)},"acustomfield1":${CSV_QUOTE(${CDR(acustomfield1)})},"acustomfield2":${CSV_QUOTE(${CDR(acustomfield2)})}} ' len 28) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CDR(userfield)' (from 'CDR(userfield)})' len 14) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CDR(userfield) result is '' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CSV_QUOTE() result is '""' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CDR(sequence)' (from 'CDR(sequence)},"acustomfield1":${CSV_QUOTE(${CDR(acustomfield1)})},"acustomfield2":${CSV_QUOTE(${CDR(acustomfield2)})}} ' len 13) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CDR(sequence) result is '36' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CSV_QUOTE(${CDR(acustomfield1)})' (from 'CSV_QUOTE(${CDR(acustomfield1)})},"acustomfield2":${CSV_QUOTE(${CDR(acustomfield2)})}} ' len 32) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CDR(acustomfield1)' (from 'CDR(acustomfield1)})' len 18) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CDR(acustomfield1) result is '' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CSV_QUOTE() result is '""' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CSV_QUOTE(${CDR(acustomfield2)})' (from 'CSV_QUOTE(${CDR(acustomfield2)})}} ' len 32) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CDR(acustomfield2)' (from 'CDR(acustomfield2)})' len 18) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CDR(acustomfield2) result is '' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CSV_QUOTE() result is '""' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CSV_QUOTE(${CDR(src)})' (from 'CSV_QUOTE(${CDR(src)})},"Destination":${CSV_QUOTE(${CDR(dst)})},"Context":${CSV_QUOTE(${CDR(dcontext)})},"SourceChannel":${CSV_QUOTE(${CDR(channel)})},"DestinationChannel":${CSV_QUOTE(${CDR(dstchannel)})},"LastAPP":${CSV_QUOTE(${CDR(lastapp)})},"LastData":${CSV_QUOTE(${CDR(lastdata)})},"Start":${CSV_QUOTE(${CDR(start)})},"Answer":${CSV_QUOTE(${CDR(answer)})},"End":${CSV_QUOTE(${CDR(end)})},"Duration":${CSV_QUOTE(${CDR(duration,f)})},"BillSec":${CSV_QUOTE(${CDR(billsec,f)})},"Disposition":${CSV_QUOTE(${CDR(disposition)})},"amaFlags":${CSV_QUOTE(${CDR(amaflags)})},"AccountCode":${CSV_QUOTE(${CDR(accountcode)})},"UniqueID":${CSV_QUOTE(${CDR(uniqueid)})},"UserField":${CSV_QUOTE(${CDR(userfield)})},"Sequence":${CDR(sequence)},"acustomfield1":${CSV_QUOTE(${CDR(acustomfield1)})},"acustomfield2":${CSV_QUOTE(${CDR(acustomfield2)})}} ' len 22) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CDR(src)' (from 'CDR(src)})' len 8) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CDR(src) result is '6001' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CSV_QUOTE(6001) result is '"6001"' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CSV_QUOTE(${CDR(dst)})' (from 'CSV_QUOTE(${CDR(dst)})},"Context":${CSV_QUOTE(${CDR(dcontext)})},"SourceChannel":${CSV_QUOTE(${CDR(channel)})},"DestinationChannel":${CSV_QUOTE(${CDR(dstchannel)})},"LastAPP":${CSV_QUOTE(${CDR(lastapp)})},"LastData":${CSV_QUOTE(${CDR(lastdata)})},"Start":${CSV_QUOTE(${CDR(start)})},"Answer":${CSV_QUOTE(${CDR(answer)})},"End":${CSV_QUOTE(${CDR(end)})},"Duration":${CSV_QUOTE(${CDR(duration,f)})},"BillSec":${CSV_QUOTE(${CDR(billsec,f)})},"Disposition":${CSV_QUOTE(${CDR(disposition)})},"amaFlags":${CSV_QUOTE(${CDR(amaflags)})},"AccountCode":${CSV_QUOTE(${CDR(accountcode)})},"UniqueID":${CSV_QUOTE(${CDR(uniqueid)})},"UserField":${CSV_QUOTE(${CDR(userfield)})},"Sequence":${CDR(sequence)},"acustomfield1":${CSV_QUOTE(${CDR(acustomfield1)})},"acustomfield2":${CSV_QUOTE(${CDR(acustomfield2)})}} ' len 22) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CDR(dst)' (from 'CDR(dst)})' len 8) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CDR(dst) result is '12' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CSV_QUOTE(12) result is '"12"' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CSV_QUOTE(${CDR(dcontext)})' (from 'CSV_QUOTE(${CDR(dcontext)})},"SourceChannel":${CSV_QUOTE(${CDR(channel)})},"DestinationChannel":${CSV_QUOTE(${CDR(dstchannel)})},"LastAPP":${CSV_QUOTE(${CDR(lastapp)})},"LastData":${CSV_QUOTE(${CDR(lastdata)})},"Start":${CSV_QUOTE(${CDR(start)})},"Answer":${CSV_QUOTE(${CDR(answer)})},"End":${CSV_QUOTE(${CDR(end)})},"Duration":${CSV_QUOTE(${CDR(duration,f)})},"BillSec":${CSV_QUOTE(${CDR(billsec,f)})},"Disposition":${CSV_QUOTE(${CDR(disposition)})},"amaFlags":${CSV_QUOTE(${CDR(amaflags)})},"AccountCode":${CSV_QUOTE(${CDR(accountcode)})},"UniqueID":${CSV_QUOTE(${CDR(uniqueid)})},"UserField":${CSV_QUOTE(${CDR(userfield)})},"Sequence":${CDR(sequence)},"acustomfield1":${CSV_QUOTE(${CDR(acustomfield1)})},"acustomfield2":${CSV_QUOTE(${CDR(acustomfield2)})}} ' len 27) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CDR(dcontext)' (from 'CDR(dcontext)})' len 13) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CDR(dcontext) result is 'agi-test-context' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CSV_QUOTE(agi-test-context) result is '"agi-test-context"' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CSV_QUOTE(${CDR(channel)})' (from 'CSV_QUOTE(${CDR(channel)})},"DestinationChannel":${CSV_QUOTE(${CDR(dstchannel)})},"LastAPP":${CSV_QUOTE(${CDR(lastapp)})},"LastData":${CSV_QUOTE(${CDR(lastdata)})},"Start":${CSV_QUOTE(${CDR(start)})},"Answer":${CSV_QUOTE(${CDR(answer)})},"End":${CSV_QUOTE(${CDR(end)})},"Duration":${CSV_QUOTE(${CDR(duration,f)})},"BillSec":${CSV_QUOTE(${CDR(billsec,f)})},"Disposition":${CSV_QUOTE(${CDR(disposition)})},"amaFlags":${CSV_QUOTE(${CDR(amaflags)})},"AccountCode":${CSV_QUOTE(${CDR(accountcode)})},"UniqueID":${CSV_QUOTE(${CDR(uniqueid)})},"UserField":${CSV_QUOTE(${CDR(userfield)})},"Sequence":${CDR(sequence)},"acustomfield1":${CSV_QUOTE(${CDR(acustomfield1)})},"acustomfield2":${CSV_QUOTE(${CDR(acustomfield2)})}} ' len 26) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CDR(channel)' (from 'CDR(channel)})' len 12) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CDR(channel) result is 'SIP/6001-0000001b' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CSV_QUOTE(SIP/6001-0000001b) result is '"SIP/6001-0000001b"' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CSV_QUOTE(${CDR(dstchannel)})' (from 'CSV_QUOTE(${CDR(dstchannel)})},"LastAPP":${CSV_QUOTE(${CDR(lastapp)})},"LastData":${CSV_QUOTE(${CDR(lastdata)})},"Start":${CSV_QUOTE(${CDR(start)})},"Answer":${CSV_QUOTE(${CDR(answer)})},"End":${CSV_QUOTE(${CDR(end)})},"Duration":${CSV_QUOTE(${CDR(duration,f)})},"BillSec":${CSV_QUOTE(${CDR(billsec,f)})},"Disposition":${CSV_QUOTE(${CDR(disposition)})},"amaFlags":${CSV_QUOTE(${CDR(amaflags)})},"AccountCode":${CSV_QUOTE(${CDR(accountcode)})},"UniqueID":${CSV_QUOTE(${CDR(uniqueid)})},"UserField":${CSV_QUOTE(${CDR(userfield)})},"Sequence":${CDR(sequence)},"acustomfield1":${CSV_QUOTE(${CDR(acustomfield1)})},"acustomfield2":${CSV_QUOTE(${CDR(acustomfield2)})}} ' len 29) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CDR(dstchannel)' (from 'CDR(dstchannel)})' len 15) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CDR(dstchannel) result is 'SIP/6002-0000001d' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CSV_QUOTE(SIP/6002-0000001d) result is '"SIP/6002-0000001d"' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CSV_QUOTE(${CDR(lastapp)})' (from 'CSV_QUOTE(${CDR(lastapp)})},"LastData":${CSV_QUOTE(${CDR(lastdata)})},"Start":${CSV_QUOTE(${CDR(start)})},"Answer":${CSV_QUOTE(${CDR(answer)})},"End":${CSV_QUOTE(${CDR(end)})},"Duration":${CSV_QUOTE(${CDR(duration,f)})},"BillSec":${CSV_QUOTE(${CDR(billsec,f)})},"Disposition":${CSV_QUOTE(${CDR(disposition)})},"amaFlags":${CSV_QUOTE(${CDR(amaflags)})},"AccountCode":${CSV_QUOTE(${CDR(accountcode)})},"UniqueID":${CSV_QUOTE(${CDR(uniqueid)})},"UserField":${CSV_QUOTE(${CDR(userfield)})},"Sequence":${CDR(sequence)},"acustomfield1":${CSV_QUOTE(${CDR(acustomfield1)})},"acustomfield2":${CSV_QUOTE(${CDR(acustomfield2)})}} ' len 26) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CDR(lastapp)' (from 'CDR(lastapp)})' len 12) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CDR(lastapp) result is 'Dial' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CSV_QUOTE(Dial) result is '"Dial"' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CSV_QUOTE(${CDR(lastdata)})' (from 'CSV_QUOTE(${CDR(lastdata)})},"Start":${CSV_QUOTE(${CDR(start)})},"Answer":${CSV_QUOTE(${CDR(answer)})},"End":${CSV_QUOTE(${CDR(end)})},"Duration":${CSV_QUOTE(${CDR(duration,f)})},"BillSec":${CSV_QUOTE(${CDR(billsec,f)})},"Disposition":${CSV_QUOTE(${CDR(disposition)})},"amaFlags":${CSV_QUOTE(${CDR(amaflags)})},"AccountCode":${CSV_QUOTE(${CDR(accountcode)})},"UniqueID":${CSV_QUOTE(${CDR(uniqueid)})},"UserField":${CSV_QUOTE(${CDR(userfield)})},"Sequence":${CDR(sequence)},"acustomfield1":${CSV_QUOTE(${CDR(acustomfield1)})},"acustomfield2":${CSV_QUOTE(${CDR(acustomfield2)})}} ' len 27) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CDR(lastdata)' (from 'CDR(lastdata)})' len 13) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CDR(lastdata) result is 'SIP/6002,45,Tt' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CSV_QUOTE(SIP/6002,45,Tt) result is '"SIP/6002,45,Tt"' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CSV_QUOTE(${CDR(start)})' (from 'CSV_QUOTE(${CDR(start)})},"Answer":${CSV_QUOTE(${CDR(answer)})},"End":${CSV_QUOTE(${CDR(end)})},"Duration":${CSV_QUOTE(${CDR(duration,f)})},"BillSec":${CSV_QUOTE(${CDR(billsec,f)})},"Disposition":${CSV_QUOTE(${CDR(disposition)})},"amaFlags":${CSV_QUOTE(${CDR(amaflags)})},"AccountCode":${CSV_QUOTE(${CDR(accountcode)})},"UniqueID":${CSV_QUOTE(${CDR(uniqueid)})},"UserField":${CSV_QUOTE(${CDR(userfield)})},"Sequence":${CDR(sequence)},"acustomfield1":${CSV_QUOTE(${CDR(acustomfield1)})},"acustomfield2":${CSV_QUOTE(${CDR(acustomfield2)})}} ' len 24) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CDR(start)' (from 'CDR(start)})' len 10) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CDR(start) result is '2014-04-08 16:05:27' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CSV_QUOTE(2014-04-08 16:05:27) result is '"2014-04-08 16:05:27"' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CSV_QUOTE(${CDR(answer)})' (from 'CSV_QUOTE(${CDR(answer)})},"End":${CSV_QUOTE(${CDR(end)})},"Duration":${CSV_QUOTE(${CDR(duration,f)})},"BillSec":${CSV_QUOTE(${CDR(billsec,f)})},"Disposition":${CSV_QUOTE(${CDR(disposition)})},"amaFlags":${CSV_QUOTE(${CDR(amaflags)})},"AccountCode":${CSV_QUOTE(${CDR(accountcode)})},"UniqueID":${CSV_QUOTE(${CDR(uniqueid)})},"UserField":${CSV_QUOTE(${CDR(userfield)})},"Sequence":${CDR(sequence)},"acustomfield1":${CSV_QUOTE(${CDR(acustomfield1)})},"acustomfield2":${CSV_QUOTE(${CDR(acustomfield2)})}} ' len 25) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CDR(answer)' (from 'CDR(answer)})' len 11) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CDR(answer) result is '2014-04-08 16:05:27' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CSV_QUOTE(2014-04-08 16:05:27) result is '"2014-04-08 16:05:27"' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CSV_QUOTE(${CDR(end)})' (from 'CSV_QUOTE(${CDR(end)})},"Duration":${CSV_QUOTE(${CDR(duration,f)})},"BillSec":${CSV_QUOTE(${CDR(billsec,f)})},"Disposition":${CSV_QUOTE(${CDR(disposition)})},"amaFlags":${CSV_QUOTE(${CDR(amaflags)})},"AccountCode":${CSV_QUOTE(${CDR(accountcode)})},"UniqueID":${CSV_QUOTE(${CDR(uniqueid)})},"UserField":${CSV_QUOTE(${CDR(userfield)})},"Sequence":${CDR(sequence)},"acustomfield1":${CSV_QUOTE(${CDR(acustomfield1)})},"acustomfield2":${CSV_QUOTE(${CDR(acustomfield2)})}} ' len 22) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CDR(end)' (from 'CDR(end)})' len 8) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CDR(end) result is '2014-04-08 16:05:27' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CSV_QUOTE(2014-04-08 16:05:27) result is '"2014-04-08 16:05:27"' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CSV_QUOTE(${CDR(duration,f)})' (from 'CSV_QUOTE(${CDR(duration,f)})},"BillSec":${CSV_QUOTE(${CDR(billsec,f)})},"Disposition":${CSV_QUOTE(${CDR(disposition)})},"amaFlags":${CSV_QUOTE(${CDR(amaflags)})},"AccountCode":${CSV_QUOTE(${CDR(accountcode)})},"UniqueID":${CSV_QUOTE(${CDR(uniqueid)})},"UserField":${CSV_QUOTE(${CDR(userfield)})},"Sequence":${CDR(sequence)},"acustomfield1":${CSV_QUOTE(${CDR(acustomfield1)})},"acustomfield2":${CSV_QUOTE(${CDR(acustomfield2)})}} ' len 29) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CDR(duration,f)' (from 'CDR(duration,f)})' len 15) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CDR(duration,f) result is '0.000000' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CSV_QUOTE(0.000000) result is '"0.000000"' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CSV_QUOTE(${CDR(billsec,f)})' (from 'CSV_QUOTE(${CDR(billsec,f)})},"Disposition":${CSV_QUOTE(${CDR(disposition)})},"amaFlags":${CSV_QUOTE(${CDR(amaflags)})},"AccountCode":${CSV_QUOTE(${CDR(accountcode)})},"UniqueID":${CSV_QUOTE(${CDR(uniqueid)})},"UserField":${CSV_QUOTE(${CDR(userfield)})},"Sequence":${CDR(sequence)},"acustomfield1":${CSV_QUOTE(${CDR(acustomfield1)})},"acustomfield2":${CSV_QUOTE(${CDR(acustomfield2)})}} ' len 28) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CDR(billsec,f)' (from 'CDR(billsec,f)})' len 14) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CDR(billsec,f) result is '0.000000' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CSV_QUOTE(0.000000) result is '"0.000000"' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CSV_QUOTE(${CDR(disposition)})' (from 'CSV_QUOTE(${CDR(disposition)})},"amaFlags":${CSV_QUOTE(${CDR(amaflags)})},"AccountCode":${CSV_QUOTE(${CDR(accountcode)})},"UniqueID":${CSV_QUOTE(${CDR(uniqueid)})},"UserField":${CSV_QUOTE(${CDR(userfield)})},"Sequence":${CDR(sequence)},"acustomfield1":${CSV_QUOTE(${CDR(acustomfield1)})},"acustomfield2":${CSV_QUOTE(${CDR(acustomfield2)})}} ' len 30) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CDR(disposition)' (from 'CDR(disposition)})' len 16) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CDR(disposition) result is 'NO ANSWER' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CSV_QUOTE(NO ANSWER) result is '"NO ANSWER"' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CSV_QUOTE(${CDR(amaflags)})' (from 'CSV_QUOTE(${CDR(amaflags)})},"AccountCode":${CSV_QUOTE(${CDR(accountcode)})},"UniqueID":${CSV_QUOTE(${CDR(uniqueid)})},"UserField":${CSV_QUOTE(${CDR(userfield)})},"Sequence":${CDR(sequence)},"acustomfield1":${CSV_QUOTE(${CDR(acustomfield1)})},"acustomfield2":${CSV_QUOTE(${CDR(acustomfield2)})}} ' len 27) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CDR(amaflags)' (from 'CDR(amaflags)})' len 13) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CDR(amaflags) result is 'DOCUMENTATION' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CSV_QUOTE(DOCUMENTATION) result is '"DOCUMENTATION"' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CSV_QUOTE(${CDR(accountcode)})' (from 'CSV_QUOTE(${CDR(accountcode)})},"UniqueID":${CSV_QUOTE(${CDR(uniqueid)})},"UserField":${CSV_QUOTE(${CDR(userfield)})},"Sequence":${CDR(sequence)},"acustomfield1":${CSV_QUOTE(${CDR(acustomfield1)})},"acustomfield2":${CSV_QUOTE(${CDR(acustomfield2)})}} ' len 30) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CDR(accountcode)' (from 'CDR(accountcode)})' len 16) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CDR(accountcode) result is '' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CSV_QUOTE() result is '""' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CSV_QUOTE(${CDR(uniqueid)})' (from 'CSV_QUOTE(${CDR(uniqueid)})},"UserField":${CSV_QUOTE(${CDR(userfield)})},"Sequence":${CDR(sequence)},"acustomfield1":${CSV_QUOTE(${CDR(acustomfield1)})},"acustomfield2":${CSV_QUOTE(${CDR(acustomfield2)})}} ' len 27) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CDR(uniqueid)' (from 'CDR(uniqueid)})' len 13) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CDR(uniqueid) result is '1396991116.45' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CSV_QUOTE(1396991116.45) result is '"1396991116.45"' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CSV_QUOTE(${CDR(userfield)})' (from 'CSV_QUOTE(${CDR(userfield)})},"Sequence":${CDR(sequence)},"acustomfield1":${CSV_QUOTE(${CDR(acustomfield1)})},"acustomfield2":${CSV_QUOTE(${CDR(acustomfield2)})}} ' len 28) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CDR(userfield)' (from 'CDR(userfield)})' len 14) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CDR(userfield) result is '' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CSV_QUOTE() result is '""' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CDR(sequence)' (from 'CDR(sequence)},"acustomfield1":${CSV_QUOTE(${CDR(acustomfield1)})},"acustomfield2":${CSV_QUOTE(${CDR(acustomfield2)})}} ' len 13) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CDR(sequence) result is '39' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CSV_QUOTE(${CDR(acustomfield1)})' (from 'CSV_QUOTE(${CDR(acustomfield1)})},"acustomfield2":${CSV_QUOTE(${CDR(acustomfield2)})}} ' len 32) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CDR(acustomfield1)' (from 'CDR(acustomfield1)})' len 18) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CDR(acustomfield1) result is '' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CSV_QUOTE() result is '""' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CSV_QUOTE(${CDR(acustomfield2)})' (from 'CSV_QUOTE(${CDR(acustomfield2)})}} ' len 32) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Evaluating 'CDR(acustomfield2)' (from 'CDR(acustomfield2)})' len 18) [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CDR(acustomfield2) result is '' [Apr 8 16:05:27] DEBUG[19896] pbx.c: Function CSV_QUOTE() result is '""' [Apr 8 16:05:27] DEBUG[19931] chan_sip.c: = Looking for Call ID: KGlMtfIl-KgrUYwasot8XUZdVQydmlVO (Checking To) --From tag as7c85b754 --To-tag zm8Y7r0zbR8Q575x4STWMxDuQZLaYZQ8 [Apr 8 16:05:27] DEBUG[19931][C-00000009] chan_sip.c: Stopping retransmission on 'KGlMtfIl-KgrUYwasot8XUZdVQydmlVO' of Request 102: Match Found [Apr 8 16:05:27] DEBUG[19931] chan_sip.c: Destroying SIP dialog KGlMtfIl-KgrUYwasot8XUZdVQydmlVO [Apr 8 16:05:27] DEBUG[19931] rtp_engine.c: Destroyed RTP instance '0x7f717002bb28' [Apr 8 16:05:27] DEBUG[19931] chan_sip.c: = Looking for Call ID: 06fc799c41afcbe357c9708226ca6e8a@10.24.18.124:5060 (Checking To) --From tag as3349f1a5 --To-tag [Apr 8 16:05:27] DEBUG[19931][C-00000009] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '06fc799c41afcbe357c9708226ca6e8a@10.24.18.124:5060' Request 102: Found [Apr 8 16:05:27] DEBUG[19931][C-00000009] chan_sip.c: SIP response 100 to standard invite [Apr 8 16:05:27] DEBUG[19931][C-00000009] chan_sip.c: Trying to put 'CANCEL sip:' onto UDP socket destined for 10.24.18.138:5060 [Apr 8 16:05:27] DEBUG[19931] chan_sip.c: = Looking for Call ID: 17ec2f31558556e17e92e5fc13412e2e@10.24.18.124:5060 (Checking To) --From tag as0f0ed517 --To-tag 1095016331 [Apr 8 16:05:27] DEBUG[19931][C-00000009] chan_sip.c: Stopping retransmission on '17ec2f31558556e17e92e5fc13412e2e@10.24.18.124:5060' of Request 103: Match Found [Apr 8 16:05:27] DEBUG[19931] chan_sip.c: = Looking for Call ID: 06fc799c41afcbe357c9708226ca6e8a@10.24.18.124:5060 (Checking To) --From tag as3349f1a5 --To-tag XPyNCPq8bE.YR-4sWRarH78UyRFdQQPO [Apr 8 16:05:27] DEBUG[19931][C-00000009] chan_sip.c: Acked pending invite 102 [Apr 8 16:05:27] DEBUG[19931][C-00000009] chan_sip.c: Stopping retransmission on '06fc799c41afcbe357c9708226ca6e8a@10.24.18.124:5060' of Request 102: Match Found [Apr 8 16:05:27] DEBUG[19931] chan_sip.c: = Looking for Call ID: 06fc799c41afcbe357c9708226ca6e8a@10.24.18.124:5060 (Checking To) --From tag as3349f1a5 --To-tag XPyNCPq8bE.YR-4sWRarH78UyRFdQQPO [Apr 8 16:05:27] DEBUG[19931][C-00000009] chan_sip.c: Stopping retransmission on '06fc799c41afcbe357c9708226ca6e8a@10.24.18.124:5060' of Request 102: Match Found [Apr 8 16:05:27] DEBUG[19931][C-00000009] chan_sip.c: SIP response 487 to standard invite [Apr 8 16:05:27] DEBUG[19931][C-00000009] chan_sip.c: Trying to put 'ACK sip:600' onto UDP socket destined for 10.24.18.138:5060 [Apr 8 16:05:27] DEBUG[19931][C-00000009] chan_sip.c: Updating call counter for outgoing call [Apr 8 16:05:31] DEBUG[19931] chan_sip.c: = Looking for Call ID: 17ec2f31558556e17e92e5fc13412e2e@10.24.18.124:5060 (Checking From) --From tag 1095016331 --To-tag as0f0ed517 [Apr 8 16:05:31] DEBUG[19931][C-00000009] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [Apr 8 16:05:31] DEBUG[19931][C-00000009] netsock2.c: Splitting '10.24.18.166:5060' into... [Apr 8 16:05:31] DEBUG[19931][C-00000009] netsock2.c: ...host '10.24.18.166' and port '5060'. [Apr 8 16:05:31] DEBUG[19931][C-00000009] chan_sip.c: Setting SIP_ALREADYGONE on dialog 17ec2f31558556e17e92e5fc13412e2e@10.24.18.124:5060 [Apr 8 16:05:31] DEBUG[19931][C-00000009] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f71d4009a18' [Apr 8 16:05:31] DEBUG[19931][C-00000009] chan_sip.c: Received bye, no owner, selfdestruct soon. [Apr 8 16:05:31] DEBUG[19931][C-00000009] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.24.18.166:5060 [Apr 8 16:05:34] DEBUG[19931] chan_sip.c: Auto destroying SIP dialog '8323200811233-281921055718516@10.24.18.166' [Apr 8 16:05:34] DEBUG[19931] chan_sip.c: Destroying SIP dialog 8323200811233-281921055718516@10.24.18.166 [Apr 8 16:05:38] VERBOSE[20233] asterisk.c: -- Remote UNIX connection disconnected [Apr 8 16:05:39] DEBUG[19931] chan_sip.c: Auto destroying SIP dialog '-.I72cbVlmiEx1OpKvsfriYoN22tzTFh' [Apr 8 16:05:39] DEBUG[19931] chan_sip.c: Destroying SIP dialog -.I72cbVlmiEx1OpKvsfriYoN22tzTFh [Apr 8 16:05:40] DEBUG[19931] chan_sip.c: Auto destroying SIP dialog 'Em8FIgh3R86-L7nayIfS7hE5KR8vfQpI' [Apr 8 16:05:40] DEBUG[19931] chan_sip.c: Destroying SIP dialog Em8FIgh3R86-L7nayIfS7hE5KR8vfQpI