span style="color: cornflowerblue; font-weight: bold;"> 2019-01-30 14:58:11.685449 [NOTICE] switch_channel.c:1104 New Channel sofia/default/0117896884@172.31.32.71 [f584c9b5-b274-4348-b31d-d2232a1f6272]
2019-01-30 14:58:11.685449 [DEBUG] switch_core_state_machine.c:584 (sofia/default/0117896884@172.31.32.71) Running State Change CS_NEW (Cur 1 Tot 142006)
2019-01-30 14:58:11.685449 [DEBUG] sofia.c:9746 sofia/default/0117896884@172.31.32.71 receiving invite from 172.31.42.61:5060 version: 1.6.13 64bit
2019-01-30 14:58:11.685449 [DEBUG] sofia.c:9858 IP 172.31.42.61 Approved by acl "default[]". Access Granted.
2019-01-30 14:58:11.685449 [DEBUG] sofia.c:7014 Channel sofia/default/0117896884@172.31.32.71 entering state [received][100]
2019-01-30 14:58:11.685449 [DEBUG] sofia.c:7024 Remote SDP:
v=0
o=FreeSWITCH 1548835251 1548835252 IN IP4 172.31.42.61
s=FreeSWITCH
c=IN IP4 172.31.42.61
t=0 0
m=audio 19154 RTP/AVP 0 101 13
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
2019-01-30 14:58:11.685449 [DEBUG] switch_core_media.c:4344 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G729:18:8000:20:8000:1]
2019-01-30 14:58:11.685449 [DEBUG] switch_core_media.c:4344 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2019-01-30 14:58:11.685449 [DEBUG] switch_core_media.c:4373 Bah HUMBUG! Sticking with PCMU@8000h@20i
2019-01-30 14:58:11.685449 [DEBUG] switch_core_media.c:4399 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2019-01-30 14:58:11.685449 [DEBUG] switch_core_media.c:4344 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2019-01-30 14:58:11.685449 [DEBUG] switch_core_media.c:4260 Set telephone-event payload to 101@8000
2019-01-30 14:58:11.685449 [DEBUG] switch_core_media.c:3043 Set Codec sofia/default/0117896884@172.31.32.71 PCMU/8000 20 ms 160 samples 64000 bits 1 channels
2019-01-30 14:58:11.685449 [DEBUG] switch_core_codec.c:111 sofia/default/0117896884@172.31.32.71 Original read codec set to PCMU:0
2019-01-30 14:58:11.685449 [DEBUG] switch_core_media.c:4603 Set telephone-event payload to 101@8000
2019-01-30 14:58:11.685449 [DEBUG] switch_core_media.c:4662 sofia/default/0117896884@172.31.32.71 Set 2833 dtmf send payload to 101 recv payload to 101
2019-01-30 14:58:11.685449 [DEBUG] sofia.c:7413 (sofia/default/0117896884@172.31.32.71) State Change CS_NEW -> CS_INIT
2019-01-30 14:58:11.685449 [DEBUG] switch_core_state_machine.c:603 (sofia/default/0117896884@172.31.32.71) State NEW
2019-01-30 14:58:11.685449 [DEBUG] switch_core_state_machine.c:584 (sofia/default/0117896884@172.31.32.71) Running State Change CS_INIT (Cur 1 Tot 142006)
2019-01-30 14:58:11.685449 [DEBUG] switch_core_state_machine.c:627 (sofia/default/0117896884@172.31.32.71) State INIT
2019-01-30 14:58:11.685449 [DEBUG] mod_sofia.c:90 sofia/default/0117896884@172.31.32.71 SOFIA INIT
2019-01-30 14:58:11.685449 [DEBUG] switch_core_state_machine.c:40 sofia/default/0117896884@172.31.32.71 Standard INIT
2019-01-30 14:58:11.685449 [DEBUG] switch_core_state_machine.c:48 (sofia/default/0117896884@172.31.32.71) State Change CS_INIT -> CS_ROUTING
2019-01-30 14:58:11.685449 [DEBUG] switch_core_state_machine.c:627 (sofia/default/0117896884@172.31.32.71) State INIT going to sleep
2019-01-30 14:58:11.685449 [DEBUG] switch_core_state_machine.c:584 (sofia/default/0117896884@172.31.32.71) Running State Change CS_ROUTING (Cur 1 Tot 142006)
2019-01-30 14:58:11.685449 [DEBUG] switch_channel.c:2249 (sofia/default/0117896884@172.31.32.71) Callstate Change DOWN -> RINGING
2019-01-30 14:58:11.685449 [DEBUG] switch_core_state_machine.c:643 (sofia/default/0117896884@172.31.32.71) State ROUTING
2019-01-30 14:58:11.685449 [DEBUG] mod_sofia.c:143 sofia/default/0117896884@172.31.32.71 SOFIA ROUTING
2019-01-30 14:58:11.685449 [DEBUG] switch_core_state_machine.c:236 sofia/default/0117896884@172.31.32.71 Standard ROUTING
2019-01-30 14:58:11.685449 [INFO] mod_dialplan_xml.c:637 Processing 0117896884 <0117896884>->999990117896884 in context default
Dialplan: sofia/default/0117896884@172.31.32.71 parsing [default->CustomVoicemail] continue=false
Dialplan: sofia/default/0117896884@172.31.32.71 Regex (PASS) [CustomVoicemail] destination_number(999990117896884) =~ /^[a-zA-Z0-9_.-]*$/ break=on-false
Dialplan: sofia/default/0117896884@172.31.32.71 Action set(send_silence_when_idle=400)
Dialplan: sofia/default/0117896884@172.31.32.71 Action answer()
Dialplan: sofia/default/0117896884@172.31.32.71 Action sleep(2000)
Dialplan: sofia/default/0117896884@172.31.32.71 Action lua(astpp.dialplan.lua)
2019-01-30 14:58:11.685449 [DEBUG] switch_core_state_machine.c:286 (sofia/default/0117896884@172.31.32.71) State Change CS_ROUTING -> CS_EXECUTE
2019-01-30 14:58:11.685449 [DEBUG] switch_core_state_machine.c:643 (sofia/default/0117896884@172.31.32.71) State ROUTING going to sleep
2019-01-30 14:58:11.685449 [DEBUG] switch_core_state_machine.c:584 (sofia/default/0117896884@172.31.32.71) Running State Change CS_EXECUTE (Cur 1 Tot 142006)
2019-01-30 14:58:11.685449 [DEBUG] switch_core_state_machine.c:650 (sofia/default/0117896884@172.31.32.71) State EXECUTE
2019-01-30 14:58:11.685449 [DEBUG] mod_sofia.c:198 sofia/default/0117896884@172.31.32.71 SOFIA EXECUTE
2019-01-30 14:58:11.685449 [DEBUG] switch_core_state_machine.c:328 sofia/default/0117896884@172.31.32.71 Standard EXECUTE
EXECUTE sofia/default/0117896884@172.31.32.71 set(send_silence_when_idle=400)
2019-01-30 14:58:11.685449 [DEBUG] mod_dptools.c:1527 SET sofia/default/0117896884@172.31.32.71 [send_silence_when_idle]=[400]
EXECUTE sofia/default/0117896884@172.31.32.71 answer()
2019-01-30 14:58:11.685449 [DEBUG] switch_core_media.c:6640 AUDIO RTP [sofia/default/0117896884@172.31.32.71] 172.31.32.71 port 21534 -> 172.31.42.61 port 19154 codec: 0 ms: 20
2019-01-30 14:58:11.685449 [DEBUG] switch_rtp.c:3878 Starting timer [soft] 160 bytes per 20ms
2019-01-30 14:58:11.705435 [DEBUG] switch_rtp.c:7976 Activate VAD codec PCMU 20ms
2019-01-30 14:58:11.705435 [DEBUG] switch_core_media.c:6813 AUDIO RTP Engage VAD for sofia/default/0117896884@172.31.32.71 ( in )
2019-01-30 14:58:11.705435 [DEBUG] switch_core_media.c:6946 sofia/default/0117896884@172.31.32.71 Set 2833 dtmf send payload to 101
2019-01-30 14:58:11.705435 [DEBUG] switch_core_media.c:6953 sofia/default/0117896884@172.31.32.71 Set 2833 dtmf receive payload to 101
2019-01-30 14:58:11.705435 [DEBUG] switch_core_media.c:6976 sofia/default/0117896884@172.31.32.71 Set rtp dtmf delay to 40
2019-01-30 14:58:11.705435 [DEBUG] mod_sofia.c:822 Local SDP sofia/default/0117896884@172.31.32.71:
v=0
o=FreeSWITCH 1548831557 1548831558 IN IP4 172.31.32.71
s=FreeSWITCH
c=IN IP4 172.31.32.71
t=0 0
m=audio 21534 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=fmtp:18 annexb=no
a=ptime:20
a=sendrecv
2019-01-30 14:58:11.705435 [NOTICE] mod_dptools.c:1309 Channel [sofia/default/0117896884@172.31.32.71] has been answered
2019-01-30 14:58:11.705435 [DEBUG] switch_channel.c:3772 (sofia/default/0117896884@172.31.32.71) Callstate Change RINGING -> ACTIVE
2019-01-30 14:58:11.705435 [DEBUG] sofia.c:7014 Channel sofia/default/0117896884@172.31.32.71 entering state [completed][200]
EXECUTE sofia/default/0117896884@172.31.32.71 sleep(2000)
2019-01-30 14:58:11.705435 [DEBUG] switch_ivr.c:195 Codec Activated L16@8000hz 1 channels 20ms
2019-01-30 14:58:11.705435 [DEBUG] sofia.c:7014 Channel sofia/default/0117896884@172.31.32.71 entering state [ready][200]
2019-01-30 14:58:12.085443 [DEBUG] switch_rtp.c:6970 Correct audio ip/port confirmed.
EXECUTE sofia/default/0117896884@172.31.32.71 lua(astpp.dialplan.lua)
2019-01-30 14:58:13.725435 [INFO] switch_cpp.cpp:1360 ===============================FAX APPLICATION========================!!!
EXECUTE sofia/default/0117896884@172.31.32.71 set(fax_enable_t38_request=true)
2019-01-30 14:58:13.725435 [DEBUG] mod_dptools.c:1527 SET sofia/default/0117896884@172.31.32.71 [fax_enable_t38_request]=[true]
EXECUTE sofia/default/0117896884@172.31.32.71 set(fax_enable_t38=true)
2019-01-30 14:58:13.725435 [DEBUG] mod_dptools.c:1527 SET sofia/default/0117896884@172.31.32.71 [fax_enable_t38]=[true]
EXECUTE sofia/default/0117896884@172.31.32.71 set(t38_passthru=true)
2019-01-30 14:58:13.725435 [DEBUG] mod_dptools.c:1527 SET sofia/default/0117896884@172.31.32.71 [t38_passthru]=[true]
EXECUTE sofia/default/0117896884@172.31.32.71 set(session_in_hangup_hook=true)
2019-01-30 14:58:13.725435 [DEBUG] mod_dptools.c:1527 SET sofia/default/0117896884@172.31.32.71 [session_in_hangup_hook]=[true]
EXECUTE sofia/default/0117896884@172.31.32.71 rxfax(/tmp/f584c9b5-b274-4348-b31d-d2232a1f6272-FAX.tif)
2019-01-30 14:58:13.725435 [DEBUG] mod_spandsp_fax.c:1440 Raw read codec activation Success L16 20000
2019-01-30 14:58:13.725435 [DEBUG] switch_core_codec.c:223 sofia/default/0117896884@172.31.32.71 Push codec L16:100
2019-01-30 14:58:13.725435 [DEBUG] mod_spandsp_fax.c:1458 Raw write codec activation Success L16
2019-01-30 14:58:13.725435 [DEBUG] switch_ivr.c:195 Codec Activated L16@8000hz 1 channels 20ms
2019-01-30 14:58:14.045435 [DEBUG] sofia.c:7014 Channel sofia/default/0117896884@172.31.32.71 entering state [received][100]
2019-01-30 14:58:14.045435 [DEBUG] sofia.c:7024 Remote SDP:
v=0
o=FreeSWITCH 1548835251 1548835253 IN IP4 172.31.42.61
s=FreeSWITCH
c=IN IP4 172.31.42.61
t=0 0
m=image 19154 udptl t38
a=T38FaxVersion:0
a=T38MaxBitRate:14400
a=T38FaxFillBitRemoval
a=T38FaxRateManagement:transferredTCF
a=T38FaxMaxBuffer:2000
a=T38FaxMaxDatagram:400
a=T38FaxUdpEC:t38UDPRedundancy
2019-01-30 14:58:14.065422 [DEBUG] mod_spandsp_fax.c:1037 T38 SDP Origin = FreeSWITCH
2019-01-30 14:58:14.065422 [DEBUG] mod_spandsp_fax.c:1038 T38FaxVersion = 0
2019-01-30 14:58:14.065422 [DEBUG] mod_spandsp_fax.c:1039 T38MaxBitRate = 14400
2019-01-30 14:58:14.065422 [DEBUG] mod_spandsp_fax.c:1040 T38FaxFillBitRemoval = 1
2019-01-30 14:58:14.065422 [DEBUG] mod_spandsp_fax.c:1041 T38FaxTranscodingMMR = 0
2019-01-30 14:58:14.065422 [DEBUG] mod_spandsp_fax.c:1042 T38FaxTranscodingJBIG = 0
2019-01-30 14:58:14.065422 [DEBUG] mod_spandsp_fax.c:1043 T38FaxRateManagement = 'transferredTCF'
2019-01-30 14:58:14.065422 [DEBUG] mod_spandsp_fax.c:1044 T38FaxMaxBuffer = 2000
2019-01-30 14:58:14.065422 [DEBUG] mod_spandsp_fax.c:1045 T38FaxMaxDatagram = 400
2019-01-30 14:58:14.065422 [DEBUG] mod_spandsp_fax.c:1046 T38FaxUdpEC = 't38UDPRedundancy'
2019-01-30 14:58:14.065422 [DEBUG] mod_spandsp_fax.c:1047 T38VendorInfo = ''
2019-01-30 14:58:14.065422 [DEBUG] mod_spandsp_fax.c:1048 ip = '172.31.42.61'
2019-01-30 14:58:14.065422 [DEBUG] mod_spandsp_fax.c:1050 port = 19154
2019-01-30 14:58:14.065422 [DEBUG] switch_core_media.c:9506 Remote address:port [172.31.42.61:19154] has not changed.
2019-01-30 14:58:14.065422 [DEBUG] switch_core_media.c:9145 sofia/default/0117896884@172.31.32.71 image media sdp:
v=0
o=FreeSWITCH 1548831557 1548831559 IN IP4 172.31.32.71
s=FreeSWITCH
c=IN IP4 172.31.32.71
t=0 0
m=image 21534 udptl t38
a=T38FaxVersion:0
a=T38MaxBitRate:14400
a=T38FaxFillBitRemoval
a=T38FaxRateManagement:transferredTCF
a=T38FaxMaxBuffer:2000
a=T38FaxMaxDatagram:400
a=T38FaxUdpEC:t38UDPRedundancy
2019-01-30 14:58:14.065422 [DEBUG] switch_core_media.c:9506 Remote address:port [172.31.42.61:19154] has not changed.
2019-01-30 14:58:14.065422 [DEBUG] sofia.c:7014 Channel sofia/default/0117896884@172.31.32.71 entering state [completed][200]
2019-01-30 14:58:14.085422 [DEBUG] sofia.c:7014 Channel sofia/default/0117896884@172.31.32.71 entering state [ready][200]
2019-01-30 14:58:21.705451 [DEBUG] mod_spandsp_fax.c:317 === Negotiation Result =======================================================
2019-01-30 14:58:21.705451 [DEBUG] mod_spandsp_fax.c:318 Remote station id: SpanDSP Fax Ident
2019-01-30 14:58:21.705451 [DEBUG] mod_spandsp_fax.c:319 Local station id: SpanDSP Fax Ident
2019-01-30 14:58:21.705451 [DEBUG] mod_spandsp_fax.c:320 Transfer Rate: 14400
2019-01-30 14:58:21.705451 [DEBUG] mod_spandsp_fax.c:322 ECM status on
2019-01-30 14:58:21.705451 [DEBUG] mod_spandsp_fax.c:323 remote country:
2019-01-30 14:58:21.705451 [DEBUG] mod_spandsp_fax.c:324 remote vendor:
2019-01-30 14:58:21.705451 [DEBUG] mod_spandsp_fax.c:325 remote model:
2019-01-30 14:58:21.705451 [DEBUG] mod_spandsp_fax.c:327 ==============================================================================
2019-01-30 14:58:55.585432 [DEBUG] mod_spandsp_fax.c:428 ==== Page Received ===========================================================
2019-01-30 14:58:55.585432 [DEBUG] mod_spandsp_fax.c:429 Page no = 1
2019-01-30 14:58:55.585432 [DEBUG] mod_spandsp_fax.c:430 Image type = bi-level (bi-level in the file)
2019-01-30 14:58:55.585432 [DEBUG] mod_spandsp_fax.c:431 Image size = 1728 x 2156 pixels (1728 x 2156 pixels in the file)
2019-01-30 14:58:55.585432 [DEBUG] mod_spandsp_fax.c:432 Image resolution = 8040/m x 7700/m (8040/m x 7700/m in the file)
2019-01-30 14:58:55.585432 [DEBUG] mod_spandsp_fax.c:433 Compression = T.85(L0) (32)
2019-01-30 14:58:55.585432 [DEBUG] mod_spandsp_fax.c:434 Compressed image size = 46632 bytes
2019-01-30 14:58:55.585432 [DEBUG] mod_spandsp_fax.c:435 Bad rows = 0
2019-01-30 14:58:55.585432 [DEBUG] mod_spandsp_fax.c:436 Longest bad row run = 0
2019-01-30 14:58:55.585432 [DEBUG] mod_spandsp_fax.c:437 ==============================================================================
2019-01-30 14:58:57.945459 [DEBUG] mod_spandsp_fax.c:496 ==============================================================================
2019-01-30 14:58:57.945459 [DEBUG] mod_spandsp_fax.c:502 Fax successfully received.
2019-01-30 14:58:57.945459 [DEBUG] mod_spandsp_fax.c:513 Remote station id: SpanDSP Fax Ident
2019-01-30 14:58:57.945459 [DEBUG] mod_spandsp_fax.c:514 Local station id: SpanDSP Fax Ident
2019-01-30 14:58:57.945459 [DEBUG] mod_spandsp_fax.c:515 Pages transferred: 1
2019-01-30 14:58:57.945459 [DEBUG] mod_spandsp_fax.c:517 Total fax pages: 1
2019-01-30 14:58:57.945459 [DEBUG] mod_spandsp_fax.c:518 Image resolution: 8040x7700
2019-01-30 14:58:57.945459 [DEBUG] mod_spandsp_fax.c:519 Transfer Rate: 14400
2019-01-30 14:58:57.945459 [DEBUG] mod_spandsp_fax.c:521 ECM status on
2019-01-30 14:58:57.945459 [DEBUG] mod_spandsp_fax.c:522 remote country:
2019-01-30 14:58:57.945459 [DEBUG] mod_spandsp_fax.c:523 remote vendor:
2019-01-30 14:58:57.945459 [DEBUG] mod_spandsp_fax.c:524 remote model:
2019-01-30 14:58:57.945459 [DEBUG] mod_spandsp_fax.c:526 ==============================================================================
2019-01-30 14:58:57.945459 [DEBUG] switch_core_codec.c:248 sofia/default/0117896884@172.31.32.71 Restore previous codec PCMU:0.
EXECUTE sofia/default/0117896884@172.31.32.71 set(api_hangup_hook=system /var/www/html/astpp/FAX/scripts/emailfax.sh /tmp/f584c9b5-b274-4348-b31d-d2232a1f6272-FAX.tif 0117896884 Hardik devang.nathwani%40inextrix.com /tmp/f584c9b5-b274-4348-b31d-d2232a1f6272-FAX.tif)
2019-01-30 14:58:57.945459 [DEBUG] mod_dptools.c:1527 SET sofia/default/0117896884@172.31.32.71 [api_hangup_hook]=[system /var/www/html/astpp/FAX/scripts/emailfax.sh /tmp/f584c9b5-b274-4348-b31d-d2232a1f6272-FAX.tif 0117896884 Hardik devang.nathwani%40inextrix.com /tmp/f584c9b5-b274-4348-b31d-d2232a1f6272-FAX.tif]
2019-01-30 14:58:57.945459 [INFO] switch_cpp.cpp:1360 =======================================================================!!!
2019-01-30 14:58:57.945459 [DEBUG] switch_cpp.cpp:722 CoreSession::hangup
2019-01-30 14:58:57.945459 [NOTICE] switch_cpp.cpp:724 Hangup sofia/default/0117896884@172.31.32.71 [CS_EXECUTE] [NORMAL_CLEARING]
2019-01-30 14:58:57.945459 [DEBUG] switch_cpp.cpp:1107 sofia/default/0117896884@172.31.32.71 destroy/unlink session from object
2019-01-30 14:58:57.945459 [DEBUG] switch_core_session.c:2797 sofia/default/0117896884@172.31.32.71 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2019-01-30 14:58:57.945459 [DEBUG] switch_core_state_machine.c:650 (sofia/default/0117896884@172.31.32.71) State EXECUTE going to sleep
2019-01-30 14:58:57.945459 [DEBUG] switch_core_state_machine.c:584 (sofia/default/0117896884@172.31.32.71) Running State Change CS_HANGUP (Cur 1 Tot 142006)
2019-01-30 14:58:57.945459 [DEBUG] switch_core_state_machine.c:850 (sofia/default/0117896884@172.31.32.71) Callstate Change ACTIVE -> HANGUP
2019-01-30 14:58:57.945459 [DEBUG] switch_core_state_machine.c:852 (sofia/default/0117896884@172.31.32.71) State HANGUP
2019-01-30 14:58:57.945459 [DEBUG] mod_sofia.c:438 Channel sofia/default/0117896884@172.31.32.71 hanging up, cause: NORMAL_CLEARING
2019-01-30 14:58:57.945459 [DEBUG] mod_sofia.c:491 Sending BYE to sofia/default/0117896884@172.31.32.71
2019-01-30 14:58:57.945459 [DEBUG] switch_core_state_machine.c:60 sofia/default/0117896884@172.31.32.71 Standard HANGUP, cause: NORMAL_CLEARING
2019-01-30 14:58:57.945459 [DEBUG] switch_core_state_machine.c:852 (sofia/default/0117896884@172.31.32.71) State HANGUP going to sleep
2019-01-30 14:58:59.805425 [DEBUG] switch_core_state_machine.c:783 Hangup Command with Session system(/var/www/html/astpp/FAX/scripts/emailfax.sh /tmp/f584c9b5-b274-4348-b31d-d2232a1f6272-FAX.tif 0117896884 Hardik devang.nathwani%40inextrix.com /tmp/f584c9b5-b274-4348-b31d-d2232a1f6272-FAX.tif):
2019-01-30 14:58:59.805425 [DEBUG] switch_core_state_machine.c:619 (sofia/default/0117896884@172.31.32.71) State Change CS_HANGUP -> CS_REPORTING
2019-01-30 14:58:59.805425 [DEBUG] switch_core_state_machine.c:584 (sofia/default/0117896884@172.31.32.71) Running State Change CS_REPORTING (Cur 1 Tot 142006)
2019-01-30 14:58:59.805425 [DEBUG] switch_core_state_machine.c:938 (sofia/default/0117896884@172.31.32.71) State REPORTING
2019-01-30 14:58:59.805425 [DEBUG] switch_core_state_machine.c:174 sofia/default/0117896884@172.31.32.71 Standard REPORTING, cause: NORMAL_CLEARING
2019-01-30 14:58:59.805425 [DEBUG] switch_core_state_machine.c:938 (sofia/default/0117896884@172.31.32.71) State REPORTING going to sleep
2019-01-30 14:58:59.805425 [DEBUG] switch_core_state_machine.c:610 (sofia/default/0117896884@172.31.32.71) State Change CS_REPORTING -> CS_DESTROY
2019-01-30 14:58:59.805425 [DEBUG] switch_core_session.c:1647 Session 142006 (sofia/default/0117896884@172.31.32.71) Locked, Waiting on external entities
2019-01-30 14:58:59.805425 [NOTICE] switch_core_session.c:1665 Session 142006 (sofia/default/0117896884@172.31.32.71) Ended
2019-01-30 14:58:59.805425 [NOTICE] switch_core_session.c:1669 Close Channel sofia/default/0117896884@172.31.32.71 [CS_DESTROY]
2019-01-30 14:58:59.805425 [DEBUG] switch_core_state_machine.c:741 (sofia/default/0117896884@172.31.32.71) Running State Change CS_DESTROY (Cur 0 Tot 142006)
2019-01-30 14:58:59.805425 [DEBUG] switch_core_state_machine.c:751 (sofia/default/0117896884@172.31.32.71) State DESTROY
2019-01-30 14:58:59.805425 [DEBUG] mod_sofia.c:343 sofia/default/0117896884@172.31.32.71 SOFIA DESTROY
2019-01-30 14:58:59.805425 [DEBUG] switch_core_state_machine.c:181 sofia/default/0117896884@172.31.32.71 Standard DESTROY
2019-01-30 14:58:59.805425 [DEBUG] switch_core_state_machine.c:751 (sofia/default/0117896884@172.31.32.71) State DESTROY going to sleep
2019-01-30 14:59:05.265446 [WARNING] sofia_reg.c:1792 SIP auth challenge (REGISTER) on sofia profile 'default' for [30208215@172.31.32.71] from ip 172.31.38.3