span style="color: goldenrod; font-weight: bold;"> 2018-12-10 13:16:26.173249 [DEBUG] sofia.c:10044 IP 117.247.91.162 Rejected by acl "default". Falling back to Digest auth.
2018-12-10 13:16:26.173249 [DEBUG] sofia.c:7084 Channel sofia/default/7661455301@fs.beconnected.co.za entering state [received][100]
2018-12-10 13:16:26.173249 [DEBUG] sofia.c:7094 Remote SDP:
v=0
o=7661455301 8001 8000 IN IP4 117.247.91.162
s=SIP Call
c=IN IP4 117.247.91.162
t=0 0
m=audio 5008 RTP/AVP 18 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
2018-12-10 13:16:26.173249 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
2018-12-10 13:16:26.173249 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
2018-12-10 13:16:26.173249 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[G729:18:8000:20:8000:1]
2018-12-10 13:16:26.173249 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [G729:18:8000:20:8000:1] ++++ is saved as a match
2018-12-10 13:16:26.173249 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 101@8000
2018-12-10 13:16:26.173249 [DEBUG] switch_core_media.c:3061 Set Codec sofia/default/7661455301@fs.beconnected.co.za G729/8000 20 ms 160 samples 8000 bits 1 channels
2018-12-10 13:16:26.173249 [DEBUG] switch_core_codec.c:111 sofia/default/7661455301@fs.beconnected.co.za Original read codec set to G729:18
2018-12-10 13:16:26.173249 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 101@8000
2018-12-10 13:16:26.173249 [DEBUG] switch_core_media.c:4767 sofia/default/7661455301@fs.beconnected.co.za Set 2833 dtmf send payload to 101 recv payload to 101
2018-12-10 13:16:26.173249 [DEBUG] sofia.c:7507 (sofia/default/7661455301@fs.beconnected.co.za) State Change CS_NEW -> CS_INIT
2018-12-10 13:16:26.173249 [DEBUG] switch_core_state_machine.c:584 (sofia/default/7661455301@fs.beconnected.co.za) Running State Change CS_INIT (Cur 2 Tot 7797)
2018-12-10 13:16:26.173249 [DEBUG] switch_core_state_machine.c:627 (sofia/default/7661455301@fs.beconnected.co.za) State INIT
2018-12-10 13:16:26.173249 [DEBUG] mod_sofia.c:90 sofia/default/7661455301@fs.beconnected.co.za SOFIA INIT
2018-12-10 13:16:26.173249 [DEBUG] switch_core_state_machine.c:40 sofia/default/7661455301@fs.beconnected.co.za Standard INIT
2018-12-10 13:16:26.173249 [DEBUG] switch_core_state_machine.c:48 (sofia/default/7661455301@fs.beconnected.co.za) State Change CS_INIT -> CS_ROUTING
2018-12-10 13:16:26.173249 [DEBUG] switch_core_state_machine.c:627 (sofia/default/7661455301@fs.beconnected.co.za) State INIT going to sleep
2018-12-10 13:16:26.173249 [DEBUG] switch_core_state_machine.c:584 (sofia/default/7661455301@fs.beconnected.co.za) Running State Change CS_ROUTING (Cur 2 Tot 7797)
2018-12-10 13:16:26.173249 [DEBUG] switch_channel.c:2249 (sofia/default/7661455301@fs.beconnected.co.za) Callstate Change DOWN -> RINGING
2018-12-10 13:16:26.173249 [DEBUG] switch_core_state_machine.c:643 (sofia/default/7661455301@fs.beconnected.co.za) State ROUTING
2018-12-10 13:16:26.173249 [DEBUG] mod_sofia.c:143 sofia/default/7661455301@fs.beconnected.co.za SOFIA ROUTING
2018-12-10 13:16:26.173249 [DEBUG] switch_core_state_machine.c:236 sofia/default/7661455301@fs.beconnected.co.za Standard ROUTING
2018-12-10 13:16:26.173249 [INFO] mod_dialplan_xml.c:637 Processing 7661455301 <7661455301>->6835959900 in context default
2018-12-10 13:16:26.173249 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7f83143cc970 Connected.
2018-12-10 13:16:26.173249 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [LOAD_CONF] Query :SELECT name,value FROM system WHERE group_title IN ('global','opensips','callingcard')
2018-12-10 13:16:26.193199 [NOTICE] switch_cpp.cpp:1365 [ASTPP] [xml_handler] Params:
'Event-Name: REQUEST_PARAMS
Core-UUID: ce67deb0-ce57-4faa-b8de-66c407c6216d
FreeSWITCH-Hostname: fs
FreeSWITCH-Switchname: fs
FreeSWITCH-IPv4: 169.255.171.130
FreeSWITCH-IPv6: %3A%3A1
Event-Date-Local: 2018-12-10%2013%3A16%3A26
Event-Date-GMT: Mon,%2010%20Dec%202018%2011%3A16%3A26%20GMT
Event-Date-Timestamp: 1544440586173249
Event-Calling-File: mod_dialplan_xml.c
Event-Calling-Function: dialplan_xml_locate
Event-Calling-Line-Number: 608
Event-Sequence: 131020
Channel-State: CS_ROUTING
Channel-Call-State: RINGING
Channel-State-Number: 2
Channel-Name: sofia/default/7661455301%40fs.beconnected.co.za
Unique-ID: ffa90ab3-4098-4b77-a0e9-662d212b2765
Call-Direction: inbound
Presence-Call-Direction: inbound
Channel-HIT-Dialplan: true
Channel-Presence-ID: 7661455301%40fs.beconnected.co.za
Channel-Call-UUID: ffa90ab3-4098-4b77-a0e9-662d212b2765
Answer-State: ringing
Channel-Read-Codec-Name: G729
Channel-Read-Codec-Rate: 8000
Channel-Read-Codec-Bit-Rate: 8000
Channel-Write-Codec-Name: G729
Channel-Write-Codec-Rate: 8000
Channel-Write-Codec-Bit-Rate: 8000
Caller-Direction: inbound
Caller-Logical-Direction: inbound
Caller-Username: 7661455301
Caller-Dialplan: XML
Caller-Caller-ID-Name: 7661455301
Caller-Caller-ID-Number: 7661455301
Caller-Orig-Caller-ID-Name: 7661455301
Caller-Orig-Caller-ID-Number: 7661455301
Caller-Network-Addr: 117.247.91.162
Caller-ANI: 7661455301
Caller-Destination-Number: 6835959900
Caller-Unique-ID: ffa90ab3-4098-4b77-a0e9-662d212b2765
Caller-Source: mod_sofia
Caller-Context: default
Caller-Channel-Name: sofia/default/7661455301%40fs.beconnected.co.za
Caller-Profile-Index: 1
Caller-Profile-Created-Time: 1544440586173249
Caller-Channel-Created-Time: 1544440586173249
Caller-Channel-Answered-Time: 0
Caller-Channel-Progress-Time: 0
Caller-Channel-Progress-Media-Time: 0
Caller-Channel-Hangup-Time: 0
Caller-Channel-Transfer-Time: 0
Caller-Channel-Resurrect-Time: 0
Caller-Channel-Bridged-Time: 0
Caller-Channel-Last-Hold: 0
Caller-Channel-Hold-Accum: 0
Caller-Screen-Bit: true
Caller-Privacy-Hide-Name: false
Caller-Privacy-Hide-Number: false
variable_direction: inbound
variable_uuid: ffa90ab3-4098-4b77-a0e9-662d212b2765
variable_session_id: 7796
variable_sip_from_user: 7661455301
variable_sip_from_uri: 7661455301%40fs.beconnected.co.za
variable_sip_from_host: fs.beconnected.co.za
variable_video_media_flow: sendrecv
variable_channel_name: sofia/default/7661455301%40fs.beconnected.co.za
variable_sip_call_id: 1673991354-27987-24%40BJC.BGI.B.BGB
variable_ep_codec_string: mod_bcg729.G729%408000h%4020i%408000b
variable_sip_local_network_addr: 169.255.171.130
variable_sip_network_ip: 117.247.91.162
variable_sip_network_port: 27987
variable_sip_invite_stamp: 1544440586173249
variable_sip_received_ip: 117.247.91.162
variable_sip_received_port: 27987
variable_sip_via_protocol: udp
variable_sip_authorized: true
variable_Event-Name: REQUEST_PARAMS
variable_Core-UUID: ce67deb0-ce57-4faa-b8de-66c407c6216d
variable_FreeSWITCH-Hostname: fs
variable_FreeSWITCH-Switchname: fs
variable_FreeSWITCH-IPv4: 169.255.171.130
variable_FreeSWITCH-IPv6: %3A%3A1
variable_Event-Date-Local: 2018-12-10%2013%3A16%3A26
variable_Event-Date-GMT: Mon,%2010%20Dec%202018%2011%3A16%3A26%20GMT
variable_Event-Date-Timestamp: 1544440586173249
variable_Event-Calling-File: sofia.c
variable_Event-Calling-Function: sofia_handle_sip_i_invite
variable_Event-Calling-Line-Number: 10096
variable_Event-Sequence: 131011
variable_sip_number_alias: 7661455301
variable_sip_auth_username: 7661455301
variable_sip_auth_realm: fs.beconnected.co.za
variable_number_alias: 7661455301
variable_requested_user_name: 7661455301
variable_requested_domain_name: fs.beconnected.co.za
variable_effective_caller_id_name: 7661455301
variable_effective_caller_id_number: 12334556
variable_sipcall: true
variable_accountcode: 6835959900
variable_user_name: 7661455301
variable_domain_name: fs.beconnected.co.za
variable_sip_from_user_stripped: 7661455301
variable_sip_from_tag: 156202635
variable_sofia_profile_name: default
variable_recovery_profile_name: default
variable_sip_P-Preferred-Identity: %227661455301%22%20%3Csip%3A7661455301%40fs.beconnected.co.za%3E
variable_sip_cid_type: pid
variable_sip_full_via: SIP/2.0/UDP%20117.247.91.162%3A27987%3Bbranch%3Dz9hG4bK932791135%3Brport%3D27987
variable_sip_from_display: 7661455301
variable_sip_full_from: %227661455301%22%20%3Csip%3A7661455301%40fs.beconnected.co.za%3E%3Btag%3D156202635
variable_sip_full_to: %3Csip%3A6835959900%40fs.beconnected.co.za%3E
variable_sip_allow: INVITE,%20ACK,%20OPTIONS,%20CANCEL,%20BYE,%20SUBSCRIBE,%20NOTIFY,%20INFO,%20REFER,%20UPDATE,%20MESSAGE
variable_sip_req_user: 6835959900
variable_sip_req_uri: 6835959900%40fs.beconnected.co.za
variable_sip_req_host: fs.beconnected.co.za
variable_sip_to_user: 6835959900
variable_sip_to_uri: 6835959900%40fs.beconnected.co.za
variable_sip_to_host: fs.beconnected.co.za
variable_sip_contact_user: 7661455301
variable_sip_contact_port: 27987
variable_sip_contact_uri: 7661455301%40117.247.91.162%3A27987
variable_sip_contact_host: 117.247.91.162
variable_sip_user_agent: Grandstream%20GXP1620%201.0.0.38
variable_sip_via_host: 117.247.91.162
variable_sip_via_port: 27987
variable_sip_via_rport: 27987
variable_max_forwards: 70
variable_presence_id: 7661455301%40fs.beconnected.co.za
variable_sip_Privacy: none
variable_switch_r_sdp: v%3D0%0D%0Ao%3D7661455301%208001%208000%20IN%20IP4%20117.247.91.162%0D%0As%3DSIP%20Call%0D%0Ac%3DIN%20IP4%20117.247.91.162%0D%0At%3D0%200%0D%0Am%3Daudio%205008%20RTP/AVP%2018%20101%0D%0Aa%3Drtpmap%3A18%20G729/8000%0D%0Aa%3Dfmtp%3A18%20annexb%3Dno%0D%0Aa%3Drtpmap%3A101%20telephone-event/8000%0D%0Aa%3Dfmtp%3A101%200-15%0D%0Aa%3Dptime%3A20%0D%0A
variable_rtp_use_codec_string: PCMA,PCMU,G729
variable_audio_media_flow: sendrecv
variable_remote_media_ip: 117.247.91.162
variable_remote_media_port: 5008
variable_rtp_audio_recv_pt: 18
variable_rtp_use_codec_name: G729
variable_rtp_use_codec_fmtp: annexb%3Dno
variable_rtp_use_codec_rate: 8000
variable_rtp_use_codec_ptime: 20
variable_rtp_use_codec_channels: 1
variable_rtp_last_audio_codec_string: G729%408000h%4020i%401c
variable_read_codec: G729
variable_original_read_codec: G729
variable_read_rate: 8000
variable_original_read_rate: 8000
variable_write_codec: G729
variable_write_rate: 8000
variable_dtmf_type: rfc2833
variable_endpoint_disposition: RECEIVED
variable_call_uuid: ffa90ab3-4098-4b77-a0e9-662d212b2765
Hunt-Direction: inbound
Hunt-Logical-Direction: inbound
Hunt-Username: 7661455301
Hunt-Dialplan: XML
Hunt-Caller-ID-Name: 7661455301
Hunt-Caller-ID-Number: 7661455301
Hunt-Orig-Caller-ID-Name: 7661455301
Hunt-Orig-Caller-ID-Number: 7661455301
Hunt-Network-Addr: 117.247.91.162
Hunt-ANI: 7661455301
Hunt-Destination-Number: 6835959900
Hunt-Unique-ID: ffa90ab3-4098-4b77-a0e9-662d212b2765
Hunt-Source: mod_sofia
Hunt-Context: default
Hunt-Channel-Name: sofia/default/7661455301%40fs.beconnected.co.za
Hunt-Profile-Index: 1
Hunt-Profile-Created-Time: 1544440586173249
Hunt-Channel-Created-Time: 1544440586173249
Hunt-Channel-Answered-Time: 0
Hunt-Channel-Progress-Time: 0
Hunt-Channel-Progress-Media-Time: 0
Hunt-Channel-Hangup-Time: 0
Hunt-Channel-Transfer-Time: 0
Hunt-Channel-Resurrect-Time: 0
Hunt-Channel-Bridged-Time: 0
Hunt-Channel-Last-Hold: 0
Hunt-Channel-Hold-Accum: 0
Hunt-Screen-Bit: true
Hunt-Privacy-Hide-Name: false
Hunt-Privacy-Hide-Number: false
'
2018-12-10 13:16:26.193199 [INFO] switch_cpp.cpp:1365 [ASTPP] [xml_REQUEST] section: dialplan
2018-12-10 13:16:26.193199 [INFO] switch_cpp.cpp:1365 [ASTPP] [xml_REQUEST] tag_name:
2018-12-10 13:16:26.193199 [INFO] switch_cpp.cpp:1365 [ASTPP] [xml_REQUEST] key_value:
2018-12-10 13:16:26.193199 [INFO] switch_cpp.cpp:1365 [ASTPP] [xml_REQUEST] key_name:
2018-12-10 13:16:26.193199 [INFO] switch_cpp.cpp:1365 [ASTPP] [Dialplan] Dialed number : 6835959900
2018-12-10 13:16:26.193199 [WARNING] switch_cpp.cpp:1365 [ASTPP] [FAXER] in custom Caller ID
2018-12-10 13:16:26.193199 [INFO] switch_cpp.cpp:1365 [ASTPP] [Dialplan] Caller Id name / number : 7661455301 / 12334556
2018-12-10 13:16:26.193199 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [CHECK_DID] Query :SELECT A.id as id,B.id as accountid,B.number as account_code,B.did_cid_translation as did_cid_translation,A.number as did_number,A.connectcost,A.includedseconds,A.cost,A.inc,A.extensions,A.maxchannels,A.call_type,A.city,A.province,A.init_inc,A.leg_timeout FROM dids AS A,accounts AS B WHERE A.status=0 AND B.status=0 AND B.deleted=0 AND B.id=A.accountid AND A.number ="6835959900" LIMIT 1
2018-12-10 13:16:26.193199 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [CHECK_LOCAL_CALL] Query :SELECT sip_devices.id as sip_id,sip_devices.username as username,accounts.number as accountcode,sip_devices.accountid as accountid,accounts.did_cid_translation as did_cid_translation FROM sip_devices as sip_devices,accounts as accounts WHERE accounts.status=0 AND accounts.deleted=0 AND accounts.id=sip_devices.accountid AND sip_devices.username="6835959900" limit 1
2018-12-10 13:16:26.193199 [INFO] switch_cpp.cpp:1365 [ASTPP] [Dialplan] Call direction : local
2018-12-10 13:16:26.193199 [NOTICE] switch_cpp.cpp:1365 [ASTPP] [Accountcode : 6835959900]
2018-12-10 13:16:26.193199 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_PRICELIST_ROUTING_INFO] Query :select id,routing_prefix,pricelist_id_admin from pricelists WHERE (routing_prefix = '6835959900' OR routing_prefix = '683595990' OR routing_prefix = '68359599' OR routing_prefix = '6835959' OR routing_prefix = '683595' OR routing_prefix = '68359' OR routing_prefix = '6835' OR routing_prefix = '683' OR routing_prefix = '68' OR routing_prefix = '6' OR routing_prefix ='--') AND status = 0 limit 1
2018-12-10 13:16:26.193199 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [DOAUTHORIZATION] Query :SELECT * FROM accounts WHERE (number = "6835959900" OR id="6835959900") AND status=0 AND deleted=0 AND (expiry >= '2018-12-10 11:16:26' OR expiry = '0000-00-00 00:00:00') limit 1
2018-12-10 13:16:26.193199 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_CALLERID_NUMBER] CALLERID :12334556
2018-12-10 13:16:26.193199 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_CUSTOMER_ID] USERID :63
2018-12-10 13:16:26.193199 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_CIDPOOL] CIDPOOL :0
2018-12-10 13:16:26.193199 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_PACKAGE_INFO] Query :SELECT * FROM packages as P inner join package_patterns as PKGPTR on P.id = PKGPTR.package_id WHERE (patterns = '^6835959900.*' OR patterns = '^683595990.*' OR patterns = '^68359599.*' OR patterns = '^6835959.*' OR patterns = '^683595.*' OR patterns = '^68359.*' OR patterns = '^6835.*' OR patterns = '^683.*' OR patterns = '^68.*' OR patterns = '^6.*' OR patterns ='--') AND status = 0 AND pricelist_id = 1 ORDER BY LENGTH(PKGPTR.patterns) DESC LIMIT 1
2018-12-10 13:16:26.213193 [INFO] switch_cpp.cpp:1365 [ASTPP] =============== Account Information ===================
2018-12-10 13:16:26.213193 [INFO] switch_cpp.cpp:1365 [ASTPP] User id : 63
2018-12-10 13:16:26.213193 [INFO] switch_cpp.cpp:1365 [ASTPP] Account code : 6835959900
2018-12-10 13:16:26.213193 [INFO] switch_cpp.cpp:1365 [ASTPP] Type : 0 [0:prepaid,1:postpaid]
2018-12-10 13:16:26.213193 [INFO] switch_cpp.cpp:1365 [ASTPP] Ratecard id : 1
2018-12-10 13:16:26.213193 [INFO] switch_cpp.cpp:1365 [ASTPP] ========================================================
2018-12-10 13:16:26.213193 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_PRICELIST_INFO] Query :select * from pricelists WHERE id = 1 AND status = 0
2018-12-10 13:16:26.213193 [INFO] switch_cpp.cpp:1365 [ASTPP] [FIND_MAXLENGTH] Call is free - assigning max length!!! :: 100
2018-12-10 13:16:26.213193 [INFO] switch_cpp.cpp:1365 [ASTPP] Call Max length duration : 100 minutes
2018-12-10 13:16:26.213193 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [CHECK_LOCAL_CALL] Query :SELECT sip_devices.id as sip_id,sip_devices.username as username,accounts.number as accountcode,sip_devices.accountid as accountid,accounts.did_cid_translation as did_cid_translation FROM sip_devices as sip_devices,accounts as accounts WHERE accounts.status=0 AND accounts.deleted=0 AND accounts.id=sip_devices.accountid AND sip_devices.username="6835959900" limit 1
2018-12-10 13:16:26.213193 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [Functions] [GET_queue_INFO] Query :SELECT id,destination_number,agent_hold_file from pbx_queue WHERE destination_number = 6835959900 and status=0 LIMIT 1
2018-12-10 13:16:26.213193 [WARNING] switch_cpp.cpp:1365 [ASTPP] [fifo_agent_flag] fifo_agent_flag0
2018-12-10 13:16:26.213193 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET multidomain] Query :SELECT * FROM multidomain WHERE accountid = 63
2018-12-10 13:16:26.213193 [WARNING] switch_cpp.cpp:1365 [ASTPP] [user_domain] user_domainfs.beconnected.co.za
2018-12-10 13:16:26.213193 [WARNING] switch_cpp.cpp:1365 [ASTPP] [FSXMLLOCAL] Caller ID Translation Starts
2018-12-10 13:16:26.213193 [WARNING] switch_cpp.cpp:1365 [ASTPP] [FSXMLLOCAL] Caller ID Translation Ends
2018-12-10 13:16:26.213193 [INFO] switch_cpp.cpp:1365 [ASTPP] [PBX_SIP_ROUTING] SIP ID : 127
2018-12-10 13:16:26.213193 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [PBX_SIP_ROUTING] [GET_ROUTING_INFO] Query :SELECT * from sip_device_routing WHERE sip_device_id = 127 limit 1
2018-12-10 13:16:26.213193 [INFO] switch_cpp.cpp:1365 [ASTPP] [PBX_SIP_ROUTING] SIP Call forwarding Disable
2018-12-10 13:16:26.213193 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [Dialplan] Generated XML:
<?xml version="1.0" encoding="UTF-8" standalone="no"?>
<document type="freeswitch/xml">
<section name="dialplan" description="ASTPP Dialplan">
<context name="default">
<extension name="6835959900">
<condition field="destination_number" expression="6835959900">
<action application="set" data="effective_destination_number=6835959900"/>
<action application="sched_hangup" data="+6000 normal_clearing"/>
<action application="set" data="callstart=2018-12-10 11:16:26"/>
<action application="set" data="hangup_after_bridge=true"/>
<action application="set" data="continue_on_fail=TRUE"/>
<action application="set" data="account_id=63"/>
<action application="set" data="parent_id=0"/>
<action application="set" data="entity_id=0"/>
<action application="set" data="call_processed=internal"/>
<action application="set" data="call_direction=local"/>
<action application="set" data="accountname=default"/>
<action application="set" data="origination_rates=ID:0|CODE:6835959900|DESTINATION:Local|CONNECTIONCOST:0|INCLUDEDSECONDS:0|COST:0|INC:60|INITIALBLOCK:0|RATEGROUP:1|MARKUP:0|ACCID:63"/>
<action application="set" data="original_caller_id_name=7661455301"/>
<action application="set" data="original_caller_id_number=12334556"/>
<action application="set" data="effective_caller_id_name=7661455301"/>
<action application="set" data="effective_caller_id_number=12334556"/>
<action application="set" data="calltype=LOCAL"/>
<action application="set" data="receiver_accid=63"/>
<action application="bridge" data="[leg_timeout=30]user/6835959900@fs.beconnected.co.za"/>
<condition field="${cond(${user_data 6835959900@${domain_name} param vm-enabled} == true ? YES : NO)}" expression="^YES$">
<action application="answer"/>
<action application="export" data="voicemail_alternate_greet_id=6835959900"/>
<action application="voicemail" data="default $${domain_name} 6835959900"/>
<anti-action application="hangup" data="${originate_disposition}"/>
</condition>
</condition>
</extension>
</context>
</section>
</document>
2018-12-10 13:16:26.213193 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7f83143cc970 released.
Dialplan: sofia/default/7661455301@fs.beconnected.co.za parsing [default->6835959900] continue=false
Dialplan: sofia/default/7661455301@fs.beconnected.co.za Regex (PASS) [6835959900] destination_number(6835959900) =~ /6835959900/ break=on-false
Dialplan: sofia/default/7661455301@fs.beconnected.co.za Action set(effective_destination_number=6835959900)
Dialplan: sofia/default/7661455301@fs.beconnected.co.za Action sched_hangup(+6000 normal_clearing)
Dialplan: sofia/default/7661455301@fs.beconnected.co.za Action set(callstart=2018-12-10 11:16:26)
Dialplan: sofia/default/7661455301@fs.beconnected.co.za Action set(hangup_after_bridge=true)
Dialplan: sofia/default/7661455301@fs.beconnected.co.za Action set(continue_on_fail=TRUE)
Dialplan: sofia/default/7661455301@fs.beconnected.co.za Action set(account_id=63)
Dialplan: sofia/default/7661455301@fs.beconnected.co.za Action set(parent_id=0)
Dialplan: sofia/default/7661455301@fs.beconnected.co.za Action set(entity_id=0)
Dialplan: sofia/default/7661455301@fs.beconnected.co.za Action set(call_processed=internal)
Dialplan: sofia/default/7661455301@fs.beconnected.co.za Action set(call_direction=local)
Dialplan: sofia/default/7661455301@fs.beconnected.co.za Action set(accountname=default)
Dialplan: sofia/default/7661455301@fs.beconnected.co.za Action set(origination_rates=ID:0|CODE:6835959900|DESTINATION:Local|CONNECTIONCOST:0|INCLUDEDSECONDS:0|COST:0|INC:60|INITIALBLOCK:0|RATEGROUP:1|MARKUP:0|ACCID:63)
Dialplan: sofia/default/7661455301@fs.beconnected.co.za Action set(original_caller_id_name=7661455301)
Dialplan: sofia/default/7661455301@fs.beconnected.co.za Action set(original_caller_id_number=12334556)
Dialplan: sofia/default/7661455301@fs.beconnected.co.za Action set(effective_caller_id_name=7661455301)
Dialplan: sofia/default/7661455301@fs.beconnected.co.za Action set(effective_caller_id_number=12334556)
Dialplan: sofia/default/7661455301@fs.beconnected.co.za Action set(calltype=LOCAL)
Dialplan: sofia/default/7661455301@fs.beconnected.co.za Action set(receiver_accid=63)
Dialplan: sofia/default/7661455301@fs.beconnected.co.za Action bridge([leg_timeout=30]user/6835959900@fs.beconnected.co.za)
|--- Dialplan: Processing recursive conditions level:1 [6835959900_recur_1] require-nested=TRUE
|--- Dialplan: sofia/default/7661455301@fs.beconnected.co.za Regex (PASS) [6835959900_recur_1] ${cond(${user_data 6835959900@${domain_name} param vm-enabled} == true ? YES : NO)}(YES) =~ /^YES$/ break=on-false
|--- Dialplan: sofia/default/7661455301@fs.beconnected.co.za Action answer()
|--- Dialplan: sofia/default/7661455301@fs.beconnected.co.za Action export(voicemail_alternate_greet_id=6835959900)
|--- Dialplan: sofia/default/7661455301@fs.beconnected.co.za Action voicemail(default $${domain_name} 6835959900)
2018-12-10 13:16:26.213193 [DEBUG] switch_core_state_machine.c:286 (sofia/default/7661455301@fs.beconnected.co.za) State Change CS_ROUTING -> CS_EXECUTE
2018-12-10 13:16:26.213193 [DEBUG] switch_core_state_machine.c:643 (sofia/default/7661455301@fs.beconnected.co.za) State ROUTING going to sleep
2018-12-10 13:16:26.213193 [DEBUG] switch_core_state_machine.c:584 (sofia/default/7661455301@fs.beconnected.co.za) Running State Change CS_EXECUTE (Cur 2 Tot 7797)
2018-12-10 13:16:26.213193 [DEBUG] switch_core_state_machine.c:650 (sofia/default/7661455301@fs.beconnected.co.za) State EXECUTE
2018-12-10 13:16:26.213193 [DEBUG] mod_sofia.c:198 sofia/default/7661455301@fs.beconnected.co.za SOFIA EXECUTE
2018-12-10 13:16:26.213193 [DEBUG] switch_core_state_machine.c:328 sofia/default/7661455301@fs.beconnected.co.za Standard EXECUTE
EXECUTE sofia/default/7661455301@fs.beconnected.co.za set(effective_destination_number=6835959900)
2018-12-10 13:16:26.213193 [DEBUG] mod_dptools.c:1548 SET sofia/default/7661455301@fs.beconnected.co.za [effective_destination_number]=[6835959900]
EXECUTE sofia/default/7661455301@fs.beconnected.co.za sched_hangup(+6000 normal_clearing)
2018-12-10 13:16:26.213193 [DEBUG] switch_scheduler.c:249 Added task 158 switch_ivr_schedule_hangup (ffa90ab3-4098-4b77-a0e9-662d212b2765) to run at 1544446586
EXECUTE sofia/default/7661455301@fs.beconnected.co.za set(callstart=2018-12-10 11:16:26)
2018-12-10 13:16:26.213193 [DEBUG] mod_dptools.c:1548 SET sofia/default/7661455301@fs.beconnected.co.za [callstart]=[2018-12-10 11:16:26]
EXECUTE sofia/default/7661455301@fs.beconnected.co.za set(hangup_after_bridge=true)
2018-12-10 13:16:26.213193 [DEBUG] mod_dptools.c:1548 SET sofia/default/7661455301@fs.beconnected.co.za [hangup_after_bridge]=[true]
EXECUTE sofia/default/7661455301@fs.beconnected.co.za set(continue_on_fail=TRUE)
2018-12-10 13:16:26.213193 [DEBUG] mod_dptools.c:1548 SET sofia/default/7661455301@fs.beconnected.co.za [continue_on_fail]=[TRUE]
EXECUTE sofia/default/7661455301@fs.beconnected.co.za set(account_id=63)
2018-12-10 13:16:26.213193 [DEBUG] mod_dptools.c:1548 SET sofia/default/7661455301@fs.beconnected.co.za [account_id]=[63]
EXECUTE sofia/default/7661455301@fs.beconnected.co.za set(parent_id=0)
2018-12-10 13:16:26.213193 [DEBUG] mod_dptools.c:1548 SET sofia/default/7661455301@fs.beconnected.co.za [parent_id]=[0]
EXECUTE sofia/default/7661455301@fs.beconnected.co.za set(entity_id=0)
2018-12-10 13:16:26.213193 [DEBUG] mod_dptools.c:1548 SET sofia/default/7661455301@fs.beconnected.co.za [entity_id]=[0]
EXECUTE sofia/default/7661455301@fs.beconnected.co.za set(call_processed=internal)
2018-12-10 13:16:26.213193 [DEBUG] mod_dptools.c:1548 SET sofia/default/7661455301@fs.beconnected.co.za [call_processed]=[internal]
EXECUTE sofia/default/7661455301@fs.beconnected.co.za set(call_direction=local)
2018-12-10 13:16:26.213193 [DEBUG] mod_dptools.c:1548 SET sofia/default/7661455301@fs.beconnected.co.za [call_direction]=[local]
EXECUTE sofia/default/7661455301@fs.beconnected.co.za set(accountname=default)
2018-12-10 13:16:26.213193 [DEBUG] mod_dptools.c:1548 SET sofia/default/7661455301@fs.beconnected.co.za [accountname]=[default]
EXECUTE sofia/default/7661455301@fs.beconnected.co.za set(origination_rates=ID:0|CODE:6835959900|DESTINATION:Local|CONNECTIONCOST:0|INCLUDEDSECONDS:0|COST:0|INC:60|INITIALBLOCK:0|RATEGROUP:1|MARKUP:0|ACCID:63)
2018-12-10 13:16:26.213193 [DEBUG] mod_dptools.c:1548 SET sofia/default/7661455301@fs.beconnected.co.za [origination_rates]=[ID:0|CODE:6835959900|DESTINATION:Local|CONNECTIONCOST:0|INCLUDEDSECONDS:0|COST:0|INC:60|INITIALBLOCK:0|RATEGROUP:1|MARKUP:0|ACCID:63]
EXECUTE sofia/default/7661455301@fs.beconnected.co.za set(original_caller_id_name=7661455301)
2018-12-10 13:16:26.213193 [DEBUG] mod_dptools.c:1548 SET sofia/default/7661455301@fs.beconnected.co.za [original_caller_id_name]=[7661455301]
EXECUTE sofia/default/7661455301@fs.beconnected.co.za set(original_caller_id_number=12334556)
2018-12-10 13:16:26.213193 [DEBUG] mod_dptools.c:1548 SET sofia/default/7661455301@fs.beconnected.co.za [original_caller_id_number]=[12334556]
EXECUTE sofia/default/7661455301@fs.beconnected.co.za set(effective_caller_id_name=7661455301)
2018-12-10 13:16:26.213193 [DEBUG] mod_dptools.c:1548 SET sofia/default/7661455301@fs.beconnected.co.za [effective_caller_id_name]=[7661455301]
EXECUTE sofia/default/7661455301@fs.beconnected.co.za set(effective_caller_id_number=12334556)
2018-12-10 13:16:26.213193 [DEBUG] mod_dptools.c:1548 SET sofia/default/7661455301@fs.beconnected.co.za [effective_caller_id_number]=[12334556]
EXECUTE sofia/default/7661455301@fs.beconnected.co.za set(calltype=LOCAL)
2018-12-10 13:16:26.213193 [DEBUG] mod_dptools.c:1548 SET sofia/default/7661455301@fs.beconnected.co.za [calltype]=[LOCAL]
EXECUTE sofia/default/7661455301@fs.beconnected.co.za set(receiver_accid=63)
2018-12-10 13:16:26.213193 [DEBUG] mod_dptools.c:1548 SET sofia/default/7661455301@fs.beconnected.co.za [receiver_accid]=[63]
EXECUTE sofia/default/7661455301@fs.beconnected.co.za bridge([leg_timeout=30]user/6835959900@fs.beconnected.co.za)
2018-12-10 13:16:26.213193 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
2018-12-10 13:16:26.213193 [DEBUG] switch_ivr_originate.c:2669 Parsing session specific variables
2018-12-10 13:16:26.233192 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
2018-12-10 13:16:26.233192 [NOTICE] switch_channel.c:1104 New Channel sofia/default/6835959900@117.247.91.162:5060 [806f29a9-ef75-424a-bb7a-e8cb4155ffa0]
2018-12-10 13:16:26.233192 [DEBUG] mod_sofia.c:4819 (sofia/default/6835959900@117.247.91.162:5060) State Change CS_NEW -> CS_INIT
2018-12-10 13:16:26.233192 [DEBUG] switch_ivr_originate.c:2963 sofia/default/6835959900@117.247.91.162:5060 Setting leg timeout to 30
2018-12-10 13:16:26.233192 [DEBUG] switch_core_state_machine.c:584 (sofia/default/6835959900@117.247.91.162:5060) Running State Change CS_INIT (Cur 3 Tot 7798)
2018-12-10 13:16:26.233192 [DEBUG] switch_core_state_machine.c:627 (sofia/default/6835959900@117.247.91.162:5060) State INIT
2018-12-10 13:16:26.233192 [DEBUG] mod_sofia.c:90 sofia/default/6835959900@117.247.91.162:5060 SOFIA INIT
2018-12-10 13:16:26.233192 [DEBUG] sofia_glue.c:1295 sofia/default/6835959900@117.247.91.162:5060 sending invite version: 1.6.19 git 7a77e0b 2017-07-13 12:01:45Z 64bit
Local SDP:
v=0
o=FreeSWITCH 1544429808 1544429809 IN IP4 169.255.171.130
s=FreeSWITCH
c=IN IP4 169.255.171.130
t=0 0
m=audio 10778 RTP/AVP 18 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
2018-12-10 13:16:26.233192 [DEBUG] switch_core_state_machine.c:40 sofia/default/6835959900@117.247.91.162:5060 Standard INIT
2018-12-10 13:16:26.233192 [DEBUG] switch_core_state_machine.c:48 (sofia/default/6835959900@117.247.91.162:5060) State Change CS_INIT -> CS_ROUTING
2018-12-10 13:16:26.233192 [DEBUG] switch_core_state_machine.c:627 (sofia/default/6835959900@117.247.91.162:5060) State INIT going to sleep
2018-12-10 13:16:26.233192 [DEBUG] switch_core_state_machine.c:584 (sofia/default/6835959900@117.247.91.162:5060) Running State Change CS_ROUTING (Cur 3 Tot 7798)
2018-12-10 13:16:26.233192 [DEBUG] sofia.c:7084 Channel sofia/default/6835959900@117.247.91.162:5060 entering state [calling][0]
2018-12-10 13:16:26.233192 [DEBUG] switch_core_state_machine.c:643 (sofia/default/6835959900@117.247.91.162:5060) State ROUTING
2018-12-10 13:16:26.233192 [DEBUG] mod_sofia.c:143 sofia/default/6835959900@117.247.91.162:5060 SOFIA ROUTING
2018-12-10 13:16:26.233192 [DEBUG] switch_ivr_originate.c:67 (sofia/default/6835959900@117.247.91.162:5060) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2018-12-10 13:16:26.233192 [DEBUG] switch_core_state_machine.c:643 (sofia/default/6835959900@117.247.91.162:5060) State ROUTING going to sleep
2018-12-10 13:16:26.233192 [DEBUG] switch_core_state_machine.c:584 (sofia/default/6835959900@117.247.91.162:5060) Running State Change CS_CONSUME_MEDIA (Cur 3 Tot 7798)
2018-12-10 13:16:26.233192 [DEBUG] switch_core_state_machine.c:662 (sofia/default/6835959900@117.247.91.162:5060) State CONSUME_MEDIA
2018-12-10 13:16:26.233192 [DEBUG] switch_core_state_machine.c:662 (sofia/default/6835959900@117.247.91.162:5060) State CONSUME_MEDIA going to sleep
2018-12-10 13:16:26.873246 [DEBUG] sofia.c:7084 Channel sofia/default/6835959900@117.247.91.162:5060 entering state [proceeding][180]
2018-12-10 13:16:26.873246 [NOTICE] sofia.c:7192 Ring-Ready sofia/default/6835959900@117.247.91.162:5060!
2018-12-10 13:16:26.873246 [DEBUG] switch_channel.c:3346 (sofia/default/6835959900@117.247.91.162:5060) Callstate Change DOWN -> RINGING
2018-12-10 13:16:26.893191 [NOTICE] mod_sofia.c:2273 Ring-Ready sofia/default/7661455301@fs.beconnected.co.za!
2018-12-10 13:16:26.893191 [DEBUG] sofia.c:7084 Channel sofia/default/7661455301@fs.beconnected.co.za entering state [early][180]
2018-12-10 13:16:26.893191 [NOTICE] switch_ivr_originate.c:525 Ring Ready sofia/default/7661455301@fs.beconnected.co.za!
2018-12-10 13:16:28.253249 [NOTICE] switch_channel.c:1104 New Channel sofia/default/5081@169.255.171.130 [1534e618-fd5f-4149-92b0-265d35812406]
2018-12-10 13:16:28.253249 [DEBUG] switch_core_state_machine.c:584 (sofia/default/5081@169.255.171.130) Running State Change CS_NEW (Cur 4 Tot 7799)
2018-12-10 13:16:28.253249 [DEBUG] sofia.c:9873 sofia/default/5081@169.255.171.130 receiving invite from 37.49.231.120:62181 version: 1.6.19 git 7a77e0b 2017-07-13 12:01:45Z 64bit
2018-12-10 13:16:28.253249 [DEBUG] sofia.c:10044 IP 37.49.231.120 Rejected by acl "default". Falling back to Digest auth.
2018-12-10 13:16:28.253249 [DEBUG] sofia.c:2334 detaching session 1534e618-fd5f-4149-92b0-265d35812406
2018-12-10 13:16:28.253249 [WARNING] sofia_reg.c:1792 SIP auth challenge (INVITE) on sofia profile 'default' for [0048221284837@169.255.171.130] from ip 37.49.231.120
2018-12-10 13:16:28.253249 [DEBUG] switch_core_state_machine.c:603 (sofia/default/5081@169.255.171.130) State NEW
2018-12-10 13:16:28.493218 [DEBUG] sofia.c:7084 Channel sofia/default/6835959900@117.247.91.162:5060 entering state [completing][200]
2018-12-10 13:16:28.493218 [DEBUG] sofia.c:7094 Remote SDP:
v=0
o=root 1509274545 1509274545 IN IP4 117.247.91.162
s=Asterisk PBX 1.6.2.13
c=IN IP4 117.247.91.162
t=0 0
m=audio 10002 RTP/AVP 18 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
2018-12-10 13:16:28.513263 [DEBUG] sofia.c:7084 Channel sofia/default/6835959900@117.247.91.162:5060 entering state [ready][200]
2018-12-10 13:16:28.513263 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[G729:18:8000:20:8000:1]
2018-12-10 13:16:28.513263 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [G729:18:8000:20:8000:1] ++++ is saved as a match
2018-12-10 13:16:28.513263 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 101@8000
2018-12-10 13:16:28.513263 [DEBUG] switch_core_media.c:3061 Set Codec sofia/default/6835959900@117.247.91.162:5060 G729/8000 20 ms 160 samples 8000 bits 1 channels
2018-12-10 13:16:28.513263 [DEBUG] switch_core_codec.c:111 sofia/default/6835959900@117.247.91.162:5060 Original read codec set to G729:18
2018-12-10 13:16:28.513263 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 101@8000
2018-12-10 13:16:28.513263 [DEBUG] switch_core_media.c:4767 sofia/default/6835959900@117.247.91.162:5060 Set 2833 dtmf send payload to 101 recv payload to 101
2018-12-10 13:16:28.513263 [DEBUG] switch_core_media.c:6878 AUDIO RTP [sofia/default/6835959900@117.247.91.162:5060] 169.255.171.130 port 10778 -> 117.247.91.162 port 10002 codec: 18 ms: 20
2018-12-10 13:16:28.513263 [DEBUG] switch_rtp.c:4111 Starting timer [soft] 160 bytes per 20ms
2018-12-10 13:16:28.513263 [DEBUG] switch_core_media.c:7179 sofia/default/6835959900@117.247.91.162:5060 Set 2833 dtmf send payload to 101
2018-12-10 13:16:28.513263 [DEBUG] switch_core_media.c:7186 sofia/default/6835959900@117.247.91.162:5060 Set 2833 dtmf receive payload to 101
2018-12-10 13:16:28.513263 [DEBUG] switch_core_media.c:7209 sofia/default/6835959900@117.247.91.162:5060 Set rtp dtmf delay to 40
2018-12-10 13:16:28.513263 [NOTICE] sofia.c:8218 Channel [sofia/default/6835959900@117.247.91.162:5060] has been answered
2018-12-10 13:16:28.513263 [DEBUG] switch_channel.c:3773 (sofia/default/6835959900@117.247.91.162:5060) Callstate Change RINGING -> ACTIVE
2018-12-10 13:16:28.533213 [DEBUG] switch_core_media.c:6878 AUDIO RTP [sofia/default/7661455301@fs.beconnected.co.za] 169.255.171.130 port 18968 -> 117.247.91.162 port 5008 codec: 18 ms: 20
2018-12-10 13:16:28.533213 [DEBUG] switch_rtp.c:4111 Starting timer [soft] 160 bytes per 20ms
2018-12-10 13:16:28.533213 [DEBUG] switch_core_media.c:7179 sofia/default/7661455301@fs.beconnected.co.za Set 2833 dtmf send payload to 101
2018-12-10 13:16:28.533213 [DEBUG] switch_core_media.c:7186 sofia/default/7661455301@fs.beconnected.co.za Set 2833 dtmf receive payload to 101
2018-12-10 13:16:28.533213 [DEBUG] switch_core_media.c:7209 sofia/default/7661455301@fs.beconnected.co.za Set rtp dtmf delay to 40
2018-12-10 13:16:28.533213 [DEBUG] mod_sofia.c:850 Local SDP sofia/default/7661455301@fs.beconnected.co.za:
v=0
o=FreeSWITCH 1544421620 1544421621 IN IP4 169.255.171.130
s=FreeSWITCH
c=IN IP4 169.255.171.130
t=0 0
m=audio 18968 RTP/AVP 18 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
2018-12-10 13:16:28.533213 [DEBUG] sofia.c:7084 Channel sofia/default/7661455301@fs.beconnected.co.za entering state [completed][200]
2018-12-10 13:16:28.533213 [NOTICE] switch_ivr_originate.c:3647 Channel [sofia/default/7661455301@fs.beconnected.co.za] has been answered
2018-12-10 13:16:28.533213 [DEBUG] switch_channel.c:3773 (sofia/default/7661455301@fs.beconnected.co.za) Callstate Change RINGING -> ACTIVE
2018-12-10 13:16:28.533213 [DEBUG] switch_ivr_originate.c:3705 Originate Resulted in Success: [sofia/default/6835959900@117.247.91.162:5060]
2018-12-10 13:16:28.533213 [DEBUG] switch_ivr_originate.c:2963 sofia/default/6835959900@117.247.91.162:5060 Setting leg timeout to 30
2018-12-10 13:16:28.533213 [DEBUG] switch_ivr_originate.c:3705 Originate Resulted in Success: [sofia/default/6835959900@117.247.91.162:5060]
2018-12-10 13:16:28.533213 [DEBUG] switch_ivr_bridge.c:1614 (sofia/default/6835959900@117.247.91.162:5060) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
2018-12-10 13:16:28.533213 [DEBUG] switch_core_state_machine.c:584 (sofia/default/6835959900@117.247.91.162:5060) Running State Change CS_EXCHANGE_MEDIA (Cur 4 Tot 7799)
2018-12-10 13:16:28.533213 [DEBUG] switch_core_state_machine.c:653 (sofia/default/6835959900@117.247.91.162:5060) State EXCHANGE_MEDIA
2018-12-10 13:16:28.533213 [DEBUG] mod_sofia.c:631 SOFIA EXCHANGE_MEDIA
2018-12-10 13:16:28.593211 [DEBUG] switch_rtp.c:7271 Correct audio ip/port confirmed.
2018-12-10 13:16:28.773213 [WARNING] switch_core_media.c:2480 [CBR]: Asynchronous PTIME not supported, changing our end from 20 to 30
2018-12-10 13:16:28.773213 [DEBUG] sofia.c:7084 Channel sofia/default/7661455301@fs.beconnected.co.za entering state [ready][200]
2018-12-10 13:16:28.793215 [DEBUG] switch_core_media.c:2959 Changing Codec from G729@20ms@8000hz to G729@30ms@8000hz
2018-12-10 13:16:28.793215 [DEBUG] sofia.c:7084 Channel sofia/default/7661455301@fs.beconnected.co.za entering state [calling][0]
2018-12-10 13:16:28.833250 [DEBUG] switch_rtp.c:3986 RE-Starting timer [soft] 240 bytes per 30ms
2018-12-10 13:16:28.833250 [DEBUG] switch_core_media.c:3061 Set Codec sofia/default/6835959900@117.247.91.162:5060 G729/8000 30 ms 240 samples 8000 bits 1 channels
2018-12-10 13:16:28.833250 [DEBUG] switch_core_codec.c:123 sofia/default/6835959900@117.247.91.162:5060 Original read codec replaced with G729:18
2018-12-10 13:16:28.893208 [DEBUG] switch_core_io.c:1448 Engaging Write Buffer at 320 bytes to accommodate 480->320
2018-12-10 13:16:29.013247 [DEBUG] switch_rtp.c:7271 Correct audio ip/port confirmed.
2018-12-10 13:16:29.013247 [DEBUG] switch_core_io.c:1448 Engaging Write Buffer at 480 bytes to accommodate 320->480
2018-12-10 13:16:29.093214 [DEBUG] sofia.c:7084 Channel sofia/default/7661455301@fs.beconnected.co.za entering state [ready][200]
2018-12-10 13:16:29.093214 [DEBUG] sofia.c:7094 Remote SDP:
v=0
o=7661455301 8001 8001 IN IP4 117.247.91.162
s=SIP Call
c=IN IP4 117.247.91.162
t=0 0
m=audio 5008 RTP/AVP 18 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
2018-12-10 13:16:29.093214 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
2018-12-10 13:16:29.093214 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
2018-12-10 13:16:29.093214 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[G729:18:8000:20:8000:1]
2018-12-10 13:16:29.093214 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [G729:18:8000:20:8000:1] ++++ is saved as a match
2018-12-10 13:16:29.093214 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 101@8000
2018-12-10 13:16:29.093214 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 101@8000
2018-12-10 13:16:29.093214 [DEBUG] switch_core_media.c:4767 sofia/default/7661455301@fs.beconnected.co.za Set 2833 dtmf send payload to 101 recv payload to 101
2018-12-10 13:16:29.093214 [DEBUG] sofia.c:8061 Processing updated SDP
2018-12-10 13:16:29.093214 [DEBUG] switch_core_media.c:6861 Audio params are unchanged for sofia/default/7661455301@fs.beconnected.co.za.
2018-12-10 13:16:32.253222 [NOTICE] switch_channel.c:1104 New Channel sofia/default/36005@169.255.171.130 [7f5a9ac0-623d-4f34-b914-be8b38416c12]
2018-12-10 13:16:32.253222 [DEBUG] switch_core_state_machine.c:584 (sofia/default/36005@169.255.171.130) Running State Change CS_NEW (Cur 5 Tot 7800)
2018-12-10 13:16:32.253222 [DEBUG] sofia.c:9873 sofia/default/36005@169.255.171.130 receiving invite from 158.69.126.203:51535 version: 1.6.19 git 7a77e0b 2017-07-13 12:01:45Z 64bit
2018-12-10 13:16:32.253222 [DEBUG] sofia.c:10044 IP 158.69.126.203 Rejected by acl "default". Falling back to Digest auth.
2018-12-10 13:16:32.253222 [DEBUG] sofia.c:2334 detaching session 7f5a9ac0-623d-4f34-b914-be8b38416c12
2018-12-10 13:16:32.253222 [WARNING] sofia_reg.c:1792 SIP auth challenge (INVITE) on sofia profile 'default' for [900441492550028@169.255.171.130] from ip 158.69.126.203
2018-12-10 13:16:32.253222 [DEBUG] switch_core_state_machine.c:603 (sofia/default/36005@169.255.171.130) State NEW
2018-12-10 13:16:32.393220 [WARNING] sofia_reg.c:1792 SIP auth challenge (REGISTER) on sofia profile 'default' for [7222@169.255.171.130] from ip 46.166.151.168
2018-12-10 13:16:32.573247 [WARNING] sofia_reg.c:2906 Can't find user [7222@169.255.171.130] from 46.166.151.168
You must define a domain called '169.255.171.130' in your directory and add a user with the id="7222" attribute
and you must configure your device to use the proper domain in it's authentication credentials.
2018-12-10 13:16:32.573247 [WARNING] sofia_reg.c:1737 SIP auth failure (REGISTER) on sofia profile 'default' for [7222@169.255.171.130] from ip 46.166.151.168
2018-12-10 13:16:33.273217 [NOTICE] switch_channel.c:1104 New Channel sofia/default/980001@169.255.171.130 [e3cb53a1-450d-4e20-82a2-7168186fd9c7]
2018-12-10 13:16:33.273217 [DEBUG] switch_core_state_machine.c:584 (sofia/default/980001@169.255.171.130) Running State Change CS_NEW (Cur 6 Tot 7801)
2018-12-10 13:16:33.273217 [DEBUG] sofia.c:9873 sofia/default/980001@169.255.171.130 receiving invite from 37.49.231.131:53999 version: 1.6.19 git 7a77e0b 2017-07-13 12:01:45Z 64bit
2018-12-10 13:16:33.273217 [DEBUG] sofia.c:10044 IP 37.49.231.131 Rejected by acl "default". Falling back to Digest auth.
2018-12-10 13:16:33.273217 [DEBUG] sofia.c:2334 detaching session e3cb53a1-450d-4e20-82a2-7168186fd9c7
2018-12-10 13:16:33.273217 [WARNING] sofia_reg.c:1792 SIP auth challenge (INVITE) on sofia profile 'default' for [000441158220041@169.255.171.130] from ip 37.49.231.131
2018-12-10 13:16:33.273217 [DEBUG] switch_core_state_machine.c:603 (sofia/default/980001@169.255.171.130) State NEW
2018-12-10 13:16:36.153245 [WARNING] switch_core_state_machine.c:687 460d13be-b2d8-4019-9ddb-e0f2f467d304 sofia/default/20001@169.255.171.130 Abandoned
2018-12-10 13:16:36.153245 [NOTICE] switch_core_state_machine.c:690 Hangup sofia/default/20001@169.255.171.130 [CS_NEW] [WRONG_CALL_STATE]
2018-12-10 13:16:36.153245 [DEBUG] switch_core_state_machine.c:584 (sofia/default/20001@169.255.171.130) Running State Change CS_HANGUP (Cur 6 Tot 7801)
2018-12-10 13:16:36.153245 [DEBUG] switch_core_state_machine.c:850 (sofia/default/20001@169.255.171.130) Callstate Change DOWN -> HANGUP
2018-12-10 13:16:36.153245 [DEBUG] switch_core_state_machine.c:852 (sofia/default/20001@169.255.171.130) State HANGUP
2018-12-10 13:16:36.153245 [DEBUG] mod_sofia.c:438 Channel sofia/default/20001@169.255.171.130 hanging up, cause: WRONG_CALL_STATE
2018-12-10 13:16:36.153245 [DEBUG] switch_core_state_machine.c:60 sofia/default/20001@169.255.171.130 Standard HANGUP, cause: WRONG_CALL_STATE
2018-12-10 13:16:36.153245 [DEBUG] switch_core_state_machine.c:852 (sofia/default/20001@169.255.171.130) State HANGUP going to sleep
2018-12-10 13:16:36.153245 [DEBUG] switch_core_state_machine.c:619 (sofia/default/20001@169.255.171.130) State Change CS_HANGUP -> CS_REPORTING
2018-12-10 13:16:36.153245 [DEBUG] switch_core_state_machine.c:584 (sofia/default/20001@169.255.171.130) Running State Change CS_REPORTING (Cur 6 Tot 7801)
2018-12-10 13:16:36.153245 [DEBUG] switch_core_state_machine.c:938 (sofia/default/20001@169.255.171.130) State REPORTING
2018-12-10 13:16:36.153245 [DEBUG] switch_core_state_machine.c:174 sofia/default/20001@169.255.171.130 Standard REPORTING, cause: WRONG_CALL_STATE
2018-12-10 13:16:36.153245 [DEBUG] switch_core_state_machine.c:938 (sofia/default/20001@169.255.171.130) State REPORTING going to sleep
2018-12-10 13:16:36.153245 [DEBUG] switch_core_state_machine.c:610 (sofia/default/20001@169.255.171.130) State Change CS_REPORTING -> CS_DESTROY
2018-12-10 13:16:36.153245 [DEBUG] switch_core_session.c:1665 Session 7797 (sofia/default/20001@169.255.171.130) Locked, Waiting on external entities
2018-12-10 13:16:36.153245 [NOTICE] switch_core_session.c:1683 Session 7797 (sofia/default/20001@169.255.171.130) Ended
2018-12-10 13:16:36.153245 [NOTICE] switch_core_session.c:1687 Close Channel sofia/default/20001@169.255.171.130 [CS_DESTROY]
2018-12-10 13:16:36.153245 [DEBUG] switch_core_state_machine.c:741 (sofia/default/20001@169.255.171.130) Running State Change CS_DESTROY (Cur 5 Tot 7801)
2018-12-10 13:16:36.153245 [DEBUG] switch_core_state_machine.c:751 (sofia/default/20001@169.255.171.130) State DESTROY
2018-12-10 13:16:36.153245 [DEBUG] mod_sofia.c:343 sofia/default/20001@169.255.171.130 SOFIA DESTROY
2018-12-10 13:16:36.153245 [DEBUG] switch_core_state_machine.c:181 sofia/default/20001@169.255.171.130 Standard DESTROY
2018-12-10 13:16:36.153245 [DEBUG] switch_core_state_machine.c:751 (sofia/default/20001@169.255.171.130) State DESTROY going to sleep
2018-12-10 13:16:36.293254 [WARNING] sofia_reg.c:1792 SIP auth challenge (REGISTER) on sofia profile 'default' for [7188363009@169.255.171.130] from ip 41.13.194.12
2018-12-10 13:16:36.333266 [WARNING] sofia_reg.c:2906 Can't find user [7188363009@169.255.171.130] from 41.13.194.12
You must define a domain called '169.255.171.130' in your directory and add a user with the id="7188363009" attribute
and you must configure your device to use the proper domain in it's authentication credentials.
2018-12-10 13:16:36.333266 [WARNING] sofia_reg.c:1737 SIP auth failure (REGISTER) on sofia profile 'default' for [7188363009@169.255.171.130] from ip 41.13.194.12
2018-12-10 13:16:37.653222 [NOTICE] sofia.c:1012 Hangup sofia/default/6835959900@117.247.91.162:5060 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]
2018-12-10 13:16:37.653222 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/default/6835959900@117.247.91.162:5060]
2018-12-10 13:16:37.653222 [DEBUG] switch_core_state_machine.c:653 (sofia/default/6835959900@117.247.91.162:5060) State EXCHANGE_MEDIA going to sleep
2018-12-10 13:16:37.653222 [DEBUG] switch_core_state_machine.c:584 (sofia/default/6835959900@117.247.91.162:5060) Running State Change CS_HANGUP (Cur 5 Tot 7801)
2018-12-10 13:16:37.653222 [DEBUG] switch_core_state_machine.c:850 (sofia/default/6835959900@117.247.91.162:5060) Callstate Change ACTIVE -> HANGUP
2018-12-10 13:16:37.653222 [DEBUG] switch_core_state_machine.c:852 (sofia/default/6835959900@117.247.91.162:5060) State HANGUP
2018-12-10 13:16:37.653222 [DEBUG] mod_sofia.c:438 Channel sofia/default/6835959900@117.247.91.162:5060 hanging up, cause: NORMAL_CLEARING
2018-12-10 13:16:37.653222 [DEBUG] switch_core_state_machine.c:60 sofia/default/6835959900@117.247.91.162:5060 Standard HANGUP, cause: NORMAL_CLEARING
2018-12-10 13:16:37.653222 [DEBUG] switch_core_state_machine.c:852 (sofia/default/6835959900@117.247.91.162:5060) State HANGUP going to sleep
2018-12-10 13:16:37.653222 [DEBUG] switch_core_state_machine.c:619 (sofia/default/6835959900@117.247.91.162:5060) State Change CS_HANGUP -> CS_REPORTING
2018-12-10 13:16:37.653222 [DEBUG] switch_core_state_machine.c:584 (sofia/default/6835959900@117.247.91.162:5060) Running State Change CS_REPORTING (Cur 5 Tot 7801)
2018-12-10 13:16:37.653222 [DEBUG] switch_core_state_machine.c:938 (sofia/default/6835959900@117.247.91.162:5060) State REPORTING
2018-12-10 13:16:37.653222 [INFO] mod_json_cdr.c:271 Process [806f29a9-ef75-424a-bb7a-e8cb4155ffa0.cdr.json]
2018-12-10 13:16:37.653222 [DEBUG] switch_ivr_bridge.c:706 sofia/default/6835959900@117.247.91.162:5060 ending bridge by request from write function
2018-12-10 13:16:37.653222 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/default/7661455301@fs.beconnected.co.za]
2018-12-10 13:16:37.653222 [DEBUG] switch_ivr_bridge.c:1712 sofia/default/6835959900@117.247.91.162:5060 skip receive message [UNBRIDGE] (channel is hungup already)