[2018-11-09 09:09:55] 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-09 09:09:55] DEBUG[12952] config.c: Parsing /etc/asterisk/logger.conf
[2018-11-09 09:09:55] VERBOSE[12952] logger.c: Asterisk Queue Logger restarted
[2018-11-09 09:09:56] DEBUG[27082] chan_sip.c: Auto destroying SIP dialog 'b8cb2b0d3775734d1c32a3932766abc3@85.111.24.111'
[2018-11-09 09:09:56] DEBUG[27082] chan_sip.c: Destroying SIP dialog b8cb2b0d3775734d1c32a3932766abc3@85.111.24.111
[2018-11-09 09:09:58] DEBUG[27082] chan_sip.c: = Looking for  Call ID: da9ea689f4e745e581d83e5782c1982b (Checking From) --From tag d70e2a9c31154661badcf3a9c94cef36 --To-tag   
[2018-11-09 09:09:58] DEBUG[27082] acl.c: For destination '78.187.100.242', our source address is '85.111.24.13'.
[2018-11-09 09:09:58] DEBUG[27082] chan_sip.c: Setting AST_TRANSPORT_UDP with address 85.111.24.13:5060
[2018-11-09 09:09:58] DEBUG[27082] netsock2.c: Splitting '192.168.1.14:64211' into...
[2018-11-09 09:09:58] DEBUG[27082] netsock2.c: ...host '192.168.1.14' and port '64211'.
[2018-11-09 09:09:58] DEBUG[27082] chan_sip.c: NAT detected for 192.168.1.14 / 78.187.100.242
[2018-11-09 09:09:58] DEBUG[27082] chan_sip.c: Allocating new SIP dialog for da9ea689f4e745e581d83e5782c1982b - INVITE (No RTP)
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] sip/reqresp_parser.c: Begin: parsing SIP "Supported: replaces, 100rel, timer, norefersub"
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] sip/reqresp_parser.c: Found SIP option: -replaces-
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] sip/reqresp_parser.c: Matched SIP option: replaces
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] sip/reqresp_parser.c: Found SIP option: -100rel-
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] sip/reqresp_parser.c: Matched SIP option: 100rel
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] sip/reqresp_parser.c: Found SIP option: -timer-
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] sip/reqresp_parser.c: Matched SIP option: timer
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] sip/reqresp_parser.c: Found SIP option: -norefersub-
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] sip/reqresp_parser.c: Matched SIP option: norefersub
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] netsock2.c: Splitting '192.168.1.14:64211' into...
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] netsock2.c: ...host '192.168.1.14' and port '64211'.
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: NAT detected for 192.168.1.14 / 78.187.100.242
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] netsock2.c: Splitting '101' into...
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] netsock2.c: ...host '101' and port ''.
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 78.187.100.242:64211
[2018-11-09 09:09:58] DEBUG[27082] chan_sip.c: = Looking for  Call ID: da9ea689f4e745e581d83e5782c1982b (Checking From) --From tag d70e2a9c31154661badcf3a9c94cef36 --To-tag as461b0bf9  
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: Stopping retransmission on 'da9ea689f4e745e581d83e5782c1982b' of Response 29001: Match Found
[2018-11-09 09:09:58] DEBUG[27082] chan_sip.c: = Looking for  Call ID: da9ea689f4e745e581d83e5782c1982b (Checking From) --From tag d70e2a9c31154661badcf3a9c94cef36 --To-tag   
[2018-11-09 09:09:58] DEBUG[27082] netsock2.c: Splitting '101' into...
[2018-11-09 09:09:58] DEBUG[27082] netsock2.c: ...host '101' and port ''.
[2018-11-09 09:09:58] DEBUG[27082] netsock2.c: Splitting '101' into...
[2018-11-09 09:09:58] DEBUG[27082] netsock2.c: ...host '101' and port ''.
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] netsock2.c: Splitting '192.168.1.14:64211' into...
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] netsock2.c: ...host '192.168.1.14' and port '64211'.
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: NAT detected for 192.168.1.14 / 78.187.100.242
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] netsock2.c: Splitting '101' into...
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] netsock2.c: ...host '101' and port ''.
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fc234362b90'
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] res_rtp_asterisk.c: Allocated port 11632 for RTP instance '0x7fc234362b90'
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] res_rtp_asterisk.c: Creating ICE session 0.0.0.0:11632 (11632) for RTP instance '0x7fc234362b90'
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] netsock2.c: Splitting '85.111.24.13' into...
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] netsock2.c: ...host '85.111.24.13' and port ''.
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] netsock2.c: Splitting '85.111.24.13' into...
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] netsock2.c: ...host '85.111.24.13' and port ''.
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] rtp_engine.c: RTP instance '0x7fc234362b90' is setup and ready to go
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] netsock2.c: Splitting 'Telsam-iex4' into...
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] netsock2.c: ...host 'Telsam-iex4' and port ''.
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fc234362b90'
[2018-11-09 09:09:58] VERBOSE[27082][C-000007ba] netsock2.c: Using SIP RTP TOS bits 184
[2018-11-09 09:09:58] VERBOSE[27082][C-000007ba] netsock2.c: Using SIP RTP CoS mark 5
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: Setting NAT on RTP to On
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED.
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: Processing session-level SDP o=- 3750743397 3750743397 IN IP4 192.168.1.14... OK.
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: Processing session-level SDP s=pjmedia... UNSUPPORTED OR FAILED.
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: Processing session-level SDP b=AS:84... UNSUPPORTED OR FAILED.
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED.
[2018-11-09 09:09:58] VERBOSE[27082][C-000007ba] netsock2.c: Using UDPTL TOS bits 184
[2018-11-09 09:09:58] VERBOSE[27082][C-000007ba] netsock2.c: Using UDPTL CoS mark 5
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: Setting NAT on UDPTL to On
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: Processing session-level SDP a=X-nat:0... UNSUPPORTED OR FAILED.
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] rtp_engine.c: Don't have a default tx payload type 123 format for m type on 0x7fc1c927b470
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7fc1c927b470
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7fc1c927b470
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] rtp_engine.c: Setting tx payload type 101 based on m type on 0x7fc1c927b470
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] netsock2.c: Splitting '192.168.1.14' into...
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] netsock2.c: ...host '192.168.1.14' and port ''.
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: Processing media-level (audio) SDP c=IN IP4 192.168.1.14... OK.
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: Processing media-level (audio) SDP b=TIAS:64000... UNSUPPORTED OR FAILED.
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: Processing media-level (audio) SDP a=rtcp:4003 IN IP4 192.168.1.14... UNSUPPORTED OR FAILED.
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK.
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:123 opus/48000/2... OK.
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: Processing media-level (audio) SDP a=fmtp:123 maxplaybackrate=24000... OK.
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED OR FAILED.
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: Processing media-level (audio) SDP a=ssrc:535560589 cname:6c744daf3c0c683f... UNSUPPORTED OR FAILED.
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] acl.c: For destination '192.168.1.14', our source address is '85.111.24.13'.
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fc234362b90'
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] rtp_engine.c: Copying payload 0 (0x7fc234365f08) from 0x7fc1c927b470 to 0x7fc234362d58
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] rtp_engine.c: Copying payload 8 (0x7fc23436a198) from 0x7fc1c927b470 to 0x7fc234362d58
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] rtp_engine.c: Copying payload 101 (0x7fc234316ba8) from 0x7fc1c927b470 to 0x7fc234362d58
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] rtp_engine.c: Copying payload 123 (0x7fc23433e8d8) from 0x7fc1c927b470 to 0x7fc234362d58
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7fc234362b90'
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: We're settling with these formats: (alaw|ulaw)
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: Checking SIP call limits for device 101
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: Updating call counter for incoming call
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] netsock2.c: Splitting '101' into...
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] netsock2.c: ...host '101' and port ''.
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] netsock2.c: Splitting '101' into...
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] netsock2.c: ...host '101' and port ''.
[2018-11-09 09:09:58] DEBUG[27045] devicestate.c: No provider found, checking channel drivers for SIP - 101
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: Incoming INVITE with 'timer' option supported
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: INVITE also has "Session-Expires" header.
[2018-11-09 09:09:58] DEBUG[27045] chan_sip.c: Checking device state for peer 101
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: Session-Expires: 1800
[2018-11-09 09:09:58] DEBUG[27045] devicestate.c: Changing state for SIP/101 - state 2 (In use)
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: INVITE also has "Min-SE" header.
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: Received Min-SE: 90
[2018-11-09 09:09:58] DEBUG[27108] app_queue.c: Removed SIP/101 from pending_members
[2018-11-09 09:09:58] DEBUG[27034] threadpool.c: Increasing threadpool stasis-core's size by 1
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] channel.c: Channel 0x7fc2343bf660 'SIP/101-00000059' allocated
[2018-11-09 09:09:58] DEBUG[27108] app_queue.c: Removed SIP/101 from pending_members
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: *** Our native formats are (alaw) 
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: *** Joint capabilities are (alaw|ulaw) 
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: *** Our capabilities are (alaw|ulaw|g729) 
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: *** AST_CODEC_CHOOSE formats are alaw 
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: This channel will not be able to handle video.
[2018-11-09 09:09:58] DEBUG[27108] app_queue.c: Device 'SIP/101' changed to state '2' (In use)
[2018-11-09 09:09:58] 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-09 09:09:58] VERBOSE[27048] cdr.c: 0x7fc228002730 - Created CDR for channel SIP/101-00000059
[2018-11-09 09:09:58] VERBOSE[27048] cdr.c: 0x7fc228002730 - Transitioning CDR for SIP/101-00000059 from state NONE to Single
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: SIP/101-00000059: New call is still down.... Trying... 
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 78.187.100.242:64211
[2018-11-09 09:09:58] DEBUG[27045] devicestate.c: No provider found, checking channel drivers for SIP - 101
[2018-11-09 09:09:58] DEBUG[27045] chan_sip.c: Checking device state for peer 101
[2018-11-09 09:09:58] DEBUG[27045] devicestate.c: Changing state for SIP/101 - state 2 (In use)
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] pbx.c: Launching 'Queue'
[2018-11-09 09:09:58] VERBOSE[13296][C-000007ba] pbx.c: Executing [630@DLPN_DialPlan1:1] Queue("SIP/101-00000059", "630,tkXx,,,,queue-set.php,") in new stack
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] app_queue.c: queue: 630, options: tkXx, url: , announce: , timeout: , agi: queue-set.php, macro: , gosub: , rule: , position: 
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] app_queue.c: NO QUEUE_PRIO variable found. Using default.
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] app_queue.c: queue: 630, expires: 0, priority: 0
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] app_queue.c: Queue 630 has no realtime members defined. No need for update
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] app_queue.c: SIP/100 is available.
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] app_queue.c: Queue '630' Join, Channel 'SIP/101-00000059', Position '1'
[2018-11-09 09:09:58] 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-09 09:09:58] VERBOSE[13296][C-000007ba] res_musiconhold.c: Started music on hold, class 'queuemusic', on channel 'SIP/101-00000059'
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] channel.c: Prodding channel 'SIP/101-00000059'
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] res_rtp_asterisk.c: Setting the marker bit due to a source update
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] chan_sip.c: ** Our capability: (alaw|ulaw) Video flag: True Text flag: True
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] chan_sip.c: ** Our prefcodec: (nothing) 
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] chan_sip.c: -- Done with adding codecs to SDP
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] chan_sip.c: Setting framing on incoming call: 0
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] chan_sip.c: Done building SDP. Settling with this capability: (alaw|ulaw)
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] chan_sip.c: Trying to put 'SIP/2.0 183' onto UDP socket destined for 78.187.100.242:64211
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] res_rtp_asterisk.c: Received frame with no data for RTP instance '0x7fc234362b90' so dropping frame
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] app_queue.c: There is 1 available member.
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] app_queue.c: It's our turn (SIP/101-00000059).
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] app_queue.c: SIP/101-00000059 is trying to call a queue member.
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] app_queue.c: Trying 'SIP/100' with metric 0
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] app_queue.c: Add SIP/100 to pending_members
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] chan_sip.c: Asked to create a SIP channel with formats: (alaw)
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] chan_sip.c: Allocating new SIP dialog for 1271dd2b7fc9e0a42bce1ba83ad2b105@127.0.0.1:5060 - INVITE (No RTP)
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fc1f45924e0'
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] res_rtp_asterisk.c: Allocated port 11232 for RTP instance '0x7fc1f45924e0'
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] res_rtp_asterisk.c: Creating ICE session 0.0.0.0:11232 (11232) for RTP instance '0x7fc1f45924e0'
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] netsock2.c: Splitting '85.111.24.13' into...
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] netsock2.c: ...host '85.111.24.13' and port ''.
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] netsock2.c: Splitting '85.111.24.13' into...
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] netsock2.c: ...host '85.111.24.13' and port ''.
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] rtp_engine.c: RTP instance '0x7fc1f45924e0' is setup and ready to go
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] netsock2.c: Splitting 'Telsam-iex4' into...
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] netsock2.c: ...host 'Telsam-iex4' and port ''.
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fc1f45924e0'
[2018-11-09 09:09:58] VERBOSE[13296][C-000007ba] netsock2.c: Using SIP RTP TOS bits 184
[2018-11-09 09:09:58] VERBOSE[13296][C-000007ba] netsock2.c: Using SIP RTP CoS mark 5
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] chan_sip.c: Setting NAT on RTP to On
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] acl.c: For destination '78.187.100.242', our source address is '85.111.24.13'.
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] chan_sip.c: Setting AST_TRANSPORT_UDP with address 85.111.24.13:5060
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] chan_sip.c: Setting NAT on RTP to On
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] chan_sip.c: SIP call-id changed from '1271dd2b7fc9e0a42bce1ba83ad2b105@127.0.0.1:5060' to '06b618ac69c26e34490ea29e24299dd3@85.111.24.13:5060'
[2018-11-09 09:09:58] DEBUG[27034] threadpool.c: Increasing threadpool stasis-core's size by 1
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] channel.c: Channel 0x7fc1f48d2a30 'SIP/100-0000005a' allocated
[2018-11-09 09:09:58] VERBOSE[27048] cdr.c: 0x7fc228002da0 - Created CDR for channel SIP/100-0000005a
[2018-11-09 09:09:58] VERBOSE[27048] cdr.c: 0x7fc228002da0 - Transitioning CDR for SIP/100-0000005a from state NONE to Single
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] chan_sip.c: *** Our native formats are (alaw) 
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] chan_sip.c: *** Joint capabilities are (alaw) 
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] chan_sip.c: *** Our capabilities are (alaw|ulaw|g729) 
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] chan_sip.c: *** AST_CODEC_CHOOSE formats are alaw 
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] chan_sip.c: *** Our preferred formats from the incoming channel are (alaw) 
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] chan_sip.c: This channel will not be able to handle video.
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] channel_internal_api.c: Channel Call ID changing from [C-000007ba] to [C-000007ba]
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] chan_sip.c: Outgoing Call for 100
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] chan_sip.c: Updating call counter for outgoing call
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] chan_sip.c: ** Our capability: (alaw|ulaw|g729) Video flag: False Text flag: False
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] chan_sip.c: ** Our prefcodec: (alaw) 
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] chan_sip.c: -- Done with adding codecs to SDP
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] chan_sip.c: Done building SDP. Settling with this capability: (alaw|ulaw|g729)
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] chan_sip.c: Initializing initreq for method INVITE - callid 06b618ac69c26e34490ea29e24299dd3@85.111.24.13:5060
[2018-11-09 09:09:58] DEBUG[27045] devicestate.c: No provider found, checking channel drivers for SIP - 100
[2018-11-09 09:09:58] DEBUG[27045] chan_sip.c: Checking device state for peer 100
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 78.187.100.242:5080
[2018-11-09 09:09:58] DEBUG[27045] devicestate.c: Changing state for SIP/100 - state 6 (Ringing)
[2018-11-09 09:09:58] DEBUG[27108] app_queue.c: Removed SIP/100 from pending_members
[2018-11-09 09:09:58] DEBUG[27108] app_queue.c: Removed SIP/100 from pending_members
[2018-11-09 09:09:58] VERBOSE[13296][C-000007ba] app_queue.c: Called SIP/100
[2018-11-09 09:09:58] DEBUG[27108] app_queue.c: Device 'SIP/100' changed to state '6' (Ringing)
[2018-11-09 09:09:58] 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-09 09:09:58] 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-09 09:09:58] VERBOSE[27048] cdr.c: Dial Begin message for SIP/101-00000059, SIP/100-0000005a: 1541743798.00430360
[2018-11-09 09:09:58] VERBOSE[27048] cdr.c: 0x7fc228002730 - Processing Dial Begin message for channel SIP/101-00000059, peer SIP/100-0000005a
[2018-11-09 09:09:58] VERBOSE[27048] cdr.c: 0x7fc228002730 - Updated Party A SIP/101-00000059 snapshot
[2018-11-09 09:09:58] VERBOSE[27048] cdr.c: 0x7fc228002730 - Updated Party B SIP/100-0000005a snapshot
[2018-11-09 09:09:58] VERBOSE[27048] cdr.c: 0x7fc228002730 - Transitioning CDR for SIP/101-00000059 from state Single to Dial
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] channel.c: Channel SIP/101-00000059 setting write format path: slin -> alaw
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] res_musiconhold.c: SIP/101-00000059 Opened file 0 '/var/lib/asterisk/sounds/moh/moh10/cisco'
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] res_rtp_asterisk.c: Ooh, format changed from none to alaw
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] res_rtp_asterisk.c: Starting RTCP transmission on RTP instance '0x7fc234362b90'
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] res_rtp_asterisk.c: Got RTCP report of 60 bytes from 78.187.100.242:4003
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] res_rtp_asterisk.c: Got RTCP report of 60 bytes from 78.187.100.242:4003
[2018-11-09 09:09:58] DEBUG[27082] chan_sip.c: = Looking for  Call ID: 06b618ac69c26e34490ea29e24299dd3@85.111.24.13:5060 (Checking To) --From tag as4cb32479 --To-tag   
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '06b618ac69c26e34490ea29e24299dd3@85.111.24.13:5060' Request 102: Found
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: SIP response 100 to standard invite
[2018-11-09 09:09:58] DEBUG[27082] chan_sip.c: = Looking for  Call ID: 06b618ac69c26e34490ea29e24299dd3@85.111.24.13:5060 (Checking To) --From tag as4cb32479 --To-tag 1871501409  
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '06b618ac69c26e34490ea29e24299dd3@85.111.24.13:5060' Request 102: Found
[2018-11-09 09:09:58] DEBUG[27082][C-000007ba] chan_sip.c: SIP response 180 to standard invite
[2018-11-09 09:09:58] DEBUG[27045] devicestate.c: No provider found, checking channel drivers for SIP - 100
[2018-11-09 09:09:58] VERBOSE[13296][C-000007ba] app_queue.c: SIP/100-0000005a is ringing
[2018-11-09 09:09:58] DEBUG[27045] chan_sip.c: Checking device state for peer 100
[2018-11-09 09:09:58] DEBUG[27045] devicestate.c: Changing state for SIP/100 - state 6 (Ringing)
[2018-11-09 09:09:58] DEBUG[27045] devicestate.c: No provider found, checking channel drivers for SIP - 100
[2018-11-09 09:09:58] DEBUG[27045] chan_sip.c: Checking device state for peer 100
[2018-11-09 09:09:58] DEBUG[27045] devicestate.c: Changing state for SIP/100 - state 6 (Ringing)
[2018-11-09 09:09:58] DEBUG[27108] app_queue.c: Device 'SIP/100' changed to state '6' (Ringing)
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] res_rtp_asterisk.c: 0x7fc23438f530 -- Received RTP packet from 78.187.100.242:4002, dropping due to strict RTP protection. Qualifying new stream.
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] res_rtp_asterisk.c: 0x7fc23438f530 -- Received RTP packet from 78.187.100.242:4002, dropping due to strict RTP protection. Will switch to it in 3 packets.
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] res_rtp_asterisk.c: 0x7fc23438f530 -- Received RTP packet from 78.187.100.242:4002, dropping due to strict RTP protection. Will switch to it in 2 packets.
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] res_rtp_asterisk.c: 0x7fc23438f530 -- Received RTP packet from 78.187.100.242:4002, dropping due to strict RTP protection. Will switch to it in 1 packets.
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] acl.c: For destination '78.187.100.242', our source address is '85.111.24.13'.
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fc234362b90'
[2018-11-09 09:09:58] DEBUG[13296][C-000007ba] res_rtp_asterisk.c: Got RTCP report of 80 bytes from 78.187.100.242:4003
[2018-11-09 09:10:00] DEBUG[27082] chan_sip.c: = Looking for  Call ID: 06b618ac69c26e34490ea29e24299dd3@85.111.24.13:5060 (Checking To) --From tag as4cb32479 --To-tag 1871501409  
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: Acked pending invite 102
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: Stopping retransmission on '06b618ac69c26e34490ea29e24299dd3@85.111.24.13:5060' of Request 102: Match Found
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: SIP response 200 to standard invite
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED.
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: Processing session-level SDP o=- 20152 20152 IN IP4 192.168.1.3... OK.
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: Processing session-level SDP s=SDP data... UNSUPPORTED OR FAILED.
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] netsock2.c: Splitting '192.168.1.3' into...
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] netsock2.c: ...host '192.168.1.3' and port ''.
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: Processing session-level SDP c=IN IP4 192.168.1.3... OK.
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: Processing session-level SDP b=AS:2097... UNSUPPORTED OR FAILED.
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED.
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7fc1c927a6d0
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7fc1c927a6d0
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] rtp_engine.c: Setting tx payload type 18 based on m type on 0x7fc1c927a6d0
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] rtp_engine.c: Setting tx payload type 101 based on m type on 0x7fc1c927a6d0
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK.
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: Processing media-level (audio) SDP a=fmtp:18 annexb=no... OK.
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK.
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED OR FAILED.
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK.
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] res_rtp_asterisk.c: Set role to CONTROLLING (0x7fc1f45924e0)
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] res_rtp_asterisk.c: Set role failed; no ice instance (0x7fc1f45924e0)
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] acl.c: For destination '192.168.1.3', our source address is '85.111.24.13'.
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fc1f45924e0'
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] rtp_engine.c: Copying payload 0 (0x7fc234359918) from 0x7fc1c927a6d0 to 0x7fc1f45926a8
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] rtp_engine.c: Copying payload 8 (0x7fc234358798) from 0x7fc1c927a6d0 to 0x7fc1f45926a8
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] rtp_engine.c: Copying payload 18 (0x7fc234360998) from 0x7fc1c927a6d0 to 0x7fc1f45926a8
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] rtp_engine.c: Copying payload 101 (0x7fc234362f48) from 0x7fc1c927a6d0 to 0x7fc1f45926a8
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7fc1f45924e0'
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: We're settling with these formats: (alaw|ulaw|g729)
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: We have an owner, now see if we need to change this call
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: Updating call counter for outgoing call
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: Trying to put 'ACK sip:100' onto UDP socket destined for 78.187.100.242:5080
[2018-11-09 09:10:00] DEBUG[27045] devicestate.c: No provider found, checking channel drivers for SIP - 100
[2018-11-09 09:10:00] DEBUG[27045] chan_sip.c: Checking device state for peer 100
[2018-11-09 09:10:00] DEBUG[27045] devicestate.c: Changing state for SIP/100 - state 2 (In use)
[2018-11-09 09:10:00] DEBUG[27108] app_queue.c: Removed SIP/100 from pending_members
[2018-11-09 09:10:00] DEBUG[27108] app_queue.c: Removed SIP/100 from pending_members
[2018-11-09 09:10:00] DEBUG[27108] app_queue.c: Device 'SIP/100' changed to state '2' (In use)
[2018-11-09 09:10:00] DEBUG[13296][C-000007ba] channel.c: SIP/101-00000059: Dropping redundant connected line update "100" <100>.
[2018-11-09 09:10:00] VERBOSE[27048] cdr.c: 0x7fc228002da0 - Set answered time to 1541743800.190748
[2018-11-09 09:10:00] VERBOSE[13296][C-000007ba] app_queue.c: SIP/100-0000005a answered SIP/101-00000059
[2018-11-09 09:10:00] DEBUG[27045] devicestate.c: No provider found, checking channel drivers for SIP - 100
[2018-11-09 09:10:00] DEBUG[27045] chan_sip.c: Checking device state for peer 100
[2018-11-09 09:10:00] DEBUG[27045] devicestate.c: Changing state for SIP/100 - state 2 (In use)
[2018-11-09 09:10:00] VERBOSE[27048] cdr.c: Dial End message for SIP/101-00000059, SIP/100-0000005a: 1541743800.00190784
[2018-11-09 09:10:00] VERBOSE[27048] cdr.c: 0x7fc228002730 - Processing Dial End message for channel SIP/101-00000059, peer SIP/100-0000005a
[2018-11-09 09:10:00] VERBOSE[27048] cdr.c: 0x7fc228002730 - Transitioning CDR for SIP/101-00000059 from state Dial to DialedPending
[2018-11-09 09:10:00] VERBOSE[13296][C-000007ba] res_musiconhold.c: Stopped music on hold on SIP/101-00000059
[2018-11-09 09:10:00] DEBUG[13296][C-000007ba] channel.c: Channel SIP/101-00000059 setting write format path: alaw -> alaw
[2018-11-09 09:10:00] DEBUG[13296][C-000007ba] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2018-11-09 09:10:00] DEBUG[13296][C-000007ba] app_queue.c: Queue '630' Leave, Channel 'SIP/101-00000059'
[2018-11-09 09:10:00] DEBUG[13296][C-000007ba] app_queue.c: app_queue: agi=queue-set.php.
[2018-11-09 09:10:00] VERBOSE[13296][C-000007ba] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/queue-set.php
[2018-11-09 09:10:00] 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-09 09:10:00] VERBOSE[13296][C-000007ba] res_agi.c: AGI Script Executing Application: (Macro) Options: (stdexten-record-test)
[2018-11-09 09:10:00] DEBUG[13296][C-000007ba] pbx.c: Launching 'NoOp'
[2018-11-09 09:10:00] VERBOSE[13296][C-000007ba] pbx.c: Executing [s@macro-stdexten-record-test:1] NoOp("SIP/101-00000059", "Test") in new stack
[2018-11-09 09:10:00] VERBOSE[27048] cdr.c: 0x7fc228002730 - Transitioning CDR for SIP/101-00000059 from state DialedPending to Finalized
[2018-11-09 09:10:00] DEBUG[27048] cdr.c: Finalized CDR for SIP/101-00000059 - start 1541743798.428324 answer 0.000000 end 1541743800.205789 dispo ANSWERED
[2018-11-09 09:10:00] VERBOSE[27048] cdr.c: 0x7fc228004710 - Created CDR for channel SIP/101-00000059
[2018-11-09 09:10:00] VERBOSE[27048] cdr.c: 0x7fc228004710 - Transitioning CDR for SIP/101-00000059 from state NONE to Single
[2018-11-09 09:10:00] DEBUG[13296][C-000007ba] app_macro.c: Executed application: NoOp
[2018-11-09 09:10:00] VERBOSE[13296][C-000007ba] res_agi.c: <SIP/101-00000059>AGI Script queue-set.php completed, returning 0
[2018-11-09 09:10:00] VERBOSE[27048] cdr.c: 0x7fc228004710 - Set answered time to 1541743800.207274
[2018-11-09 09:10:00] DEBUG[27045] devicestate.c: No provider found, checking channel drivers for SIP - 101
[2018-11-09 09:10:00] DEBUG[27045] chan_sip.c: Checking device state for peer 101
[2018-11-09 09:10:00] DEBUG[27045] devicestate.c: Changing state for SIP/101 - state 2 (In use)
[2018-11-09 09:10:00] DEBUG[13296][C-000007ba] chan_sip.c: SIP answering channel: SIP/101-00000059
[2018-11-09 09:10:00] DEBUG[13296][C-000007ba] res_rtp_asterisk.c: Setting the marker bit due to a source update
[2018-11-09 09:10:00] DEBUG[13296][C-000007ba] chan_sip.c: ** Our capability: (alaw|ulaw) Video flag: True Text flag: True
[2018-11-09 09:10:00] DEBUG[13296][C-000007ba] chan_sip.c: ** Our prefcodec: (nothing) 
[2018-11-09 09:10:00] DEBUG[13296][C-000007ba] chan_sip.c: -- Done with adding codecs to SDP
[2018-11-09 09:10:00] DEBUG[13296][C-000007ba] chan_sip.c: Setting framing on incoming call: 0
[2018-11-09 09:10:00] DEBUG[13296][C-000007ba] chan_sip.c: Done building SDP. Settling with this capability: (alaw|ulaw)
[2018-11-09 09:10:00] DEBUG[13296][C-000007ba] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 78.187.100.242:64211
[2018-11-09 09:10:00] DEBUG[13296][C-000007ba] dahdi/bridge_native_dahdi.c: Bridge 58ad0839-be20-40a9-9a63-f5c426970f7f: Cannot use native DAHDI.  Must have two channels.
[2018-11-09 09:10:00] DEBUG[13296][C-000007ba] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge.
[2018-11-09 09:10:00] DEBUG[13296][C-000007ba] bridge_native_rtp.c: Bridge '58ad0839-be20-40a9-9a63-f5c426970f7f' can not use native RTP bridge as two channels are required
[2018-11-09 09:10:00] DEBUG[13296][C-000007ba] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge.
[2018-11-09 09:10:00] DEBUG[13296][C-000007ba] bridge.c: Bridge technology holding_bridge does not have any capabilities we want.
[2018-11-09 09:10:00] DEBUG[13296][C-000007ba] bridge.c: Chose bridge technology simple_bridge
[2018-11-09 09:10:00] DEBUG[13296][C-000007ba] bridge.c: Bridge 58ad0839-be20-40a9-9a63-f5c426970f7f: calling simple_bridge technology constructor
[2018-11-09 09:10:00] DEBUG[13296][C-000007ba] bridge.c: Bridge 58ad0839-be20-40a9-9a63-f5c426970f7f: calling simple_bridge technology start
[2018-11-09 09:10:00] DEBUG[13303][C-000007ba] bridge_channel.c: Bridge 58ad0839-be20-40a9-9a63-f5c426970f7f: 0x7fc1f476e100(SIP/100-0000005a) is joining
[2018-11-09 09:10:00] DEBUG[13303][C-000007ba] bridge_channel.c: Bridge 58ad0839-be20-40a9-9a63-f5c426970f7f: pushing 0x7fc1f476e100(SIP/100-0000005a)
[2018-11-09 09:10:00] VERBOSE[13303][C-000007ba] bridge_channel.c: Channel SIP/100-0000005a joined 'simple_bridge' basic-bridge <58ad0839-be20-40a9-9a63-f5c426970f7f>
[2018-11-09 09:10:00] DEBUG[27034] threadpool.c: Increasing threadpool stasis-core's size by 1
[2018-11-09 09:10:00] DEBUG[13303][C-000007ba] dahdi/bridge_native_dahdi.c: Bridge 58ad0839-be20-40a9-9a63-f5c426970f7f: Cannot use native DAHDI.  Must have two channels.
[2018-11-09 09:10:00] DEBUG[13303][C-000007ba] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge.
[2018-11-09 09:10:00] VERBOSE[27048] cdr.c: Bridge Enter message for channel SIP/100-0000005a: 1541743800.00207815
[2018-11-09 09:10:00] DEBUG[13303][C-000007ba] bridge_native_rtp.c: Bridge '58ad0839-be20-40a9-9a63-f5c426970f7f' can not use native RTP bridge as two channels are required
[2018-11-09 09:10:00] DEBUG[13303][C-000007ba] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge.
[2018-11-09 09:10:00] VERBOSE[27048] cdr.c: 0x7fc228002da0 - Updating Party A SIP/100-0000005a snapshot
[2018-11-09 09:10:00] DEBUG[13303][C-000007ba] bridge.c: Bridge technology softmix does not have any capabilities we want.
[2018-11-09 09:10:00] DEBUG[13303][C-000007ba] bridge.c: Bridge technology holding_bridge does not have any capabilities we want.
[2018-11-09 09:10:00] VERBOSE[27048] cdr.c: 0x7fc228002da0 - Processing bridge enter for SIP/100-0000005a
[2018-11-09 09:10:00] DEBUG[13303][C-000007ba] bridge.c: Chose bridge technology simple_bridge
[2018-11-09 09:10:00] DEBUG[13303][C-000007ba] bridge.c: Bridge 58ad0839-be20-40a9-9a63-f5c426970f7f is already using the new technology.
[2018-11-09 09:10:00] DEBUG[13303][C-000007ba] bridge.c: Bridge 58ad0839-be20-40a9-9a63-f5c426970f7f: 0x7fc1f476e100(SIP/100-0000005a) is joining simple_bridge technology
[2018-11-09 09:10:00] VERBOSE[27048] cdr.c: 0x7fc228002da0 - Transitioning CDR for SIP/100-0000005a from state Single to Bridged
[2018-11-09 09:10:00] DEBUG[13303][C-000007ba] res_rtp_asterisk.c: Not changing SSRC since we haven't sent any RTP yet
[2018-11-09 09:10:00] DEBUG[13296][C-000007ba] bridge_channel.c: Bridge 58ad0839-be20-40a9-9a63-f5c426970f7f: 0x7fc1f45941e0(SIP/101-00000059) is joining
[2018-11-09 09:10:00] DEBUG[13296][C-000007ba] bridge_channel.c: Bridge 58ad0839-be20-40a9-9a63-f5c426970f7f: pushing 0x7fc1f45941e0(SIP/101-00000059)
[2018-11-09 09:10:00] VERBOSE[13296][C-000007ba] bridge_channel.c: Channel SIP/101-00000059 joined 'simple_bridge' basic-bridge <58ad0839-be20-40a9-9a63-f5c426970f7f>
[2018-11-09 09:10:00] VERBOSE[27048] cdr.c: Bridge Enter message for channel SIP/101-00000059: 1541743800.00208421
[2018-11-09 09:10:00] VERBOSE[27048] cdr.c: 0x7fc228002730 - Updating Party A SIP/101-00000059 snapshot
[2018-11-09 09:10:00] VERBOSE[27048] cdr.c: 0x7fc228002730 - Processing bridge enter for SIP/101-00000059
[2018-11-09 09:10:00] VERBOSE[27048] cdr.c: 0x7fc228004710 - Updating Party A SIP/101-00000059 snapshot
[2018-11-09 09:10:00] VERBOSE[27048] cdr.c: 0x7fc228004710 - Processing bridge enter for SIP/101-00000059
[2018-11-09 09:10:00] DEBUG[13295] app_queue.c: Detected entry of caller channel SIP/101-00000059 into bridge 58ad0839-be20-40a9-9a63-f5c426970f7f
[2018-11-09 09:10:00] VERBOSE[27048] cdr.c: 0x7fc228004710 - Party A SIP/101-00000059 has new Party B SIP/100-0000005a
[2018-11-09 09:10:00] DEBUG[27048] cdr.c: Finalized CDR for SIP/100-0000005a - start 1541743798.429948 answer 1541743800.190748 end 1541743800.208461 dispo ANSWERED
[2018-11-09 09:10:00] VERBOSE[27048] cdr.c: 0x7fc228004710 - Transitioning CDR for SIP/101-00000059 from state Single to Bridged
[2018-11-09 09:10:00] DEBUG[13296][C-000007ba] dahdi/bridge_native_dahdi.c: Channel 'SIP/100-0000005a' has DTMF hooks.
[2018-11-09 09:10:00] DEBUG[13296][C-000007ba] dahdi/bridge_native_dahdi.c: Bridge 58ad0839-be20-40a9-9a63-f5c426970f7f: Cannot use native DAHDI.  Channel 'SIP/100-0000005a' not compatible.
[2018-11-09 09:10:00] DEBUG[13296][C-000007ba] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge.
[2018-11-09 09:10:00] DEBUG[13296][C-000007ba] bridge_native_rtp.c: Bridge '58ad0839-be20-40a9-9a63-f5c426970f7f'.  Checking compatability for channels 'SIP/100-0000005a' and 'SIP/101-00000059'
[2018-11-09 09:10:00] DEBUG[13296][C-000007ba] bridge_native_rtp.c: Bridge '58ad0839-be20-40a9-9a63-f5c426970f7f' can not use native RTP bridge as channel 'SIP/100-0000005a' has DTMF hooks
[2018-11-09 09:10:00] DEBUG[13296][C-000007ba] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge.
[2018-11-09 09:10:00] DEBUG[13296][C-000007ba] bridge.c: Bridge technology softmix does not have any capabilities we want.
[2018-11-09 09:10:00] DEBUG[13296][C-000007ba] bridge.c: Bridge technology holding_bridge does not have any capabilities we want.
[2018-11-09 09:10:00] DEBUG[13296][C-000007ba] bridge.c: Chose bridge technology simple_bridge
[2018-11-09 09:10:00] DEBUG[13296][C-000007ba] bridge.c: Bridge 58ad0839-be20-40a9-9a63-f5c426970f7f is already using the new technology.
[2018-11-09 09:10:00] DEBUG[13296][C-000007ba] bridge.c: Bridge 58ad0839-be20-40a9-9a63-f5c426970f7f: 0x7fc1f45941e0(SIP/101-00000059) is joining simple_bridge technology
[2018-11-09 09:10:00] DEBUG[27034] threadpool.c: Increasing threadpool stasis-core's size by 1
[2018-11-09 09:10:00] DEBUG[13296][C-000007ba] res_rtp_asterisk.c: Changing ssrc from 1391332677 to 1154331392 due to a source change
[2018-11-09 09:10:00] DEBUG[13303][C-000007ba] res_rtp_asterisk.c: Ooh, format changed from none to alaw
[2018-11-09 09:10:00] DEBUG[13303][C-000007ba] res_rtp_asterisk.c: Starting RTCP transmission on RTP instance '0x7fc1f45924e0'
[2018-11-09 09:10:00] DEBUG[27082] chan_sip.c: = Looking for  Call ID: da9ea689f4e745e581d83e5782c1982b (Checking From) --From tag d70e2a9c31154661badcf3a9c94cef36 --To-tag as69e185b3  
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: Stopping retransmission on 'da9ea689f4e745e581d83e5782c1982b' of Response 29002: Match Found
[2018-11-09 09:10:00] DEBUG[27082] chan_sip.c: Session timer started: 11 - da9ea689f4e745e581d83e5782c1982b 900000ms
[2018-11-09 09:10:00] DEBUG[27082] chan_sip.c: = Looking for  Call ID: da9ea689f4e745e581d83e5782c1982b (Checking From) --From tag d70e2a9c31154661badcf3a9c94cef36 --To-tag as69e185b3  
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] netsock2.c: Splitting '192.168.1.14:64211' into...
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] netsock2.c: ...host '192.168.1.14' and port '64211'.
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: NAT detected for 192.168.1.14 / 78.187.100.242
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED.
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: Processing session-level SDP o=- 3750743397 3750743398 IN IP4 192.168.1.14... OK.
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: Processing session-level SDP s=pjmedia... UNSUPPORTED OR FAILED.
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: Processing session-level SDP b=AS:84... UNSUPPORTED OR FAILED.
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED.
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: Processing session-level SDP a=X-nat:0... UNSUPPORTED OR FAILED.
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7fc1c927b470
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] rtp_engine.c: Setting tx payload type 101 based on m type on 0x7fc1c927b470
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] netsock2.c: Splitting '192.168.1.14' into...
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] netsock2.c: ...host '192.168.1.14' and port ''.
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: Processing media-level (audio) SDP c=IN IP4 192.168.1.14... OK.
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: Processing media-level (audio) SDP b=TIAS:64000... UNSUPPORTED OR FAILED.
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: Processing media-level (audio) SDP a=rtcp:4003 IN IP4 192.168.1.14... UNSUPPORTED OR FAILED.
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: Processing media-level (audio) SDP a=ssrc:535560589 cname:6c744daf3c0c683f... UNSUPPORTED OR FAILED.
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED OR FAILED.
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK.
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] acl.c: For destination '192.168.1.14', our source address is '85.111.24.13'.
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fc234362b90'
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] rtp_engine.c: Copying payload 8 (0x7fc23437b6f8) from 0x7fc1c927b470 to 0x7fc234362d58
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] rtp_engine.c: Copying payload 101 (0x7fc234378078) from 0x7fc1c927b470 to 0x7fc234362d58
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7fc234362b90'
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: We're settling with these formats: (alaw)
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: We have an owner, now see if we need to change this call
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: Incoming INVITE with 'timer' option supported
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: INVITE also has "Session-Expires" header.
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: Session-Expires: 1800
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: Refresher: UAS
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: INVITE also has "Min-SE" header.
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: Received Min-SE: 90
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: Restarting session-timers on a refresh - da9ea689f4e745e581d83e5782c1982b
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: SIP/101-00000059: This call is UP.... 
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 78.187.100.242:64211
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: ** Our capability: (alaw) Video flag: True Text flag: True
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: ** Our prefcodec: (nothing) 
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: -- Done with adding codecs to SDP
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: Setting framing on incoming call: 0
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: Done building SDP. Settling with this capability: (alaw)
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 78.187.100.242:64211
[2018-11-09 09:10:00] DEBUG[27082] chan_sip.c: Session timer stopped: 11 - da9ea689f4e745e581d83e5782c1982b
[2018-11-09 09:10:00] DEBUG[27082] chan_sip.c: Session timer started: 9 - da9ea689f4e745e581d83e5782c1982b 900000ms
[2018-11-09 09:10:00] DEBUG[13303][C-000007ba] res_rtp_asterisk.c: Setting the marker bit due to a source update
[2018-11-09 09:10:00] DEBUG[13296][C-000007ba] acl.c: For destination '78.187.100.242', our source address is '85.111.24.13'.
[2018-11-09 09:10:00] DEBUG[13296][C-000007ba] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fc234362b90'
[2018-11-09 09:10:00] DEBUG[27082] chan_sip.c: = Looking for  Call ID: da9ea689f4e745e581d83e5782c1982b (Checking From) --From tag d70e2a9c31154661badcf3a9c94cef36 --To-tag as69e185b3  
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[2018-11-09 09:10:00] DEBUG[27082][C-000007ba] chan_sip.c: Stopping retransmission on 'da9ea689f4e745e581d83e5782c1982b' of Response 29003: Match Found
[2018-11-09 09:10:00] DEBUG[13303][C-000007ba] res_rtp_asterisk.c: 0x7fc1f4414620 -- Received RTP packet from 78.187.100.242:50018, dropping due to strict RTP protection. Qualifying new stream.
[2018-11-09 09:10:00] DEBUG[13303][C-000007ba] res_rtp_asterisk.c: 0x7fc1f4414620 -- Received RTP packet from 78.187.100.242:50018, dropping due to strict RTP protection. Will switch to it in 3 packets.
[2018-11-09 09:10:00] DEBUG[13303][C-000007ba] res_rtp_asterisk.c: 0x7fc1f4414620 -- Received RTP packet from 78.187.100.242:50018, dropping due to strict RTP protection. Will switch to it in 2 packets.
[2018-11-09 09:10:00] DEBUG[13303][C-000007ba] res_rtp_asterisk.c: 0x7fc1f4414620 -- Received RTP packet from 78.187.100.242:50018, dropping due to strict RTP protection. Will switch to it in 1 packets.
[2018-11-09 09:10:00] DEBUG[13303][C-000007ba] acl.c: For destination '78.187.100.242', our source address is '85.111.24.13'.
[2018-11-09 09:10:00] DEBUG[13303][C-000007ba] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fc1f45924e0'
[2018-11-09 09:10:03] DEBUG[13296][C-000007ba] res_rtp_asterisk.c: Got RTCP report of 80 bytes from 78.187.100.242:4003
[2018-11-09 09:10:05] DEBUG[13303][C-000007ba] res_rtp_asterisk.c: Got RTCP report of 72 bytes from 78.187.100.242:1072
[2018-11-09 09:10:06] DEBUG[27082] chan_sip.c: = Looking for  Call ID: 06b618ac69c26e34490ea29e24299dd3@85.111.24.13:5060 (Checking From) --From tag 1871501409 --To-tag as4cb32479  
[2018-11-09 09:10:06] DEBUG[27082][C-000007ba] chan_sip.c: **** Received BYE (8) - Command in SIP BYE
[2018-11-09 09:10:06] DEBUG[27082][C-000007ba] netsock2.c: Splitting '192.168.1.3:5080' into...
[2018-11-09 09:10:06] DEBUG[27082][C-000007ba] netsock2.c: ...host '192.168.1.3' and port '5080'.
[2018-11-09 09:10:06] DEBUG[27082][C-000007ba] chan_sip.c: NAT detected for 192.168.1.3 / 78.187.100.242
[2018-11-09 09:10:06] DEBUG[27082][C-000007ba] chan_sip.c: Setting SIP_ALREADYGONE on dialog 06b618ac69c26e34490ea29e24299dd3@85.111.24.13:5060
[2018-11-09 09:10:06] DEBUG[27082][C-000007ba] chan_sip.c: Received bye, issuing owner hangup
[2018-11-09 09:10:06] DEBUG[27082][C-000007ba] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 78.187.100.242:5080
[2018-11-09 09:10:06] DEBUG[13304] app_queue.c: Detected hangup of queue member channel SIP/100-0000005a
[2018-11-09 09:10:06] DEBUG[13304] app_queue.c: Removed SIP/100 from pending_members
[2018-11-09 09:10:06] DEBUG[13303][C-000007ba] bridge_channel.c: Setting 0x7fc1f476e100(SIP/100-0000005a) state from:0 to:1
[2018-11-09 09:10:06] DEBUG[13303][C-000007ba] bridge_channel.c: Bridge 58ad0839-be20-40a9-9a63-f5c426970f7f: pulling 0x7fc1f476e100(SIP/100-0000005a)
[2018-11-09 09:10:06] VERBOSE[13303][C-000007ba] bridge_channel.c: Channel SIP/100-0000005a left 'simple_bridge' basic-bridge <58ad0839-be20-40a9-9a63-f5c426970f7f>
[2018-11-09 09:10:06] DEBUG[13303][C-000007ba] bridge_channel.c: Bridge 58ad0839-be20-40a9-9a63-f5c426970f7f: 0x7fc1f476e100(SIP/100-0000005a) is leaving simple_bridge technology
[2018-11-09 09:10:06] DEBUG[13303][C-000007ba] bridge.c: Bridge 58ad0839-be20-40a9-9a63-f5c426970f7f: dissolving bridge with cause 16(Normal Clearing)
[2018-11-09 09:10:06] DEBUG[13303][C-000007ba] bridge_channel.c: Setting 0x7fc1f45941e0(SIP/101-00000059) state from:0 to:2
[2018-11-09 09:10:06] DEBUG[13303][C-000007ba] bridge.c: Bridge 58ad0839-be20-40a9-9a63-f5c426970f7f: queueing action type:13 sub:1001
[2018-11-09 09:10:06] DEBUG[13303][C-000007ba] bridge.c: Bridge 58ad0839-be20-40a9-9a63-f5c426970f7f is dissolved, not performing smart bridge operation.
[2018-11-09 09:10:06] VERBOSE[27048] cdr.c: Bridge Leave message for SIP/100-0000005a: 1541743806.00246930
[2018-11-09 09:10:06] VERBOSE[27048] cdr.c: 0x7fc228002da0 - Processing Bridge Leave for SIP/100-0000005a
[2018-11-09 09:10:06] VERBOSE[27048] cdr.c: 0x7fc228002da0 - Transitioning CDR for SIP/100-0000005a from state Bridged to Finalized
[2018-11-09 09:10:06] DEBUG[13296][C-000007ba] bridge_channel.c: Bridge 58ad0839-be20-40a9-9a63-f5c426970f7f: pulling 0x7fc1f45941e0(SIP/101-00000059)
[2018-11-09 09:10:06] DEBUG[27048] cdr.c: Finalized CDR for SIP/101-00000059 - start 1541743800.205809 answer 1541743800.207274 end 1541743806.246960 dispo ANSWERED
[2018-11-09 09:10:06] VERBOSE[13296][C-000007ba] bridge_channel.c: Channel SIP/101-00000059 left 'simple_bridge' basic-bridge <58ad0839-be20-40a9-9a63-f5c426970f7f>
[2018-11-09 09:10:06] DEBUG[13296][C-000007ba] bridge_channel.c: Bridge 58ad0839-be20-40a9-9a63-f5c426970f7f: 0x7fc1f45941e0(SIP/101-00000059) is leaving simple_bridge technology
[2018-11-09 09:10:06] DEBUG[13296][C-000007ba] bridge.c: Bridge 58ad0839-be20-40a9-9a63-f5c426970f7f is dissolved, not performing smart bridge operation.
[2018-11-09 09:10:06] VERBOSE[27048] cdr.c: Bridge Leave message for SIP/101-00000059: 1541743806.00246970
[2018-11-09 09:10:06] VERBOSE[27048] cdr.c: 0x7fc228004710 - Processing Bridge Leave for SIP/101-00000059
[2018-11-09 09:10:06] VERBOSE[27048] cdr.c: 0x7fc228004710 - Transitioning CDR for SIP/101-00000059 from state Bridged to Finalized
[2018-11-09 09:10:06] DEBUG[13296][C-000007ba] res_rtp_asterisk.c: Changing ssrc from 1154331392 to 1025407071 due to a source change
[2018-11-09 09:10:06] DEBUG[13296][C-000007ba] pbx.c: Spawn extension (DLPN_DialPlan1,630,1) exited non-zero on 'SIP/101-00000059'
[2018-11-09 09:10:06] VERBOSE[13296][C-000007ba] pbx.c: Spawn extension (DLPN_DialPlan1, 630, 1) exited non-zero on 'SIP/101-00000059'
[2018-11-09 09:10:06] DEBUG[13296][C-000007ba] channel.c: Soft-Hanging (0x10) up channel 'SIP/101-00000059'
[2018-11-09 09:10:06] DEBUG[13296][C-000007ba] channel.c: Channel 0x7fc2343bf660 'SIP/101-00000059' hanging up.  Refs: 2
[2018-11-09 09:10:06] DEBUG[13296][C-000007ba] chan_sip.c: Hangup call SIP/101-00000059, SIP callid da9ea689f4e745e581d83e5782c1982b
[2018-11-09 09:10:06] DEBUG[13296][C-000007ba] chan_sip.c: Updating call counter for incoming call
[2018-11-09 09:10:06] DEBUG[27045] devicestate.c: No provider found, checking channel drivers for SIP - 101
[2018-11-09 09:10:06] DEBUG[27045] chan_sip.c: Checking device state for peer 101
[2018-11-09 09:10:06] DEBUG[27045] devicestate.c: Changing state for SIP/101 - state 1 (Not in use)
[2018-11-09 09:10:06] DEBUG[27108] app_queue.c: Removed SIP/101 from pending_members
[2018-11-09 09:10:06] DEBUG[27108] app_queue.c: Removed SIP/101 from pending_members
[2018-11-09 09:10:06] DEBUG[27108] app_queue.c: Device 'SIP/101' changed to state '1' (Not in use)
[2018-11-09 09:10:06] 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-09 09:10:06] 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-09 09:10:06] DEBUG[13296][C-000007ba] chan_sip.c: Trying to put 'BYE sip:101' onto UDP socket destined for 78.187.100.242:64211
[2018-11-09 09:10:06] DEBUG[13296][C-000007ba] channel.c: Channel 0x7fc2343bf660 'SIP/101-00000059' destroying
[2018-11-09 09:10:06] DEBUG[27082] chan_sip.c: Session timer stopped: 9 - da9ea689f4e745e581d83e5782c1982b
[2018-11-09 09:10:06] VERBOSE[27048] cdr.c: 0x7fc228002730 - Beginning finalize/dispatch for SIP/101-00000059
[2018-11-09 09:10:06] VERBOSE[27048] cdr.c: 0x7fc228002730 - Dispatching CDR for Party A SIP/101-00000059, Party B SIP/100-0000005a
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(calltype) result is ''
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(recordfile) result is ''
[2018-11-09 09:10:06] DEBUG[13303][C-000007ba] bridge.c: Bridge 58ad0839-be20-40a9-9a63-f5c426970f7f: actually destroying basic bridge, nobody wants it anymore
[2018-11-09 09:10:06] 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-09 09:10:06] DEBUG[13303][C-000007ba] bridge.c: Bridge 58ad0839-be20-40a9-9a63-f5c426970f7f: calling basic bridge destructor
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Evaluating 'ISNULL(${CDR(acid)})' (from 'ISNULL(${CDR(acid)})}' len 20)
[2018-11-09 09:10:06] DEBUG[13303][C-000007ba] bridge.c: Bridge 58ad0839-be20-40a9-9a63-f5c426970f7f: calling simple_bridge technology stop
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Evaluating 'CDR(acid)' (from 'CDR(acid)})' len 9)
[2018-11-09 09:10:06] DEBUG[13303][C-000007ba] bridge.c: Bridge 58ad0839-be20-40a9-9a63-f5c426970f7f: calling simple_bridge technology destructor
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(acid) result is ''
[2018-11-09 09:10:06] DEBUG[13303][C-000007ba] channel.c: Channel 0x7fc1f48d2a30 'SIP/100-0000005a' hanging up.  Refs: 2
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function ISNULL() result is '1'
[2018-11-09 09:10:06] DEBUG[13303][C-000007ba] chan_sip.c: Hangup call SIP/100-0000005a, SIP callid 06b618ac69c26e34490ea29e24299dd3@85.111.24.13:5060
[2018-11-09 09:10:06] DEBUG[13303][C-000007ba] chan_sip.c: Updating call counter for outgoing call
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Expression result is '1'
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Evaluating 'CDR(clid)' (from 'CDR(clid)}:${CDR(acid)})' len 9)
[2018-11-09 09:10:06] DEBUG[13303][C-000007ba] channel.c: Channel 0x7fc1f48d2a30 'SIP/100-0000005a' destroying
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(clid) result is '"101" <101>'
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Evaluating 'CDR(acid)' (from 'CDR(acid)})' len 9)
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(acid) result is ''
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function IF(1?"101" <101>:) result is '101 <101>'
[2018-11-09 09:10:06] 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-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(dst) result is '100'
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Evaluating 'CDR(calleeid)' (from 'CDR(calleeid)}","${CDR(start)}","${CDR(accountcode)}","${CDR(billsec)}","${CDR(disposition)}"
' len 13)
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(calleeid) result is ''
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Evaluating 'CDR(start)' (from 'CDR(start)}","${CDR(accountcode)}","${CDR(billsec)}","${CDR(disposition)}"
' len 10)
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(start) result is '2018-11-09 09:09:58'
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Evaluating 'CDR(accountcode)' (from 'CDR(accountcode)}","${CDR(billsec)}","${CDR(disposition)}"
' len 16)
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(accountcode) result is ''
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Evaluating 'CDR(billsec)' (from 'CDR(billsec)}","${CDR(disposition)}"
' len 12)
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(billsec) result is '0'
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Evaluating 'CDR(disposition)' (from 'CDR(disposition)}"
' len 16)
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(disposition) result is 'ANSWERED'
[2018-11-09 09:10:06] DEBUG[27045] devicestate.c: No provider found, checking channel drivers for SIP - 101
[2018-11-09 09:10:06] DEBUG[27045] chan_sip.c: Checking device state for peer 101
[2018-11-09 09:10:06] DEBUG[27045] devicestate.c: Changing state for SIP/101 - state 1 (Not in use)
[2018-11-09 09:10:06] DEBUG[27045] devicestate.c: No provider found, checking channel drivers for SIP - 100
[2018-11-09 09:10:06] DEBUG[27045] chan_sip.c: Checking device state for peer 100
[2018-11-09 09:10:06] DEBUG[27045] devicestate.c: Changing state for SIP/100 - state 1 (Not in use)
[2018-11-09 09:10:06] DEBUG[27045] devicestate.c: No provider found, checking channel drivers for SIP - 100
[2018-11-09 09:10:06] DEBUG[27045] chan_sip.c: Checking device state for peer 100
[2018-11-09 09:10:06] DEBUG[27045] devicestate.c: Changing state for SIP/100 - state 1 (Not in use)
[2018-11-09 09:10:06] DEBUG[27048] res_odbc.c: Reusing ODBC handle 0x7fc228003100 from class 'PT1C_asteriskcdrdb'
[2018-11-09 09:10:06] DEBUG[27108] app_queue.c: Removed SIP/100 from pending_members
[2018-11-09 09:10:06] DEBUG[27108] app_queue.c: Removed SIP/100 from pending_members
[2018-11-09 09:10:06] 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-09 09:09:58' },'"101" <101>','101','100','DLPN_DialPlan1','Queue','630,tkXx,,,,queue-set.php,',1.777465,0.000000,'ANSWERED','SIP/101-00000059','SIP/100-0000005a','1541743798.293',{ ts '2018-11-09 09:10:00' })]
[2018-11-09 09:10:06] DEBUG[27108] app_queue.c: Device 'SIP/100' changed to state '1' (Not in use)
[2018-11-09 09:10:06] 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-09 09:10:06] DEBUG[27048] res_odbc.c: Releasing ODBC handle 0x7fc228003100 into pool
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(cid) result is ''
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function ISNULL() result is '1'
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Expression result is '1'
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(src) result is '101'
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(cid) result is ''
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function IF(1?101:) result is '101'
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(dst) result is '100'
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(start) result is '2018-11-09 09:09:58'
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(end) result is '2018-11-09 09:10:00'
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(duration) result is '1'
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(billsec) result is '0'
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(disposition) result is 'ANSWERED'
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(channel) result is 'SIP/101-00000059'
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(dstchannel) result is 'SIP/100-0000005a'
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(calltype) result is ''
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(uniqueid) result is '1541743798.293'
[2018-11-09 09:10:06] 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-09 09:09:58','2018-11-09 09:10:00','1','0','ANSWERED','SIP/101-00000059','SIP/100-0000005a','','1541743798.293')
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(calltype) result is ''
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(recordfile) result is ''
[2018-11-09 09:10:06] 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-09 09:10:06] DEBUG[27048] pbx_variables.c: Evaluating 'ISNULL(${CDR(acid)})' (from 'ISNULL(${CDR(acid)})}' len 20)
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Evaluating 'CDR(acid)' (from 'CDR(acid)})' len 9)
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(acid) result is ''
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function ISNULL() result is '1'
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Expression result is '1'
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Evaluating 'CDR(clid)' (from 'CDR(clid)}:${CDR(acid)})' len 9)
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(clid) result is '"101" <101>'
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Evaluating 'CDR(acid)' (from 'CDR(acid)})' len 9)
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(acid) result is ''
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function IF(1?"101" <101>:) result is '101 <101>'
[2018-11-09 09:10:06] 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-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(dst) result is '100'
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Evaluating 'CDR(calleeid)' (from 'CDR(calleeid)}","${CDR(start)}","${CDR(accountcode)}","${CDR(billsec)}","${CDR(disposition)}"
' len 13)
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(calleeid) result is ''
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Evaluating 'CDR(start)' (from 'CDR(start)}","${CDR(accountcode)}","${CDR(billsec)}","${CDR(disposition)}"
' len 10)
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(start) result is '2018-11-09 09:10:00'
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Evaluating 'CDR(accountcode)' (from 'CDR(accountcode)}","${CDR(billsec)}","${CDR(disposition)}"
' len 16)
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(accountcode) result is ''
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Evaluating 'CDR(billsec)' (from 'CDR(billsec)}","${CDR(disposition)}"
' len 12)
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(billsec) result is '6'
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Evaluating 'CDR(disposition)' (from 'CDR(disposition)}"
' len 16)
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(disposition) result is 'ANSWERED'
[2018-11-09 09:10:06] DEBUG[27048] res_odbc.c: Reusing ODBC handle 0x7fc228003100 from class 'PT1C_asteriskcdrdb'
[2018-11-09 09:10:06] 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-09 09:10:00' },'"101" <101>','101','100','DLPN_DialPlan1','Queue','630,tkXx,,,,queue-set.php,',6.041151,6.039686,'ANSWERED','SIP/101-00000059','SIP/100-0000005a','1541743798.293',{ ts '2018-11-09 09:10:00' },{ ts '2018-11-09 09:10:06' })]
[2018-11-09 09:10:06] DEBUG[27048] res_odbc.c: Releasing ODBC handle 0x7fc228003100 into pool
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(cid) result is ''
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function ISNULL() result is '1'
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Expression result is '1'
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(src) result is '101'
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(cid) result is ''
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function IF(1?101:) result is '101'
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(dst) result is '100'
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(start) result is '2018-11-09 09:10:00'
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(end) result is '2018-11-09 09:10:06'
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(duration) result is '6'
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(billsec) result is '6'
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(disposition) result is 'ANSWERED'
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(channel) result is 'SIP/101-00000059'
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(dstchannel) result is 'SIP/100-0000005a'
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(calltype) result is ''
[2018-11-09 09:10:06] DEBUG[27048] pbx_variables.c: Function CDR(uniqueid) result is '1541743798.293'
[2018-11-09 09:10:06] 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-09 09:10:00','2018-11-09 09:10:06','6','6','ANSWERED','SIP/101-00000059','SIP/100-0000005a','','1541743798.293')
[2018-11-09 09:10:06] VERBOSE[27048] cdr.c: 0x7fc228002da0 - Beginning finalize/dispatch for SIP/100-0000005a
[2018-11-09 09:10:06] VERBOSE[27048] cdr.c: 0x7fc228002da0 - Dispatching CDR for Party A SIP/100-0000005a, Party B <none>
[2018-11-09 09:10:06] DEBUG[27048] cdr.c: CDR for SIP/100-0000005a is dialed and has no Party B; discarding
[2018-11-09 09:10:06] DEBUG[27082] chan_sip.c: = Looking for  Call ID: da9ea689f4e745e581d83e5782c1982b (Checking To) --From tag as69e185b3 --To-tag d70e2a9c31154661badcf3a9c94cef36  
[2018-11-09 09:10:06] DEBUG[27082][C-000007ba] chan_sip.c: Stopping retransmission on 'da9ea689f4e745e581d83e5782c1982b' of Request 102: Match Found
[2018-11-09 09:10:06] DEBUG[27082] chan_sip.c: Destroying SIP dialog da9ea689f4e745e581d83e5782c1982b
[2018-11-09 09:10:06] DEBUG[27082] rtp_engine.c: Destroyed RTP instance '0x7fc234362b90'
[2018-11-09 09:10:09] DEBUG[27075] res_pjsip_registrar.c: Woke up at 1541743809  Interval: 30
[2018-11-09 09:10:09] DEBUG[27075] res_pjsip_registrar.c: Expiring 0 contacts
[2018-11-09 09:10:12] DEBUG[27089] chan_iax2.c: Determining if address 127.0.0.1 with username vfax4 requires calltoken validation.  Optional = 0  calltoken_required = 3 
[2018-11-09 09:10:12] DEBUG[27089] chan_iax2.c: ip callno count incremented to 9 for 127.0.0.1
[2018-11-09 09:10:12] DEBUG[27045] devicestate.c: No provider found, checking channel drivers for IAX2 - vfax4
[2018-11-09 09:10:12] DEBUG[27045] chan_iax2.c: Checking device state for device vfax4
[2018-11-09 09:10:12] DEBUG[27045] chan_iax2.c: Found peer. What's device state of vfax4? addr=127.0.0.1:52844, defaddr=(null) maxms=2000, lastms=3
[2018-11-09 09:10:12] DEBUG[27045] devicestate.c: Changing state for IAX2/vfax4 - state 0 (Unknown)
[2018-11-09 09:10:12] DEBUG[27090] chan_iax2.c: schedule decrement of callno used for 127.0.0.1 in 60 seconds
[2018-11-09 09:10:12] DEBUG[27082] chan_sip.c: Auto destroying SIP dialog '06b618ac69c26e34490ea29e24299dd3@85.111.24.13:5060'
[2018-11-09 09:10:12] DEBUG[27082] chan_sip.c: Destroying SIP dialog 06b618ac69c26e34490ea29e24299dd3@85.111.24.13:5060
[2018-11-09 09:10:12] DEBUG[27082] rtp_engine.c: Destroyed RTP instance '0x7fc1f45924e0'
[2018-11-09 09:10:17] DEBUG[27085] chan_iax2.c: ip callno count decremented to 8 for 127.0.0.1