Originate Failed. Cause: NONE
Hi, I finally managed to setup Telekom DeutschlandLAN Voip sip trunk. Most of it is working now, but some calls get droped without clear reason. After one ring freeswitch drops the call: Originate Failed. Cause: NONE. That happens only if the caller uses a mobile phone. Some mobile phones work, others dont. This was not happening before when I used a ISDN / SIP Gateway. Here is the log file: 2018-07-23 16:32:57.539715 [NOTICE] switch_channel.c:1104 New Channel sofia/external/+49171XXXXXXX@sip-trunk.telekom.de [1a4d0118-09cc-46e7-906e-c2bfd1cecba1] 2018-07-23 16:32:57.539715 [DEBUG] switch_core_state_machine.c:584 (sofia/external/+@sip-trunk.telekom.de) Running State Change CS_NEW (Cur 1 Tot 229) 2018-07-23 16:32:57.539715 [DEBUG] sofia.c:9873 sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de receiving invite from 217.0.15.67:5060 version: 1.6.20 git 43a9feb 2018-05-07 18:56:11Z 32bit 2018-07-23 16:32:57.539715 [DEBUG] sofia.c:7084 Channel sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de entering state [received][100] 2018-07-23 16:32:57.539715 [DEBUG] sofia.c:7094 Remote SDP: v=0 o=- 1532356377 1532356377 IN IP4 217.0.15.67 s=on transit c=IN IP4 217.0.132.101 t=0 0 a=sendrecv m=audio 22482 RTP/AVP 9 8 100 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:100 telephone-event/8000 a=fmtp:100 0-15 a=maxptime:40 a=ptime:20 2018-07-23 16:32:57.559717 [DEBUG] sofia.c:7486 (sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de) State Change CS_NEW -> CS_INIT 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:603 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State NEW 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:584 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) Running State Change CS_INIT (Cur 1 Tot 229) 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:627 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State INIT 2018-07-23 16:32:57.559717 [DEBUG] mod_sofia.c:90 sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de SOFIA INIT 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:40 sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Standard INIT 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:48 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State Change CS_INIT -> CS_ROUTING 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:627 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State INIT going to sleep 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:584 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) Running State Change CS_ROUTING (Cur 1 Tot 229) 2018-07-23 16:32:57.559717 [DEBUG] switch_channel.c:2249 (sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de) Callstate Change DOWN -> RINGING 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:643 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State ROUTING 2018-07-23 16:32:57.559717 [DEBUG] mod_sofia.c:143 sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de SOFIA ROUTING 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:236 sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Standard ROUTING 2018-07-23 16:32:57.559717 [INFO] mod_dialplan_xml.c:637 Processing +49171XXXXXXX <+49171XXXXXXX>->551130118089 in context public Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de parsing [public->unloop] continue=false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de parsing [public->outside_call] continue=true Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Absolute Condition [outside_call] Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action set(outside_call=true) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de parsing [public->call_debug] continue=true Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Regex (FAIL) [call_debug] ${call_debug}(false) =~ /^true$/ break=never Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de parsing [public->telekom-voip-inbound-main] continue=false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Regex (PASS) [telekom-voip-inbound-main] ${sip_h_P-Called-Party-ID}(< sip:+49XXXXXXXXX@sip-trunk.telekom.de;user=phone>) =~ /(XXXXXXXXX)/ break=on-false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action set(domain_name=10.0.200.2) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action set(effective_caller_id_number=${caller_id_number}) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action set(effective_caller_id_name=${caller_id_number}) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action set(ringback=%(1000,4000,425)) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action transfer(operator XML default) 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:286 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State Change CS_ROUTING -> CS_EXECUTE 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:643 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State ROUTING going to sleep 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:584 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) Running State Change CS_EXECUTE (Cur 1 Tot 229) 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:650 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State EXECUTE 2018-07-23 16:32:57.559717 [DEBUG] mod_sofia.c:198 sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de SOFIA EXECUTE 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:328 sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Standard EXECUTE EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de set(outside_call=true) 2018-07-23 16:32:57.559717 [DEBUG] mod_dptools.c:1548 SET sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de [outside_call]=[true] EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de export(RFC2822_DATE=Mon, 23 Jul 2018 16:32:57 +0200) 2018-07-23 16:32:57.559717 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [RFC2822_DATE]=[Mon, 23 Jul 2018 16:32:57 +0200] EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de set(domain_name=10.0.200.2) 2018-07-23 16:32:57.559717 [DEBUG] mod_dptools.c:1548 SET sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de [domain_name]=[10.0.200.2] EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de set(effective_caller_id_number=+49171XXXXXXX) 2018-07-23 16:32:57.559717 [DEBUG] mod_dptools.c:1548 SET sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de [effective_caller_id_number]=[+49171XXXXXXX] EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de set(effective_caller_id_name=+49171XXXXXXX) 2018-07-23 16:32:57.559717 [DEBUG] mod_dptools.c:1548 SET sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de [effective_caller_id_name]=[+49171XXXXXXX] EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de set(ringback=%(1000,4000,425)) 2018-07-23 16:32:57.559717 [DEBUG] mod_dptools.c:1548 SET sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de [ringback]=[%(1000,4000,425)] EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de transfer(operator XML default) 2018-07-23 16:32:57.559717 [DEBUG] switch_ivr.c:2165 (sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de) State Change CS_EXECUTE -> CS_ROUTING 2018-07-23 16:32:57.559717 [NOTICE] switch_ivr.c:2172 Transfer sofia/external/+49171XXXXXXX@sip-trunk.telekom.de to XML[operator@default] 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:650 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State EXECUTE going to sleep 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:584 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) Running State Change CS_ROUTING (Cur 1 Tot 229) 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:643 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State ROUTING 2018-07-23 16:32:57.559717 [DEBUG] mod_sofia.c:143 sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de SOFIA ROUTING 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:236 sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Standard ROUTING 2018-07-23 16:32:57.559717 [INFO] mod_dialplan_xml.c:637 Processing +49171XXXXXXX <+49171XXXXXXX>->operator in context default Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de parsing [default->unloop] continue=false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de parsing [default->blacklist_check1] continue=false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Regex (FAIL) [blacklist_check1] ${regex(${caller_id_number}|(XXXXXXXXX))}(false) =~ /^true$/ break=on-false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de parsing [default->Time of day] continue=true Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Date/Time Match (PASS) [Time of day] break=never Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action set(office_status=closed) INLINE EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de set(office_status=closed) 2018-07-23 16:32:57.559717 [DEBUG] mod_dptools.c:1548 SET sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de [office_status]=[closed] Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Date/TimeMatch (FAIL) [Time of day] break=never Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de parsing [default->global] continue=true Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Absolute Condition [global] Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action export(nolocal:api_on_answer=uuid_setvar ${uuid} transfer false) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action set(ringback=%(1000,4000,425)) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de parsing [default->global-pickup] continue=false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Regex (FAIL) [global-pickup] destination_number(operator) =~ /^#$/ break=on-false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de parsing [default->local-pickup] continue=false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Regex (FAIL) [local-pickup] destination_number(operator) =~ /^\*\*(\d+)$/ break=on-false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de parsing [default->group_dial_werkstatt] continue=false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Regex (FAIL) [group_dial_werkstatt] destination_number(operator) =~ /^16$/ break=on-false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de parsing [default->Operator] continue=false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Regex (PASS) [Operator] destination_number(operator) =~ /^(operator)$|^(90)$/ break=on-false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action export(dialed_extension=operator) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action set(dialed_user=operator@${domain_name}) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action set(call_timeout=90) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action set(hangup_after_bridge=true) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action set(continue_on_fail=true) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action bind_digit_action(get_digits,~^([1-9][0-9])$,exec:lua,get_digits.lua,peer,self) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action digit_action_set_realm(get_digits) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action ring_ready() |--- Dialplan: Processing recursive conditions level:1 [Operator_recur_1] require-nested=FALSE |--- Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Regex (FAIL) [Operator_recur_1] ${office_status}(closed) =~ /^(open)$/ break=on-true |--- Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Regex (PASS) [Operator_recur_1] ${office_status}(closed) =~ /^(closed)$/ break=on-true |--- Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action bridge(group/buero :_: group/werkstatt,pickup/global) |--- Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action hangup(NO_ANSWER) 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:286 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State Change CS_ROUTING -> CS_EXECUTE 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:643 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State ROUTING going to sleep 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:584 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) Running State Change CS_EXECUTE (Cur 1 Tot 229) 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:650 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State EXECUTE 2018-07-23 16:32:57.559717 [DEBUG] mod_sofia.c:198 sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de SOFIA EXECUTE 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:328 sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Standard EXECUTE EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de export(nolocal:api_on_answer=uuid_setvar 1a4d0118-09cc-46e7-906e-c2bfd1cecba1 transfer false) 2018-07-23 16:32:57.559717 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) (REMOTE ONLY) [api_on_answer]=[uuid_setvar 1a4d0118-09cc-46e7-906e-c2bfd1cecba1 transfer false] EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de set(ringback=%(1000,4000,425)) 2018-07-23 16:32:57.559717 [DEBUG] mod_dptools.c:1548 SET sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de [ringback]=[%(1000,4000,425)] EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de export(dialed_extension=operator) 2018-07-23 16:32:57.559717 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [dialed_extension]=[operator] EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de set(dialed_user= operator@10.0.200.2) 2018-07-23 16:32:57.559717 [DEBUG] mod_dptools.c:1548 SET sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de [dialed_user]=[operator@10.0.200.2] EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de set(call_timeout=90) 2018-07-23 16:32:57.579719 [DEBUG] mod_dptools.c:1548 SET sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de [call_timeout]=[90] EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de set(hangup_after_bridge=true) 2018-07-23 16:32:57.579719 [DEBUG] mod_dptools.c:1548 SET sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de [hangup_after_bridge]=[true] EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de set(continue_on_fail=true) 2018-07-23 16:32:57.579719 [DEBUG] mod_dptools.c:1548 SET sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de [continue_on_fail]=[true] EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de bind_digit_action(get_digits,~^([1-9][0-9])$,exec:lua,get_digits.lua,peer,self) 2018-07-23 16:32:57.579719 [INFO] switch_ivr_async.c:214 Digit parser DPTOOLS: Setting realm to 'get_digits' 2018-07-23 16:32:57.579719 [DEBUG] switch_ivr_async.c:320 Digit parser DPTOOLS: binding ^([1-9][0-9])$/get_digits/0 callback: 0xb58163e0 data: 0x8f414d0 EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de digit_action_set_realm(get_digits) EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de ring_ready() 2018-07-23 16:32:57.579719 [NOTICE] mod_sofia.c:2273 Ring-Ready sofia/external/+49171XXXXXXX@sip-trunk.telekom.de! 2018-07-23 16:32:57.579719 [DEBUG] sofia.c:7084 Channel sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de entering state [early][180] 2018-07-23 16:32:57.579719 [NOTICE] mod_dptools.c:1028 Ring Ready sofia/external/+49171XXXXXXX@sip-trunk.telekom.de! EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de bridge(group/buero :_: group/werkstatt,pickup/global) 2018-07-23 16:32:57.579719 [DEBUG] switch_channel.c:1250 sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de EXPORTING[export_vars] [RFC2822_DATE]=[Mon, 23 Jul 2018 16:32:57 +0200] to event 2018-07-23 16:32:57.579719 [DEBUG] switch_channel.c:1250 sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de EXPORTING[export_vars] [api_on_answer]=[uuid_setvar 1a4d0118-09cc-46e7-906e-c2bfd1cecba1 transfer false] to event 2018-07-23 16:32:57.579719 [DEBUG] switch_channel.c:1250 sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de EXPORTING[export_vars] [dialed_extension]=[operator] to event 2018-07-23 16:32:57.579719 [DEBUG] switch_ivr_originate.c:1548 Parsing ultra-global variables 2018-07-23 16:32:57.579719 [INFO] switch_ivr_originate.c:1614 Sending early media 2018-07-23 16:32:57.579719 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables 2018-07-23 16:32:57.579719 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2018-07-23 16:32:57.579719 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2018-07-23 16:32:57.579719 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2018-07-23 16:32:57.579719 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match 2018-07-23 16:32:57.579719 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2018-07-23 16:32:57.579719 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2018-07-23 16:32:57.579719 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2018-07-23 16:32:57.579719 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2018-07-23 16:32:57.579719 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 100@8000 2018-07-23 16:32:57.579719 [DEBUG] switch_core_media.c:3061 Set Codec sofia/external/+49171XXXXXXX@sip-trunk.telekom.de G722/8000 20 ms 160 samples 64000 bits 1 channels 2018-07-23 16:32:57.579719 [DEBUG] switch_core_codec.c:111 sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de Original read codec set to G722:9 2018-07-23 16:32:57.579719 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 100@8000 2018-07-23 16:32:57.579719 [DEBUG] switch_core_media.c:4767 sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de Set 2833 dtmf send payload to 100 recv payload to 100 2018-07-23 16:32:57.579719 [DEBUG] switch_core_media.c:6878 AUDIO RTP [sofia/external/+49171XXXXXXX@sip-trunk.telekom.de] 10.0.200.2 port 7082 -> 217.0.132.101 port 22482 codec: 9 ms: 20 2018-07-23 16:32:57.579719 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables 2018-07-23 16:32:57.579719 [DEBUG] switch_rtp.c:4137 Starting timer [soft] 160 bytes per 20ms 2018-07-23 16:32:57.579719 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables 2018-07-23 16:32:57.579719 [DEBUG] switch_ivr_originate.c:2669 Parsing session specific variables 2018-07-23 16:32:57.579719 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/10@10.0.200.10:5060 [6306dfab-d366-4060-8b39-8e8349f72417] 2018-07-23 16:32:57.579719 [DEBUG] mod_sofia.c:4819 (sofia/internal/ 10@10.0.200.10:5060) State Change CS_NEW -> CS_INIT 2018-07-23 16:32:57.579719 [DEBUG] switch_ivr_originate.c:2669 Parsing session specific variables 2018-07-23 16:32:57.579719 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables 2018-07-23 16:32:57.579719 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/11@10.0.200.11:5060 [ed0352eb-0d61-41f0-87c0-5837c5de4ef8] 2018-07-23 16:32:57.579719 [WARNING] switch_ivr_originate.c:2647 Only calling the first element in the list in this mode. 2018-07-23 16:32:57.579719 [DEBUG] switch_ivr_originate.c:2669 Parsing session specific variables 2018-07-23 16:32:57.579719 [DEBUG] mod_sofia.c:4819 (sofia/internal/ 11@10.0.200.11:5060) State Change CS_NEW -> CS_INIT 2018-07-23 16:32:57.579719 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/15@10.0.200.15:5060 [9c8a2e89-cab4-40f6-b760-4a9e3ea6ef05] 2018-07-23 16:32:57.579719 [DEBUG] mod_sofia.c:4819 (sofia/internal/ 15@10.0.200.15:5060) State Change CS_NEW -> CS_INIT 2018-07-23 16:32:57.579719 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/10@10.0.200.10:5060) Running State Change CS_INIT (Cur 4 Tot 232) 2018-07-23 16:32:57.579719 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/10@10.0.200.10:5060) State INIT 2018-07-23 16:32:57.579719 [DEBUG] mod_sofia.c:90 sofia/internal/ 10@10.0.200.10:5060 SOFIA INIT 2018-07-23 16:32:57.579719 [DEBUG] sofia_glue.c:1295 sofia/internal/ 10@10.0.200.10:5060 sending invite version: 1.6.20 git 43a9feb 2018-05-07 18:56:11Z 32bit Local SDP: v=0 o=FreeSWITCH 1532349289 1532349290 IN IP4 10.0.200.2 s=FreeSWITCH c=IN IP4 10.0.200.2 t=0 0 m=audio 7088 RTP/AVP 8 0 9 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:9 G722/8000 a=ptime:20 a=sendrecv 2018-07-23 16:32:57.579719 [DEBUG] switch_core_state_machine.c:40 sofia/internal/10@10.0.200.10:5060 Standard INIT 2018-07-23 16:32:57.579719 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/10@10.0.200.10:5060) State Change CS_INIT -> CS_ROUTING 2018-07-23 16:32:57.579719 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/10@10.0.200.10:5060) State INIT going to sleep 2018-07-23 16:32:57.579719 [DEBUG] mod_dptools.c:3872 () State Change CS_NEW -> CS_ROUTING 2018-07-23 16:32:57.579719 [NOTICE] switch_channel.c:1104 New Channel pickup/global [66ab149c-54a4-4d17-8428-26e1872e6f9d] 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/11@10.0.200.11:5060) Running State Change CS_INIT (Cur 5 Tot 233) 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/11@10.0.200.11:5060) State INIT 2018-07-23 16:32:57.599721 [DEBUG] mod_sofia.c:90 sofia/internal/ 11@10.0.200.11:5060 SOFIA INIT 2018-07-23 16:32:57.599721 [DEBUG] sofia_glue.c:1295 sofia/internal/ 11@10.0.200.11:5060 sending invite version: 1.6.20 git 43a9feb 2018-05-07 18:56:11Z 32bit Local SDP: v=0 o=FreeSWITCH 1532349305 1532349306 IN IP4 10.0.200.2 s=FreeSWITCH c=IN IP4 10.0.200.2 t=0 0 m=audio 7072 RTP/AVP 8 0 9 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:9 G722/8000 a=ptime:20 a=sendrecv 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:40 sofia/internal/11@10.0.200.11:5060 Standard INIT 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/11@10.0.200.11:5060) State Change CS_INIT -> CS_ROUTING 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/11@10.0.200.11:5060) State INIT going to sleep 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/11@10.0.200.11:5060) Running State Change CS_ROUTING (Cur 5 Tot 233) 2018-07-23 16:32:57.599721 [DEBUG] sofia.c:7084 Channel sofia/internal/ 11@10.0.200.11:5060 entering state [calling][0] 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/11@10.0.200.11:5060) State ROUTING 2018-07-23 16:32:57.599721 [DEBUG] mod_sofia.c:143 sofia/internal/ 11@10.0.200.11:5060 SOFIA ROUTING 2018-07-23 16:32:57.599721 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/11@10.0.200.11:5060) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/11@10.0.200.11:5060) State ROUTING going to sleep 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/15@10.0.200.15:5060) Running State Change CS_INIT (Cur 5 Tot 233) 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/15@10.0.200.15:5060) State INIT 2018-07-23 16:32:57.599721 [DEBUG] mod_sofia.c:90 sofia/internal/ 15@10.0.200.15:5060 SOFIA INIT 2018-07-23 16:32:57.599721 [DEBUG] sofia_glue.c:1295 sofia/internal/ 15@10.0.200.15:5060 sending invite version: 1.6.20 git 43a9feb 2018-05-07 18:56:11Z 32bit Local SDP: v=0 o=FreeSWITCH 1532349297 1532349298 IN IP4 10.0.200.2 s=FreeSWITCH c=IN IP4 10.0.200.2 t=0 0 m=audio 7080 RTP/AVP 8 0 9 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:9 G722/8000 a=ptime:20 a=sendrecv 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/11@10.0.200.11:5060) Running State Change CS_CONSUME_MEDIA (Cur 5 Tot 233) 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:40 sofia/internal/15@10.0.200.15:5060 Standard INIT 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/15@10.0.200.15:5060) State Change CS_INIT -> CS_ROUTING 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/15@10.0.200.15:5060) State INIT going to sleep 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/11@10.0.200.11:5060) State CONSUME_MEDIA 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/11@10.0.200.11:5060) State CONSUME_MEDIA going to sleep 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:584 (pickup/global) Running State Change CS_ROUTING (Cur 5 Tot 233) 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/15@10.0.200.15:5060) Running State Change CS_ROUTING (Cur 5 Tot 233) 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:643 (pickup/global) State ROUTING 2018-07-23 16:32:57.599721 [DEBUG] switch_ivr_originate.c:67 (pickup/global) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:643 (pickup/global) State ROUTING going to sleep 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:584 (pickup/global) Running State Change CS_CONSUME_MEDIA (Cur 5 Tot 233) 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:662 (pickup/global) State CONSUME_MEDIA 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:662 (pickup/global) State CONSUME_MEDIA going to sleep 2018-07-23 16:32:57.599721 [DEBUG] sofia.c:7084 Channel sofia/internal/ 15@10.0.200.15:5060 entering state [calling][0] 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/15@10.0.200.15:5060) State ROUTING 2018-07-23 16:32:57.599721 [DEBUG] mod_sofia.c:143 sofia/internal/ 15@10.0.200.15:5060 SOFIA ROUTING 2018-07-23 16:32:57.599721 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/15@10.0.200.15:5060) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/15@10.0.200.15:5060) State ROUTING going to sleep 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/15@10.0.200.15:5060) Running State Change CS_CONSUME_MEDIA (Cur 5 Tot 233) 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/15@10.0.200.15:5060) State CONSUME_MEDIA 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/15@10.0.200.15:5060) State CONSUME_MEDIA going to sleep 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/10@10.0.200.10:5060) Running State Change CS_ROUTING (Cur 5 Tot 233) 2018-07-23 16:32:57.599721 [DEBUG] sofia.c:7084 Channel sofia/internal/ 10@10.0.200.10:5060 entering state [calling][0] 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/10@10.0.200.10:5060) State ROUTING 2018-07-23 16:32:57.599721 [DEBUG] mod_sofia.c:143 sofia/internal/ 10@10.0.200.10:5060 SOFIA ROUTING 2018-07-23 16:32:57.599721 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/10@10.0.200.10:5060) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/10@10.0.200.10:5060) State ROUTING going to sleep 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/10@10.0.200.10:5060) Running State Change CS_CONSUME_MEDIA (Cur 5 Tot 233) 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/10@10.0.200.10:5060) State CONSUME_MEDIA 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/10@10.0.200.10:5060) State CONSUME_MEDIA going to sleep 2018-07-23 16:32:57.599721 [DEBUG] switch_core_media.c:7180 sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de Set 2833 dtmf send payload to 100 2018-07-23 16:32:57.599721 [DEBUG] switch_core_media.c:7187 sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de Set 2833 dtmf receive payload to 100 2018-07-23 16:32:57.599721 [DEBUG] switch_core_media.c:7210 sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de Set rtp dtmf delay to 40 2018-07-23 16:32:57.599721 [NOTICE] sofia_media.c:92 Pre-Answer sofia/external/+49171XXXXXXX@sip-trunk.telekom.de! 2018-07-23 16:32:57.599721 [DEBUG] switch_channel.c:3474 (sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de) Callstate Change RINGING -> EARLY 2018-07-23 16:32:57.619722 [DEBUG] switch_core_media.c:6861 Audio params are unchanged for sofia/external/+49171XXXXXXX@sip-trunk.telekom.de. 2018-07-23 16:32:57.619722 [DEBUG] mod_sofia.c:2364 Ring SDP: v=0 o=FreeSWITCH 1532349295 1532349296 IN IP4 10.0.200.2 s=FreeSWITCH c=IN IP4 10.0.200.2 t=0 0 m=audio 7082 RTP/AVP 9 100 a=rtpmap:9 G722/8000 a=rtpmap:100 telephone-event/8000 a=fmtp:100 0-16 a=ptime:20 a=sendrecv 2018-07-23 16:32:57.619722 [DEBUG] sofia.c:7084 Channel sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de entering state [early][183] 2018-07-23 16:32:57.639724 [DEBUG] sofia.c:7084 Channel sofia/internal/ 15@10.0.200.15:5060 entering state [proceeding][180] 2018-07-23 16:32:57.639724 [NOTICE] sofia.c:7192 Ring-Ready sofia/internal/ 15@10.0.200.15:5060! 2018-07-23 16:32:57.639724 [DEBUG] switch_channel.c:3346 (sofia/internal/ 15@10.0.200.15:5060) Callstate Change DOWN -> RINGING 2018-07-23 16:32:57.639724 [DEBUG] sofia.c:7084 Channel sofia/internal/ 10@10.0.200.10:5060 entering state [proceeding][180] 2018-07-23 16:32:57.639724 [NOTICE] sofia.c:7192 Ring-Ready sofia/internal/ 10@10.0.200.10:5060! 2018-07-23 16:32:57.639724 [DEBUG] switch_channel.c:3346 (sofia/internal/ 10@10.0.200.10:5060) Callstate Change DOWN -> RINGING 2018-07-23 16:32:57.679728 [DEBUG] sofia.c:7084 Channel sofia/internal/ 11@10.0.200.11:5060 entering state [proceeding][180] 2018-07-23 16:32:57.679728 [NOTICE] sofia.c:7192 Ring-Ready sofia/internal/ 11@10.0.200.11:5060! 2018-07-23 16:32:57.679728 [DEBUG] switch_channel.c:3346 (sofia/internal/ 11@10.0.200.11:5060) Callstate Change DOWN -> RINGING 2018-07-23 16:32:58.879835 [DEBUG] sofia.c:7084 Channel sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de entering state [terminated][487] 2018-07-23 16:32:58.879835 [NOTICE] sofia.c:8273 Hangup sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de [CS_EXECUTE] [ORIGINATOR_CANCEL] 2018-07-23 16:32:58.899837 [NOTICE] switch_ivr_originate.c:3612 Hangup sofia/internal/15@10.0.200.15:5060 [CS_CONSUME_MEDIA] [LOSE_RACE] 2018-07-23 16:32:58.899837 [NOTICE] switch_ivr_originate.c:3612 Hangup pickup/global [CS_CONSUME_MEDIA] [LOSE_RACE] 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/15@10.0.200.15:5060) Running State Change CS_HANGUP (Cur 5 Tot 233) 2018-07-23 16:32:58.899837 [DEBUG] switch_ivr_originate.c:3837 Originate Cancelled by originator termination Cause: 487 [ORIGINATOR_CANCEL] 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:584 (pickup/global) Running State Change CS_HANGUP (Cur 5 Tot 233) 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/15@10.0.200.15:5060) Callstate Change RINGING -> HANGUP 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:850 (pickup/global) Callstate Change DOWN -> HANGUP 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:852 (pickup/global) State HANGUP 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/15@10.0.200.15:5060) State HANGUP 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:60 pickup/global Standard HANGUP, cause: LOSE_RACE 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:852 (pickup/global) State HANGUP going to sleep 2018-07-23 16:32:58.899837 [DEBUG] mod_sofia.c:438 Channel sofia/internal/ 15@10.0.200.15:5060 hanging up, cause: LOSE_RACE 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:619 (pickup/global) State Change CS_HANGUP -> CS_REPORTING 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:584 (pickup/global) Running State Change CS_REPORTING (Cur 5 Tot 233) 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:938 (pickup/global) State REPORTING 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:938 (pickup/global) State REPORTING going to sleep 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:610 (pickup/global) State Change CS_REPORTING -> CS_DESTROY 2018-07-23 16:32:58.899837 [DEBUG] switch_core_session.c:1665 Session 233 (pickup/global) Locked, Waiting on external entities 2018-07-23 16:32:58.899837 [NOTICE] switch_core_session.c:1683 Session 233 (pickup/global) Ended 2018-07-23 16:32:58.899837 [NOTICE] switch_core_session.c:1687 Close Channel pickup/global [CS_DESTROY] 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:741 (pickup/global) Running State Change CS_DESTROY (Cur 4 Tot 233) 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:751 (pickup/global) State DESTROY 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:181 pickup/global Standard DESTROY 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:751 (pickup/global) State DESTROY going to sleep 2018-07-23 16:32:58.899837 [NOTICE] switch_ivr_originate.c:3612 Hangup sofia/internal/10@10.0.200.10:5060 [CS_CONSUME_MEDIA] [LOSE_RACE] 2018-07-23 16:32:58.899837 [DEBUG] mod_sofia.c:502 Sending CANCEL to sofia/internal/15@10.0.200.15:5060 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:60 sofia/internal/15@10.0.200.15:5060 Standard HANGUP, cause: LOSE_RACE 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/15@10.0.200.15:5060) State HANGUP going to sleep 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/15@10.0.200.15:5060) State Change CS_HANGUP -> CS_REPORTING 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/15@10.0.200.15:5060) Running State Change CS_REPORTING (Cur 4 Tot 233) 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/15@10.0.200.15:5060) State REPORTING 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:174 sofia/internal/15@10.0.200.15:5060 Standard REPORTING, cause: LOSE_RACE 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/15@10.0.200.15:5060) State REPORTING going to sleep 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/15@10.0.200.15:5060) State Change CS_REPORTING -> CS_DESTROY 2018-07-23 16:32:58.899837 [DEBUG] switch_core_session.c:1665 Session 232 (sofia/internal/15@10.0.200.15:5060) Locked, Waiting on external entities 2018-07-23 16:32:58.899837 [NOTICE] switch_core_session.c:1683 Session 232 (sofia/internal/15@10.0.200.15:5060) Ended 2018-07-23 16:32:58.899837 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/15@10.0.200.15:5060 [CS_DESTROY] 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/15@10.0.200.15:5060) Running State Change CS_DESTROY (Cur 3 Tot 233) 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/15@10.0.200.15:5060) State DESTROY 2018-07-23 16:32:58.899837 [DEBUG] mod_sofia.c:343 sofia/internal/ 15@10.0.200.15:5060 SOFIA DESTROY 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:181 sofia/internal/15@10.0.200.15:5060 Standard DESTROY 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/15@10.0.200.15:5060) State DESTROY going to sleep 2018-07-23 16:32:58.899837 [NOTICE] switch_ivr_originate.c:3612 Hangup sofia/internal/11@10.0.200.11:5060 [CS_CONSUME_MEDIA] [LOSE_RACE] 2018-07-23 16:32:58.899837 [DEBUG] switch_ivr_originate.c:3837 Originate Cancelled by originator termination Cause: 487 [ORIGINATOR_CANCEL] 2018-07-23 16:32:58.899837 [NOTICE] switch_ivr_originate.c:2851 Cannot create outgoing channel of type [group] cause: [LOSE_RACE] 2018-07-23 16:32:58.899837 [DEBUG] switch_ivr_originate.c:3848 Originate Resulted in Error Cause: 502 [LOSE_RACE] 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/10@10.0.200.10:5060) Running State Change CS_HANGUP (Cur 3 Tot 233) 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/10@10.0.200.10:5060) Callstate Change RINGING -> HANGUP 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/10@10.0.200.10:5060) State HANGUP 2018-07-23 16:32:58.899837 [DEBUG] mod_sofia.c:438 Channel sofia/internal/ 10@10.0.200.10:5060 hanging up, cause: LOSE_RACE 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/11@10.0.200.11:5060) Running State Change CS_HANGUP (Cur 3 Tot 233) 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/11@10.0.200.11:5060) Callstate Change RINGING -> HANGUP 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/11@10.0.200.11:5060) State HANGUP 2018-07-23 16:32:58.899837 [DEBUG] mod_sofia.c:438 Channel sofia/internal/ 11@10.0.200.11:5060 hanging up, cause: LOSE_RACE 2018-07-23 16:32:58.899837 [INFO] mod_dptools.c:3436 Originate Failed. Cause: NONE 2018-07-23 16:32:58.899837 [DEBUG] switch_core_session.c:2815 sofia/external/+49171XXXXXXX@sip-trunk.telekom.de skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:650 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State EXECUTE going to sleep 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:584 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) Running State Change CS_HANGUP (Cur 3 Tot 233) 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:850 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) Callstate Change EARLY -> HANGUP 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:852 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State HANGUP 2018-07-23 16:32:58.919839 [DEBUG] mod_sofia.c:438 Channel sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de hanging up, cause: ORIGINATOR_CANCEL 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:60 sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Standard HANGUP, cause: ORIGINATOR_CANCEL 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:852 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State HANGUP going to sleep 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:619 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State Change CS_HANGUP -> CS_REPORTING 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:584 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) Running State Change CS_REPORTING (Cur 3 Tot 233) 2018-07-23 16:32:58.919839 [DEBUG] mod_sofia.c:502 Sending CANCEL to sofia/internal/10@10.0.200.10:5060 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:938 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State REPORTING 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:60 sofia/internal/10@10.0.200.10:5060 Standard HANGUP, cause: LOSE_RACE 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/10@10.0.200.10:5060) State HANGUP going to sleep 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/10@10.0.200.10:5060) State Change CS_HANGUP -> CS_REPORTING 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:174 sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Standard REPORTING, cause: ORIGINATOR_CANCEL 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:938 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State REPORTING going to sleep 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/10@10.0.200.10:5060) Running State Change CS_REPORTING (Cur 3 Tot 233) 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:610 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State Change CS_REPORTING -> CS_DESTROY 2018-07-23 16:32:58.919839 [DEBUG] switch_core_session.c:1665 Session 229 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) Locked, Waiting on external entities 2018-07-23 16:32:58.919839 [NOTICE] switch_core_session.c:1683 Session 229 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) Ended 2018-07-23 16:32:58.919839 [NOTICE] switch_core_session.c:1687 Close Channel sofia/external/+49171XXXXXXX@sip-trunk.telekom.de [CS_DESTROY] 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:741 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) Running State Change CS_DESTROY (Cur 2 Tot 233) 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:751 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State DESTROY 2018-07-23 16:32:58.919839 [DEBUG] mod_sofia.c:343 sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de SOFIA DESTROY 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:181 sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Standard DESTROY 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:751 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State DESTROY going to sleep 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/10@10.0.200.10:5060) State REPORTING 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:174 sofia/internal/10@10.0.200.10:5060 Standard REPORTING, cause: LOSE_RACE 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/10@10.0.200.10:5060) State REPORTING going to sleep 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/10@10.0.200.10:5060) State Change CS_REPORTING -> CS_DESTROY 2018-07-23 16:32:58.919839 [DEBUG] switch_core_session.c:1665 Session 230 (sofia/internal/10@10.0.200.10:5060) Locked, Waiting on external entities 2018-07-23 16:32:58.919839 [NOTICE] switch_core_session.c:1683 Session 230 (sofia/internal/10@10.0.200.10:5060) Ended 2018-07-23 16:32:58.919839 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/10@10.0.200.10:5060 [CS_DESTROY] 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/10@10.0.200.10:5060) Running State Change CS_DESTROY (Cur 1 Tot 233) 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/10@10.0.200.10:5060) State DESTROY 2018-07-23 16:32:58.919839 [DEBUG] mod_sofia.c:343 sofia/internal/ 10@10.0.200.10:5060 SOFIA DESTROY 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:181 sofia/internal/10@10.0.200.10:5060 Standard DESTROY 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/10@10.0.200.10:5060) State DESTROY going to sleep 2018-07-23 16:32:58.919839 [DEBUG] mod_sofia.c:502 Sending CANCEL to sofia/internal/11@10.0.200.11:5060 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:60 sofia/internal/11@10.0.200.11:5060 Standard HANGUP, cause: LOSE_RACE 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/11@10.0.200.11:5060) State HANGUP going to sleep 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/11@10.0.200.11:5060) State Change CS_HANGUP -> CS_REPORTING 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/11@10.0.200.11:5060) Running State Change CS_REPORTING (Cur 1 Tot 233) 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/11@10.0.200.11:5060) State REPORTING 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:174 sofia/internal/11@10.0.200.11:5060 Standard REPORTING, cause: LOSE_RACE 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/11@10.0.200.11:5060) State REPORTING going to sleep 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/11@10.0.200.11:5060) State Change CS_REPORTING -> CS_DESTROY 2018-07-23 16:32:58.919839 [DEBUG] switch_core_session.c:1665 Session 231 (sofia/internal/11@10.0.200.11:5060) Locked, Waiting on external entities 2018-07-23 16:32:58.919839 [NOTICE] switch_core_session.c:1683 Session 231 (sofia/internal/11@10.0.200.11:5060) Ended 2018-07-23 16:32:58.919839 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/11@10.0.200.11:5060 [CS_DESTROY] 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/11@10.0.200.11:5060) Running State Change CS_DESTROY (Cur 0 Tot 233) 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/11@10.0.200.11:5060) State DESTROY 2018-07-23 16:32:58.919839 [DEBUG] mod_sofia.c:343 sofia/internal/ 11@10.0.200.11:5060 SOFIA DESTROY 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:181 sofia/internal/11@10.0.200.11:5060 Standard DESTROY 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/11@10.0.200.11:5060) State DESTROY going to sleep
Could you send an actual trace? sofia profile [your-profile] siptrace on On Tue, Jul 24, 2018, 10:35 Paul Muaddib <paul.muaddib83@gmail.com> wrote:
Hi,
I finally managed to setup Telekom DeutschlandLAN Voip sip trunk. Most of it is working now, but some calls get droped without clear reason. After one ring freeswitch drops the call: Originate Failed. Cause: NONE. That happens only if the caller uses a mobile phone. Some mobile phones work, others dont. This was not happening before when I used a ISDN / SIP Gateway.
Here is the log file:
2018-07-23 16:32:57.539715 [NOTICE] switch_channel.c:1104 New Channel sofia/external/+49171XXXXXXX@sip-trunk.telekom.de [1a4d0118-09cc-46e7-906e-c2bfd1cecba1] 2018-07-23 16:32:57.539715 [DEBUG] switch_core_state_machine.c:584 (sofia/external/+@sip-trunk.telekom.de) Running State Change CS_NEW (Cur 1 Tot 229) 2018-07-23 16:32:57.539715 [DEBUG] sofia.c:9873 sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de receiving invite from 217.0.15.67:5060 version: 1.6.20 git 43a9feb 2018-05-07 18:56:11Z 32bit 2018-07-23 16:32:57.539715 [DEBUG] sofia.c:7084 Channel sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de entering state [received][100] 2018-07-23 16:32:57.539715 [DEBUG] sofia.c:7094 Remote SDP: v=0 o=- 1532356377 1532356377 IN IP4 217.0.15.67 s=on transit c=IN IP4 217.0.132.101 t=0 0 a=sendrecv m=audio 22482 RTP/AVP 9 8 100 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:100 telephone-event/8000 a=fmtp:100 0-15 a=maxptime:40 a=ptime:20
2018-07-23 16:32:57.559717 [DEBUG] sofia.c:7486 (sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de) State Change CS_NEW -> CS_INIT 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:603 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State NEW 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:584 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) Running State Change CS_INIT (Cur 1 Tot 229) 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:627 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State INIT 2018-07-23 16:32:57.559717 [DEBUG] mod_sofia.c:90 sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de SOFIA INIT 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:40 sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Standard INIT 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:48 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State Change CS_INIT -> CS_ROUTING 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:627 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State INIT going to sleep 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:584 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) Running State Change CS_ROUTING (Cur 1 Tot 229) 2018-07-23 16:32:57.559717 [DEBUG] switch_channel.c:2249 (sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de) Callstate Change DOWN -> RINGING 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:643 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State ROUTING 2018-07-23 16:32:57.559717 [DEBUG] mod_sofia.c:143 sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de SOFIA ROUTING 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:236 sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Standard ROUTING 2018-07-23 16:32:57.559717 [INFO] mod_dialplan_xml.c:637 Processing +49171XXXXXXX <+49171XXXXXXX>->551130118089 in context public Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de parsing [public->unloop] continue=false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de parsing [public->outside_call] continue=true Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Absolute Condition [outside_call] Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action set(outside_call=true) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de parsing [public->call_debug] continue=true Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Regex (FAIL) [call_debug] ${call_debug}(false) =~ /^true$/ break=never Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de parsing [public->telekom-voip-inbound-main] continue=false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Regex (PASS) [telekom-voip-inbound-main] ${sip_h_P-Called-Party-ID}(< sip:+49XXXXXXXXX@sip-trunk.telekom.de;user=phone>) =~ /(XXXXXXXXX)/ break=on-false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action set(domain_name=10.0.200.2) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action set(effective_caller_id_number=${caller_id_number}) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action set(effective_caller_id_name=${caller_id_number}) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action set(ringback=%(1000,4000,425)) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action transfer(operator XML default) 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:286 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State Change CS_ROUTING -> CS_EXECUTE 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:643 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State ROUTING going to sleep 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:584 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) Running State Change CS_EXECUTE (Cur 1 Tot 229) 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:650 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State EXECUTE 2018-07-23 16:32:57.559717 [DEBUG] mod_sofia.c:198 sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de SOFIA EXECUTE 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:328 sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Standard EXECUTE EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de set(outside_call=true) 2018-07-23 16:32:57.559717 [DEBUG] mod_dptools.c:1548 SET sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de [outside_call]=[true] EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de export(RFC2822_DATE=Mon, 23 Jul 2018 16:32:57 +0200) 2018-07-23 16:32:57.559717 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [RFC2822_DATE]=[Mon, 23 Jul 2018 16:32:57 +0200] EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de set(domain_name=10.0.200.2) 2018-07-23 16:32:57.559717 [DEBUG] mod_dptools.c:1548 SET sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de [domain_name]=[10.0.200.2] EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de set(effective_caller_id_number=+49171XXXXXXX) 2018-07-23 16:32:57.559717 [DEBUG] mod_dptools.c:1548 SET sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de [effective_caller_id_number]=[+49171XXXXXXX] EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de set(effective_caller_id_name=+49171XXXXXXX) 2018-07-23 16:32:57.559717 [DEBUG] mod_dptools.c:1548 SET sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de [effective_caller_id_name]=[+49171XXXXXXX] EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de set(ringback=%(1000,4000,425)) 2018-07-23 16:32:57.559717 [DEBUG] mod_dptools.c:1548 SET sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de [ringback]=[%(1000,4000,425)] EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de transfer(operator XML default) 2018-07-23 16:32:57.559717 [DEBUG] switch_ivr.c:2165 (sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de) State Change CS_EXECUTE -> CS_ROUTING 2018-07-23 16:32:57.559717 [NOTICE] switch_ivr.c:2172 Transfer sofia/external/+49171XXXXXXX@sip-trunk.telekom.de to XML[operator@default] 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:650 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State EXECUTE going to sleep 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:584 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) Running State Change CS_ROUTING (Cur 1 Tot 229) 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:643 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State ROUTING 2018-07-23 16:32:57.559717 [DEBUG] mod_sofia.c:143 sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de SOFIA ROUTING 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:236 sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Standard ROUTING 2018-07-23 16:32:57.559717 [INFO] mod_dialplan_xml.c:637 Processing +49171XXXXXXX <+49171XXXXXXX>->operator in context default Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de parsing [default->unloop] continue=false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de parsing [default->blacklist_check1] continue=false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Regex (FAIL) [blacklist_check1] ${regex(${caller_id_number}|(XXXXXXXXX))}(false) =~ /^true$/ break=on-false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de parsing [default->Time of day] continue=true Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Date/Time Match (PASS) [Time of day] break=never Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action set(office_status=closed) INLINE EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de set(office_status=closed) 2018-07-23 16:32:57.559717 [DEBUG] mod_dptools.c:1548 SET sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de [office_status]=[closed] Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Date/TimeMatch (FAIL) [Time of day] break=never Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de parsing [default->global] continue=true Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Absolute Condition [global] Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action export(nolocal:api_on_answer=uuid_setvar ${uuid} transfer false) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action set(ringback=%(1000,4000,425)) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de parsing [default->global-pickup] continue=false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Regex (FAIL) [global-pickup] destination_number(operator) =~ /^#$/ break=on-false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de parsing [default->local-pickup] continue=false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Regex (FAIL) [local-pickup] destination_number(operator) =~ /^\*\*(\d+)$/ break=on-false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de parsing [default->group_dial_werkstatt] continue=false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Regex (FAIL) [group_dial_werkstatt] destination_number(operator) =~ /^16$/ break=on-false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de parsing [default->Operator] continue=false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Regex (PASS) [Operator] destination_number(operator) =~ /^(operator)$|^(90)$/ break=on-false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action export(dialed_extension=operator) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action set(dialed_user=operator@${domain_name}) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action set(call_timeout=90) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action set(hangup_after_bridge=true) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action set(continue_on_fail=true) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action bind_digit_action(get_digits,~^([1-9][0-9])$,exec:lua,get_digits.lua,peer,self) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action digit_action_set_realm(get_digits) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action ring_ready() |--- Dialplan: Processing recursive conditions level:1 [Operator_recur_1] require-nested=FALSE |--- Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Regex (FAIL) [Operator_recur_1] ${office_status}(closed) =~ /^(open)$/ break=on-true |--- Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Regex (PASS) [Operator_recur_1] ${office_status}(closed) =~ /^(closed)$/ break=on-true |--- Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action bridge(group/buero :_: group/werkstatt,pickup/global) |--- Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action hangup(NO_ANSWER) 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:286 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State Change CS_ROUTING -> CS_EXECUTE 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:643 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State ROUTING going to sleep 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:584 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) Running State Change CS_EXECUTE (Cur 1 Tot 229) 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:650 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State EXECUTE 2018-07-23 16:32:57.559717 [DEBUG] mod_sofia.c:198 sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de SOFIA EXECUTE 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:328 sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Standard EXECUTE EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de export(nolocal:api_on_answer=uuid_setvar 1a4d0118-09cc-46e7-906e-c2bfd1cecba1 transfer false) 2018-07-23 16:32:57.559717 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) (REMOTE ONLY) [api_on_answer]=[uuid_setvar 1a4d0118-09cc-46e7-906e-c2bfd1cecba1 transfer false] EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de set(ringback=%(1000,4000,425)) 2018-07-23 16:32:57.559717 [DEBUG] mod_dptools.c:1548 SET sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de [ringback]=[%(1000,4000,425)] EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de export(dialed_extension=operator) 2018-07-23 16:32:57.559717 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [dialed_extension]=[operator] EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de set(dialed_user= operator@10.0.200.2) 2018-07-23 16:32:57.559717 [DEBUG] mod_dptools.c:1548 SET sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de [dialed_user]=[operator@10.0.200.2] EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de set(call_timeout=90) 2018-07-23 16:32:57.579719 [DEBUG] mod_dptools.c:1548 SET sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de [call_timeout]=[90] EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de set(hangup_after_bridge=true) 2018-07-23 16:32:57.579719 [DEBUG] mod_dptools.c:1548 SET sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de [hangup_after_bridge]=[true] EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de set(continue_on_fail=true) 2018-07-23 16:32:57.579719 [DEBUG] mod_dptools.c:1548 SET sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de [continue_on_fail]=[true] EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de bind_digit_action(get_digits,~^([1-9][0-9])$,exec:lua,get_digits.lua,peer,self) 2018-07-23 16:32:57.579719 [INFO] switch_ivr_async.c:214 Digit parser DPTOOLS: Setting realm to 'get_digits' 2018-07-23 16:32:57.579719 [DEBUG] switch_ivr_async.c:320 Digit parser DPTOOLS: binding ^([1-9][0-9])$/get_digits/0 callback: 0xb58163e0 data: 0x8f414d0 EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de digit_action_set_realm(get_digits) EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de ring_ready() 2018-07-23 16:32:57.579719 [NOTICE] mod_sofia.c:2273 Ring-Ready sofia/external/+49171XXXXXXX@sip-trunk.telekom.de! 2018-07-23 16:32:57.579719 [DEBUG] sofia.c:7084 Channel sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de entering state [early][180] 2018-07-23 16:32:57.579719 [NOTICE] mod_dptools.c:1028 Ring Ready sofia/external/+49171XXXXXXX@sip-trunk.telekom.de! EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de bridge(group/buero :_: group/werkstatt,pickup/global) 2018-07-23 16:32:57.579719 [DEBUG] switch_channel.c:1250 sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de EXPORTING[export_vars] [RFC2822_DATE]=[Mon, 23 Jul 2018 16:32:57 +0200] to event 2018-07-23 16:32:57.579719 [DEBUG] switch_channel.c:1250 sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de EXPORTING[export_vars] [api_on_answer]=[uuid_setvar 1a4d0118-09cc-46e7-906e-c2bfd1cecba1 transfer false] to event 2018-07-23 16:32:57.579719 [DEBUG] switch_channel.c:1250 sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de EXPORTING[export_vars] [dialed_extension]=[operator] to event 2018-07-23 16:32:57.579719 [DEBUG] switch_ivr_originate.c:1548 Parsing ultra-global variables 2018-07-23 16:32:57.579719 [INFO] switch_ivr_originate.c:1614 Sending early media 2018-07-23 16:32:57.579719 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables 2018-07-23 16:32:57.579719 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2018-07-23 16:32:57.579719 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2018-07-23 16:32:57.579719 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2018-07-23 16:32:57.579719 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match 2018-07-23 16:32:57.579719 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2018-07-23 16:32:57.579719 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2018-07-23 16:32:57.579719 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2018-07-23 16:32:57.579719 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2018-07-23 16:32:57.579719 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 100@8000 2018-07-23 16:32:57.579719 [DEBUG] switch_core_media.c:3061 Set Codec sofia/external/+49171XXXXXXX@sip-trunk.telekom.de G722/8000 20 ms 160 samples 64000 bits 1 channels 2018-07-23 16:32:57.579719 [DEBUG] switch_core_codec.c:111 sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de Original read codec set to G722:9 2018-07-23 16:32:57.579719 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 100@8000 2018-07-23 16:32:57.579719 [DEBUG] switch_core_media.c:4767 sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Set 2833 dtmf send payload to 100 recv payload to 100 2018-07-23 16:32:57.579719 [DEBUG] switch_core_media.c:6878 AUDIO RTP [sofia/external/+49171XXXXXXX@sip-trunk.telekom.de] 10.0.200.2 port 7082 -> 217.0.132.101 port 22482 codec: 9 ms: 20 2018-07-23 16:32:57.579719 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables 2018-07-23 16:32:57.579719 [DEBUG] switch_rtp.c:4137 Starting timer [soft] 160 bytes per 20ms 2018-07-23 16:32:57.579719 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables 2018-07-23 16:32:57.579719 [DEBUG] switch_ivr_originate.c:2669 Parsing session specific variables 2018-07-23 16:32:57.579719 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/10@10.0.200.10:5060 [6306dfab-d366-4060-8b39-8e8349f72417] 2018-07-23 16:32:57.579719 [DEBUG] mod_sofia.c:4819 (sofia/internal/ 10@10.0.200.10:5060) State Change CS_NEW -> CS_INIT 2018-07-23 16:32:57.579719 [DEBUG] switch_ivr_originate.c:2669 Parsing session specific variables 2018-07-23 16:32:57.579719 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables 2018-07-23 16:32:57.579719 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/11@10.0.200.11:5060 [ed0352eb-0d61-41f0-87c0-5837c5de4ef8] 2018-07-23 16:32:57.579719 [WARNING] switch_ivr_originate.c:2647 Only calling the first element in the list in this mode. 2018-07-23 16:32:57.579719 [DEBUG] switch_ivr_originate.c:2669 Parsing session specific variables 2018-07-23 16:32:57.579719 [DEBUG] mod_sofia.c:4819 (sofia/internal/ 11@10.0.200.11:5060) State Change CS_NEW -> CS_INIT 2018-07-23 16:32:57.579719 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/15@10.0.200.15:5060 [9c8a2e89-cab4-40f6-b760-4a9e3ea6ef05] 2018-07-23 16:32:57.579719 [DEBUG] mod_sofia.c:4819 (sofia/internal/ 15@10.0.200.15:5060) State Change CS_NEW -> CS_INIT 2018-07-23 16:32:57.579719 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/10@10.0.200.10:5060) Running State Change CS_INIT (Cur 4 Tot 232) 2018-07-23 16:32:57.579719 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/10@10.0.200.10:5060) State INIT 2018-07-23 16:32:57.579719 [DEBUG] mod_sofia.c:90 sofia/internal/ 10@10.0.200.10:5060 SOFIA INIT 2018-07-23 16:32:57.579719 [DEBUG] sofia_glue.c:1295 sofia/internal/ 10@10.0.200.10:5060 sending invite version: 1.6.20 git 43a9feb 2018-05-07 18:56:11Z 32bit Local SDP: v=0 o=FreeSWITCH 1532349289 1532349290 IN IP4 10.0.200.2 s=FreeSWITCH c=IN IP4 10.0.200.2 t=0 0 m=audio 7088 RTP/AVP 8 0 9 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:9 G722/8000 a=ptime:20 a=sendrecv
2018-07-23 16:32:57.579719 [DEBUG] switch_core_state_machine.c:40 sofia/internal/10@10.0.200.10:5060 Standard INIT 2018-07-23 16:32:57.579719 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/10@10.0.200.10:5060) State Change CS_INIT -> CS_ROUTING 2018-07-23 16:32:57.579719 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/10@10.0.200.10:5060) State INIT going to sleep 2018-07-23 16:32:57.579719 [DEBUG] mod_dptools.c:3872 () State Change CS_NEW -> CS_ROUTING 2018-07-23 16:32:57.579719 [NOTICE] switch_channel.c:1104 New Channel pickup/global [66ab149c-54a4-4d17-8428-26e1872e6f9d] 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/11@10.0.200.11:5060) Running State Change CS_INIT (Cur 5 Tot 233) 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/11@10.0.200.11:5060) State INIT 2018-07-23 16:32:57.599721 [DEBUG] mod_sofia.c:90 sofia/internal/ 11@10.0.200.11:5060 SOFIA INIT 2018-07-23 16:32:57.599721 [DEBUG] sofia_glue.c:1295 sofia/internal/ 11@10.0.200.11:5060 sending invite version: 1.6.20 git 43a9feb 2018-05-07 18:56:11Z 32bit Local SDP: v=0 o=FreeSWITCH 1532349305 1532349306 IN IP4 10.0.200.2 s=FreeSWITCH c=IN IP4 10.0.200.2 t=0 0 m=audio 7072 RTP/AVP 8 0 9 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:9 G722/8000 a=ptime:20 a=sendrecv
2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:40 sofia/internal/11@10.0.200.11:5060 Standard INIT 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/11@10.0.200.11:5060) State Change CS_INIT -> CS_ROUTING 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/11@10.0.200.11:5060) State INIT going to sleep 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/11@10.0.200.11:5060) Running State Change CS_ROUTING (Cur 5 Tot 233) 2018-07-23 16:32:57.599721 [DEBUG] sofia.c:7084 Channel sofia/internal/ 11@10.0.200.11:5060 entering state [calling][0] 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/11@10.0.200.11:5060) State ROUTING 2018-07-23 16:32:57.599721 [DEBUG] mod_sofia.c:143 sofia/internal/ 11@10.0.200.11:5060 SOFIA ROUTING 2018-07-23 16:32:57.599721 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/11@10.0.200.11:5060) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/11@10.0.200.11:5060) State ROUTING going to sleep 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/15@10.0.200.15:5060) Running State Change CS_INIT (Cur 5 Tot 233) 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/15@10.0.200.15:5060) State INIT 2018-07-23 16:32:57.599721 [DEBUG] mod_sofia.c:90 sofia/internal/ 15@10.0.200.15:5060 SOFIA INIT 2018-07-23 16:32:57.599721 [DEBUG] sofia_glue.c:1295 sofia/internal/ 15@10.0.200.15:5060 sending invite version: 1.6.20 git 43a9feb 2018-05-07 18:56:11Z 32bit Local SDP: v=0 o=FreeSWITCH 1532349297 1532349298 IN IP4 10.0.200.2 s=FreeSWITCH c=IN IP4 10.0.200.2 t=0 0 m=audio 7080 RTP/AVP 8 0 9 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:9 G722/8000 a=ptime:20 a=sendrecv
2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/11@10.0.200.11:5060) Running State Change CS_CONSUME_MEDIA (Cur 5 Tot 233) 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:40 sofia/internal/15@10.0.200.15:5060 Standard INIT 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/15@10.0.200.15:5060) State Change CS_INIT -> CS_ROUTING 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/15@10.0.200.15:5060) State INIT going to sleep 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/11@10.0.200.11:5060) State CONSUME_MEDIA 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/11@10.0.200.11:5060) State CONSUME_MEDIA going to sleep 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:584 (pickup/global) Running State Change CS_ROUTING (Cur 5 Tot 233) 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/15@10.0.200.15:5060) Running State Change CS_ROUTING (Cur 5 Tot 233) 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:643 (pickup/global) State ROUTING 2018-07-23 16:32:57.599721 [DEBUG] switch_ivr_originate.c:67 (pickup/global) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:643 (pickup/global) State ROUTING going to sleep 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:584 (pickup/global) Running State Change CS_CONSUME_MEDIA (Cur 5 Tot 233) 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:662 (pickup/global) State CONSUME_MEDIA 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:662 (pickup/global) State CONSUME_MEDIA going to sleep 2018-07-23 16:32:57.599721 [DEBUG] sofia.c:7084 Channel sofia/internal/ 15@10.0.200.15:5060 entering state [calling][0] 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/15@10.0.200.15:5060) State ROUTING 2018-07-23 16:32:57.599721 [DEBUG] mod_sofia.c:143 sofia/internal/ 15@10.0.200.15:5060 SOFIA ROUTING 2018-07-23 16:32:57.599721 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/15@10.0.200.15:5060) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/15@10.0.200.15:5060) State ROUTING going to sleep 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/15@10.0.200.15:5060) Running State Change CS_CONSUME_MEDIA (Cur 5 Tot 233) 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/15@10.0.200.15:5060) State CONSUME_MEDIA 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/15@10.0.200.15:5060) State CONSUME_MEDIA going to sleep 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/10@10.0.200.10:5060) Running State Change CS_ROUTING (Cur 5 Tot 233) 2018-07-23 16:32:57.599721 [DEBUG] sofia.c:7084 Channel sofia/internal/ 10@10.0.200.10:5060 entering state [calling][0] 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/10@10.0.200.10:5060) State ROUTING 2018-07-23 16:32:57.599721 [DEBUG] mod_sofia.c:143 sofia/internal/ 10@10.0.200.10:5060 SOFIA ROUTING 2018-07-23 16:32:57.599721 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/10@10.0.200.10:5060) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/10@10.0.200.10:5060) State ROUTING going to sleep 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/10@10.0.200.10:5060) Running State Change CS_CONSUME_MEDIA (Cur 5 Tot 233) 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/10@10.0.200.10:5060) State CONSUME_MEDIA 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/10@10.0.200.10:5060) State CONSUME_MEDIA going to sleep 2018-07-23 16:32:57.599721 [DEBUG] switch_core_media.c:7180 sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Set 2833 dtmf send payload to 100 2018-07-23 16:32:57.599721 [DEBUG] switch_core_media.c:7187 sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Set 2833 dtmf receive payload to 100 2018-07-23 16:32:57.599721 [DEBUG] switch_core_media.c:7210 sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Set rtp dtmf delay to 40 2018-07-23 16:32:57.599721 [NOTICE] sofia_media.c:92 Pre-Answer sofia/external/+49171XXXXXXX@sip-trunk.telekom.de! 2018-07-23 16:32:57.599721 [DEBUG] switch_channel.c:3474 (sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de) Callstate Change RINGING -> EARLY 2018-07-23 16:32:57.619722 [DEBUG] switch_core_media.c:6861 Audio params are unchanged for sofia/external/+49171XXXXXXX@sip-trunk.telekom.de. 2018-07-23 16:32:57.619722 [DEBUG] mod_sofia.c:2364 Ring SDP: v=0 o=FreeSWITCH 1532349295 1532349296 IN IP4 10.0.200.2 s=FreeSWITCH c=IN IP4 10.0.200.2 t=0 0 m=audio 7082 RTP/AVP 9 100 a=rtpmap:9 G722/8000 a=rtpmap:100 telephone-event/8000 a=fmtp:100 0-16 a=ptime:20 a=sendrecv
2018-07-23 16:32:57.619722 [DEBUG] sofia.c:7084 Channel sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de entering state [early][183] 2018-07-23 16:32:57.639724 [DEBUG] sofia.c:7084 Channel sofia/internal/ 15@10.0.200.15:5060 entering state [proceeding][180] 2018-07-23 16:32:57.639724 [NOTICE] sofia.c:7192 Ring-Ready sofia/internal/ 15@10.0.200.15:5060! 2018-07-23 16:32:57.639724 [DEBUG] switch_channel.c:3346 (sofia/internal/ 15@10.0.200.15:5060) Callstate Change DOWN -> RINGING 2018-07-23 16:32:57.639724 [DEBUG] sofia.c:7084 Channel sofia/internal/ 10@10.0.200.10:5060 entering state [proceeding][180] 2018-07-23 16:32:57.639724 [NOTICE] sofia.c:7192 Ring-Ready sofia/internal/ 10@10.0.200.10:5060! 2018-07-23 16:32:57.639724 [DEBUG] switch_channel.c:3346 (sofia/internal/ 10@10.0.200.10:5060) Callstate Change DOWN -> RINGING 2018-07-23 16:32:57.679728 [DEBUG] sofia.c:7084 Channel sofia/internal/ 11@10.0.200.11:5060 entering state [proceeding][180] 2018-07-23 16:32:57.679728 [NOTICE] sofia.c:7192 Ring-Ready sofia/internal/ 11@10.0.200.11:5060! 2018-07-23 16:32:57.679728 [DEBUG] switch_channel.c:3346 (sofia/internal/ 11@10.0.200.11:5060) Callstate Change DOWN -> RINGING 2018-07-23 16:32:58.879835 [DEBUG] sofia.c:7084 Channel sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de entering state [terminated][487] 2018-07-23 16:32:58.879835 [NOTICE] sofia.c:8273 Hangup sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de [CS_EXECUTE] [ORIGINATOR_CANCEL] 2018-07-23 16:32:58.899837 [NOTICE] switch_ivr_originate.c:3612 Hangup sofia/internal/15@10.0.200.15:5060 [CS_CONSUME_MEDIA] [LOSE_RACE] 2018-07-23 16:32:58.899837 [NOTICE] switch_ivr_originate.c:3612 Hangup pickup/global [CS_CONSUME_MEDIA] [LOSE_RACE] 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/15@10.0.200.15:5060) Running State Change CS_HANGUP (Cur 5 Tot 233) 2018-07-23 16:32:58.899837 [DEBUG] switch_ivr_originate.c:3837 Originate Cancelled by originator termination Cause: 487 [ORIGINATOR_CANCEL] 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:584 (pickup/global) Running State Change CS_HANGUP (Cur 5 Tot 233) 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/15@10.0.200.15:5060) Callstate Change RINGING -> HANGUP 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:850 (pickup/global) Callstate Change DOWN -> HANGUP 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:852 (pickup/global) State HANGUP 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/15@10.0.200.15:5060) State HANGUP 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:60 pickup/global Standard HANGUP, cause: LOSE_RACE 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:852 (pickup/global) State HANGUP going to sleep 2018-07-23 16:32:58.899837 [DEBUG] mod_sofia.c:438 Channel sofia/internal/ 15@10.0.200.15:5060 hanging up, cause: LOSE_RACE 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:619 (pickup/global) State Change CS_HANGUP -> CS_REPORTING 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:584 (pickup/global) Running State Change CS_REPORTING (Cur 5 Tot 233) 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:938 (pickup/global) State REPORTING 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:938 (pickup/global) State REPORTING going to sleep 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:610 (pickup/global) State Change CS_REPORTING -> CS_DESTROY 2018-07-23 16:32:58.899837 [DEBUG] switch_core_session.c:1665 Session 233 (pickup/global) Locked, Waiting on external entities 2018-07-23 16:32:58.899837 [NOTICE] switch_core_session.c:1683 Session 233 (pickup/global) Ended 2018-07-23 16:32:58.899837 [NOTICE] switch_core_session.c:1687 Close Channel pickup/global [CS_DESTROY] 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:741 (pickup/global) Running State Change CS_DESTROY (Cur 4 Tot 233) 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:751 (pickup/global) State DESTROY 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:181 pickup/global Standard DESTROY 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:751 (pickup/global) State DESTROY going to sleep 2018-07-23 16:32:58.899837 [NOTICE] switch_ivr_originate.c:3612 Hangup sofia/internal/10@10.0.200.10:5060 [CS_CONSUME_MEDIA] [LOSE_RACE] 2018-07-23 16:32:58.899837 [DEBUG] mod_sofia.c:502 Sending CANCEL to sofia/internal/15@10.0.200.15:5060 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:60 sofia/internal/15@10.0.200.15:5060 Standard HANGUP, cause: LOSE_RACE 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/15@10.0.200.15:5060) State HANGUP going to sleep 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/15@10.0.200.15:5060) State Change CS_HANGUP -> CS_REPORTING 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/15@10.0.200.15:5060) Running State Change CS_REPORTING (Cur 4 Tot 233) 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/15@10.0.200.15:5060) State REPORTING 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:174 sofia/internal/15@10.0.200.15:5060 Standard REPORTING, cause: LOSE_RACE 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/15@10.0.200.15:5060) State REPORTING going to sleep 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/15@10.0.200.15:5060) State Change CS_REPORTING -> CS_DESTROY 2018-07-23 16:32:58.899837 [DEBUG] switch_core_session.c:1665 Session 232 (sofia/internal/15@10.0.200.15:5060) Locked, Waiting on external entities 2018-07-23 16:32:58.899837 [NOTICE] switch_core_session.c:1683 Session 232 (sofia/internal/15@10.0.200.15:5060) Ended 2018-07-23 16:32:58.899837 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/15@10.0.200.15:5060 [CS_DESTROY] 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/15@10.0.200.15:5060) Running State Change CS_DESTROY (Cur 3 Tot 233) 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/15@10.0.200.15:5060) State DESTROY 2018-07-23 16:32:58.899837 [DEBUG] mod_sofia.c:343 sofia/internal/ 15@10.0.200.15:5060 SOFIA DESTROY 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:181 sofia/internal/15@10.0.200.15:5060 Standard DESTROY 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/15@10.0.200.15:5060) State DESTROY going to sleep 2018-07-23 16:32:58.899837 [NOTICE] switch_ivr_originate.c:3612 Hangup sofia/internal/11@10.0.200.11:5060 [CS_CONSUME_MEDIA] [LOSE_RACE] 2018-07-23 16:32:58.899837 [DEBUG] switch_ivr_originate.c:3837 Originate Cancelled by originator termination Cause: 487 [ORIGINATOR_CANCEL] 2018-07-23 16:32:58.899837 [NOTICE] switch_ivr_originate.c:2851 Cannot create outgoing channel of type [group] cause: [LOSE_RACE] 2018-07-23 16:32:58.899837 [DEBUG] switch_ivr_originate.c:3848 Originate Resulted in Error Cause: 502 [LOSE_RACE] 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/10@10.0.200.10:5060) Running State Change CS_HANGUP (Cur 3 Tot 233) 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/10@10.0.200.10:5060) Callstate Change RINGING -> HANGUP 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/10@10.0.200.10:5060) State HANGUP 2018-07-23 16:32:58.899837 [DEBUG] mod_sofia.c:438 Channel sofia/internal/ 10@10.0.200.10:5060 hanging up, cause: LOSE_RACE 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/11@10.0.200.11:5060) Running State Change CS_HANGUP (Cur 3 Tot 233) 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/11@10.0.200.11:5060) Callstate Change RINGING -> HANGUP 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/11@10.0.200.11:5060) State HANGUP 2018-07-23 16:32:58.899837 [DEBUG] mod_sofia.c:438 Channel sofia/internal/ 11@10.0.200.11:5060 hanging up, cause: LOSE_RACE 2018-07-23 16:32:58.899837 [INFO] mod_dptools.c:3436 Originate Failed. Cause: NONE 2018-07-23 16:32:58.899837 [DEBUG] switch_core_session.c:2815 sofia/external/+49171XXXXXXX@sip-trunk.telekom.de skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:650 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State EXECUTE going to sleep 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:584 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) Running State Change CS_HANGUP (Cur 3 Tot 233) 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:850 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) Callstate Change EARLY -> HANGUP 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:852 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State HANGUP 2018-07-23 16:32:58.919839 [DEBUG] mod_sofia.c:438 Channel sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de hanging up, cause: ORIGINATOR_CANCEL 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:60 sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Standard HANGUP, cause: ORIGINATOR_CANCEL 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:852 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State HANGUP going to sleep 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:619 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State Change CS_HANGUP -> CS_REPORTING 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:584 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) Running State Change CS_REPORTING (Cur 3 Tot 233) 2018-07-23 16:32:58.919839 [DEBUG] mod_sofia.c:502 Sending CANCEL to sofia/internal/10@10.0.200.10:5060 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:938 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State REPORTING 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:60 sofia/internal/10@10.0.200.10:5060 Standard HANGUP, cause: LOSE_RACE 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/10@10.0.200.10:5060) State HANGUP going to sleep 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/10@10.0.200.10:5060) State Change CS_HANGUP -> CS_REPORTING 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:174 sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Standard REPORTING, cause: ORIGINATOR_CANCEL 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:938 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State REPORTING going to sleep 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/10@10.0.200.10:5060) Running State Change CS_REPORTING (Cur 3 Tot 233) 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:610 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State Change CS_REPORTING -> CS_DESTROY 2018-07-23 16:32:58.919839 [DEBUG] switch_core_session.c:1665 Session 229 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) Locked, Waiting on external entities 2018-07-23 16:32:58.919839 [NOTICE] switch_core_session.c:1683 Session 229 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) Ended 2018-07-23 16:32:58.919839 [NOTICE] switch_core_session.c:1687 Close Channel sofia/external/+49171XXXXXXX@sip-trunk.telekom.de [CS_DESTROY] 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:741 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) Running State Change CS_DESTROY (Cur 2 Tot 233) 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:751 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State DESTROY 2018-07-23 16:32:58.919839 [DEBUG] mod_sofia.c:343 sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de SOFIA DESTROY 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:181 sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Standard DESTROY 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:751 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State DESTROY going to sleep 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/10@10.0.200.10:5060) State REPORTING 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:174 sofia/internal/10@10.0.200.10:5060 Standard REPORTING, cause: LOSE_RACE 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/10@10.0.200.10:5060) State REPORTING going to sleep 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/10@10.0.200.10:5060) State Change CS_REPORTING -> CS_DESTROY 2018-07-23 16:32:58.919839 [DEBUG] switch_core_session.c:1665 Session 230 (sofia/internal/10@10.0.200.10:5060) Locked, Waiting on external entities 2018-07-23 16:32:58.919839 [NOTICE] switch_core_session.c:1683 Session 230 (sofia/internal/10@10.0.200.10:5060) Ended 2018-07-23 16:32:58.919839 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/10@10.0.200.10:5060 [CS_DESTROY] 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/10@10.0.200.10:5060) Running State Change CS_DESTROY (Cur 1 Tot 233) 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/10@10.0.200.10:5060) State DESTROY 2018-07-23 16:32:58.919839 [DEBUG] mod_sofia.c:343 sofia/internal/ 10@10.0.200.10:5060 SOFIA DESTROY 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:181 sofia/internal/10@10.0.200.10:5060 Standard DESTROY 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/10@10.0.200.10:5060) State DESTROY going to sleep 2018-07-23 16:32:58.919839 [DEBUG] mod_sofia.c:502 Sending CANCEL to sofia/internal/11@10.0.200.11:5060 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:60 sofia/internal/11@10.0.200.11:5060 Standard HANGUP, cause: LOSE_RACE 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/11@10.0.200.11:5060) State HANGUP going to sleep 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/11@10.0.200.11:5060) State Change CS_HANGUP -> CS_REPORTING 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/11@10.0.200.11:5060) Running State Change CS_REPORTING (Cur 1 Tot 233) 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/11@10.0.200.11:5060) State REPORTING 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:174 sofia/internal/11@10.0.200.11:5060 Standard REPORTING, cause: LOSE_RACE 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/11@10.0.200.11:5060) State REPORTING going to sleep 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/11@10.0.200.11:5060) State Change CS_REPORTING -> CS_DESTROY 2018-07-23 16:32:58.919839 [DEBUG] switch_core_session.c:1665 Session 231 (sofia/internal/11@10.0.200.11:5060) Locked, Waiting on external entities 2018-07-23 16:32:58.919839 [NOTICE] switch_core_session.c:1683 Session 231 (sofia/internal/11@10.0.200.11:5060) Ended 2018-07-23 16:32:58.919839 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/11@10.0.200.11:5060 [CS_DESTROY] 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/11@10.0.200.11:5060) Running State Change CS_DESTROY (Cur 0 Tot 233) 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/11@10.0.200.11:5060) State DESTROY 2018-07-23 16:32:58.919839 [DEBUG] mod_sofia.c:343 sofia/internal/ 11@10.0.200.11:5060 SOFIA DESTROY 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:181 sofia/internal/11@10.0.200.11:5060 Standard DESTROY 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/11@10.0.200.11:5060) State DESTROY going to sleep
_________________________________________________________________________ Professional FreeSWITCH Services sales@freeswitch.com https://freeswitch.com
Official FreeSWITCH Sites https://freeswitch.com/oss https://freeswitch.org/confluence https://cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users https://freeswitch.com
Sorry, I could not make a SIP Trace. The error happens only rarely. I removed G722 from the allowed codecs and added <param name="NDLB-allow-bad-iananame" value="true"/> So far I havent had this problem again. Best regards, Paul Am Mo., 30. Juli 2018 um 21:30 Uhr schrieb David Villasmil < david.villasmil.work@gmail.com>:
Could you send an actual trace? sofia profile [your-profile] siptrace on
On Tue, Jul 24, 2018, 10:35 Paul Muaddib <paul.muaddib83@gmail.com> wrote:
Hi,
I finally managed to setup Telekom DeutschlandLAN Voip sip trunk. Most of it is working now, but some calls get droped without clear reason. After one ring freeswitch drops the call: Originate Failed. Cause: NONE. That happens only if the caller uses a mobile phone. Some mobile phones work, others dont. This was not happening before when I used a ISDN / SIP Gateway.
Here is the log file:
2018-07-23 16:32:57.539715 [NOTICE] switch_channel.c:1104 New Channel sofia/external/+49171XXXXXXX@sip-trunk.telekom.de [1a4d0118-09cc-46e7-906e-c2bfd1cecba1] 2018-07-23 16:32:57.539715 [DEBUG] switch_core_state_machine.c:584 (sofia/external/+@sip-trunk.telekom.de) Running State Change CS_NEW (Cur 1 Tot 229) 2018-07-23 16:32:57.539715 [DEBUG] sofia.c:9873 sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de receiving invite from 217.0.15.67:5060 version: 1.6.20 git 43a9feb 2018-05-07 18:56:11Z 32bit 2018-07-23 16:32:57.539715 [DEBUG] sofia.c:7084 Channel sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de entering state [received][100] 2018-07-23 16:32:57.539715 [DEBUG] sofia.c:7094 Remote SDP: v=0 o=- 1532356377 1532356377 IN IP4 217.0.15.67 s=on transit c=IN IP4 217.0.132.101 t=0 0 a=sendrecv m=audio 22482 RTP/AVP 9 8 100 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:100 telephone-event/8000 a=fmtp:100 0-15 a=maxptime:40 a=ptime:20
2018-07-23 16:32:57.559717 [DEBUG] sofia.c:7486 (sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de) State Change CS_NEW -> CS_INIT 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:603 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State NEW 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:584 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) Running State Change CS_INIT (Cur 1 Tot 229) 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:627 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State INIT 2018-07-23 16:32:57.559717 [DEBUG] mod_sofia.c:90 sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de SOFIA INIT 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:40 sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Standard INIT 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:48 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State Change CS_INIT -> CS_ROUTING 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:627 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State INIT going to sleep 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:584 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) Running State Change CS_ROUTING (Cur 1 Tot 229) 2018-07-23 16:32:57.559717 [DEBUG] switch_channel.c:2249 (sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de) Callstate Change DOWN -> RINGING 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:643 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State ROUTING 2018-07-23 16:32:57.559717 [DEBUG] mod_sofia.c:143 sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de SOFIA ROUTING 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:236 sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Standard ROUTING 2018-07-23 16:32:57.559717 [INFO] mod_dialplan_xml.c:637 Processing +49171XXXXXXX <+49171XXXXXXX>->551130118089 in context public Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de parsing [public->unloop] continue=false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de parsing [public->outside_call] continue=true Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Absolute Condition [outside_call] Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action set(outside_call=true) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de parsing [public->call_debug] continue=true Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Regex (FAIL) [call_debug] ${call_debug}(false) =~ /^true$/ break=never Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de parsing [public->telekom-voip-inbound-main] continue=false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Regex (PASS) [telekom-voip-inbound-main] ${sip_h_P-Called-Party-ID}(< sip:+49XXXXXXXXX@sip-trunk.telekom.de;user=phone>) =~ /(XXXXXXXXX)/ break=on-false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action set(domain_name=10.0.200.2) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action set(effective_caller_id_number=${caller_id_number}) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action set(effective_caller_id_name=${caller_id_number}) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action set(ringback=%(1000,4000,425)) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action transfer(operator XML default) 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:286 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State Change CS_ROUTING -> CS_EXECUTE 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:643 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State ROUTING going to sleep 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:584 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) Running State Change CS_EXECUTE (Cur 1 Tot 229) 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:650 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State EXECUTE 2018-07-23 16:32:57.559717 [DEBUG] mod_sofia.c:198 sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de SOFIA EXECUTE 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:328 sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Standard EXECUTE EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de set(outside_call=true) 2018-07-23 16:32:57.559717 [DEBUG] mod_dptools.c:1548 SET sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de [outside_call]=[true] EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de export(RFC2822_DATE=Mon, 23 Jul 2018 16:32:57 +0200) 2018-07-23 16:32:57.559717 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [RFC2822_DATE]=[Mon, 23 Jul 2018 16:32:57 +0200] EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de set(domain_name=10.0.200.2) 2018-07-23 16:32:57.559717 [DEBUG] mod_dptools.c:1548 SET sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de [domain_name]=[10.0.200.2] EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de set(effective_caller_id_number=+49171XXXXXXX) 2018-07-23 16:32:57.559717 [DEBUG] mod_dptools.c:1548 SET sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de [effective_caller_id_number]=[+49171XXXXXXX] EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de set(effective_caller_id_name=+49171XXXXXXX) 2018-07-23 16:32:57.559717 [DEBUG] mod_dptools.c:1548 SET sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de [effective_caller_id_name]=[+49171XXXXXXX] EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de set(ringback=%(1000,4000,425)) 2018-07-23 16:32:57.559717 [DEBUG] mod_dptools.c:1548 SET sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de [ringback]=[%(1000,4000,425)] EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de transfer(operator XML default) 2018-07-23 16:32:57.559717 [DEBUG] switch_ivr.c:2165 (sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de) State Change CS_EXECUTE -> CS_ROUTING 2018-07-23 16:32:57.559717 [NOTICE] switch_ivr.c:2172 Transfer sofia/external/+49171XXXXXXX@sip-trunk.telekom.de to XML[operator@default ] 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:650 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State EXECUTE going to sleep 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:584 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) Running State Change CS_ROUTING (Cur 1 Tot 229) 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:643 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State ROUTING 2018-07-23 16:32:57.559717 [DEBUG] mod_sofia.c:143 sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de SOFIA ROUTING 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:236 sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Standard ROUTING 2018-07-23 16:32:57.559717 [INFO] mod_dialplan_xml.c:637 Processing +49171XXXXXXX <+49171XXXXXXX>->operator in context default Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de parsing [default->unloop] continue=false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de parsing [default->blacklist_check1] continue=false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Regex (FAIL) [blacklist_check1] ${regex(${caller_id_number}|(XXXXXXXXX))}(false) =~ /^true$/ break=on-false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de parsing [default->Time of day] continue=true Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Date/Time Match (PASS) [Time of day] break=never Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action set(office_status=closed) INLINE EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de set(office_status=closed) 2018-07-23 16:32:57.559717 [DEBUG] mod_dptools.c:1548 SET sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de [office_status]=[closed] Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Date/TimeMatch (FAIL) [Time of day] break=never Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de parsing [default->global] continue=true Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Absolute Condition [global] Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action export(nolocal:api_on_answer=uuid_setvar ${uuid} transfer false) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action set(ringback=%(1000,4000,425)) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de parsing [default->global-pickup] continue=false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Regex (FAIL) [global-pickup] destination_number(operator) =~ /^#$/ break=on-false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de parsing [default->local-pickup] continue=false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Regex (FAIL) [local-pickup] destination_number(operator) =~ /^\*\*(\d+)$/ break=on-false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de parsing [default->group_dial_werkstatt] continue=false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Regex (FAIL) [group_dial_werkstatt] destination_number(operator) =~ /^16$/ break=on-false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de parsing [default->Operator] continue=false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Regex (PASS) [Operator] destination_number(operator) =~ /^(operator)$|^(90)$/ break=on-false Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action export(dialed_extension=operator) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action set(dialed_user=operator@${domain_name}) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action set(call_timeout=90) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action set(hangup_after_bridge=true) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action set(continue_on_fail=true) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action bind_digit_action(get_digits,~^([1-9][0-9])$,exec:lua,get_digits.lua,peer,self) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action digit_action_set_realm(get_digits) Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action ring_ready() |--- Dialplan: Processing recursive conditions level:1 [Operator_recur_1] require-nested=FALSE |--- Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Regex (FAIL) [Operator_recur_1] ${office_status}(closed) =~ /^(open)$/ break=on-true |--- Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Regex (PASS) [Operator_recur_1] ${office_status}(closed) =~ /^(closed)$/ break=on-true |--- Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action bridge(group/buero :_: group/werkstatt,pickup/global) |--- Dialplan: sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Action hangup(NO_ANSWER) 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:286 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State Change CS_ROUTING -> CS_EXECUTE 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:643 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State ROUTING going to sleep 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:584 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) Running State Change CS_EXECUTE (Cur 1 Tot 229) 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:650 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State EXECUTE 2018-07-23 16:32:57.559717 [DEBUG] mod_sofia.c:198 sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de SOFIA EXECUTE 2018-07-23 16:32:57.559717 [DEBUG] switch_core_state_machine.c:328 sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Standard EXECUTE EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de export(nolocal:api_on_answer=uuid_setvar 1a4d0118-09cc-46e7-906e-c2bfd1cecba1 transfer false) 2018-07-23 16:32:57.559717 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) (REMOTE ONLY) [api_on_answer]=[uuid_setvar 1a4d0118-09cc-46e7-906e-c2bfd1cecba1 transfer false] EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de set(ringback=%(1000,4000,425)) 2018-07-23 16:32:57.559717 [DEBUG] mod_dptools.c:1548 SET sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de [ringback]=[%(1000,4000,425)] EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de export(dialed_extension=operator) 2018-07-23 16:32:57.559717 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [dialed_extension]=[operator] EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de set(dialed_user=operator@10.0.200.2) 2018-07-23 16:32:57.559717 [DEBUG] mod_dptools.c:1548 SET sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de [dialed_user]=[operator@10.0.200.2] EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de set(call_timeout=90) 2018-07-23 16:32:57.579719 [DEBUG] mod_dptools.c:1548 SET sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de [call_timeout]=[90] EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de set(hangup_after_bridge=true) 2018-07-23 16:32:57.579719 [DEBUG] mod_dptools.c:1548 SET sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de [hangup_after_bridge]=[true] EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de set(continue_on_fail=true) 2018-07-23 16:32:57.579719 [DEBUG] mod_dptools.c:1548 SET sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de [continue_on_fail]=[true] EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de bind_digit_action(get_digits,~^([1-9][0-9])$,exec:lua,get_digits.lua,peer,self) 2018-07-23 16:32:57.579719 [INFO] switch_ivr_async.c:214 Digit parser DPTOOLS: Setting realm to 'get_digits' 2018-07-23 16:32:57.579719 [DEBUG] switch_ivr_async.c:320 Digit parser DPTOOLS: binding ^([1-9][0-9])$/get_digits/0 callback: 0xb58163e0 data: 0x8f414d0 EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de digit_action_set_realm(get_digits) EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de ring_ready() 2018-07-23 16:32:57.579719 [NOTICE] mod_sofia.c:2273 Ring-Ready sofia/external/+49171XXXXXXX@sip-trunk.telekom.de! 2018-07-23 16:32:57.579719 [DEBUG] sofia.c:7084 Channel sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de entering state [early][180] 2018-07-23 16:32:57.579719 [NOTICE] mod_dptools.c:1028 Ring Ready sofia/external/+49171XXXXXXX@sip-trunk.telekom.de! EXECUTE sofia/external/+49171XXXXXXX@sip-trunk.telekom.de bridge(group/buero :_: group/werkstatt,pickup/global) 2018-07-23 16:32:57.579719 [DEBUG] switch_channel.c:1250 sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de EXPORTING[export_vars] [RFC2822_DATE]=[Mon, 23 Jul 2018 16:32:57 +0200] to event 2018-07-23 16:32:57.579719 [DEBUG] switch_channel.c:1250 sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de EXPORTING[export_vars] [api_on_answer]=[uuid_setvar 1a4d0118-09cc-46e7-906e-c2bfd1cecba1 transfer false] to event 2018-07-23 16:32:57.579719 [DEBUG] switch_channel.c:1250 sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de EXPORTING[export_vars] [dialed_extension]=[operator] to event 2018-07-23 16:32:57.579719 [DEBUG] switch_ivr_originate.c:1548 Parsing ultra-global variables 2018-07-23 16:32:57.579719 [INFO] switch_ivr_originate.c:1614 Sending early media 2018-07-23 16:32:57.579719 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables 2018-07-23 16:32:57.579719 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2018-07-23 16:32:57.579719 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2018-07-23 16:32:57.579719 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2018-07-23 16:32:57.579719 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match 2018-07-23 16:32:57.579719 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2018-07-23 16:32:57.579719 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2018-07-23 16:32:57.579719 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2018-07-23 16:32:57.579719 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2018-07-23 16:32:57.579719 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 100@8000 2018-07-23 16:32:57.579719 [DEBUG] switch_core_media.c:3061 Set Codec sofia/external/+49171XXXXXXX@sip-trunk.telekom.de G722/8000 20 ms 160 samples 64000 bits 1 channels 2018-07-23 16:32:57.579719 [DEBUG] switch_core_codec.c:111 sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Original read codec set to G722:9 2018-07-23 16:32:57.579719 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 100@8000 2018-07-23 16:32:57.579719 [DEBUG] switch_core_media.c:4767 sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Set 2833 dtmf send payload to 100 recv payload to 100 2018-07-23 16:32:57.579719 [DEBUG] switch_core_media.c:6878 AUDIO RTP [sofia/external/+49171XXXXXXX@sip-trunk.telekom.de] 10.0.200.2 port 7082 -> 217.0.132.101 port 22482 codec: 9 ms: 20 2018-07-23 16:32:57.579719 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables 2018-07-23 16:32:57.579719 [DEBUG] switch_rtp.c:4137 Starting timer [soft] 160 bytes per 20ms 2018-07-23 16:32:57.579719 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables 2018-07-23 16:32:57.579719 [DEBUG] switch_ivr_originate.c:2669 Parsing session specific variables 2018-07-23 16:32:57.579719 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/10@10.0.200.10:5060 [6306dfab-d366-4060-8b39-8e8349f72417] 2018-07-23 16:32:57.579719 [DEBUG] mod_sofia.c:4819 (sofia/internal/ 10@10.0.200.10:5060) State Change CS_NEW -> CS_INIT 2018-07-23 16:32:57.579719 [DEBUG] switch_ivr_originate.c:2669 Parsing session specific variables 2018-07-23 16:32:57.579719 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables 2018-07-23 16:32:57.579719 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/11@10.0.200.11:5060 [ed0352eb-0d61-41f0-87c0-5837c5de4ef8] 2018-07-23 16:32:57.579719 [WARNING] switch_ivr_originate.c:2647 Only calling the first element in the list in this mode. 2018-07-23 16:32:57.579719 [DEBUG] switch_ivr_originate.c:2669 Parsing session specific variables 2018-07-23 16:32:57.579719 [DEBUG] mod_sofia.c:4819 (sofia/internal/ 11@10.0.200.11:5060) State Change CS_NEW -> CS_INIT 2018-07-23 16:32:57.579719 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/15@10.0.200.15:5060 [9c8a2e89-cab4-40f6-b760-4a9e3ea6ef05] 2018-07-23 16:32:57.579719 [DEBUG] mod_sofia.c:4819 (sofia/internal/ 15@10.0.200.15:5060) State Change CS_NEW -> CS_INIT 2018-07-23 16:32:57.579719 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/10@10.0.200.10:5060) Running State Change CS_INIT (Cur 4 Tot 232) 2018-07-23 16:32:57.579719 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/10@10.0.200.10:5060) State INIT 2018-07-23 16:32:57.579719 [DEBUG] mod_sofia.c:90 sofia/internal/ 10@10.0.200.10:5060 SOFIA INIT 2018-07-23 16:32:57.579719 [DEBUG] sofia_glue.c:1295 sofia/internal/ 10@10.0.200.10:5060 sending invite version: 1.6.20 git 43a9feb 2018-05-07 18:56:11Z 32bit Local SDP: v=0 o=FreeSWITCH 1532349289 1532349290 IN IP4 10.0.200.2 s=FreeSWITCH c=IN IP4 10.0.200.2 t=0 0 m=audio 7088 RTP/AVP 8 0 9 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:9 G722/8000 a=ptime:20 a=sendrecv
2018-07-23 16:32:57.579719 [DEBUG] switch_core_state_machine.c:40 sofia/internal/10@10.0.200.10:5060 Standard INIT 2018-07-23 16:32:57.579719 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/10@10.0.200.10:5060) State Change CS_INIT -> CS_ROUTING 2018-07-23 16:32:57.579719 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/10@10.0.200.10:5060) State INIT going to sleep 2018-07-23 16:32:57.579719 [DEBUG] mod_dptools.c:3872 () State Change CS_NEW -> CS_ROUTING 2018-07-23 16:32:57.579719 [NOTICE] switch_channel.c:1104 New Channel pickup/global [66ab149c-54a4-4d17-8428-26e1872e6f9d] 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/11@10.0.200.11:5060) Running State Change CS_INIT (Cur 5 Tot 233) 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/11@10.0.200.11:5060) State INIT 2018-07-23 16:32:57.599721 [DEBUG] mod_sofia.c:90 sofia/internal/ 11@10.0.200.11:5060 SOFIA INIT 2018-07-23 16:32:57.599721 [DEBUG] sofia_glue.c:1295 sofia/internal/ 11@10.0.200.11:5060 sending invite version: 1.6.20 git 43a9feb 2018-05-07 18:56:11Z 32bit Local SDP: v=0 o=FreeSWITCH 1532349305 1532349306 IN IP4 10.0.200.2 s=FreeSWITCH c=IN IP4 10.0.200.2 t=0 0 m=audio 7072 RTP/AVP 8 0 9 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:9 G722/8000 a=ptime:20 a=sendrecv
2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:40 sofia/internal/11@10.0.200.11:5060 Standard INIT 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/11@10.0.200.11:5060) State Change CS_INIT -> CS_ROUTING 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/11@10.0.200.11:5060) State INIT going to sleep 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/11@10.0.200.11:5060) Running State Change CS_ROUTING (Cur 5 Tot 233) 2018-07-23 16:32:57.599721 [DEBUG] sofia.c:7084 Channel sofia/internal/ 11@10.0.200.11:5060 entering state [calling][0] 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/11@10.0.200.11:5060) State ROUTING 2018-07-23 16:32:57.599721 [DEBUG] mod_sofia.c:143 sofia/internal/ 11@10.0.200.11:5060 SOFIA ROUTING 2018-07-23 16:32:57.599721 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/11@10.0.200.11:5060) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/11@10.0.200.11:5060) State ROUTING going to sleep 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/15@10.0.200.15:5060) Running State Change CS_INIT (Cur 5 Tot 233) 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/15@10.0.200.15:5060) State INIT 2018-07-23 16:32:57.599721 [DEBUG] mod_sofia.c:90 sofia/internal/ 15@10.0.200.15:5060 SOFIA INIT 2018-07-23 16:32:57.599721 [DEBUG] sofia_glue.c:1295 sofia/internal/ 15@10.0.200.15:5060 sending invite version: 1.6.20 git 43a9feb 2018-05-07 18:56:11Z 32bit Local SDP: v=0 o=FreeSWITCH 1532349297 1532349298 IN IP4 10.0.200.2 s=FreeSWITCH c=IN IP4 10.0.200.2 t=0 0 m=audio 7080 RTP/AVP 8 0 9 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:9 G722/8000 a=ptime:20 a=sendrecv
2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/11@10.0.200.11:5060) Running State Change CS_CONSUME_MEDIA (Cur 5 Tot 233) 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:40 sofia/internal/15@10.0.200.15:5060 Standard INIT 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/15@10.0.200.15:5060) State Change CS_INIT -> CS_ROUTING 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/15@10.0.200.15:5060) State INIT going to sleep 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/11@10.0.200.11:5060) State CONSUME_MEDIA 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/11@10.0.200.11:5060) State CONSUME_MEDIA going to sleep 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:584 (pickup/global) Running State Change CS_ROUTING (Cur 5 Tot 233) 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/15@10.0.200.15:5060) Running State Change CS_ROUTING (Cur 5 Tot 233) 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:643 (pickup/global) State ROUTING 2018-07-23 16:32:57.599721 [DEBUG] switch_ivr_originate.c:67 (pickup/global) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:643 (pickup/global) State ROUTING going to sleep 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:584 (pickup/global) Running State Change CS_CONSUME_MEDIA (Cur 5 Tot 233) 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:662 (pickup/global) State CONSUME_MEDIA 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:662 (pickup/global) State CONSUME_MEDIA going to sleep 2018-07-23 16:32:57.599721 [DEBUG] sofia.c:7084 Channel sofia/internal/ 15@10.0.200.15:5060 entering state [calling][0] 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/15@10.0.200.15:5060) State ROUTING 2018-07-23 16:32:57.599721 [DEBUG] mod_sofia.c:143 sofia/internal/ 15@10.0.200.15:5060 SOFIA ROUTING 2018-07-23 16:32:57.599721 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/15@10.0.200.15:5060) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/15@10.0.200.15:5060) State ROUTING going to sleep 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/15@10.0.200.15:5060) Running State Change CS_CONSUME_MEDIA (Cur 5 Tot 233) 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/15@10.0.200.15:5060) State CONSUME_MEDIA 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/15@10.0.200.15:5060) State CONSUME_MEDIA going to sleep 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/10@10.0.200.10:5060) Running State Change CS_ROUTING (Cur 5 Tot 233) 2018-07-23 16:32:57.599721 [DEBUG] sofia.c:7084 Channel sofia/internal/ 10@10.0.200.10:5060 entering state [calling][0] 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/10@10.0.200.10:5060) State ROUTING 2018-07-23 16:32:57.599721 [DEBUG] mod_sofia.c:143 sofia/internal/ 10@10.0.200.10:5060 SOFIA ROUTING 2018-07-23 16:32:57.599721 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/10@10.0.200.10:5060) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/10@10.0.200.10:5060) State ROUTING going to sleep 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/10@10.0.200.10:5060) Running State Change CS_CONSUME_MEDIA (Cur 5 Tot 233) 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/10@10.0.200.10:5060) State CONSUME_MEDIA 2018-07-23 16:32:57.599721 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/10@10.0.200.10:5060) State CONSUME_MEDIA going to sleep 2018-07-23 16:32:57.599721 [DEBUG] switch_core_media.c:7180 sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Set 2833 dtmf send payload to 100 2018-07-23 16:32:57.599721 [DEBUG] switch_core_media.c:7187 sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Set 2833 dtmf receive payload to 100 2018-07-23 16:32:57.599721 [DEBUG] switch_core_media.c:7210 sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Set rtp dtmf delay to 40 2018-07-23 16:32:57.599721 [NOTICE] sofia_media.c:92 Pre-Answer sofia/external/+49171XXXXXXX@sip-trunk.telekom.de! 2018-07-23 16:32:57.599721 [DEBUG] switch_channel.c:3474 (sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de) Callstate Change RINGING -> EARLY 2018-07-23 16:32:57.619722 [DEBUG] switch_core_media.c:6861 Audio params are unchanged for sofia/external/+49171XXXXXXX@sip-trunk.telekom.de. 2018-07-23 16:32:57.619722 [DEBUG] mod_sofia.c:2364 Ring SDP: v=0 o=FreeSWITCH 1532349295 1532349296 IN IP4 10.0.200.2 s=FreeSWITCH c=IN IP4 10.0.200.2 t=0 0 m=audio 7082 RTP/AVP 9 100 a=rtpmap:9 G722/8000 a=rtpmap:100 telephone-event/8000 a=fmtp:100 0-16 a=ptime:20 a=sendrecv
2018-07-23 16:32:57.619722 [DEBUG] sofia.c:7084 Channel sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de entering state [early][183] 2018-07-23 16:32:57.639724 [DEBUG] sofia.c:7084 Channel sofia/internal/ 15@10.0.200.15:5060 entering state [proceeding][180] 2018-07-23 16:32:57.639724 [NOTICE] sofia.c:7192 Ring-Ready sofia/internal/15@10.0.200.15:5060! 2018-07-23 16:32:57.639724 [DEBUG] switch_channel.c:3346 (sofia/internal/ 15@10.0.200.15:5060) Callstate Change DOWN -> RINGING 2018-07-23 16:32:57.639724 [DEBUG] sofia.c:7084 Channel sofia/internal/ 10@10.0.200.10:5060 entering state [proceeding][180] 2018-07-23 16:32:57.639724 [NOTICE] sofia.c:7192 Ring-Ready sofia/internal/10@10.0.200.10:5060! 2018-07-23 16:32:57.639724 [DEBUG] switch_channel.c:3346 (sofia/internal/ 10@10.0.200.10:5060) Callstate Change DOWN -> RINGING 2018-07-23 16:32:57.679728 [DEBUG] sofia.c:7084 Channel sofia/internal/ 11@10.0.200.11:5060 entering state [proceeding][180] 2018-07-23 16:32:57.679728 [NOTICE] sofia.c:7192 Ring-Ready sofia/internal/11@10.0.200.11:5060! 2018-07-23 16:32:57.679728 [DEBUG] switch_channel.c:3346 (sofia/internal/ 11@10.0.200.11:5060) Callstate Change DOWN -> RINGING 2018-07-23 16:32:58.879835 [DEBUG] sofia.c:7084 Channel sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de entering state [terminated][487] 2018-07-23 16:32:58.879835 [NOTICE] sofia.c:8273 Hangup sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de [CS_EXECUTE] [ORIGINATOR_CANCEL] 2018-07-23 16:32:58.899837 [NOTICE] switch_ivr_originate.c:3612 Hangup sofia/internal/15@10.0.200.15:5060 [CS_CONSUME_MEDIA] [LOSE_RACE] 2018-07-23 16:32:58.899837 [NOTICE] switch_ivr_originate.c:3612 Hangup pickup/global [CS_CONSUME_MEDIA] [LOSE_RACE] 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/15@10.0.200.15:5060) Running State Change CS_HANGUP (Cur 5 Tot 233) 2018-07-23 16:32:58.899837 [DEBUG] switch_ivr_originate.c:3837 Originate Cancelled by originator termination Cause: 487 [ORIGINATOR_CANCEL] 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:584 (pickup/global) Running State Change CS_HANGUP (Cur 5 Tot 233) 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/15@10.0.200.15:5060) Callstate Change RINGING -> HANGUP 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:850 (pickup/global) Callstate Change DOWN -> HANGUP 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:852 (pickup/global) State HANGUP 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/15@10.0.200.15:5060) State HANGUP 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:60 pickup/global Standard HANGUP, cause: LOSE_RACE 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:852 (pickup/global) State HANGUP going to sleep 2018-07-23 16:32:58.899837 [DEBUG] mod_sofia.c:438 Channel sofia/internal/ 15@10.0.200.15:5060 hanging up, cause: LOSE_RACE 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:619 (pickup/global) State Change CS_HANGUP -> CS_REPORTING 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:584 (pickup/global) Running State Change CS_REPORTING (Cur 5 Tot 233) 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:938 (pickup/global) State REPORTING 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:938 (pickup/global) State REPORTING going to sleep 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:610 (pickup/global) State Change CS_REPORTING -> CS_DESTROY 2018-07-23 16:32:58.899837 [DEBUG] switch_core_session.c:1665 Session 233 (pickup/global) Locked, Waiting on external entities 2018-07-23 16:32:58.899837 [NOTICE] switch_core_session.c:1683 Session 233 (pickup/global) Ended 2018-07-23 16:32:58.899837 [NOTICE] switch_core_session.c:1687 Close Channel pickup/global [CS_DESTROY] 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:741 (pickup/global) Running State Change CS_DESTROY (Cur 4 Tot 233) 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:751 (pickup/global) State DESTROY 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:181 pickup/global Standard DESTROY 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:751 (pickup/global) State DESTROY going to sleep 2018-07-23 16:32:58.899837 [NOTICE] switch_ivr_originate.c:3612 Hangup sofia/internal/10@10.0.200.10:5060 [CS_CONSUME_MEDIA] [LOSE_RACE] 2018-07-23 16:32:58.899837 [DEBUG] mod_sofia.c:502 Sending CANCEL to sofia/internal/15@10.0.200.15:5060 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:60 sofia/internal/15@10.0.200.15:5060 Standard HANGUP, cause: LOSE_RACE 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/15@10.0.200.15:5060) State HANGUP going to sleep 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/15@10.0.200.15:5060) State Change CS_HANGUP -> CS_REPORTING 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/15@10.0.200.15:5060) Running State Change CS_REPORTING (Cur 4 Tot 233) 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/15@10.0.200.15:5060) State REPORTING 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:174 sofia/internal/15@10.0.200.15:5060 Standard REPORTING, cause: LOSE_RACE 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/15@10.0.200.15:5060) State REPORTING going to sleep 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/15@10.0.200.15:5060) State Change CS_REPORTING -> CS_DESTROY 2018-07-23 16:32:58.899837 [DEBUG] switch_core_session.c:1665 Session 232 (sofia/internal/15@10.0.200.15:5060) Locked, Waiting on external entities 2018-07-23 16:32:58.899837 [NOTICE] switch_core_session.c:1683 Session 232 (sofia/internal/15@10.0.200.15:5060) Ended 2018-07-23 16:32:58.899837 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/15@10.0.200.15:5060 [CS_DESTROY] 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/15@10.0.200.15:5060) Running State Change CS_DESTROY (Cur 3 Tot 233) 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/15@10.0.200.15:5060) State DESTROY 2018-07-23 16:32:58.899837 [DEBUG] mod_sofia.c:343 sofia/internal/ 15@10.0.200.15:5060 SOFIA DESTROY 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:181 sofia/internal/15@10.0.200.15:5060 Standard DESTROY 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/15@10.0.200.15:5060) State DESTROY going to sleep 2018-07-23 16:32:58.899837 [NOTICE] switch_ivr_originate.c:3612 Hangup sofia/internal/11@10.0.200.11:5060 [CS_CONSUME_MEDIA] [LOSE_RACE] 2018-07-23 16:32:58.899837 [DEBUG] switch_ivr_originate.c:3837 Originate Cancelled by originator termination Cause: 487 [ORIGINATOR_CANCEL] 2018-07-23 16:32:58.899837 [NOTICE] switch_ivr_originate.c:2851 Cannot create outgoing channel of type [group] cause: [LOSE_RACE] 2018-07-23 16:32:58.899837 [DEBUG] switch_ivr_originate.c:3848 Originate Resulted in Error Cause: 502 [LOSE_RACE] 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/10@10.0.200.10:5060) Running State Change CS_HANGUP (Cur 3 Tot 233) 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/10@10.0.200.10:5060) Callstate Change RINGING -> HANGUP 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/10@10.0.200.10:5060) State HANGUP 2018-07-23 16:32:58.899837 [DEBUG] mod_sofia.c:438 Channel sofia/internal/ 10@10.0.200.10:5060 hanging up, cause: LOSE_RACE 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/11@10.0.200.11:5060) Running State Change CS_HANGUP (Cur 3 Tot 233) 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/11@10.0.200.11:5060) Callstate Change RINGING -> HANGUP 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/11@10.0.200.11:5060) State HANGUP 2018-07-23 16:32:58.899837 [DEBUG] mod_sofia.c:438 Channel sofia/internal/ 11@10.0.200.11:5060 hanging up, cause: LOSE_RACE 2018-07-23 16:32:58.899837 [INFO] mod_dptools.c:3436 Originate Failed. Cause: NONE 2018-07-23 16:32:58.899837 [DEBUG] switch_core_session.c:2815 sofia/external/+49171XXXXXXX@sip-trunk.telekom.de skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:650 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State EXECUTE going to sleep 2018-07-23 16:32:58.899837 [DEBUG] switch_core_state_machine.c:584 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) Running State Change CS_HANGUP (Cur 3 Tot 233) 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:850 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) Callstate Change EARLY -> HANGUP 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:852 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State HANGUP 2018-07-23 16:32:58.919839 [DEBUG] mod_sofia.c:438 Channel sofia/external/+49171XXXXXXX@sip-trunk.telekom.de hanging up, cause: ORIGINATOR_CANCEL 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:60 sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Standard HANGUP, cause: ORIGINATOR_CANCEL 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:852 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State HANGUP going to sleep 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:619 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State Change CS_HANGUP -> CS_REPORTING 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:584 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) Running State Change CS_REPORTING (Cur 3 Tot 233) 2018-07-23 16:32:58.919839 [DEBUG] mod_sofia.c:502 Sending CANCEL to sofia/internal/10@10.0.200.10:5060 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:938 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State REPORTING 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:60 sofia/internal/10@10.0.200.10:5060 Standard HANGUP, cause: LOSE_RACE 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/10@10.0.200.10:5060) State HANGUP going to sleep 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/10@10.0.200.10:5060) State Change CS_HANGUP -> CS_REPORTING 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:174 sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Standard REPORTING, cause: ORIGINATOR_CANCEL 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:938 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State REPORTING going to sleep 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/10@10.0.200.10:5060) Running State Change CS_REPORTING (Cur 3 Tot 233) 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:610 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State Change CS_REPORTING -> CS_DESTROY 2018-07-23 16:32:58.919839 [DEBUG] switch_core_session.c:1665 Session 229 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) Locked, Waiting on external entities 2018-07-23 16:32:58.919839 [NOTICE] switch_core_session.c:1683 Session 229 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) Ended 2018-07-23 16:32:58.919839 [NOTICE] switch_core_session.c:1687 Close Channel sofia/external/+49171XXXXXXX@sip-trunk.telekom.de [CS_DESTROY] 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:741 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) Running State Change CS_DESTROY (Cur 2 Tot 233) 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:751 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State DESTROY 2018-07-23 16:32:58.919839 [DEBUG] mod_sofia.c:343 sofia/external/+ 49171XXXXXXX@sip-trunk.telekom.de SOFIA DESTROY 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:181 sofia/external/+49171XXXXXXX@sip-trunk.telekom.de Standard DESTROY 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:751 (sofia/external/+49171XXXXXXX@sip-trunk.telekom.de) State DESTROY going to sleep 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/10@10.0.200.10:5060) State REPORTING 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:174 sofia/internal/10@10.0.200.10:5060 Standard REPORTING, cause: LOSE_RACE 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/10@10.0.200.10:5060) State REPORTING going to sleep 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/10@10.0.200.10:5060) State Change CS_REPORTING -> CS_DESTROY 2018-07-23 16:32:58.919839 [DEBUG] switch_core_session.c:1665 Session 230 (sofia/internal/10@10.0.200.10:5060) Locked, Waiting on external entities 2018-07-23 16:32:58.919839 [NOTICE] switch_core_session.c:1683 Session 230 (sofia/internal/10@10.0.200.10:5060) Ended 2018-07-23 16:32:58.919839 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/10@10.0.200.10:5060 [CS_DESTROY] 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/10@10.0.200.10:5060) Running State Change CS_DESTROY (Cur 1 Tot 233) 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/10@10.0.200.10:5060) State DESTROY 2018-07-23 16:32:58.919839 [DEBUG] mod_sofia.c:343 sofia/internal/ 10@10.0.200.10:5060 SOFIA DESTROY 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:181 sofia/internal/10@10.0.200.10:5060 Standard DESTROY 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/10@10.0.200.10:5060) State DESTROY going to sleep 2018-07-23 16:32:58.919839 [DEBUG] mod_sofia.c:502 Sending CANCEL to sofia/internal/11@10.0.200.11:5060 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:60 sofia/internal/11@10.0.200.11:5060 Standard HANGUP, cause: LOSE_RACE 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/11@10.0.200.11:5060) State HANGUP going to sleep 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/11@10.0.200.11:5060) State Change CS_HANGUP -> CS_REPORTING 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/11@10.0.200.11:5060) Running State Change CS_REPORTING (Cur 1 Tot 233) 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/11@10.0.200.11:5060) State REPORTING 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:174 sofia/internal/11@10.0.200.11:5060 Standard REPORTING, cause: LOSE_RACE 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/11@10.0.200.11:5060) State REPORTING going to sleep 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/11@10.0.200.11:5060) State Change CS_REPORTING -> CS_DESTROY 2018-07-23 16:32:58.919839 [DEBUG] switch_core_session.c:1665 Session 231 (sofia/internal/11@10.0.200.11:5060) Locked, Waiting on external entities 2018-07-23 16:32:58.919839 [NOTICE] switch_core_session.c:1683 Session 231 (sofia/internal/11@10.0.200.11:5060) Ended 2018-07-23 16:32:58.919839 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/11@10.0.200.11:5060 [CS_DESTROY] 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/11@10.0.200.11:5060) Running State Change CS_DESTROY (Cur 0 Tot 233) 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/11@10.0.200.11:5060) State DESTROY 2018-07-23 16:32:58.919839 [DEBUG] mod_sofia.c:343 sofia/internal/ 11@10.0.200.11:5060 SOFIA DESTROY 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:181 sofia/internal/11@10.0.200.11:5060 Standard DESTROY 2018-07-23 16:32:58.919839 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/11@10.0.200.11:5060) State DESTROY going to sleep
_________________________________________________________________________ Professional FreeSWITCH Services sales@freeswitch.com https://freeswitch.com
Official FreeSWITCH Sites https://freeswitch.com/oss https://freeswitch.org/confluence https://cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users https://freeswitch.com
_________________________________________________________________________ Professional FreeSWITCH Services sales@freeswitch.com https://freeswitch.com
Official FreeSWITCH Sites https://freeswitch.com/oss https://freeswitch.org/confluence https://cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users https://freeswitch.com
participants (2)
-
David Villasmil
-
Paul Muaddib