[2018-11-06 10:06:53] Asterisk 13.23.1 built by root @ Telsam-iex4 on a x86_64 running Linux on 2018-10-27 10:34:20 UTC [2018-11-06 10:06:53] DEBUG[31020] config.c: Parsing /etc/asterisk/logger.conf [2018-11-06 10:06:53] VERBOSE[31020] logger.c: Asterisk Queue Logger restarted [2018-11-06 10:06:57] DEBUG[27082] chan_sip.c: = Looking for Call ID: 9a4ce1a31deb412896093d809b626491 (Checking From) --From tag 9cf7c824cb8148f0abdf2a413f8b4cac --To-tag [2018-11-06 10:06:57] DEBUG[27082] acl.c: For destination '78.187.100.242', our source address is '85.111.24.13'. [2018-11-06 10:06:57] DEBUG[27082] chan_sip.c: Setting AST_TRANSPORT_UDP with address 85.111.24.13:5060 [2018-11-06 10:06:57] DEBUG[27082] netsock2.c: Splitting '192.168.1.14:54256' into... [2018-11-06 10:06:57] DEBUG[27082] netsock2.c: ...host '192.168.1.14' and port '54256'. [2018-11-06 10:06:57] DEBUG[27082] chan_sip.c: NAT detected for 192.168.1.14 / 78.187.100.242 [2018-11-06 10:06:57] DEBUG[27082] chan_sip.c: Allocating new SIP dialog for 9a4ce1a31deb412896093d809b626491 - INVITE (No RTP) [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] sip/reqresp_parser.c: Begin: parsing SIP "Supported: replaces, 100rel, timer, norefersub" [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] sip/reqresp_parser.c: Found SIP option: -replaces- [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] sip/reqresp_parser.c: Matched SIP option: replaces [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] sip/reqresp_parser.c: Found SIP option: -100rel- [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] sip/reqresp_parser.c: Matched SIP option: 100rel [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] sip/reqresp_parser.c: Found SIP option: -timer- [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] sip/reqresp_parser.c: Matched SIP option: timer [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] sip/reqresp_parser.c: Found SIP option: -norefersub- [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] sip/reqresp_parser.c: Matched SIP option: norefersub [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] netsock2.c: Splitting '192.168.1.14:54256' into... [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] netsock2.c: ...host '192.168.1.14' and port '54256'. [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: NAT detected for 192.168.1.14 / 78.187.100.242 [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] netsock2.c: Splitting '101' into... [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] netsock2.c: ...host '101' and port ''. [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 78.187.100.242:54256 [2018-11-06 10:06:57] DEBUG[27082] chan_sip.c: = Looking for Call ID: 9a4ce1a31deb412896093d809b626491 (Checking From) --From tag 9cf7c824cb8148f0abdf2a413f8b4cac --To-tag as07561fb4 [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: Stopping retransmission on '9a4ce1a31deb412896093d809b626491' of Response 10421: Match Found [2018-11-06 10:06:57] DEBUG[27082] chan_sip.c: = Looking for Call ID: 9a4ce1a31deb412896093d809b626491 (Checking From) --From tag 9cf7c824cb8148f0abdf2a413f8b4cac --To-tag [2018-11-06 10:06:57] DEBUG[27082] netsock2.c: Splitting '101' into... [2018-11-06 10:06:57] DEBUG[27082] netsock2.c: ...host '101' and port ''. [2018-11-06 10:06:57] DEBUG[27082] netsock2.c: Splitting '101' into... [2018-11-06 10:06:57] DEBUG[27082] netsock2.c: ...host '101' and port ''. [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] netsock2.c: Splitting '192.168.1.14:54256' into... [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] netsock2.c: ...host '192.168.1.14' and port '54256'. [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: NAT detected for 192.168.1.14 / 78.187.100.242 [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] netsock2.c: Splitting '101' into... [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] netsock2.c: ...host '101' and port ''. [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fc234217570' [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] res_rtp_asterisk.c: Allocated port 11638 for RTP instance '0x7fc234217570' [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] res_rtp_asterisk.c: Creating ICE session 0.0.0.0:11638 (11638) for RTP instance '0x7fc234217570' [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] netsock2.c: Splitting '85.111.24.13' into... [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] netsock2.c: ...host '85.111.24.13' and port ''. [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] netsock2.c: Splitting '85.111.24.13' into... [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] netsock2.c: ...host '85.111.24.13' and port ''. [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] rtp_engine.c: RTP instance '0x7fc234217570' is setup and ready to go [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] netsock2.c: Splitting 'Telsam-iex4' into... [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] netsock2.c: ...host 'Telsam-iex4' and port ''. [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fc234217570' [2018-11-06 10:06:57] VERBOSE[27082][C-000007b3] netsock2.c: Using SIP RTP TOS bits 184 [2018-11-06 10:06:57] VERBOSE[27082][C-000007b3] netsock2.c: Using SIP RTP CoS mark 5 [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: Setting NAT on RTP to On [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: Processing session-level SDP o=- 3750487615 3750487615 IN IP4 192.168.1.14... OK. [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: Processing session-level SDP s=pjmedia... UNSUPPORTED OR FAILED. [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: Processing session-level SDP b=AS:84... UNSUPPORTED OR FAILED. [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [2018-11-06 10:06:57] VERBOSE[27082][C-000007b3] netsock2.c: Using UDPTL TOS bits 184 [2018-11-06 10:06:57] VERBOSE[27082][C-000007b3] netsock2.c: Using UDPTL CoS mark 5 [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: Setting NAT on UDPTL to On [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: Processing session-level SDP a=X-nat:0... UNSUPPORTED OR FAILED. [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] rtp_engine.c: Don't have a default tx payload type 123 format for m type on 0x7fc1c927b470 [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7fc1c927b470 [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7fc1c927b470 [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] rtp_engine.c: Setting tx payload type 101 based on m type on 0x7fc1c927b470 [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] netsock2.c: Splitting '192.168.1.14' into... [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] netsock2.c: ...host '192.168.1.14' and port ''. [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: Processing media-level (audio) SDP c=IN IP4 192.168.1.14... OK. [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: Processing media-level (audio) SDP b=TIAS:64000... UNSUPPORTED OR FAILED. [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: Processing media-level (audio) SDP a=rtcp:4017 IN IP4 192.168.1.14... UNSUPPORTED OR FAILED. [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:123 opus/48000/2... OK. [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: Processing media-level (audio) SDP a=fmtp:123 maxplaybackrate=24000... OK. [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED OR FAILED. [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: Processing media-level (audio) SDP a=ssrc:1021131860 cname:5bc525dd780c01c5... UNSUPPORTED OR FAILED. [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] acl.c: For destination '192.168.1.14', our source address is '85.111.24.13'. [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fc234217570' [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] rtp_engine.c: Copying payload 0 (0x7fc2341dabc8) from 0x7fc1c927b470 to 0x7fc234217738 [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] rtp_engine.c: Copying payload 8 (0x7fc2341ee018) from 0x7fc1c927b470 to 0x7fc234217738 [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] rtp_engine.c: Copying payload 101 (0x7fc23406a1a8) from 0x7fc1c927b470 to 0x7fc234217738 [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] rtp_engine.c: Copying payload 123 (0x7fc2340204c8) from 0x7fc1c927b470 to 0x7fc234217738 [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7fc234217570' [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: We're settling with these formats: (alaw|ulaw) [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: Checking SIP call limits for device 101 [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: Updating call counter for incoming call [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] netsock2.c: Splitting '101' into... [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] netsock2.c: ...host '101' and port ''. [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] netsock2.c: Splitting '101' into... [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] netsock2.c: ...host '101' and port ''. [2018-11-06 10:06:57] DEBUG[27045] devicestate.c: No provider found, checking channel drivers for SIP - 101 [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: Incoming INVITE with 'timer' option supported [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: INVITE also has "Session-Expires" header. [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: Session-Expires: 1800 [2018-11-06 10:06:57] DEBUG[27045] chan_sip.c: Checking device state for peer 101 [2018-11-06 10:06:57] DEBUG[27045] devicestate.c: Changing state for SIP/101 - state 2 (In use) [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: INVITE also has "Min-SE" header. [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: Received Min-SE: 90 [2018-11-06 10:06:57] DEBUG[27108] app_queue.c: Removed SIP/101 from pending_members [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] channel.c: Channel 0x7fc234267480 'SIP/101-00000053' allocated [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: *** Our native formats are (alaw) [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: *** Joint capabilities are (alaw|ulaw) [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: *** Our capabilities are (alaw|ulaw|g729) [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: *** AST_CODEC_CHOOSE formats are alaw [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: This channel will not be able to handle video. [2018-11-06 10:06:57] DEBUG[27108] app_queue.c: Removed SIP/101 from pending_members [2018-11-06 10:06:57] DEBUG[27108] app_queue.c: Device 'SIP/101' changed to state '2' (In use) [2018-11-06 10:06:57] DEBUG[27108] app_queue.c: Device 'Queue:631_avail' changed to state '2' (In use) but we don't care because they're not a member of any queue. [2018-11-06 10:06:57] DEBUG[27034] threadpool.c: Increasing threadpool stasis-core's size by 1 [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: SIP/101-00000053: New call is still down.... Trying... [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 78.187.100.242:54256 [2018-11-06 10:06:57] DEBUG[27045] devicestate.c: No provider found, checking channel drivers for SIP - 101 [2018-11-06 10:06:57] DEBUG[27045] chan_sip.c: Checking device state for peer 101 [2018-11-06 10:06:57] DEBUG[27045] devicestate.c: Changing state for SIP/101 - state 2 (In use) [2018-11-06 10:06:57] DEBUG[734][C-000007b3] pbx.c: Launching 'Queue' [2018-11-06 10:06:57] VERBOSE[734][C-000007b3] pbx.c: Executing [630@DLPN_DialPlan1:1] Queue("SIP/101-00000053", "630,tkXx,,,,queue-set.php,") in new stack [2018-11-06 10:06:57] DEBUG[734][C-000007b3] app_queue.c: queue: 630, options: tkXx, url: , announce: , timeout: , agi: queue-set.php, macro: , gosub: , rule: , position: [2018-11-06 10:06:57] DEBUG[734][C-000007b3] app_queue.c: NO QUEUE_PRIO variable found. Using default. [2018-11-06 10:06:57] DEBUG[734][C-000007b3] app_queue.c: queue: 630, expires: 0, priority: 0 [2018-11-06 10:06:57] DEBUG[734][C-000007b3] app_queue.c: Queue 630 has no realtime members defined. No need for update [2018-11-06 10:06:57] DEBUG[734][C-000007b3] app_queue.c: SIP/100 is available. [2018-11-06 10:06:57] DEBUG[734][C-000007b3] app_queue.c: Queue '630' Join, Channel 'SIP/101-00000053', Position '1' [2018-11-06 10:06:57] DEBUG[27108] app_queue.c: Device 'Queue:630' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [2018-11-06 10:06:57] VERBOSE[734][C-000007b3] res_musiconhold.c: Started music on hold, class 'queuemusic', on channel 'SIP/101-00000053' [2018-11-06 10:06:57] DEBUG[734][C-000007b3] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [2018-11-06 10:06:57] DEBUG[734][C-000007b3] channel.c: Prodding channel 'SIP/101-00000053' [2018-11-06 10:06:57] DEBUG[734][C-000007b3] res_rtp_asterisk.c: Setting the marker bit due to a source update [2018-11-06 10:06:57] DEBUG[734][C-000007b3] chan_sip.c: ** Our capability: (alaw|ulaw) Video flag: True Text flag: True [2018-11-06 10:06:57] DEBUG[734][C-000007b3] chan_sip.c: ** Our prefcodec: (nothing) [2018-11-06 10:06:57] DEBUG[734][C-000007b3] chan_sip.c: -- Done with adding codecs to SDP [2018-11-06 10:06:57] DEBUG[734][C-000007b3] chan_sip.c: Setting framing on incoming call: 0 [2018-11-06 10:06:57] DEBUG[734][C-000007b3] chan_sip.c: Done building SDP. Settling with this capability: (alaw|ulaw) [2018-11-06 10:06:57] DEBUG[734][C-000007b3] chan_sip.c: Trying to put 'SIP/2.0 183' onto UDP socket destined for 78.187.100.242:54256 [2018-11-06 10:06:57] DEBUG[734][C-000007b3] res_rtp_asterisk.c: Received frame with no data for RTP instance '0x7fc234217570' so dropping frame [2018-11-06 10:06:57] DEBUG[734][C-000007b3] app_queue.c: There is 1 available member. [2018-11-06 10:06:57] DEBUG[734][C-000007b3] app_queue.c: It's our turn (SIP/101-00000053). [2018-11-06 10:06:57] DEBUG[734][C-000007b3] app_queue.c: SIP/101-00000053 is trying to call a queue member. [2018-11-06 10:06:57] DEBUG[734][C-000007b3] app_queue.c: Trying 'SIP/100' with metric 0 [2018-11-06 10:06:57] DEBUG[734][C-000007b3] app_queue.c: Add SIP/100 to pending_members [2018-11-06 10:06:57] DEBUG[734][C-000007b3] chan_sip.c: Asked to create a SIP channel with formats: (alaw) [2018-11-06 10:06:57] DEBUG[734][C-000007b3] chan_sip.c: Allocating new SIP dialog for 0bef55a543aae8d5149e11ac276df95d@127.0.0.1:5060 - INVITE (No RTP) [2018-11-06 10:06:57] DEBUG[734][C-000007b3] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fc1f44da3a0' [2018-11-06 10:06:57] DEBUG[734][C-000007b3] res_rtp_asterisk.c: Allocated port 10930 for RTP instance '0x7fc1f44da3a0' [2018-11-06 10:06:57] DEBUG[734][C-000007b3] res_rtp_asterisk.c: Creating ICE session 0.0.0.0:10930 (10930) for RTP instance '0x7fc1f44da3a0' [2018-11-06 10:06:57] DEBUG[734][C-000007b3] netsock2.c: Splitting '85.111.24.13' into... [2018-11-06 10:06:57] DEBUG[734][C-000007b3] netsock2.c: ...host '85.111.24.13' and port ''. [2018-11-06 10:06:57] DEBUG[734][C-000007b3] netsock2.c: Splitting '85.111.24.13' into... [2018-11-06 10:06:57] DEBUG[734][C-000007b3] netsock2.c: ...host '85.111.24.13' and port ''. [2018-11-06 10:06:57] DEBUG[734][C-000007b3] rtp_engine.c: RTP instance '0x7fc1f44da3a0' is setup and ready to go [2018-11-06 10:06:57] DEBUG[734][C-000007b3] netsock2.c: Splitting 'Telsam-iex4' into... [2018-11-06 10:06:57] DEBUG[734][C-000007b3] netsock2.c: ...host 'Telsam-iex4' and port ''. [2018-11-06 10:06:57] DEBUG[734][C-000007b3] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fc1f44da3a0' [2018-11-06 10:06:57] VERBOSE[734][C-000007b3] netsock2.c: Using SIP RTP TOS bits 184 [2018-11-06 10:06:57] VERBOSE[734][C-000007b3] netsock2.c: Using SIP RTP CoS mark 5 [2018-11-06 10:06:57] DEBUG[734][C-000007b3] chan_sip.c: Setting NAT on RTP to On [2018-11-06 10:06:57] DEBUG[734][C-000007b3] acl.c: For destination '78.187.100.242', our source address is '85.111.24.13'. [2018-11-06 10:06:57] DEBUG[734][C-000007b3] chan_sip.c: Setting AST_TRANSPORT_UDP with address 85.111.24.13:5060 [2018-11-06 10:06:57] DEBUG[734][C-000007b3] chan_sip.c: Setting NAT on RTP to On [2018-11-06 10:06:57] DEBUG[734][C-000007b3] chan_sip.c: SIP call-id changed from '0bef55a543aae8d5149e11ac276df95d@127.0.0.1:5060' to '3dfa22ea421c5163212b601e74a19f39@85.111.24.13:5060' [2018-11-06 10:06:57] DEBUG[734][C-000007b3] channel.c: Channel 0x7fc1f45e6480 'SIP/100-00000054' allocated [2018-11-06 10:06:57] DEBUG[734][C-000007b3] chan_sip.c: *** Our native formats are (alaw) [2018-11-06 10:06:57] DEBUG[734][C-000007b3] chan_sip.c: *** Joint capabilities are (alaw) [2018-11-06 10:06:57] DEBUG[734][C-000007b3] chan_sip.c: *** Our capabilities are (alaw|ulaw|g729) [2018-11-06 10:06:57] DEBUG[734][C-000007b3] chan_sip.c: *** AST_CODEC_CHOOSE formats are alaw [2018-11-06 10:06:57] DEBUG[734][C-000007b3] chan_sip.c: *** Our preferred formats from the incoming channel are (alaw) [2018-11-06 10:06:57] DEBUG[734][C-000007b3] chan_sip.c: This channel will not be able to handle video. [2018-11-06 10:06:57] DEBUG[734][C-000007b3] channel_internal_api.c: Channel Call ID changing from [C-000007b3] to [C-000007b3] [2018-11-06 10:06:57] DEBUG[734][C-000007b3] chan_sip.c: Outgoing Call for 100 [2018-11-06 10:06:57] DEBUG[734][C-000007b3] chan_sip.c: Updating call counter for outgoing call [2018-11-06 10:06:57] DEBUG[27045] devicestate.c: No provider found, checking channel drivers for SIP - 100 [2018-11-06 10:06:57] DEBUG[27045] chan_sip.c: Checking device state for peer 100 [2018-11-06 10:06:57] DEBUG[27045] devicestate.c: Changing state for SIP/100 - state 6 (Ringing) [2018-11-06 10:06:57] DEBUG[27108] app_queue.c: Removed SIP/100 from pending_members [2018-11-06 10:06:57] DEBUG[734][C-000007b3] chan_sip.c: ** Our capability: (alaw|ulaw|g729) Video flag: False Text flag: False [2018-11-06 10:06:57] DEBUG[734][C-000007b3] chan_sip.c: ** Our prefcodec: (alaw) [2018-11-06 10:06:57] DEBUG[27108] app_queue.c: Removed SIP/100 from pending_members [2018-11-06 10:06:57] DEBUG[734][C-000007b3] chan_sip.c: -- Done with adding codecs to SDP [2018-11-06 10:06:57] DEBUG[27108] app_queue.c: Device 'SIP/100' changed to state '6' (Ringing) [2018-11-06 10:06:57] DEBUG[734][C-000007b3] chan_sip.c: Done building SDP. Settling with this capability: (alaw|ulaw|g729) [2018-11-06 10:06:57] DEBUG[734][C-000007b3] chan_sip.c: Initializing initreq for method INVITE - callid 3dfa22ea421c5163212b601e74a19f39@85.111.24.13:5060 [2018-11-06 10:06:57] DEBUG[27108] app_queue.c: Device 'Queue:630_avail' changed to state '2' (In use) but we don't care because they're not a member of any queue. [2018-11-06 10:06:57] DEBUG[27108] app_queue.c: Device 'Queue:632_avail' changed to state '2' (In use) but we don't care because they're not a member of any queue. [2018-11-06 10:06:57] DEBUG[734][C-000007b3] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 78.187.100.242:5080 [2018-11-06 10:06:57] VERBOSE[734][C-000007b3] app_queue.c: Called SIP/100 [2018-11-06 10:06:57] DEBUG[734][C-000007b3] channel.c: Channel SIP/101-00000053 setting write format path: slin -> alaw [2018-11-06 10:06:57] DEBUG[734][C-000007b3] res_musiconhold.c: SIP/101-00000053 Opened file 0 '/var/lib/asterisk/sounds/moh/moh10/cisco' [2018-11-06 10:06:57] DEBUG[734][C-000007b3] res_rtp_asterisk.c: Ooh, format changed from none to alaw [2018-11-06 10:06:57] DEBUG[734][C-000007b3] res_rtp_asterisk.c: Starting RTCP transmission on RTP instance '0x7fc234217570' [2018-11-06 10:06:57] DEBUG[27082] chan_sip.c: = Looking for Call ID: 3dfa22ea421c5163212b601e74a19f39@85.111.24.13:5060 (Checking To) --From tag as6384a1d9 --To-tag [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '3dfa22ea421c5163212b601e74a19f39@85.111.24.13:5060' Request 102: Found [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: SIP response 100 to standard invite [2018-11-06 10:06:57] DEBUG[734][C-000007b3] res_rtp_asterisk.c: Got RTCP report of 60 bytes from 78.187.100.242:4017 [2018-11-06 10:06:57] DEBUG[734][C-000007b3] res_rtp_asterisk.c: Got RTCP report of 60 bytes from 78.187.100.242:4017 [2018-11-06 10:06:57] DEBUG[27082] chan_sip.c: = Looking for Call ID: 3dfa22ea421c5163212b601e74a19f39@85.111.24.13:5060 (Checking To) --From tag as6384a1d9 --To-tag 1998064583 [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '3dfa22ea421c5163212b601e74a19f39@85.111.24.13:5060' Request 102: Found [2018-11-06 10:06:57] DEBUG[27082][C-000007b3] chan_sip.c: SIP response 180 to standard invite [2018-11-06 10:06:57] DEBUG[27045] devicestate.c: No provider found, checking channel drivers for SIP - 100 [2018-11-06 10:06:57] DEBUG[27045] chan_sip.c: Checking device state for peer 100 [2018-11-06 10:06:57] DEBUG[27045] devicestate.c: Changing state for SIP/100 - state 6 (Ringing) [2018-11-06 10:06:57] VERBOSE[734][C-000007b3] app_queue.c: SIP/100-00000054 is ringing [2018-11-06 10:06:57] DEBUG[27045] devicestate.c: No provider found, checking channel drivers for SIP - 100 [2018-11-06 10:06:57] DEBUG[27045] chan_sip.c: Checking device state for peer 100 [2018-11-06 10:06:57] DEBUG[27045] devicestate.c: Changing state for SIP/100 - state 6 (Ringing) [2018-11-06 10:06:57] DEBUG[27108] app_queue.c: Device 'SIP/100' changed to state '6' (Ringing) [2018-11-06 10:06:57] DEBUG[734][C-000007b3] res_rtp_asterisk.c: 0x7fc23423a520 -- Received RTP packet from 78.187.100.242:4016, dropping due to strict RTP protection. Qualifying new stream. [2018-11-06 10:06:57] DEBUG[734][C-000007b3] res_rtp_asterisk.c: 0x7fc23423a520 -- Received RTP packet from 78.187.100.242:4016, dropping due to strict RTP protection. Will switch to it in 3 packets. [2018-11-06 10:06:57] DEBUG[734][C-000007b3] res_rtp_asterisk.c: 0x7fc23423a520 -- Received RTP packet from 78.187.100.242:4016, dropping due to strict RTP protection. Will switch to it in 2 packets. [2018-11-06 10:06:57] DEBUG[734][C-000007b3] res_rtp_asterisk.c: 0x7fc23423a520 -- Received RTP packet from 78.187.100.242:4016, dropping due to strict RTP protection. Will switch to it in 1 packets. [2018-11-06 10:06:57] DEBUG[734][C-000007b3] acl.c: For destination '78.187.100.242', our source address is '85.111.24.13'. [2018-11-06 10:06:57] DEBUG[734][C-000007b3] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fc234217570' [2018-11-06 10:06:57] DEBUG[734][C-000007b3] res_rtp_asterisk.c: Got RTCP report of 80 bytes from 78.187.100.242:4017 [2018-11-06 10:06:59] DEBUG[27082] chan_sip.c: = Looking for Call ID: 3dfa22ea421c5163212b601e74a19f39@85.111.24.13:5060 (Checking To) --From tag as6384a1d9 --To-tag 1998064583 [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: Acked pending invite 102 [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: Stopping retransmission on '3dfa22ea421c5163212b601e74a19f39@85.111.24.13:5060' of Request 102: Match Found [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: SIP response 200 to standard invite [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: Processing session-level SDP o=- 20148 20148 IN IP4 192.168.1.3... OK. [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: Processing session-level SDP s=SDP data... UNSUPPORTED OR FAILED. [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] netsock2.c: Splitting '192.168.1.3' into... [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] netsock2.c: ...host '192.168.1.3' and port ''. [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: Processing session-level SDP c=IN IP4 192.168.1.3... OK. [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: Processing session-level SDP b=AS:2097... UNSUPPORTED OR FAILED. [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7fc1c927a6d0 [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7fc1c927a6d0 [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] rtp_engine.c: Setting tx payload type 18 based on m type on 0x7fc1c927a6d0 [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] rtp_engine.c: Setting tx payload type 101 based on m type on 0x7fc1c927a6d0 [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK. [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: Processing media-level (audio) SDP a=fmtp:18 annexb=no... OK. [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK. [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED OR FAILED. [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] res_rtp_asterisk.c: Set role to CONTROLLING (0x7fc1f44da3a0) [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] res_rtp_asterisk.c: Set role failed; no ice instance (0x7fc1f44da3a0) [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] acl.c: For destination '192.168.1.3', our source address is '85.111.24.13'. [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fc1f44da3a0' [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] rtp_engine.c: Copying payload 0 (0x7fc234051988) from 0x7fc1c927a6d0 to 0x7fc1f44da568 [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] rtp_engine.c: Copying payload 8 (0x7fc2341ea528) from 0x7fc1c927a6d0 to 0x7fc1f44da568 [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] rtp_engine.c: Copying payload 18 (0x7fc23417eb18) from 0x7fc1c927a6d0 to 0x7fc1f44da568 [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] rtp_engine.c: Copying payload 101 (0x7fc23422ad68) from 0x7fc1c927a6d0 to 0x7fc1f44da568 [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7fc1f44da3a0' [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: We're settling with these formats: (alaw|ulaw|g729) [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: We have an owner, now see if we need to change this call [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: Updating call counter for outgoing call [2018-11-06 10:06:59] DEBUG[27045] devicestate.c: No provider found, checking channel drivers for SIP - 100 [2018-11-06 10:06:59] DEBUG[27045] chan_sip.c: Checking device state for peer 100 [2018-11-06 10:06:59] DEBUG[27045] devicestate.c: Changing state for SIP/100 - state 2 (In use) [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: Trying to put 'ACK sip:100' onto UDP socket destined for 78.187.100.242:5080 [2018-11-06 10:06:59] DEBUG[27108] app_queue.c: Removed SIP/100 from pending_members [2018-11-06 10:06:59] DEBUG[27108] app_queue.c: Removed SIP/100 from pending_members [2018-11-06 10:06:59] DEBUG[27108] app_queue.c: Device 'SIP/100' changed to state '2' (In use) [2018-11-06 10:06:59] DEBUG[734][C-000007b3] channel.c: SIP/101-00000053: Dropping redundant connected line update "100" <100>. [2018-11-06 10:06:59] VERBOSE[734][C-000007b3] app_queue.c: SIP/100-00000054 answered SIP/101-00000053 [2018-11-06 10:06:59] VERBOSE[734][C-000007b3] res_musiconhold.c: Stopped music on hold on SIP/101-00000053 [2018-11-06 10:06:59] DEBUG[734][C-000007b3] channel.c: Channel SIP/101-00000053 setting write format path: alaw -> alaw [2018-11-06 10:06:59] DEBUG[734][C-000007b3] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2018-11-06 10:06:59] DEBUG[27034] threadpool.c: Increasing threadpool stasis-core's size by 1 [2018-11-06 10:06:59] DEBUG[734][C-000007b3] app_queue.c: Queue '630' Leave, Channel 'SIP/101-00000053' [2018-11-06 10:06:59] DEBUG[734][C-000007b3] app_queue.c: app_queue: agi=queue-set.php. [2018-11-06 10:06:59] DEBUG[27108] app_queue.c: Device 'Queue:630' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [2018-11-06 10:06:59] VERBOSE[734][C-000007b3] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/queue-set.php [2018-11-06 10:06:59] DEBUG[27045] devicestate.c: No provider found, checking channel drivers for SIP - 100 [2018-11-06 10:06:59] DEBUG[27045] chan_sip.c: Checking device state for peer 100 [2018-11-06 10:06:59] DEBUG[27045] devicestate.c: Changing state for SIP/100 - state 2 (In use) [2018-11-06 10:06:59] VERBOSE[734][C-000007b3] res_agi.c: AGI Script Executing Application: (Macro) Options: (stdexten-record-test,,) [2018-11-06 10:06:59] DEBUG[734][C-000007b3] pbx.c: Launching 'NoOp' [2018-11-06 10:06:59] VERBOSE[734][C-000007b3] pbx.c: Executing [s@macro-stdexten-record-test:1] NoOp("SIP/101-00000053", "Test") in new stack [2018-11-06 10:06:59] DEBUG[27048] cdr.c: Finalized CDR for SIP/101-00000053 - start 1541488017.398431 answer 0.000000 end 1541488019.336454 dispo ANSWERED [2018-11-06 10:06:59] DEBUG[734][C-000007b3] app_macro.c: Executed application: NoOp [2018-11-06 10:06:59] VERBOSE[734][C-000007b3] res_agi.c: AGI Script queue-set.php completed, returning 0 [2018-11-06 10:06:59] DEBUG[734][C-000007b3] chan_sip.c: SIP answering channel: SIP/101-00000053 [2018-11-06 10:06:59] DEBUG[27045] devicestate.c: No provider found, checking channel drivers for SIP - 101 [2018-11-06 10:06:59] DEBUG[734][C-000007b3] res_rtp_asterisk.c: Setting the marker bit due to a source update [2018-11-06 10:06:59] DEBUG[27045] chan_sip.c: Checking device state for peer 101 [2018-11-06 10:06:59] DEBUG[27045] devicestate.c: Changing state for SIP/101 - state 2 (In use) [2018-11-06 10:06:59] DEBUG[734][C-000007b3] chan_sip.c: ** Our capability: (alaw|ulaw) Video flag: True Text flag: True [2018-11-06 10:06:59] DEBUG[734][C-000007b3] chan_sip.c: ** Our prefcodec: (nothing) [2018-11-06 10:06:59] DEBUG[734][C-000007b3] chan_sip.c: -- Done with adding codecs to SDP [2018-11-06 10:06:59] DEBUG[734][C-000007b3] chan_sip.c: Setting framing on incoming call: 0 [2018-11-06 10:06:59] DEBUG[734][C-000007b3] chan_sip.c: Done building SDP. Settling with this capability: (alaw|ulaw) [2018-11-06 10:06:59] DEBUG[734][C-000007b3] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 78.187.100.242:54256 [2018-11-06 10:06:59] DEBUG[27082] chan_sip.c: Session timer started: 10 - 9a4ce1a31deb412896093d809b626491 900000ms [2018-11-06 10:06:59] DEBUG[734][C-000007b3] dahdi/bridge_native_dahdi.c: Bridge a5807729-516a-4dc1-af50-c2db71f6e611: Cannot use native DAHDI. Must have two channels. [2018-11-06 10:06:59] DEBUG[734][C-000007b3] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge. [2018-11-06 10:06:59] DEBUG[734][C-000007b3] bridge_native_rtp.c: Bridge 'a5807729-516a-4dc1-af50-c2db71f6e611' can not use native RTP bridge as two channels are required [2018-11-06 10:06:59] DEBUG[734][C-000007b3] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [2018-11-06 10:06:59] DEBUG[734][C-000007b3] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [2018-11-06 10:06:59] DEBUG[734][C-000007b3] bridge.c: Chose bridge technology simple_bridge [2018-11-06 10:06:59] DEBUG[734][C-000007b3] bridge.c: Bridge a5807729-516a-4dc1-af50-c2db71f6e611: calling simple_bridge technology constructor [2018-11-06 10:06:59] DEBUG[734][C-000007b3] bridge.c: Bridge a5807729-516a-4dc1-af50-c2db71f6e611: calling simple_bridge technology start [2018-11-06 10:06:59] DEBUG[741][C-000007b3] bridge_channel.c: Bridge a5807729-516a-4dc1-af50-c2db71f6e611: 0x7fc1f47ae100(SIP/100-00000054) is joining [2018-11-06 10:06:59] DEBUG[741][C-000007b3] bridge_channel.c: Bridge a5807729-516a-4dc1-af50-c2db71f6e611: pushing 0x7fc1f47ae100(SIP/100-00000054) [2018-11-06 10:06:59] DEBUG[27034] threadpool.c: Increasing threadpool stasis-core's size by 1 [2018-11-06 10:06:59] VERBOSE[741][C-000007b3] bridge_channel.c: Channel SIP/100-00000054 joined 'simple_bridge' basic-bridge [2018-11-06 10:06:59] DEBUG[741][C-000007b3] dahdi/bridge_native_dahdi.c: Bridge a5807729-516a-4dc1-af50-c2db71f6e611: Cannot use native DAHDI. Must have two channels. [2018-11-06 10:06:59] DEBUG[741][C-000007b3] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge. [2018-11-06 10:06:59] DEBUG[741][C-000007b3] bridge_native_rtp.c: Bridge 'a5807729-516a-4dc1-af50-c2db71f6e611' can not use native RTP bridge as two channels are required [2018-11-06 10:06:59] DEBUG[741][C-000007b3] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [2018-11-06 10:06:59] DEBUG[741][C-000007b3] bridge.c: Bridge technology softmix does not have any capabilities we want. [2018-11-06 10:06:59] DEBUG[741][C-000007b3] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [2018-11-06 10:06:59] DEBUG[741][C-000007b3] bridge.c: Chose bridge technology simple_bridge [2018-11-06 10:06:59] DEBUG[741][C-000007b3] bridge.c: Bridge a5807729-516a-4dc1-af50-c2db71f6e611 is already using the new technology. [2018-11-06 10:06:59] DEBUG[741][C-000007b3] bridge.c: Bridge a5807729-516a-4dc1-af50-c2db71f6e611: 0x7fc1f47ae100(SIP/100-00000054) is joining simple_bridge technology [2018-11-06 10:06:59] DEBUG[741][C-000007b3] res_rtp_asterisk.c: Not changing SSRC since we haven't sent any RTP yet [2018-11-06 10:06:59] DEBUG[734][C-000007b3] bridge_channel.c: Bridge a5807729-516a-4dc1-af50-c2db71f6e611: 0x7fc1f41e2970(SIP/101-00000053) is joining [2018-11-06 10:06:59] DEBUG[734][C-000007b3] bridge_channel.c: Bridge a5807729-516a-4dc1-af50-c2db71f6e611: pushing 0x7fc1f41e2970(SIP/101-00000053) [2018-11-06 10:06:59] VERBOSE[734][C-000007b3] bridge_channel.c: Channel SIP/101-00000053 joined 'simple_bridge' basic-bridge [2018-11-06 10:06:59] DEBUG[27048] cdr.c: Finalized CDR for SIP/100-00000054 - start 1541488017.399675 answer 1541488019.320696 end 1541488019.338703 dispo ANSWERED [2018-11-06 10:06:59] DEBUG[734][C-000007b3] dahdi/bridge_native_dahdi.c: Channel 'SIP/100-00000054' has DTMF hooks. [2018-11-06 10:06:59] DEBUG[734][C-000007b3] dahdi/bridge_native_dahdi.c: Bridge a5807729-516a-4dc1-af50-c2db71f6e611: Cannot use native DAHDI. Channel 'SIP/100-00000054' not compatible. [2018-11-06 10:06:59] DEBUG[734][C-000007b3] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge. [2018-11-06 10:06:59] DEBUG[734][C-000007b3] bridge_native_rtp.c: Bridge 'a5807729-516a-4dc1-af50-c2db71f6e611'. Checking compatability for channels 'SIP/100-00000054' and 'SIP/101-00000053' [2018-11-06 10:06:59] DEBUG[734][C-000007b3] bridge_native_rtp.c: Bridge 'a5807729-516a-4dc1-af50-c2db71f6e611' can not use native RTP bridge as channel 'SIP/100-00000054' has DTMF hooks [2018-11-06 10:06:59] DEBUG[734][C-000007b3] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [2018-11-06 10:06:59] DEBUG[734][C-000007b3] bridge.c: Bridge technology softmix does not have any capabilities we want. [2018-11-06 10:06:59] DEBUG[734][C-000007b3] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [2018-11-06 10:06:59] DEBUG[734][C-000007b3] bridge.c: Chose bridge technology simple_bridge [2018-11-06 10:06:59] DEBUG[734][C-000007b3] bridge.c: Bridge a5807729-516a-4dc1-af50-c2db71f6e611 is already using the new technology. [2018-11-06 10:06:59] DEBUG[734][C-000007b3] bridge.c: Bridge a5807729-516a-4dc1-af50-c2db71f6e611: 0x7fc1f41e2970(SIP/101-00000053) is joining simple_bridge technology [2018-11-06 10:06:59] DEBUG[733] app_queue.c: Detected entry of caller channel SIP/101-00000053 into bridge a5807729-516a-4dc1-af50-c2db71f6e611 [2018-11-06 10:06:59] DEBUG[27034] threadpool.c: Increasing threadpool stasis-core's size by 1 [2018-11-06 10:06:59] DEBUG[27034] threadpool.c: Increasing threadpool stasis-core's size by 1 [2018-11-06 10:06:59] DEBUG[734][C-000007b3] res_rtp_asterisk.c: Changing ssrc from 2034811891 to 1331571945 due to a source change [2018-11-06 10:06:59] DEBUG[741][C-000007b3] res_rtp_asterisk.c: Ooh, format changed from none to alaw [2018-11-06 10:06:59] DEBUG[741][C-000007b3] res_rtp_asterisk.c: Starting RTCP transmission on RTP instance '0x7fc1f44da3a0' [2018-11-06 10:06:59] DEBUG[27082] chan_sip.c: = Looking for Call ID: 9a4ce1a31deb412896093d809b626491 (Checking From) --From tag 9cf7c824cb8148f0abdf2a413f8b4cac --To-tag as485033c8 [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: Stopping retransmission on '9a4ce1a31deb412896093d809b626491' of Response 10422: Match Found [2018-11-06 10:06:59] DEBUG[27082] chan_sip.c: = Looking for Call ID: 9a4ce1a31deb412896093d809b626491 (Checking From) --From tag 9cf7c824cb8148f0abdf2a413f8b4cac --To-tag as485033c8 [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] netsock2.c: Splitting '192.168.1.14:54256' into... [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] netsock2.c: ...host '192.168.1.14' and port '54256'. [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: NAT detected for 192.168.1.14 / 78.187.100.242 [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: Processing session-level SDP o=- 3750487615 3750487616 IN IP4 192.168.1.14... OK. [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: Processing session-level SDP s=pjmedia... UNSUPPORTED OR FAILED. [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: Processing session-level SDP b=AS:84... UNSUPPORTED OR FAILED. [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: Processing session-level SDP a=X-nat:0... UNSUPPORTED OR FAILED. [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7fc1c927b470 [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] rtp_engine.c: Setting tx payload type 101 based on m type on 0x7fc1c927b470 [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] netsock2.c: Splitting '192.168.1.14' into... [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] netsock2.c: ...host '192.168.1.14' and port ''. [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: Processing media-level (audio) SDP c=IN IP4 192.168.1.14... OK. [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: Processing media-level (audio) SDP b=TIAS:64000... UNSUPPORTED OR FAILED. [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: Processing media-level (audio) SDP a=rtcp:4017 IN IP4 192.168.1.14... UNSUPPORTED OR FAILED. [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: Processing media-level (audio) SDP a=ssrc:1021131860 cname:5bc525dd780c01c5... UNSUPPORTED OR FAILED. [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED OR FAILED. [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] acl.c: For destination '192.168.1.14', our source address is '85.111.24.13'. [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fc234217570' [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] rtp_engine.c: Copying payload 8 (0x7fc2341ff218) from 0x7fc1c927b470 to 0x7fc234217738 [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] rtp_engine.c: Copying payload 101 (0x7fc234070178) from 0x7fc1c927b470 to 0x7fc234217738 [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7fc234217570' [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: We're settling with these formats: (alaw) [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: We have an owner, now see if we need to change this call [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: Incoming INVITE with 'timer' option supported [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: INVITE also has "Session-Expires" header. [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: Session-Expires: 1800 [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: Refresher: UAS [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: INVITE also has "Min-SE" header. [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: Received Min-SE: 90 [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: Restarting session-timers on a refresh - 9a4ce1a31deb412896093d809b626491 [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: SIP/101-00000053: This call is UP.... [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 78.187.100.242:54256 [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: ** Our capability: (alaw) Video flag: True Text flag: True [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: ** Our prefcodec: (nothing) [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: -- Done with adding codecs to SDP [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: Setting framing on incoming call: 0 [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: Done building SDP. Settling with this capability: (alaw) [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 78.187.100.242:54256 [2018-11-06 10:06:59] DEBUG[27082] chan_sip.c: Session timer stopped: 10 - 9a4ce1a31deb412896093d809b626491 [2018-11-06 10:06:59] DEBUG[27082] chan_sip.c: Session timer started: 15 - 9a4ce1a31deb412896093d809b626491 900000ms [2018-11-06 10:06:59] DEBUG[741][C-000007b3] res_rtp_asterisk.c: Setting the marker bit due to a source update [2018-11-06 10:06:59] DEBUG[734][C-000007b3] acl.c: For destination '78.187.100.242', our source address is '85.111.24.13'. [2018-11-06 10:06:59] DEBUG[734][C-000007b3] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fc234217570' [2018-11-06 10:06:59] DEBUG[741][C-000007b3] res_rtp_asterisk.c: 0x7fc1f4454020 -- Received RTP packet from 78.187.100.242:50002, dropping due to strict RTP protection. Qualifying new stream. [2018-11-06 10:06:59] DEBUG[27082] chan_sip.c: = Looking for Call ID: 9a4ce1a31deb412896093d809b626491 (Checking From) --From tag 9cf7c824cb8148f0abdf2a413f8b4cac --To-tag as485033c8 [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [2018-11-06 10:06:59] DEBUG[27082][C-000007b3] chan_sip.c: Stopping retransmission on '9a4ce1a31deb412896093d809b626491' of Response 10423: Match Found [2018-11-06 10:06:59] DEBUG[741][C-000007b3] res_rtp_asterisk.c: 0x7fc1f4454020 -- Received RTP packet from 78.187.100.242:50002, dropping due to strict RTP protection. Will switch to it in 3 packets. [2018-11-06 10:06:59] DEBUG[741][C-000007b3] res_rtp_asterisk.c: 0x7fc1f4454020 -- Received RTP packet from 78.187.100.242:50002, dropping due to strict RTP protection. Will switch to it in 2 packets. [2018-11-06 10:06:59] DEBUG[741][C-000007b3] res_rtp_asterisk.c: 0x7fc1f4454020 -- Received RTP packet from 78.187.100.242:50002, dropping due to strict RTP protection. Will switch to it in 1 packets. [2018-11-06 10:06:59] DEBUG[741][C-000007b3] acl.c: For destination '78.187.100.242', our source address is '85.111.24.13'. [2018-11-06 10:06:59] DEBUG[741][C-000007b3] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fc1f44da3a0' [2018-11-06 10:07:01] DEBUG[27082] chan_sip.c: = Looking for Call ID: 3dfa22ea421c5163212b601e74a19f39@85.111.24.13:5060 (Checking From) --From tag 1998064583 --To-tag as6384a1d9 [2018-11-06 10:07:01] DEBUG[27082][C-000007b3] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [2018-11-06 10:07:01] DEBUG[27082][C-000007b3] netsock2.c: Splitting '192.168.1.3:5080' into... [2018-11-06 10:07:01] DEBUG[27082][C-000007b3] netsock2.c: ...host '192.168.1.3' and port '5080'. [2018-11-06 10:07:01] DEBUG[27082][C-000007b3] chan_sip.c: NAT detected for 192.168.1.3 / 78.187.100.242 [2018-11-06 10:07:01] DEBUG[27082][C-000007b3] chan_sip.c: Setting SIP_ALREADYGONE on dialog 3dfa22ea421c5163212b601e74a19f39@85.111.24.13:5060 [2018-11-06 10:07:01] DEBUG[27082][C-000007b3] chan_sip.c: Received bye, issuing owner hangup [2018-11-06 10:07:01] DEBUG[27082][C-000007b3] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 78.187.100.242:5080 [2018-11-06 10:07:01] DEBUG[741][C-000007b3] bridge_channel.c: Setting 0x7fc1f47ae100(SIP/100-00000054) state from:0 to:1 [2018-11-06 10:07:01] DEBUG[741][C-000007b3] bridge_channel.c: Bridge a5807729-516a-4dc1-af50-c2db71f6e611: pulling 0x7fc1f47ae100(SIP/100-00000054) [2018-11-06 10:07:01] VERBOSE[741][C-000007b3] bridge_channel.c: Channel SIP/100-00000054 left 'simple_bridge' basic-bridge [2018-11-06 10:07:01] DEBUG[741][C-000007b3] bridge_channel.c: Bridge a5807729-516a-4dc1-af50-c2db71f6e611: 0x7fc1f47ae100(SIP/100-00000054) is leaving simple_bridge technology [2018-11-06 10:07:01] DEBUG[741][C-000007b3] bridge.c: Bridge a5807729-516a-4dc1-af50-c2db71f6e611: dissolving bridge with cause 16(Normal Clearing) [2018-11-06 10:07:01] DEBUG[741][C-000007b3] bridge_channel.c: Setting 0x7fc1f41e2970(SIP/101-00000053) state from:0 to:2 [2018-11-06 10:07:01] DEBUG[741][C-000007b3] bridge.c: Bridge a5807729-516a-4dc1-af50-c2db71f6e611: queueing action type:13 sub:1001 [2018-11-06 10:07:01] DEBUG[741][C-000007b3] bridge.c: Bridge a5807729-516a-4dc1-af50-c2db71f6e611 is dissolved, not performing smart bridge operation. [2018-11-06 10:07:01] DEBUG[27048] cdr.c: Finalized CDR for SIP/101-00000053 - start 1541488019.336474 answer 1541488019.338049 end 1541488021.461958 dispo ANSWERED [2018-11-06 10:07:01] DEBUG[741][C-000007b3] channel.c: Channel 0x7fc1f45e6480 'SIP/100-00000054' hanging up. Refs: 3 [2018-11-06 10:07:01] DEBUG[733] app_queue.c: Detected hangup of queue member channel SIP/100-00000054 [2018-11-06 10:07:01] DEBUG[733] app_queue.c: Removed SIP/100 from pending_members [2018-11-06 10:07:01] DEBUG[741][C-000007b3] chan_sip.c: Hangup call SIP/100-00000054, SIP callid 3dfa22ea421c5163212b601e74a19f39@85.111.24.13:5060 [2018-11-06 10:07:01] DEBUG[741][C-000007b3] chan_sip.c: Updating call counter for outgoing call [2018-11-06 10:07:01] DEBUG[741][C-000007b3] channel.c: Channel 0x7fc1f45e6480 'SIP/100-00000054' destroying [2018-11-06 10:07:01] DEBUG[27045] devicestate.c: No provider found, checking channel drivers for SIP - 100 [2018-11-06 10:07:01] DEBUG[27045] chan_sip.c: Checking device state for peer 100 [2018-11-06 10:07:01] DEBUG[27045] devicestate.c: Changing state for SIP/100 - state 1 (Not in use) [2018-11-06 10:07:01] DEBUG[27048] cdr.c: CDR for SIP/100-00000054 is dialed and has no Party B; discarding [2018-11-06 10:07:01] DEBUG[27108] app_queue.c: Removed SIP/100 from pending_members [2018-11-06 10:07:01] DEBUG[27045] devicestate.c: No provider found, checking channel drivers for SIP - 100 [2018-11-06 10:07:01] DEBUG[27045] chan_sip.c: Checking device state for peer 100 [2018-11-06 10:07:01] DEBUG[27045] devicestate.c: Changing state for SIP/100 - state 1 (Not in use) [2018-11-06 10:07:01] DEBUG[27108] app_queue.c: Removed SIP/100 from pending_members [2018-11-06 10:07:01] DEBUG[27108] app_queue.c: Device 'SIP/100' changed to state '1' (Not in use) [2018-11-06 10:07:01] DEBUG[27108] app_queue.c: Device 'Queue:630_avail' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [2018-11-06 10:07:01] DEBUG[27108] app_queue.c: Device 'Queue:632_avail' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [2018-11-06 10:07:01] DEBUG[734][C-000007b3] bridge_channel.c: Bridge a5807729-516a-4dc1-af50-c2db71f6e611: pulling 0x7fc1f41e2970(SIP/101-00000053) [2018-11-06 10:07:01] VERBOSE[734][C-000007b3] bridge_channel.c: Channel SIP/101-00000053 left 'simple_bridge' basic-bridge [2018-11-06 10:07:01] DEBUG[734][C-000007b3] bridge_channel.c: Bridge a5807729-516a-4dc1-af50-c2db71f6e611: 0x7fc1f41e2970(SIP/101-00000053) is leaving simple_bridge technology [2018-11-06 10:07:01] DEBUG[734][C-000007b3] bridge.c: Bridge a5807729-516a-4dc1-af50-c2db71f6e611 is dissolved, not performing smart bridge operation. [2018-11-06 10:07:01] DEBUG[734][C-000007b3] res_rtp_asterisk.c: Changing ssrc from 1331571945 to 650861919 due to a source change [2018-11-06 10:07:01] DEBUG[734][C-000007b3] pbx.c: Spawn extension (DLPN_DialPlan1,630,1) exited non-zero on 'SIP/101-00000053' [2018-11-06 10:07:01] VERBOSE[734][C-000007b3] pbx.c: Spawn extension (DLPN_DialPlan1, 630, 1) exited non-zero on 'SIP/101-00000053' [2018-11-06 10:07:01] DEBUG[734][C-000007b3] channel.c: Soft-Hanging (0x10) up channel 'SIP/101-00000053' [2018-11-06 10:07:01] DEBUG[734][C-000007b3] channel.c: Channel 0x7fc234267480 'SIP/101-00000053' hanging up. Refs: 2 [2018-11-06 10:07:01] DEBUG[734][C-000007b3] chan_sip.c: Hangup call SIP/101-00000053, SIP callid 9a4ce1a31deb412896093d809b626491 [2018-11-06 10:07:01] DEBUG[734][C-000007b3] chan_sip.c: Updating call counter for incoming call [2018-11-06 10:07:01] DEBUG[27044][C-000007b3] bridge.c: Bridge a5807729-516a-4dc1-af50-c2db71f6e611: actually destroying basic bridge, nobody wants it anymore [2018-11-06 10:07:01] DEBUG[27044][C-000007b3] bridge.c: Bridge a5807729-516a-4dc1-af50-c2db71f6e611: calling basic bridge destructor [2018-11-06 10:07:01] DEBUG[27044][C-000007b3] bridge.c: Bridge a5807729-516a-4dc1-af50-c2db71f6e611: calling simple_bridge technology stop [2018-11-06 10:07:01] DEBUG[27044][C-000007b3] bridge.c: Bridge a5807729-516a-4dc1-af50-c2db71f6e611: calling simple_bridge technology destructor [2018-11-06 10:07:01] DEBUG[27045] devicestate.c: No provider found, checking channel drivers for SIP - 101 [2018-11-06 10:07:01] DEBUG[27045] chan_sip.c: Checking device state for peer 101 [2018-11-06 10:07:01] DEBUG[27045] devicestate.c: Changing state for SIP/101 - state 1 (Not in use) [2018-11-06 10:07:01] DEBUG[27108] app_queue.c: Removed SIP/101 from pending_members [2018-11-06 10:07:01] DEBUG[27108] app_queue.c: Removed SIP/101 from pending_members [2018-11-06 10:07:01] DEBUG[27108] app_queue.c: Device 'SIP/101' changed to state '1' (Not in use) [2018-11-06 10:07:01] DEBUG[27108] app_queue.c: Device 'Queue:631_avail' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [2018-11-06 10:07:01] DEBUG[734][C-000007b3] chan_sip.c: Trying to put 'BYE sip:101' onto UDP socket destined for 78.187.100.242:54256 [2018-11-06 10:07:01] DEBUG[734][C-000007b3] channel.c: Channel 0x7fc234267480 'SIP/101-00000053' destroying [2018-11-06 10:07:01] DEBUG[27082] chan_sip.c: Session timer stopped: 15 - 9a4ce1a31deb412896093d809b626491 [2018-11-06 10:07:01] DEBUG[27045] devicestate.c: No provider found, checking channel drivers for SIP - 101 [2018-11-06 10:07:01] DEBUG[27045] chan_sip.c: Checking device state for peer 101 [2018-11-06 10:07:01] DEBUG[27045] devicestate.c: Changing state for SIP/101 - state 1 (Not in use) [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(calltype) result is '' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(recordfile) result is '' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Evaluating 'IF($[${ISNULL(${CDR(acid)})}]?${CDR(clid)}:${CDR(acid)})' (from 'IF($[${ISNULL(${CDR(acid)})}]?${CDR(clid)}:${CDR(acid)})}","${CDR(dst)}${CDR(calleeid)}","${CDR(start)}","${CDR(accountcode)}","${CDR(billsec)}","${CDR(disposition)}" ' len 56) [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Evaluating 'ISNULL(${CDR(acid)})' (from 'ISNULL(${CDR(acid)})}' len 20) [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Evaluating 'CDR(acid)' (from 'CDR(acid)})' len 9) [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(acid) result is '' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function ISNULL() result is '1' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Expression result is '1' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Evaluating 'CDR(clid)' (from 'CDR(clid)}:${CDR(acid)})' len 9) [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(clid) result is '"101" <101>' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Evaluating 'CDR(acid)' (from 'CDR(acid)})' len 9) [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(acid) result is '' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function IF(1?"101" <101>:) result is '101 <101>' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Evaluating 'CDR(dst)' (from 'CDR(dst)}${CDR(calleeid)}","${CDR(start)}","${CDR(accountcode)}","${CDR(billsec)}","${CDR(disposition)}" ' len 8) [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(dst) result is '100' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Evaluating 'CDR(calleeid)' (from 'CDR(calleeid)}","${CDR(start)}","${CDR(accountcode)}","${CDR(billsec)}","${CDR(disposition)}" ' len 13) [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(calleeid) result is '' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Evaluating 'CDR(start)' (from 'CDR(start)}","${CDR(accountcode)}","${CDR(billsec)}","${CDR(disposition)}" ' len 10) [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(start) result is '2018-11-06 10:06:57' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Evaluating 'CDR(accountcode)' (from 'CDR(accountcode)}","${CDR(billsec)}","${CDR(disposition)}" ' len 16) [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(accountcode) result is '' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Evaluating 'CDR(billsec)' (from 'CDR(billsec)}","${CDR(disposition)}" ' len 12) [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(billsec) result is '0' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Evaluating 'CDR(disposition)' (from 'CDR(disposition)}" ' len 16) [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(disposition) result is 'ANSWERED' [2018-11-06 10:07:01] DEBUG[27048] res_odbc.c: Reusing ODBC handle 0x7fc1f45e3860 from class 'PT1C_asteriskcdrdb' [2018-11-06 10:07:01] DEBUG[27048] cdr_adaptive_odbc.c: Executing [INSERT INTO cdr (calldate,clid,src,dst,dcontext,lastapp,lastdata,duration,billsec,disposition,channel,dstchannel,uniqueid,end) VALUES ({ ts '2018-11-06 10:06:57' },'"101" <101>','101','100','DLPN_DialPlan1','Queue','630,tkXx,,,,queue-set.php,',1.938023,0.000000,'ANSWERED','SIP/101-00000053','SIP/100-00000054','1541488017.269',{ ts '2018-11-06 10:06:59' })] [2018-11-06 10:07:01] DEBUG[27048] res_odbc.c: Releasing ODBC handle 0x7fc1f45e3860 into pool [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(cid) result is '' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function ISNULL() result is '1' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Expression result is '1' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(src) result is '101' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(cid) result is '' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function IF(1?101:) result is '101' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(dst) result is '100' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(start) result is '2018-11-06 10:06:57' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(end) result is '2018-11-06 10:06:59' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(duration) result is '1' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(billsec) result is '0' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(disposition) result is 'ANSWERED' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(channel) result is 'SIP/101-00000053' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(dstchannel) result is 'SIP/100-00000054' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(calltype) result is '' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(uniqueid) result is '1541488017.269' [2018-11-06 10:07:01] DEBUG[27048] cdr_sqlite3_custom.c: About to log: INSERT INTO cdr (src,dst,start,end,duration,billsec,disposition,channel,dstchannel,calltype,uniqueid) VALUES ('101','100','2018-11-06 10:06:57','2018-11-06 10:06:59','1','0','ANSWERED','SIP/101-00000053','SIP/100-00000054','','1541488017.269') [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(calltype) result is '' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(recordfile) result is '' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Evaluating 'IF($[${ISNULL(${CDR(acid)})}]?${CDR(clid)}:${CDR(acid)})' (from 'IF($[${ISNULL(${CDR(acid)})}]?${CDR(clid)}:${CDR(acid)})}","${CDR(dst)}${CDR(calleeid)}","${CDR(start)}","${CDR(accountcode)}","${CDR(billsec)}","${CDR(disposition)}" ' len 56) [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Evaluating 'ISNULL(${CDR(acid)})' (from 'ISNULL(${CDR(acid)})}' len 20) [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Evaluating 'CDR(acid)' (from 'CDR(acid)})' len 9) [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(acid) result is '' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function ISNULL() result is '1' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Expression result is '1' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Evaluating 'CDR(clid)' (from 'CDR(clid)}:${CDR(acid)})' len 9) [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(clid) result is '"101" <101>' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Evaluating 'CDR(acid)' (from 'CDR(acid)})' len 9) [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(acid) result is '' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function IF(1?"101" <101>:) result is '101 <101>' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Evaluating 'CDR(dst)' (from 'CDR(dst)}${CDR(calleeid)}","${CDR(start)}","${CDR(accountcode)}","${CDR(billsec)}","${CDR(disposition)}" ' len 8) [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(dst) result is '100' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Evaluating 'CDR(calleeid)' (from 'CDR(calleeid)}","${CDR(start)}","${CDR(accountcode)}","${CDR(billsec)}","${CDR(disposition)}" ' len 13) [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(calleeid) result is '' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Evaluating 'CDR(start)' (from 'CDR(start)}","${CDR(accountcode)}","${CDR(billsec)}","${CDR(disposition)}" ' len 10) [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(start) result is '2018-11-06 10:06:59' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Evaluating 'CDR(accountcode)' (from 'CDR(accountcode)}","${CDR(billsec)}","${CDR(disposition)}" ' len 16) [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(accountcode) result is '' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Evaluating 'CDR(billsec)' (from 'CDR(billsec)}","${CDR(disposition)}" ' len 12) [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(billsec) result is '2' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Evaluating 'CDR(disposition)' (from 'CDR(disposition)}" ' len 16) [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(disposition) result is 'ANSWERED' [2018-11-06 10:07:01] DEBUG[27048] res_odbc.c: Reusing ODBC handle 0x7fc1f45e3860 from class 'PT1C_asteriskcdrdb' [2018-11-06 10:07:01] DEBUG[27048] cdr_adaptive_odbc.c: Executing [INSERT INTO cdr (calldate,clid,src,dst,dcontext,lastapp,lastdata,duration,billsec,disposition,channel,dstchannel,uniqueid,answer,end) VALUES ({ ts '2018-11-06 10:06:59' },'"101" <101>','101','100','DLPN_DialPlan1','Queue','630,tkXx,,,,queue-set.php,',2.125484,2.123909,'ANSWERED','SIP/101-00000053','SIP/100-00000054','1541488017.269',{ ts '2018-11-06 10:06:59' },{ ts '2018-11-06 10:07:01' })] [2018-11-06 10:07:01] DEBUG[27048] res_odbc.c: Releasing ODBC handle 0x7fc1f45e3860 into pool [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(cid) result is '' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function ISNULL() result is '1' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Expression result is '1' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(src) result is '101' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(cid) result is '' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function IF(1?101:) result is '101' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(dst) result is '100' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(start) result is '2018-11-06 10:06:59' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(end) result is '2018-11-06 10:07:01' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(duration) result is '2' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(billsec) result is '2' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(disposition) result is 'ANSWERED' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(channel) result is 'SIP/101-00000053' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(dstchannel) result is 'SIP/100-00000054' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(calltype) result is '' [2018-11-06 10:07:01] DEBUG[27048] pbx_variables.c: Function CDR(uniqueid) result is '1541488017.269' [2018-11-06 10:07:01] DEBUG[27048] cdr_sqlite3_custom.c: About to log: INSERT INTO cdr (src,dst,start,end,duration,billsec,disposition,channel,dstchannel,calltype,uniqueid) VALUES ('101','100','2018-11-06 10:06:59','2018-11-06 10:07:01','2','2','ANSWERED','SIP/101-00000053','SIP/100-00000054','','1541488017.269') [2018-11-06 10:07:01] DEBUG[27082] chan_sip.c: = Looking for Call ID: 9a4ce1a31deb412896093d809b626491 (Checking To) --From tag as485033c8 --To-tag 9cf7c824cb8148f0abdf2a413f8b4cac [2018-11-06 10:07:01] DEBUG[27082][C-000007b3] chan_sip.c: Stopping retransmission on '9a4ce1a31deb412896093d809b626491' of Request 102: Match Found [2018-11-06 10:07:01] DEBUG[27082] chan_sip.c: Destroying SIP dialog 9a4ce1a31deb412896093d809b626491 [2018-11-06 10:07:01] DEBUG[27082] rtp_engine.c: Destroyed RTP instance '0x7fc234217570'