2017-06-20 22:42:53.947939 [DEBUG] switch_core_state_machine.c:40 sofia/external/XXXXXXXXXX Standard INIT
2017-06-20 22:42:53.947939 [DEBUG] switch_core_state_machine.c:48 (sofia/external/XXXXXXXXXX) State Change CS_INIT -> CS_ROUTING
2017-06-20 22:42:53.947939 [DEBUG] switch_core_state_machine.c:516 (sofia/external/XXXXXXXXXX) State INIT going to sleep
2017-06-20 22:42:53.947939 [DEBUG] switch_core_state_machine.c:473 (sofia/external/XXXXXXXXXX) Running State Change CS_ROUTING
2017-06-20 22:42:53.947939 [DEBUG] sofia.c:6760 Channel sofia/external/XXXXXXXXXX entering state [calling][0]
2017-06-20 22:42:53.947939 [DEBUG] switch_core_state_machine.c:532 (sofia/external/XXXXXXXXXX) State ROUTING
2017-06-20 22:42:53.947939 [DEBUG] mod_sofia.c:141 sofia/external/XXXXXXXXXX SOFIA ROUTING
2017-06-20 22:42:53.947939 [DEBUG] switch_ivr_originate.c:67 (sofia/external/XXXXXXXXXX) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2017-06-20 22:42:53.947939 [DEBUG] switch_core_state_machine.c:532 (sofia/external/XXXXXXXXXX) State ROUTING going to sleep
2017-06-20 22:42:53.947939 [DEBUG] switch_core_state_machine.c:473 (sofia/external/XXXXXXXXXX) Running State Change CS_CONSUME_MEDIA
2017-06-20 22:42:53.947939 [DEBUG] switch_core_state_machine.c:551 (sofia/external/XXXXXXXXXX) State CONSUME_MEDIA
2017-06-20 22:42:53.947939 [DEBUG] switch_core_state_machine.c:551 (sofia/external/XXXXXXXXXX) State CONSUME_MEDIA going to sleep
2017-06-20 22:42:54.087940 [DEBUG] sofia.c:6760 Channel sofia/external/XXXXXXXXXX entering state [terminated][403]
2017-06-20 22:42:54.087940 [NOTICE] sofia.c:7779 Hangup sofia/external/XXXXXXXXXX [CS_CONSUME_MEDIA] [CALL_REJECTED]
2017-06-20 22:42:54.087940 [DEBUG] switch_core_state_machine.c:473 (sofia/external/XXXXXXXXXX) Running State Change CS_HANGUP
2017-06-20 22:42:54.087940 [DEBUG] switch_core_state_machine.c:739 (sofia/external/XXXXXXXXXX) Callstate Change DOWN -> HANGUP
2017-06-20 22:42:54.087940 [DEBUG] switch_core_state_machine.c:741 (sofia/external/XXXXXXXXXX) State HANGUP
2017-06-20 22:42:54.087940 [DEBUG] mod_sofia.c:431 Channel sofia/external/XXXXXXXXXX hanging up, cause: CALL_REJECTED
2017-06-20 22:42:54.087940 [DEBUG] switch_core_state_machine.c:60 sofia/external/XXXXXXXXXX Standard HANGUP, cause: CALL_REJECTED
2017-06-20 22:42:54.087940 [DEBUG] switch_core_state_machine.c:741 (sofia/external/XXXXXXXXXX) State HANGUP going to sleep
2017-06-20 22:42:54.087940 [DEBUG] switch_core_state_machine.c:508 (sofia/external/XXXXXXXXXX) State Change CS_HANGUP -> CS_REPORTING
2017-06-20 22:42:54.087940 [DEBUG] switch_core_state_machine.c:473 (sofia/external/XXXXXXXXXX) Running State Change CS_REPORTING
2017-06-20 22:42:54.087940 [DEBUG] switch_core_state_machine.c:827 (sofia/external/XXXXXXXXXX) State REPORTING
2017-06-20 22:42:54.087940 [DEBUG] switch_core_state_machine.c:104 sofia/external/XXXXXXXXXX Standard REPORTING, cause: CALL_REJECTED
2017-06-20 22:42:54.087940 [DEBUG] switch_core_state_machine.c:827 (sofia/external/XXXXXXXXXX) State REPORTING going to sleep
2017-06-20 22:42:54.087940 [DEBUG] switch_core_state_machine.c:499 (sofia/external/XXXXXXXXXX) State Change CS_REPORTING -> CS_DESTROY
2017-06-20 22:42:54.087940 [DEBUG] switch_core_session.c:1646 Session 14 (sofia/external/XXXXXXXXXX) Locked, Waiting on external entities
2017-06-20 22:42:54.107935 [DEBUG] switch_ivr_originate.c:3751 Originate Resulted in Error Cause: 21 [CALL_REJECTED]
2017-06-20 22:42:54.107935 [NOTICE] switch_core_session.c:1664 Session 14 (sofia/external/XXXXXXXXXX) Ended
2017-06-20 22:42:54.107935 [NOTICE] switch_core_session.c:1668 Close Channel sofia/external/XXXXXXXXXX [CS_DESTROY]
2017-06-20 22:42:54.107935 [DEBUG] switch_core_state_machine.c:630 (sofia/external/XXXXXXXXXX) Running State Change CS_DESTROY
2017-06-20 22:42:54.107935 [INFO] mod_dptools.c:3379 Originate Failed.  Cause: CALL_REJECTED
2017-06-20 22:42:54.107935 [DEBUG] switch_core_state_machine.c:640 (sofia/external/XXXXXXXXXX) State DESTROY
2017-06-20 22:42:54.107935 [DEBUG] mod_sofia.c:341 sofia/external/XXXXXXXXXX SOFIA DESTROY
2017-06-20 22:42:54.107935 [DEBUG] switch_core_state_machine.c:111 sofia/external/XXXXXXXXXX Standard DESTROY
2017-06-20 22:42:54.107935 [DEBUG] switch_core_state_machine.c:640 (sofia/external/XXXXXXXXXX) State DESTROY going to sleep
EXECUTE sofia/external/12146846400@999.999.999.2 bridge(sofia/gateway/3c820e49-450b-4626-8bbe-561188fc09f2/XXXXXXXXXX)
2017-06-20 22:42:54.107935 [DEBUG] switch_channel.c:1247 sofia/external/12146846400@999.999.999.2 EXPORTING[export_vars] [origination_callee_id_name]=[XXXXXXXXXX] to event
2017-06-20 22:42:54.107935 [DEBUG] switch_channel.c:1247 sofia/external/12146846400@999.999.999.2 EXPORTING[export_vars] [dialed_extension]=[1502] to event
2017-06-20 22:42:54.107935 [DEBUG] switch_channel.c:1247 sofia/external/12146846400@999.999.999.2 EXPORTING[export_vars] [origination_callee_id_name]=[XXXXXXXXXX] to event
2017-06-20 22:42:54.107935 [DEBUG] switch_channel.c:1247 sofia/external/12146846400@999.999.999.2 EXPORTING[export_vars] [origination_callee_id_name]=[XXXXXXXXXX] to event
2017-06-20 22:42:54.107935 [DEBUG] switch_ivr_originate.c:2128 Parsing global variables
2017-06-20 22:42:54.107935 [NOTICE] switch_channel.c:1101 New Channel sofia/external/XXXXXXXXXX [b52f5008-5633-11e7-8041-4d076d508355]
2017-06-20 22:42:54.107935 [DEBUG] mod_sofia.c:4776 (sofia/external/XXXXXXXXXX) State Change CS_NEW -> CS_INIT
2017-06-20 22:42:54.107935 [DEBUG] switch_core_state_machine.c:473 (sofia/external/XXXXXXXXXX) Running State Change CS_INIT
2017-06-20 22:42:54.107935 [DEBUG] switch_core_state_machine.c:516 (sofia/external/XXXXXXXXXX) State INIT
2017-06-20 22:42:54.107935 [DEBUG] mod_sofia.c:88 sofia/external/XXXXXXXXXX SOFIA INIT
2017-06-20 22:42:54.107935 [DEBUG] sofia_glue.c:1257 sofia/external/XXXXXXXXXX sending invite version: 1.6.6  64bit
Local SDP:
v=0
o=FreeSWITCH 1497991928 1497991929 IN IP4 999.999.999.3
s=FreeSWITCH
c=IN IP4 999.999.999.3
t=0 0
m=audio 24646 RTP/AVP 0 101 13
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=ptime:20
a=sendrecv

2017-06-20 22:42:54.107935 [DEBUG] switch_core_state_machine.c:40 sofia/external/XXXXXXXXXX Standard INIT
2017-06-20 22:42:54.107935 [DEBUG] switch_core_state_machine.c:48 (sofia/external/XXXXXXXXXX) State Change CS_INIT -> CS_ROUTING
2017-06-20 22:42:54.107935 [DEBUG] switch_core_state_machine.c:516 (sofia/external/XXXXXXXXXX) State INIT going to sleep
2017-06-20 22:42:54.107935 [DEBUG] switch_core_state_machine.c:473 (sofia/external/XXXXXXXXXX) Running State Change CS_ROUTING
2017-06-20 22:42:54.107935 [DEBUG] sofia.c:6760 Channel sofia/external/XXXXXXXXXX entering state [calling][0]
2017-06-20 22:42:54.107935 [DEBUG] switch_core_state_machine.c:532 (sofia/external/XXXXXXXXXX) State ROUTING
2017-06-20 22:42:54.107935 [DEBUG] mod_sofia.c:141 sofia/external/XXXXXXXXXX SOFIA ROUTING
2017-06-20 22:42:54.107935 [DEBUG] switch_ivr_originate.c:67 (sofia/external/XXXXXXXXXX) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2017-06-20 22:42:54.107935 [DEBUG] switch_core_state_machine.c:532 (sofia/external/XXXXXXXXXX) State ROUTING going to sleep
2017-06-20 22:42:54.107935 [DEBUG] switch_core_state_machine.c:473 (sofia/external/XXXXXXXXXX) Running State Change CS_CONSUME_MEDIA
2017-06-20 22:42:54.107935 [DEBUG] switch_core_state_machine.c:551 (sofia/external/XXXXXXXXXX) State CONSUME_MEDIA
2017-06-20 22:42:54.107935 [DEBUG] switch_core_state_machine.c:551 (sofia/external/XXXXXXXXXX) State CONSUME_MEDIA going to sleep

HERE'S THE DELAY


2017-06-20 22:42:57.547949 [DEBUG] sofia.c:6760 Channel sofia/external/XXXXXXXXXX entering state [proceeding][183]
2017-06-20 22:42:57.547949 [DEBUG] sofia.c:6770 Remote SDP:
v=0
o=FreeSWITCH 2838459558 2838459560 IN IP4 162.212.218.151
s=FreeSWITCH
c=IN IP4 162.212.218.151
t=0 0
m=audio 49540 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=maxptime:20

2017-06-20 22:42:57.547949 [DEBUG] switch_core_media.c:4161 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2017-06-20 22:42:57.547949 [DEBUG] switch_core_media.c:4216 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2017-06-20 22:42:57.547949 [DEBUG] switch_core_media.c:4077 Set telephone-event payload to 101@8000
2017-06-20 22:42:57.547949 [DEBUG] switch_core_media.c:2906 Set Codec sofia/external/XXXXXXXXXX PCMU/8000 20 ms 160 samples 64000 bits 1 channels
2017-06-20 22:42:57.547949 [DEBUG] switch_core_codec.c:111 sofia/external/XXXXXXXXXX Original read codec set to PCMU:0
2017-06-20 22:42:57.547949 [DEBUG] switch_core_media.c:4429 Set telephone-event payload to 101@8000
2017-06-20 22:42:57.547949 [DEBUG] switch_core_media.c:4485 sofia/external/XXXXXXXXXX Set 2833 dtmf send payload to 101 recv payload to 101
2017-06-20 22:42:57.547949 [DEBUG] switch_core_media.c:6033 AUDIO RTP [sofia/external/XXXXXXXXXX] 999.999.999.3 port 24646 -> 162.212.218.151 port 49540 codec: 0 ms: 20
2017-06-20 22:42:57.547949 [DEBUG] switch_rtp.c:3802 Starting timer [soft] 160 bytes per 20ms
2017-06-20 22:42:57.547949 [DEBUG] switch_core_media.c:6332 sofia/external/XXXXXXXXXX Set 2833 dtmf send payload to 101
2017-06-20 22:42:57.547949 [DEBUG] switch_core_media.c:6339 sofia/external/XXXXXXXXXX Set 2833 dtmf receive payload to 101
2017-06-20 22:42:57.547949 [DEBUG] switch_core_media.c:6362 sofia/external/XXXXXXXXXX Set rtp dtmf delay to 40
2017-06-20 22:42:57.547949 [NOTICE] sofia_media.c:92 Pre-Answer sofia/external/XXXXXXXXXX!