· 7 years ago · Nov 23, 2017, 02:16 PM
12017-11-23 06:13:21.935268 [NOTICE] switch_channel.c:1104 New Channel sofia/external/dialer@208.64.5.163 [2248fe02-8a3d-4c65-b83b-462425cf531e]
22017-11-23 06:13:21.935268 [DEBUG] switch_core_state_machine.c:584 (sofia/external/dialer@208.64.5.163) Running State Change CS_NEW
32017-11-23 06:13:21.935268 [DEBUG] sofia.c:9603 sofia/external/dialer@208.64.5.163 receiving invite from 208.64.5.201:5060 version: 1.6.12 -20-b91a0a6 64bit
42017-11-23 06:13:21.935268 [DEBUG] sofia.c:6965 Channel sofia/external/dialer@208.64.5.163 entering state [received][100]
52017-11-23 06:13:21.935268 [DEBUG] sofia.c:6975 Remote SDP:
6v=0
7o=aculab-00119801 12096 12096 IN IP4 10.10.19.201
8s=-
9c=IN IP4 10.10.19.201
10t=0 0
11m=audio 33114 RTP/AVP 0 8 18 96
12a=rtpmap:0 PCMU/8000
13a=rtpmap:8 PCMA/8000
14a=rtpmap:18 G729/8000
15a=rtpmap:96 telephone-event/8000
16a=fmtp:96 0-15
17a=ptime:20
18a=ptime:20
19a=ptime:30
20
212017-11-23 06:13:21.935268 [DEBUG] sofia.c:7343 (sofia/external/dialer@208.64.5.163) State Change CS_NEW -> CS_INIT
222017-11-23 06:13:21.935268 [DEBUG] switch_core_state_machine.c:603 (sofia/external/dialer@208.64.5.163) State NEW
232017-11-23 06:13:21.935268 [DEBUG] switch_core_state_machine.c:584 (sofia/external/dialer@208.64.5.163) Running State Change CS_INIT
242017-11-23 06:13:21.935268 [DEBUG] switch_core_state_machine.c:627 (sofia/external/dialer@208.64.5.163) State INIT
252017-11-23 06:13:21.935268 [DEBUG] mod_sofia.c:90 sofia/external/dialer@208.64.5.163 SOFIA INIT
262017-11-23 06:13:21.935268 [DEBUG] switch_core_state_machine.c:40 sofia/external/dialer@208.64.5.163 Standard INIT
272017-11-23 06:13:21.935268 [DEBUG] switch_core_state_machine.c:48 (sofia/external/dialer@208.64.5.163) State Change CS_INIT -> CS_ROUTING
282017-11-23 06:13:21.935268 [DEBUG] switch_core_state_machine.c:627 (sofia/external/dialer@208.64.5.163) State INIT going to sleep
292017-11-23 06:13:21.935268 [DEBUG] switch_core_state_machine.c:584 (sofia/external/dialer@208.64.5.163) Running State Change CS_ROUTING
302017-11-23 06:13:21.935268 [DEBUG] switch_channel.c:2249 (sofia/external/dialer@208.64.5.163) Callstate Change DOWN -> RINGING
312017-11-23 06:13:21.935268 [DEBUG] switch_core_state_machine.c:643 (sofia/external/dialer@208.64.5.163) State ROUTING
322017-11-23 06:13:21.935268 [DEBUG] mod_sofia.c:143 sofia/external/dialer@208.64.5.163 SOFIA ROUTING
332017-11-23 06:13:21.935268 [DEBUG] switch_core_state_machine.c:236 sofia/external/dialer@208.64.5.163 Standard ROUTING
342017-11-23 06:13:21.935268 [INFO] mod_dialplan_xml.c:637 Processing dialer <dialer>->sipb_gustavo in context public
35Dialplan: sofia/external/dialer@208.64.5.163 parsing [public->unloop] continue=false
36Dialplan: sofia/external/dialer@208.64.5.163 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
37Dialplan: sofia/external/dialer@208.64.5.163 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
38Dialplan: sofia/external/dialer@208.64.5.163 parsing [public->outside_call] continue=true
39Dialplan: sofia/external/dialer@208.64.5.163 Absolute Condition [outside_call]
40Dialplan: sofia/external/dialer@208.64.5.163 Action set(outside_call=true)
41Dialplan: sofia/external/dialer@208.64.5.163 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
42Dialplan: sofia/external/dialer@208.64.5.163 parsing [public->call_debug] continue=true
43Dialplan: sofia/external/dialer@208.64.5.163 Regex (FAIL) [call_debug] ${call_debug}(false) =~ /^true$/ break=never
44Dialplan: sofia/external/dialer@208.64.5.163 parsing [public->public_extensions] continue=false
45Dialplan: sofia/external/dialer@208.64.5.163 Regex (PASS) [public_extensions] destination_number(sipb_gustavo) =~ /(.*)/ break=on-false
46Dialplan: sofia/external/dialer@208.64.5.163 Action set(bypass_media=false)
47Dialplan: sofia/external/dialer@208.64.5.163 Action bridge(sofia/${domain_name}/sipb_gustavo)
48Dialplan: sofia/external/dialer@208.64.5.163 Action playback(silence_stream://0)
492017-11-23 06:13:21.935268 [DEBUG] switch_core_state_machine.c:286 (sofia/external/dialer@208.64.5.163) State Change CS_ROUTING -> CS_EXECUTE
502017-11-23 06:13:21.935268 [DEBUG] switch_core_state_machine.c:643 (sofia/external/dialer@208.64.5.163) State ROUTING going to sleep
512017-11-23 06:13:21.935268 [DEBUG] switch_core_state_machine.c:584 (sofia/external/dialer@208.64.5.163) Running State Change CS_EXECUTE
522017-11-23 06:13:21.935268 [DEBUG] switch_core_state_machine.c:650 (sofia/external/dialer@208.64.5.163) State EXECUTE
532017-11-23 06:13:21.935268 [DEBUG] mod_sofia.c:198 sofia/external/dialer@208.64.5.163 SOFIA EXECUTE
542017-11-23 06:13:21.935268 [DEBUG] switch_core_state_machine.c:328 sofia/external/dialer@208.64.5.163 Standard EXECUTE
55EXECUTE sofia/external/dialer@208.64.5.163 set(outside_call=true)
562017-11-23 06:13:21.935268 [DEBUG] mod_dptools.c:1519 SET sofia/external/dialer@208.64.5.163 [outside_call]=[true]
57EXECUTE sofia/external/dialer@208.64.5.163 export(RFC2822_DATE=Thu, 23 Nov 2017 06:13:21 -0800)
582017-11-23 06:13:21.935268 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [RFC2822_DATE]=[Thu, 23 Nov 2017 06:13:21 -0800]
59EXECUTE sofia/external/dialer@208.64.5.163 set(bypass_media=false)
602017-11-23 06:13:21.935268 [DEBUG] mod_dptools.c:1519 SET sofia/external/dialer@208.64.5.163 [bypass_media]=[false]
61EXECUTE sofia/external/dialer@208.64.5.163 bridge(sofia/208.64.4.246/sipb_gustavo)
622017-11-23 06:13:21.935268 [DEBUG] switch_channel.c:1250 sofia/external/dialer@208.64.5.163 EXPORTING[export_vars] [RFC2822_DATE]=[Thu, 23 Nov 2017 06:13:21 -0800] to event
632017-11-23 06:13:21.935268 [DEBUG] switch_ivr_originate.c:2138 Parsing global variables
642017-11-23 06:13:21.935268 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/sipb_gustavo [d36c0a77-6c50-478a-ba12-16b881808a97]
652017-11-23 06:13:21.935268 [DEBUG] mod_sofia.c:4753 (sofia/internal/sipb_gustavo) State Change CS_NEW -> CS_INIT
662017-11-23 06:13:21.935268 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/sipb_gustavo) Running State Change CS_INIT
672017-11-23 06:13:21.935268 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/sipb_gustavo) State INIT
682017-11-23 06:13:21.935268 [DEBUG] mod_sofia.c:90 sofia/internal/sipb_gustavo SOFIA INIT
692017-11-23 06:13:21.935268 [DEBUG] sofia_glue.c:1253 sip:2n248bd4@190.180.66.90:51965;transport=wss Setting proxy route to sofia/internal/sipb_gustavo
702017-11-23 06:13:21.935268 [DEBUG] sofia_glue.c:1282 sofia/internal/sipb_gustavo sending invite version: 1.6.12 -20-b91a0a6 64bit
71Local SDP:
72v=0
73o=FreeSWITCH 1511421555 1511421556 IN IP4 208.64.4.246
74s=FreeSWITCH
75c=IN IP4 208.64.4.246
76t=0 0
77a=msid-semantic: WMS 6VsTg4byUc2srbcMH5h52EEgzEKLh0Qd
78m=audio 24846 RTP/SAVPF 0 8 101
79a=rtpmap:0 PCMU/8000
80a=rtpmap:8 PCMA/8000
81a=rtpmap:101 telephone-event/8000
82a=fingerprint:sha-256 3C:35:62:0F:6C:34:D2:D4:70:F8:8C:18:67:EC:97:59:D7:1A:3E:7C:D4:09:8B:6B:79:B6:64:73:7A:A3:7F:52
83a=setup:actpass
84a=rtcp-mux
85a=rtcp:24846 IN IP4 208.64.4.246
86a=ssrc:907588865 cname:L9WR3XfN086ia8UH
87a=ssrc:907588865 msid:6VsTg4byUc2srbcMH5h52EEgzEKLh0Qd a0
88a=ssrc:907588865 mslabel:6VsTg4byUc2srbcMH5h52EEgzEKLh0Qd
89a=ssrc:907588865 label:6VsTg4byUc2srbcMH5h52EEgzEKLh0Qda0
90a=ice-ufrag:41DWv73VBEwIudM5
91a=ice-pwd:cyN6mSJcRGlRF5pzWTmiQf3i
92a=candidate:2918983158 1 udp 659136 208.64.4.246 24846 typ host generation 0
93a=candidate:2918983158 2 udp 659136 208.64.4.246 24846 typ host generation 0
94a=ptime:20
95a=sendrecv
96
972017-11-23 06:13:21.935268 [DEBUG] switch_core_state_machine.c:40 sofia/internal/sipb_gustavo Standard INIT
982017-11-23 06:13:21.935268 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/sipb_gustavo) State Change CS_INIT -> CS_ROUTING
992017-11-23 06:13:21.935268 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/sipb_gustavo) State INIT going to sleep
1002017-11-23 06:13:21.935268 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/sipb_gustavo) Running State Change CS_ROUTING
1012017-11-23 06:13:21.935268 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/sipb_gustavo) State ROUTING
1022017-11-23 06:13:21.935268 [DEBUG] mod_sofia.c:143 sofia/internal/sipb_gustavo SOFIA ROUTING
1032017-11-23 06:13:21.935268 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/sipb_gustavo) State Change CS_ROUTING -> CS_CONSUME_MEDIA
1042017-11-23 06:13:21.935268 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/sipb_gustavo) State ROUTING going to sleep
1052017-11-23 06:13:21.935268 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/sipb_gustavo) Running State Change CS_CONSUME_MEDIA
1062017-11-23 06:13:21.935268 [DEBUG] sofia.c:6965 Channel sofia/internal/sipb_gustavo entering state [calling][0]
1072017-11-23 06:13:21.935268 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/sipb_gustavo) State CONSUME_MEDIA
1082017-11-23 06:13:21.935268 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/sipb_gustavo) State CONSUME_MEDIA going to sleep
1092017-11-23 06:13:22.175347 [DEBUG] sofia.c:6965 Channel sofia/internal/sipb_gustavo entering state [proceeding][180]
1102017-11-23 06:13:22.175347 [NOTICE] sofia.c:7073 Ring-Ready sofia/internal/sipb_gustavo!
1112017-11-23 06:13:22.175347 [DEBUG] switch_channel.c:3343 (sofia/internal/sipb_gustavo) Callstate Change DOWN -> RINGING
1122017-11-23 06:13:22.175347 [NOTICE] mod_sofia.c:2216 Ring-Ready sofia/external/dialer@208.64.5.163!
1132017-11-23 06:13:22.175347 [DEBUG] sofia.c:6965 Channel sofia/external/dialer@208.64.5.163 entering state [early][180]
1142017-11-23 06:13:22.175347 [NOTICE] switch_ivr_originate.c:525 Ring Ready sofia/external/dialer@208.64.5.163!
1152017-11-23 06:13:22.575355 [DEBUG] sofia.c:6965 Channel sofia/internal/sipb_gustavo entering state [completing][200]
1162017-11-23 06:13:22.575355 [DEBUG] sofia.c:6975 Remote SDP:
117v=0
118o=- 3620012283161058240 2 IN IP4 127.0.0.1
119s=-
120t=0 0
121a=msid-semantic: WMS eF9XaoruU8QlIy7obudjiUSjSRxMEss9aPBj
122m=audio 58038 UDP/TLS/RTP/SAVPF 0 8 101
123c=IN IP4 190.180.66.90
124a=rtpmap:0 PCMU/8000
125a=rtpmap:8 PCMA/8000
126a=rtpmap:101 telephone-event/8000
127a=rtcp:9 IN IP4 0.0.0.0
128a=candidate:1493399139 1 udp 2122260223 192.168.1.12 58038 typ host generation 0 network-id 1 network-cost 10
129a=candidate:394300051 1 tcp 1518280447 192.168.1.12 9 typ host tcptype active generation 0 network-id 1 network-cost 10
130a=candidate:2937262007 1 udp 1686052607 190.180.66.90 58038 typ srflx raddr 192.168.1.12 rport 58038 generation 0 network-id 1 network-cost 10
131a=ice-ufrag:YeBf
132a=ice-pwd:i4+oO17b/oV4UeVjc0+9gh3l
133a=ice-options:trickle
134a=fingerprint:sha-256 3B:78:AD:3A:91:75:79:A4:56:88:8F:88:B0:8D:AC:68:6B:95:C2:12:A4:37:B0:C9:7B:C0:BA:93:34:61:89:87
135a=setup:active
136a=mid:audio
137a=rtcp-mux
138a=ptime:20
139a=ssrc:2000161744 cname://Q9krx+83R1v/yf
140a=ssrc:2000161744 msid:eF9XaoruU8QlIy7obudjiUSjSRxMEss9aPBj 0974c99e-ced3-4003-a8d7-5d17cc5169bf
141a=ssrc:2000161744 mslabel:eF9XaoruU8QlIy7obudjiUSjSRxMEss9aPBj
142a=ssrc:2000161744 label:0974c99e-ced3-4003-a8d7-5d17cc5169bf
143
1442017-11-23 06:13:22.575355 [DEBUG] sofia.c:6965 Channel sofia/internal/sipb_gustavo entering state [ready][200]
1452017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
1462017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:4366 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
1472017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
1482017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
1492017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
1502017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:4366 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
1512017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:4227 Set telephone-event payload to 101@8000
1522017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:3021 Set Codec sofia/internal/sipb_gustavo PCMU/8000 20 ms 160 samples 64000 bits 1 channels
1532017-11-23 06:13:22.575355 [DEBUG] switch_core_codec.c:111 sofia/internal/sipb_gustavo Original read codec set to PCMU:0
1542017-11-23 06:13:22.575355 [WARNING] switch_core_media.c:3395 NO candidate ACL defined, Defaulting to wan.auto
1552017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:3425 Save audio Candidate cid: 1 proto: udp type: host addr: 192.168.1.12:58038
1562017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:3425 Save audio Candidate cid: 1 proto: udp type: srflx addr: 190.180.66.90:58038
1572017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:3467 Searching for rtp candidate.
1582017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:3472 Choose rtp candidate, index 1, 190.180.66.90:58038
1592017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:3250 sofia/internal/sipb_gustavo choosing family v4
1602017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:3483 Choose same candidate, index 0, for rtcp based on rtcp-mux attribute 190.180.66.90:58038
1612017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:3528 setting remote audio ice addr to index 1 190.180.66.90:58038 based on candidate
1622017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:3549 Setting remote rtcp audio addr to 190.180.66.90:58038 based on candidate
1632017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:4572 Set telephone-event payload to 101@8000
1642017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:4631 sofia/internal/sipb_gustavo Set 2833 dtmf send payload to 101 recv payload to 101
1652017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:6588 AUDIO RTP [sofia/internal/sipb_gustavo] 208.64.4.246 port 24846 -> 190.180.66.90 port 58038 codec: 0 ms: 20
1662017-11-23 06:13:22.575355 [DEBUG] switch_rtp.c:3875 Starting timer [soft] 160 bytes per 20ms
1672017-11-23 06:13:22.575355 [WARNING] switch_rtp.c:3914 You can not have ZRTP and SRTP enabled simultaneously, ZRTP will be disabled for this call!
1682017-11-23 06:13:22.575355 [INFO] switch_core_media.c:6763 Activating Audio ICE
1692017-11-23 06:13:22.575355 [NOTICE] switch_rtp.c:4364 Activating RTP audio ICE: YeBf:41DWv73VBEwIudM5 190.180.66.90:58038
1702017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:6806 Activating RTCP PORT 58038
1712017-11-23 06:13:22.575355 [DEBUG] switch_rtp.c:4261 RTCP send rate is: 5000 and packet rate is: 20000 Remote Port: 58038
1722017-11-23 06:13:22.575355 [INFO] switch_core_media.c:6814 Skipping RTCP ICE (Same as RTP)
1732017-11-23 06:13:22.575355 [INFO] switch_rtp.c:3368 Activate RTP/RTCP audio DTLS server
1742017-11-23 06:13:22.575355 [INFO] switch_rtp.c:3502 Changing audio DTLS state from OFF to HANDSHAKE
1752017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:6887 sofia/internal/sipb_gustavo Set 2833 dtmf send payload to 101
1762017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:6894 sofia/internal/sipb_gustavo Set 2833 dtmf receive payload to 101
1772017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:6917 sofia/internal/sipb_gustavo Set rtp dtmf delay to 40
1782017-11-23 06:13:22.575355 [NOTICE] sofia.c:8023 Channel [sofia/internal/sipb_gustavo] has been answered
1792017-11-23 06:13:22.575355 [DEBUG] switch_channel.c:3770 (sofia/internal/sipb_gustavo) Callstate Change RINGING -> ACTIVE
1802017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [PCMU:0:8000:30:64000:1]/[G722:9:8000:20:64000:1]
1812017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [PCMU:0:8000:30:64000:1]/[PCMU:0:8000:20:64000:1]
1822017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:4347 Audio Codec Compare [PCMU:0:8000:20:64000:1] is saved as a near-match
1832017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [PCMU:0:8000:30:64000:1]/[PCMA:8:8000:20:64000:1]
1842017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [PCMU:0:8000:30:64000:1]/[GSM:3:8000:20:13200:1]
1852017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [PCMA:8:8000:30:64000:1]/[G722:9:8000:20:64000:1]
1862017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [PCMA:8:8000:30:64000:1]/[PCMU:0:8000:20:64000:1]
1872017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [PCMA:8:8000:30:64000:1]/[PCMA:8:8000:20:64000:1]
1882017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:4347 Audio Codec Compare [PCMA:8:8000:20:64000:1] is saved as a near-match
1892017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [PCMA:8:8000:30:64000:1]/[GSM:3:8000:20:13200:1]
1902017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [G729:18:8000:30:8000:1]/[G722:9:8000:20:64000:1]
1912017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [G729:18:8000:30:8000:1]/[PCMU:0:8000:20:64000:1]
1922017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [G729:18:8000:30:8000:1]/[PCMA:8:8000:20:64000:1]
1932017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [G729:18:8000:30:8000:1]/[GSM:3:8000:20:13200:1]
1942017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:4227 Set telephone-event payload to 96@8000
1952017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:4418 Substituting codec PCMU@30i@8000h@1c
1962017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:3021 Set Codec sofia/external/dialer@208.64.5.163 PCMU/8000 30 ms 240 samples 64000 bits 1 channels
1972017-11-23 06:13:22.575355 [DEBUG] switch_core_codec.c:111 sofia/external/dialer@208.64.5.163 Original read codec set to PCMU:0
1982017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:4572 Set telephone-event payload to 96@8000
1992017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:4631 sofia/external/dialer@208.64.5.163 Set 2833 dtmf send payload to 96 recv payload to 96
2002017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:6588 AUDIO RTP [sofia/external/dialer@208.64.5.163] 208.64.4.246 port 31100 -> 10.10.19.201 port 33114 codec: 0 ms: 30
2012017-11-23 06:13:22.575355 [DEBUG] switch_rtp.c:3875 Starting timer [soft] 240 bytes per 30ms
2022017-11-23 06:13:22.575355 [DEBUG] switch_rtp.c:1454 [ zrtp main]: START SESSION INITIALIZATION. sID=120.
2032017-11-23 06:13:22.575355 [DEBUG] switch_rtp.c:1454 [ zrtp main]: ZID=643034303034663664366363.
2042017-11-23 06:13:22.575355 [DEBUG] switch_rtp.c:1454 [ zrtp main]: Loading User's profile:
2052017-11-23 06:13:22.575355 [DEBUG] switch_rtp.c:1454 [ zrtp main]: allowclear: OFF
2062017-11-23 06:13:22.575355 [DEBUG] switch_rtp.c:1454 [ zrtp main]: autosecure: ON
2072017-11-23 06:13:22.575355 [DEBUG] switch_rtp.c:1454 [ zrtp main]: disclose_bit: OFF
2082017-11-23 06:13:22.575355 [DEBUG] switch_rtp.c:1454 [ zrtp main]: signal. role: Unknown
2092017-11-23 06:13:22.575355 [DEBUG] switch_rtp.c:1454 [ zrtp main]: TTL: 4294967295
2102017-11-23 06:13:22.575355 [DEBUG] switch_rtp.c:1454 [ zrtp main]: SAS schemes:
2112017-11-23 06:13:22.575355 [DEBUG] switch_rtp.c:1454 B256
2122017-11-23 06:13:22.575355 [DEBUG] switch_rtp.c:1454 B32
2132017-11-23 06:13:22.575355 [DEBUG] switch_rtp.c:1454
2142017-11-23 06:13:22.575355 [DEBUG] switch_rtp.c:1454 [ zrtp main]: Ciphers:
2152017-11-23 06:13:22.575355 [DEBUG] switch_rtp.c:1454 AES3
2162017-11-23 06:13:22.575355 [DEBUG] switch_rtp.c:1454 AES1
2172017-11-23 06:13:22.575355 [DEBUG] switch_rtp.c:1454
2182017-11-23 06:13:22.575355 [DEBUG] switch_rtp.c:1454 [ zrtp main]: PK schemes:
2192017-11-23 06:13:22.575355 [DEBUG] switch_rtp.c:1454 EC25
2202017-11-23 06:13:22.575355 [DEBUG] switch_rtp.c:1454 DH3k
2212017-11-23 06:13:22.575355 [DEBUG] switch_rtp.c:1454 DH2k
2222017-11-23 06:13:22.575355 [DEBUG] switch_rtp.c:1454 Mult
2232017-11-23 06:13:22.575355 [DEBUG] switch_rtp.c:1454
2242017-11-23 06:13:22.575355 [DEBUG] switch_rtp.c:1454 [ zrtp main]: ATL:
2252017-11-23 06:13:22.575355 [DEBUG] switch_rtp.c:1454 HS32
2262017-11-23 06:13:22.575355 [DEBUG] switch_rtp.c:1454 HS80
2272017-11-23 06:13:22.575355 [DEBUG] switch_rtp.c:1454
2282017-11-23 06:13:22.575355 [DEBUG] switch_rtp.c:1454 [ zrtp main]: Hashes:
2292017-11-23 06:13:22.575355 [DEBUG] switch_rtp.c:1454 S256
2302017-11-23 06:13:22.575355 [DEBUG] switch_rtp.c:1454
2312017-11-23 06:13:22.575355 [DEBUG] switch_rtp.c:1454 [ zrtp main]: Session initialization - DONE. sID=120.
232
2332017-11-23 06:13:22.575355 [DEBUG] switch_rtp.c:1454 [ zrtp main]: ATTACH NEW STREAM to sID=120:
2342017-11-23 06:13:22.575355 [DEBUG] switch_rtp.c:1454 [ zrtp]: Stream ID=0 UNKNOWN switching <NONE> ---> <ACTIVE>.
2352017-11-23 06:13:22.575355 [DEBUG] switch_rtp.c:1454 [ zrtp main]: Empty slot was found - initializing new stream with ID=120.
2362017-11-23 06:13:22.575355 [DEBUG] switch_rtp.c:1454 [ zrtp main]: Preparing ZRTP Hello according to the Session profile.
2372017-11-23 06:13:22.575355 [DEBUG] switch_rtp.c:1454 [ zrtp main]: ATTACH NEW STREAM - DONE.
2382017-11-23 06:13:22.575355 [DEBUG] switch_rtp.c:1454 [ zrtp engine]: START STREAM ID=120 mode=CLEAR state=ACTIVE.
2392017-11-23 06:13:22.575355 [DEBUG] switch_rtp.c:1454 [ zrtp]: Stream ID=120 CLEAR switching <ACTIVE> ---> <START>.
2402017-11-23 06:13:22.575355 [DEBUG] switch_rtp.c:1454 [ zrtp utils]: Send <HELLO> ssrc=907681338 seq=7961 size=148. Stream 120:CLEAR:START
2412017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:6887 sofia/external/dialer@208.64.5.163 Set 2833 dtmf send payload to 96
2422017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:6894 sofia/external/dialer@208.64.5.163 Set 2833 dtmf receive payload to 96
2432017-11-23 06:13:22.575355 [DEBUG] switch_core_media.c:6917 sofia/external/dialer@208.64.5.163 Set rtp dtmf delay to 40
2442017-11-23 06:13:22.575355 [NOTICE] sofia_media.c:92 Pre-Answer sofia/external/dialer@208.64.5.163!
2452017-11-23 06:13:22.575355 [DEBUG] switch_channel.c:3471 (sofia/external/dialer@208.64.5.163) Callstate Change RINGING -> EARLY
2462017-11-23 06:13:22.575355 [DEBUG] mod_sofia.c:822 Local SDP sofia/external/dialer@208.64.5.163:
247v=0
248o=FreeSWITCH 1511415302 1511415303 IN IP4 208.64.4.246
249s=FreeSWITCH
250c=IN IP4 208.64.4.246
251t=0 0
252m=audio 31100 RTP/AVP 0 96
253a=rtpmap:0 PCMU/8000
254a=rtpmap:96 telephone-event/8000
255a=fmtp:96 0-16
256a=ptime:30
257a=sendrecv
258
2592017-11-23 06:13:22.575355 [NOTICE] switch_ivr_originate.c:3628 Channel [sofia/external/dialer@208.64.5.163] has been answered
2602017-11-23 06:13:22.575355 [DEBUG] switch_channel.c:3770 (sofia/external/dialer@208.64.5.163) Callstate Change EARLY -> ACTIVE
2612017-11-23 06:13:22.575355 [DEBUG] sofia.c:6965 Channel sofia/external/dialer@208.64.5.163 entering state [completed][200]
2622017-11-23 06:13:22.575355 [DEBUG] switch_ivr_originate.c:3686 Originate Resulted in Success: [sofia/internal/sipb_gustavo]
2632017-11-23 06:13:22.575355 [DEBUG] switch_ivr_bridge.c:1522 (sofia/internal/sipb_gustavo) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
2642017-11-23 06:13:22.575355 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/sipb_gustavo) Running State Change CS_EXCHANGE_MEDIA
2652017-11-23 06:13:22.575355 [DEBUG] switch_core_state_machine.c:653 (sofia/internal/sipb_gustavo) State EXCHANGE_MEDIA
2662017-11-23 06:13:22.575355 [DEBUG] mod_sofia.c:631 SOFIA EXCHANGE_MEDIA
2672017-11-23 06:13:22.575355 [DEBUG] sofia.c:6965 Channel sofia/external/dialer@208.64.5.163 entering state [ready][200]
2682017-11-23 06:13:22.655343 [DEBUG] switch_rtp.c:1454 [ zrtp utils]: Send <HELLO> ssrc=907681338 seq=7962 size=148. Stream 120:CLEAR:START
2692017-11-23 06:13:22.755354 [DEBUG] switch_rtp.c:1454 [ zrtp utils]: Send <HELLO> ssrc=907681338 seq=7963 size=148. Stream 120:CLEAR:START
2702017-11-23 06:13:22.935342 [DEBUG] switch_rtp.c:1454 [ zrtp utils]: Send <HELLO> ssrc=907681338 seq=7964 size=148. Stream 120:CLEAR:START
2712017-11-23 06:13:22.995320 [INFO] switch_rtp.c:3159 Changing audio DTLS state from HANDSHAKE to SETUP
2722017-11-23 06:13:22.995320 [INFO] switch_rtp.c:3068 audio Fingerprint Verified.
2732017-11-23 06:13:22.995320 [INFO] switch_rtp.c:3687 Activating Audio Secure RTP SEND
2742017-11-23 06:13:22.995320 [INFO] switch_rtp.c:3665 Activating Audio Secure RTP RECV
2752017-11-23 06:13:22.995320 [DEBUG] switch_core_sqldb.c:2612 Secure Type: srtp:dtls:AES_CM_128_HMAC_SHA1_80
2762017-11-23 06:13:22.995320 [INFO] switch_rtp.c:3108 Changing audio DTLS state from SETUP to READY
2772017-11-23 06:13:22.995320 [DEBUG] switch_core_sqldb.c:2612 Secure Type: srtp:dtls:AES_CM_128_HMAC_SHA1_80
2782017-11-23 06:13:23.155284 [DEBUG] switch_rtp.c:1454 [ zrtp utils]: Send <HELLO> ssrc=907681338 seq=7965 size=148. Stream 120:CLEAR:START
2792017-11-23 06:13:23.235334 [DEBUG] switch_rtp.c:1875 rtcp_stats_init: audio ssrc[2000161744] base_seq[25678]
2802017-11-23 06:13:23.235334 [DEBUG] switch_core_io.c:1448 Engaging Write Buffer at 480 bytes to accommodate 320->480
2812017-11-23 06:13:23.355288 [DEBUG] switch_rtp.c:1454 [ zrtp engine]: WARNING! HELLO have been resent 5 times without a response. Raising ZRTP_EVENT_NO_ZRTP_QUICK event. ID=120
2822017-11-23 06:13:23.355288 [DEBUG] switch_rtp.c:1454 [ zrtp utils]: Send <HELLO> ssrc=907681338 seq=7966 size=148. Stream 120:CLEAR:START
2832017-11-23 06:13:23.575269 [DEBUG] switch_rtp.c:1454 [ zrtp utils]: Send <HELLO> ssrc=907681338 seq=7967 size=148. Stream 120:CLEAR:START
2842017-11-23 06:13:23.755321 [DEBUG] switch_rtp.c:1454 [ zrtp utils]: Send <HELLO> ssrc=907681338 seq=7968 size=148. Stream 120:CLEAR:START
2852017-11-23 06:13:23.975387 [DEBUG] switch_rtp.c:1454 [ zrtp utils]: Send <HELLO> ssrc=907681338 seq=7969 size=148. Stream 120:CLEAR:START
2862017-11-23 06:13:24.175335 [DEBUG] switch_rtp.c:1454 [ zrtp utils]: Send <HELLO> ssrc=907681338 seq=7970 size=148. Stream 120:CLEAR:START
2872017-11-23 06:13:24.355351 [DEBUG] switch_rtp.c:1454 [ zrtp utils]: Send <HELLO> ssrc=907681338 seq=7971 size=148. Stream 120:CLEAR:START
2882017-11-23 06:13:24.575284 [DEBUG] switch_rtp.c:1454 [ zrtp utils]: Send <HELLO> ssrc=907681338 seq=7972 size=148. Stream 120:CLEAR:START
2892017-11-23 06:13:24.775280 [DEBUG] switch_rtp.c:1454 [ zrtp utils]: Send <HELLO> ssrc=907681338 seq=7973 size=148. Stream 120:CLEAR:START
2902017-11-23 06:13:24.975307 [DEBUG] switch_rtp.c:1454 [ zrtp utils]: Send <HELLO> ssrc=907681338 seq=7974 size=148. Stream 120:CLEAR:START
2912017-11-23 06:13:25.155370 [DEBUG] switch_rtp.c:1454 [ zrtp utils]: Send <HELLO> ssrc=907681338 seq=7975 size=148. Stream 120:CLEAR:START
2922017-11-23 06:13:25.355336 [DEBUG] switch_rtp.c:1454 [ zrtp utils]: Send <HELLO> ssrc=907681338 seq=7976 size=148. Stream 120:CLEAR:START
2932017-11-23 06:13:25.575304 [DEBUG] switch_rtp.c:1454 [ zrtp utils]: Send <HELLO> ssrc=907681338 seq=7977 size=148. Stream 120:CLEAR:START
2942017-11-23 06:13:25.755315 [DEBUG] switch_rtp.c:1454 [ zrtp utils]: Send <HELLO> ssrc=907681338 seq=7978 size=148. Stream 120:CLEAR:START
2952017-11-23 06:13:25.975312 [DEBUG] switch_rtp.c:1454 [ zrtp utils]: Send <HELLO> ssrc=907681338 seq=7979 size=148. Stream 120:CLEAR:START
2962017-11-23 06:13:26.155319 [DEBUG] switch_rtp.c:1454 [ zrtp utils]: Send <HELLO> ssrc=907681338 seq=7980 size=148. Stream 120:CLEAR:START
2972017-11-23 06:13:26.375273 [DEBUG] switch_rtp.c:1454 [ zrtp engine]: WARNING! HELLO Max retransmissions count reached (20 retries). ID=120
2982017-11-23 06:13:26.375273 [DEBUG] switch_rtp.c:1454 [ zrtp]: Stream ID=120 CLEAR switching <START> ---> <NOZRTP>.