1. 2019-06-10 16:33:44.646270 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/202@connec.cpbx.co.za:5060 [649a8a76-4fc0-45df-b8d6-32848e8e7312]
2. 2019-06-10 16:33:44.646270 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/202@connec.cpbx.co.za:5060) Running State Change CS_NEW (Cur 3 Tot 37375)
3. 2019-06-10 16:33:44.646270 [DEBUG] sofia.c:9873 sofia/internal/202@connec.cpbx.co.za:5060 receiving invite from 160.119.232.78:5239 version: 1.6.20 -37-987c9                                        b9 64bit
4. 2019-06-10 16:33:44.646270 [DEBUG] sofia.c:10044 IP 160.119.232.78 Rejected by acl "domains". Falling back to Digest auth.
5. 2019-06-10 16:33:44.646270 [WARNING] sofia_reg.c:1792 SIP auth challenge (INVITE) on sofia profile 'internal' for [00497822780875@connec.cpbx.co.za] from ip                                         160.119.232.78
6. 2019-06-10 16:33:44.646270 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/202@connec.cpbx.co.za:5060) State NEW
7. 2019-06-10 16:33:44.646270 [DEBUG] sofia.c:2334 detaching session 649a8a76-4fc0-45df-b8d6-32848e8e7312
8. 2019-06-10 16:33:44.706276 [DEBUG] sofia.c:2442 Re-attaching to session 649a8a76-4fc0-45df-b8d6-32848e8e7312
9. 2019-06-10 16:33:44.706276 [DEBUG] sofia.c:9873 sofia/internal/202@connec.cpbx.co.za:5060 receiving invite from 160.119.232.78:5239 version: 1.6.20 -37-987c9                                        b9 64bit
10. 2019-06-10 16:33:44.706276 [DEBUG] sofia.c:10044 IP 160.119.232.78 Rejected by acl "domains". Falling back to Digest auth.
11. 2019-06-10 16:33:44.726278 [DEBUG] sofia.c:7084 Channel sofia/internal/202@connec.cpbx.co.za:5060 entering state [received][100]
12. 2019-06-10 16:33:44.726278 [DEBUG] sofia.c:7094 Remote SDP:
13. v=0
14. o=202 5457184 1912527719 IN IP4 160.119.232.78
15. s=A conversation
16. c=IN IP4 160.119.232.78
17. t=0 0
18. m=audio 10320 RTP/AVP 18 101
19. a=rtpmap:18 G729/8000
20. a=fmtp:18 annexb=no
21. a=rtpmap:101 telephone-event/8000
22. a=fmtp:101 0-15
23.  
24. 2019-06-10 16:33:44.726278 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[G729:18:8000:20:8000:1]
25. 2019-06-10 16:33:44.726278 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [G729:18:8000:20:8000:1] ++++ is saved as a match
26. 2019-06-10 16:33:44.726278 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
27. 2019-06-10 16:33:44.726278 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
28. 2019-06-10 16:33:44.726278 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 101@8000
29. 2019-06-10 16:33:44.726278 [DEBUG] switch_core_media.c:3061 Set Codec sofia/internal/202@connec.cpbx.co.za:5060 G729/8000 20 ms 160 samples 8000 bits 1 chann                                        els
30. 2019-06-10 16:33:44.726278 [DEBUG] switch_core_codec.c:111 sofia/internal/202@connec.cpbx.co.za:5060 Original read codec set to G729:18
31. 2019-06-10 16:33:44.726278 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 101@8000
32. 2019-06-10 16:33:44.726278 [DEBUG] switch_core_media.c:4767 sofia/internal/202@connec.cpbx.co.za:5060 Set 2833 dtmf send payload to 101 recv payload to 101
33. 2019-06-10 16:33:44.726278 [DEBUG] sofia.c:7507 (sofia/internal/202@connec.cpbx.co.za:5060) State Change CS_NEW -> CS_INIT
34. 2019-06-10 16:33:44.726278 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/202@connec.cpbx.co.za:5060) Running State Change CS_INIT (Cur 3 Tot 37375)
35. 2019-06-10 16:33:44.726278 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/202@connec.cpbx.co.za:5060) State INIT
36. 2019-06-10 16:33:44.726278 [DEBUG] mod_sofia.c:90 sofia/internal/202@connec.cpbx.co.za:5060 SOFIA INIT
37. 2019-06-10 16:33:44.726278 [DEBUG] switch_core_state_machine.c:40 sofia/internal/202@connec.cpbx.co.za:5060 Standard INIT
38. 2019-06-10 16:33:44.726278 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/202@connec.cpbx.co.za:5060) State Change CS_INIT -> CS_ROUTING
39. 2019-06-10 16:33:44.726278 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/202@connec.cpbx.co.za:5060) State INIT going to sleep
40. 2019-06-10 16:33:44.726278 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/202@connec.cpbx.co.za:5060) Running State Change CS_ROUTING (Cur 3 Tot 373                                        75)
41. 2019-06-10 16:33:44.726278 [DEBUG] switch_channel.c:2249 (sofia/internal/202@connec.cpbx.co.za:5060) Callstate Change DOWN -> RINGING
42. 2019-06-10 16:33:44.726278 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/202@connec.cpbx.co.za:5060) State ROUTING
43. 2019-06-10 16:33:44.726278 [DEBUG] mod_sofia.c:143 sofia/internal/202@connec.cpbx.co.za:5060 SOFIA ROUTING
44. 2019-06-10 16:33:44.726278 [DEBUG] switch_core_state_machine.c:236 sofia/internal/202@connec.cpbx.co.za:5060 Standard ROUTING
45. 2019-06-10 16:33:44.726278 [INFO] mod_dialplan_xml.c:637 Processing 202 <202>->00497822780875 in context connec.cpbx.co.za
46. 2019-06-10 16:33:44.726278 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7fe0bc24d870 Connected.
47. 2019-06-10 16:33:44.726278 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7fe0bc24d870 released.
48. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 parsing [connec.cpbx.co.za->user_exists] continue=true
49. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (PASS) [user_exists] () =~ // break=on-false
50. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(user_exists=${user_exists id ${destination_number} ${domain_name}}) INLINE
51. 2019-06-10 16:33:44.746271 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7fe0bc24d870 Connected.
52. 2019-06-10 16:33:44.746271 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7fe0bc24d870 released.
53. EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(user_exists=false)
54. 2019-06-10 16:33:44.746271 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [user_exists]=[false]
55. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (FAIL) [user_exists] ${user_exists}(false) =~ /^true$/ break=on-false
56. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 parsing [connec.cpbx.co.za->caller-details] continue=true
57. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (PASS) [caller-details] ${caller_destination}() =~ /^$/ break=never
58. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(caller_destination=${destination_number}) INLINE
59. EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(caller_destination=00497822780875)
60. 2019-06-10 16:33:44.746271 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [caller_destination]=[00497822780875]
61. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(caller_id_name=${caller_id_name}) INLINE
62. EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(caller_id_name=202)
63. 2019-06-10 16:33:44.746271 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [caller_id_name]=[202]
64. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(caller_id_number=${caller_id_number}) INLINE
65. EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(caller_id_number=202)
66. 2019-06-10 16:33:44.746271 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [caller_id_number]=[202]
67. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 parsing [connec.cpbx.co.za->variables] continue=true
68. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (PASS) [variables] () =~ // break=on-false
69. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action export(origination_callee_id_name=${destination_number})
70. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
71. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 parsing [connec.cpbx.co.za->call-direction] continue=true
72. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (FAIL) [call-direction] ${call_direction}() =~ /^(inbound|outbound|local)$/ break=never
73. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 ANTI-Action export(call_direction=local)
74. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 parsing [connec.cpbx.co.za->user_record] continue=true
75. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (PASS) [user_record] () =~ // break=on-false
76. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(user_record=${user_data ${destination_number}@${domain_name} var user_record}) INLINE
77. 2019-06-10 16:33:44.746271 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7fe0bc24d870 Connected.
78. 2019-06-10 16:33:44.746271 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7fe0bc24d870 released.
79. 2019-06-10 16:33:44.746271 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7fe0bc24d870 Connected.
80. 2019-06-10 16:33:44.746271 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7fe0bc24d870 released.
81. EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(user_record=)
82. 2019-06-10 16:33:44.746271 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [user_record]=[UNDEF]
83. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(from_user_exists=${user_exists id ${sip_from_user} ${sip_from_host}}) INLINE
84. EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(from_user_exists=true)
85. 2019-06-10 16:33:44.786267 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [from_user_exists]=[true]
86. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
87. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (FAIL) [user_record] ${user_record}() =~ /^all$/ break=never
88. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
89. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (FAIL) [user_record] ${call_direction}() =~ /^inbound$/ break=never
90. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (FAIL) [user_record] ${user_record}() =~ /^inbound$/ break=never
91. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
92. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (FAIL) [user_record] ${call_direction}() =~ /^outbound$/ break=never
93. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (FAIL) [user_record] ${user_record}() =~ /^outbound$/ break=never
94. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
95. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (FAIL) [user_record] ${call_direction}() =~ /^local$/ break=never
96. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (FAIL) [user_record] ${user_record}() =~ /^local$/ break=never
97. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
98. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(from_user_record=${user_data ${sip_from_user}@${sip_from_host} var user_record}) INLINE
99. EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(from_user_record=all)
100. 2019-06-10 16:33:44.786267 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [from_user_record]=[all]
101. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
102. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (PASS) [user_record] ${from_user_record}(all) =~ /^all$/ break=never
103. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(record_session=true) INLINE
104. EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(record_session=true)
105. 2019-06-10 16:33:44.786267 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [record_session]=[true]
106. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
107. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (FAIL) [user_record] ${call_direction}() =~ /^inbound$/ break=never
108. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (FAIL) [user_record] ${from_user_record}(all) =~ /^inbound$/ break=never
109. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
110. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (FAIL) [user_record] ${call_direction}() =~ /^outbound$/ break=never
111. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (FAIL) [user_record] ${from_user_record}(all) =~ /^outbound$/ break=never
112. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
113. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (FAIL) [user_record] ${call_direction}() =~ /^local$/ break=never
114. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (FAIL) [user_record] ${from_user_record}(all) =~ /^local$/ break=never
115. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (PASS) [user_record] ${record_session}(true) =~ /^true$/ break=on-false
116. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(record_path=${recordings_dir}/${domain_name}/archive/${strftime(%Y)}/${strftime(%b)}/${strftim                                        e(%d)}) INLINE
117. EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(record_path=/var/lib/freeswitch/recordings/connec.cpbx.co.za/archive/2019/Jun/10)
118. 2019-06-10 16:33:44.786267 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [record_path]=[/var/lib/freeswitch/recordings/connec.cpbx                                        .co.za/archive/2019/Jun/10]
119. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(record_name=${uuid}.${record_ext}) INLINE
120. EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(record_name=649a8a76-4fc0-45df-b8d6-32848e8e7312.mp3)
121. 2019-06-10 16:33:44.786267 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [record_name]=[649a8a76-4fc0-45df-b8d6-32848e8e7312.mp3]
122. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(recording_follow_transfer=true) INLINE
123. EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(recording_follow_transfer=true)
124. 2019-06-10 16:33:44.786267 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [recording_follow_transfer]=[true]
125. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(record_append=true) INLINE
126. EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(record_append=true)
127. 2019-06-10 16:33:44.786267 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [record_append]=[true]
128. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(record_in_progress=true) INLINE
129. EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(record_in_progress=true)
130. 2019-06-10 16:33:44.786267 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [record_in_progress]=[true]
131. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(execute_on_answer=record_session ${record_path}/${record_name})
132. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 parsing [connec.cpbx.co.za->redial] continue=true
133. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (FAIL) [redial] destination_number(00497822780875) =~ /^(redial|\*870)$/ break=on-true
134. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (PASS) [redial] () =~ // break=never
135. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
136. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 parsing [connec.cpbx.co.za->speed_dial] continue=false
137. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (FAIL) [speed_dial] destination_number(00497822780875) =~ /^\*0(.*)$/ break=on-false
138. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 parsing [connec.cpbx.co.za->default_caller_id] continue=true
139. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (PASS) [default_caller_id] ${emergency_caller_id_number}() =~ /^$/ break=never
140. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(emergency_caller_id_name=${default_emergency_caller_id_name}) INLINE
141. EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(emergency_caller_id_name=)
142. 2019-06-10 16:33:44.786267 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [emergency_caller_id_name]=[UNDEF]
143. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(emergency_caller_id_number=${default_emergency_caller_id_number}) INLINE
144. EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(emergency_caller_id_number=)
145. 2019-06-10 16:33:44.786267 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [emergency_caller_id_number]=[UNDEF]
146. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (FAIL) [default_caller_id] ${outbound_caller_id_number}(0100210777) =~ /^$/ break=never
147. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 parsing [connec.cpbx.co.za->WS-Connec.d420] continue=false
148. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (PASS) [WS-Connec.d420] ${user_exists}(false) =~ /false/ break=on-false
149. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (PASS) [WS-Connec.d420] destination_number(00497822780875) =~ /^(\d{4,20})$/ break=on-false
150. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(sip_h_X-accountcode=${accountcode})
151. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action export(call_direction=outbound)
152. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action unset(call_timeout)
153. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(hangup_after_bridge=true)
154. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(effective_caller_id_name=${outbound_caller_id_name})
155. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(effective_caller_id_number=${outbound_caller_id_number})
156. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(inherit_codec=true)
157. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(ignore_display_updates=true)
158. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(callee_id_number=00497822780875)
159. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(continue_on_fail=true)
160. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action bridge(sofia/gateway/8bfbc79d-cf27-4364-a463-b5227af7f55a/00497822780875)
161. 2019-06-10 16:33:44.786267 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/202@connec.cpbx.co.za:5060) State Change CS_ROUTING -> CS_EXECUTE
162. 2019-06-10 16:33:44.786267 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/202@connec.cpbx.co.za:5060) State ROUTING going to sleep
163. 2019-06-10 16:33:44.786267 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/202@connec.cpbx.co.za:5060) Running State Change CS_EXECUTE (Cur 3 Tot 373                                        75)
164. 2019-06-10 16:33:44.786267 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/202@connec.cpbx.co.za:5060) State EXECUTE
165. 2019-06-10 16:33:44.786267 [DEBUG] mod_sofia.c:198 sofia/internal/202@connec.cpbx.co.za:5060 SOFIA EXECUTE
166. 2019-06-10 16:33:44.786267 [DEBUG] switch_core_state_machine.c:328 sofia/internal/202@connec.cpbx.co.za:5060 Standard EXECUTE
167. EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 export(origination_callee_id_name=00497822780875)
168. 2019-06-10 16:33:44.786267 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [origination_callee_id_name]=[00497822780875]
169. EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(RFC2822_DATE=Mon, 10 Jun 2019 16:33:44 +0200)
170. 2019-06-10 16:33:44.806263 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [RFC2822_DATE]=[Mon, 10 Jun 2019 16:33:44 +0200]
171. EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 export(call_direction=local)
172. 2019-06-10 16:33:44.806263 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [call_direction]=[local]
173. EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(execute_on_answer=record_session /var/lib/freeswitch/recordings/connec.cpbx.co.za/archive/2019/Jun/10/6                                        49a8a76-4fc0-45df-b8d6-32848e8e7312.mp3)
174. 2019-06-10 16:33:44.806263 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [execute_on_answer]=[record_session /var/lib/freeswitch/r                                        ecordings/connec.cpbx.co.za/archive/2019/Jun/10/649a8a76-4fc0-45df-b8d6-32848e8e7312.mp3]
175. EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 hash(insert/connec.cpbx.co.za-last_dial/202/00497822780875)
176. EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(sip_h_X-accountcode=)
177. 2019-06-10 16:33:44.806263 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [sip_h_X-accountcode]=[UNDEF]
178. EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 export(call_direction=outbound)
179. 2019-06-10 16:33:44.806263 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [call_direction]=[outbound]
180. EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 unset(call_timeout)
181. 2019-06-10 16:33:44.806263 [DEBUG] mod_dptools.c:1693 UNSET [call_timeout]
182. EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(hangup_after_bridge=true)
183. 2019-06-10 16:33:44.806263 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [hangup_after_bridge]=[true]
184. EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(effective_caller_id_name=Connec Telecoms)
185. 2019-06-10 16:33:44.806263 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [effective_caller_id_name]=[Connec Telecoms]
186. EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(effective_caller_id_number=0100210777)
187. 2019-06-10 16:33:44.806263 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [effective_caller_id_number]=[0100210777]
188. EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(inherit_codec=true)
189. 2019-06-10 16:33:44.806263 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [inherit_codec]=[true]
190. EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(ignore_display_updates=true)
191. 2019-06-10 16:33:44.806263 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [ignore_display_updates]=[true]
192. EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(callee_id_number=00497822780875)
193. 2019-06-10 16:33:44.806263 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [callee_id_number]=[00497822780875]
194. EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(continue_on_fail=true)
195. 2019-06-10 16:33:44.806263 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [continue_on_fail]=[true]
196. EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 bridge(sofia/gateway/8bfbc79d-cf27-4364-a463-b5227af7f55a/00497822780875)
197. 2019-06-10 16:33:44.806263 [DEBUG] switch_channel.c:1250 sofia/internal/202@connec.cpbx.co.za:5060 EXPORTING[export_vars] [domain_name]=[connec.cpbx.co.za] t                                        o event
198. 2019-06-10 16:33:44.806263 [DEBUG] switch_channel.c:1250 sofia/internal/202@connec.cpbx.co.za:5060 EXPORTING[export_vars] [origination_callee_id_name]=[00497                                        822780875] to event
199. 2019-06-10 16:33:44.806263 [DEBUG] switch_channel.c:1250 sofia/internal/202@connec.cpbx.co.za:5060 EXPORTING[export_vars] [call_direction]=[outbound] to even                                        t
200. 2019-06-10 16:33:44.806263 [DEBUG] switch_channel.c:1250 sofia/internal/202@connec.cpbx.co.za:5060 EXPORTING[export_vars] [call_direction]=[outbound] to even                                        t
201. 2019-06-10 16:33:44.806263 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
202. 2019-06-10 16:33:44.806263 [NOTICE] switch_channel.c:1104 New Channel sofia/external/00497822780875 [92645798-c180-439c-ad16-5a1f5de4a620]
203. 2019-06-10 16:33:44.806263 [DEBUG] mod_sofia.c:4819 (sofia/external/00497822780875) State Change CS_NEW -> CS_INIT
204. 2019-06-10 16:33:44.806263 [DEBUG] switch_core_state_machine.c:584 (sofia/external/00497822780875) Running State Change CS_INIT (Cur 4 Tot 37376)
205. 2019-06-10 16:33:44.806263 [DEBUG] switch_core_state_machine.c:627 (sofia/external/00497822780875) State INIT
206. 2019-06-10 16:33:44.806263 [DEBUG] mod_sofia.c:90 sofia/external/00497822780875 SOFIA INIT
207. 2019-06-10 16:33:44.806263 [DEBUG] sofia_glue.c:1295 sofia/external/00497822780875 sending invite version: 1.6.20 -37-987c9b9 64bit
208. Local SDP:
209. v=0
210. o=FreeSWITCH 1560159566 1560159567 IN IP4 192.168.255.2
211. s=FreeSWITCH
212. c=IN IP4 192.168.255.2
213. t=0 0
214. m=audio 17658 RTP/AVP 18 0 8 101 13
215. a=rtpmap:18 G729/8000
216. a=fmtp:18 annexb=no
217. a=rtpmap:0 PCMU/8000
218. a=rtpmap:8 PCMA/8000
219. a=rtpmap:101 telephone-event/8000
220. a=fmtp:101 0-16
221. a=rtpmap:13 CN/8000
222. a=ptime:20
223. a=sendrecv
224.  
225. 2019-06-10 16:33:44.806263 [DEBUG] switch_core_state_machine.c:40 sofia/external/00497822780875 Standard INIT
226. 2019-06-10 16:33:44.806263 [DEBUG] switch_core_state_machine.c:48 (sofia/external/00497822780875) State Change CS_INIT -> CS_ROUTING
227. 2019-06-10 16:33:44.806263 [DEBUG] switch_core_state_machine.c:627 (sofia/external/00497822780875) State INIT going to sleep
228. 2019-06-10 16:33:44.806263 [DEBUG] switch_core_state_machine.c:584 (sofia/external/00497822780875) Running State Change CS_ROUTING (Cur 4 Tot 37376)
229. 2019-06-10 16:33:44.806263 [DEBUG] sofia.c:7084 Channel sofia/external/00497822780875 entering state [calling][0]
230. 2019-06-10 16:33:44.806263 [DEBUG] switch_core_state_machine.c:643 (sofia/external/00497822780875) State ROUTING
231. 2019-06-10 16:33:44.806263 [DEBUG] mod_sofia.c:143 sofia/external/00497822780875 SOFIA ROUTING
232. 2019-06-10 16:33:44.806263 [DEBUG] switch_ivr_originate.c:67 (sofia/external/00497822780875) State Change CS_ROUTING -> CS_CONSUME_MEDIA
233. 2019-06-10 16:33:44.806263 [DEBUG] switch_core_state_machine.c:643 (sofia/external/00497822780875) State ROUTING going to sleep
234. 2019-06-10 16:33:44.806263 [DEBUG] switch_core_state_machine.c:584 (sofia/external/00497822780875) Running State Change CS_CONSUME_MEDIA (Cur 4 Tot 37376)
235. 2019-06-10 16:33:44.806263 [DEBUG] switch_core_state_machine.c:662 (sofia/external/00497822780875) State CONSUME_MEDIA
236. 2019-06-10 16:33:44.806263 [DEBUG] switch_core_state_machine.c:662 (sofia/external/00497822780875) State CONSUME_MEDIA going to sleep
237. 2019-06-10 16:33:45.086474 [DEBUG] sofia.c:7084 Channel sofia/external/00497822780875 entering state [calling][0]
238. 2019-06-10 16:33:45.186294 [DEBUG] sofia.c:6257 Remote Reason: 16
239. 2019-06-10 16:33:45.186294 [DEBUG] sofia.c:7084 Channel sofia/external/00497822780875 entering state [terminated][480]
240. 2019-06-10 16:33:45.186294 [NOTICE] sofia.c:8273 Hangup sofia/external/00497822780875 [CS_CONSUME_MEDIA] [NORMAL_CLEARING]
241. 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:584 (sofia/external/00497822780875) Running State Change CS_HANGUP (Cur 4 Tot 37376)
242. 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:850 (sofia/external/00497822780875) Callstate Change DOWN -> HANGUP
243. 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:852 (sofia/external/00497822780875) State HANGUP
244. 2019-06-10 16:33:45.186294 [DEBUG] mod_sofia.c:438 Channel sofia/external/00497822780875 hanging up, cause: NORMAL_CLEARING
245. 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:60 sofia/external/00497822780875 Standard HANGUP, cause: NORMAL_CLEARING
246. 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:852 (sofia/external/00497822780875) State HANGUP going to sleep
247. 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:619 (sofia/external/00497822780875) State Change CS_HANGUP -> CS_REPORTING
248. 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:584 (sofia/external/00497822780875) Running State Change CS_REPORTING (Cur 4 Tot 37376)
249. 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:938 (sofia/external/00497822780875) State REPORTING
250. 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:174 sofia/external/00497822780875 Standard REPORTING, cause: NORMAL_CLEARING
251. 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:938 (sofia/external/00497822780875) State REPORTING going to sleep
252. 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:610 (sofia/external/00497822780875) State Change CS_REPORTING -> CS_DESTROY
253. 2019-06-10 16:33:45.186294 [DEBUG] switch_core_session.c:1665 Session 37376 (sofia/external/00497822780875) Locked, Waiting on external entities
254. 2019-06-10 16:33:45.186294 [DEBUG] switch_ivr_originate.c:3848 Originate Resulted in Error Cause: 16 [NORMAL_CLEARING]
255. 2019-06-10 16:33:45.186294 [NOTICE] switch_core_session.c:1683 Session 37376 (sofia/external/00497822780875) Ended
256. 2019-06-10 16:33:45.186294 [NOTICE] switch_core_session.c:1687 Close Channel sofia/external/00497822780875 [CS_DESTROY]
257. 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:741 (sofia/external/00497822780875) Running State Change CS_DESTROY (Cur 3 Tot 37376)
258. 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:751 (sofia/external/00497822780875) State DESTROY
259. 2019-06-10 16:33:45.186294 [DEBUG] mod_sofia.c:343 sofia/external/00497822780875 SOFIA DESTROY
260. 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:181 sofia/external/00497822780875 Standard DESTROY
261. 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:751 (sofia/external/00497822780875) State DESTROY going to sleep
262. 2019-06-10 16:33:45.186294 [INFO] mod_dptools.c:3436 Originate Failed.  Cause: NORMAL_CLEARING
263. 2019-06-10 16:33:45.186294 [NOTICE] switch_core_state_machine.c:385 sofia/internal/202@connec.cpbx.co.za:5060 has executed the last dialplan instruction, han                                        ging up.
264. 2019-06-10 16:33:45.186294 [NOTICE] switch_core_state_machine.c:387 Hangup sofia/internal/202@connec.cpbx.co.za:5060 [CS_EXECUTE] [NORMAL_CLEARING]
265. 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/202@connec.cpbx.co.za:5060) State EXECUTE going to sleep
266. 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/202@connec.cpbx.co.za:5060) Running State Change CS_HANGUP (Cur 3 Tot 3737                                        6)
267. 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/202@connec.cpbx.co.za:5060) Callstate Change RINGING -> HANGUP
268. 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/202@connec.cpbx.co.za:5060) State HANGUP
269. 2019-06-10 16:33:45.186294 [DEBUG] mod_sofia.c:432 sofia/internal/202@connec.cpbx.co.za:5060 Overriding SIP cause 480 with 480 from the other leg
270. 2019-06-10 16:33:45.186294 [DEBUG] mod_sofia.c:438 Channel sofia/internal/202@connec.cpbx.co.za:5060 hanging up, cause: NORMAL_CLEARING
271. 2019-06-10 16:33:45.186294 [DEBUG] mod_sofia.c:577 Responding to INVITE with: 480
272. 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:60 sofia/internal/202@connec.cpbx.co.za:5060 Standard HANGUP, cause: NORMAL_CLEARING
273. 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/202@connec.cpbx.co.za:5060) State HANGUP going to sleep
274. 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/202@connec.cpbx.co.za:5060) State Change CS_HANGUP -> CS_REPORTING
275. 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/202@connec.cpbx.co.za:5060) Running State Change CS_REPORTING (Cur 3 Tot 3                                        7376)
276. 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/202@connec.cpbx.co.za:5060) State REPORTING
277. 2019-06-10 16:33:45.306276 [DEBUG] switch_core_state_machine.c:174 sofia/internal/202@connec.cpbx.co.za:5060 Standard REPORTING, cause: NORMAL_CLEARING
278. 2019-06-10 16:33:45.306276 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/202@connec.cpbx.co.za:5060) State REPORTING going to sleep
279. 2019-06-10 16:33:45.306276 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/202@connec.cpbx.co.za:5060) State Change CS_REPORTING -> CS_DESTROY
280. 2019-06-10 16:33:45.306276 [DEBUG] switch_core_session.c:1665 Session 37375 (sofia/internal/202@connec.cpbx.co.za:5060) Locked, Waiting on external entities
281. 2019-06-10 16:33:45.306276 [NOTICE] switch_core_session.c:1683 Session 37375 (sofia/internal/202@connec.cpbx.co.za:5060) Ended
282. 2019-06-10 16:33:45.306276 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/202@connec.cpbx.co.za:5060 [CS_DESTROY]
283. 2019-06-10 16:33:45.306276 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/202@connec.cpbx.co.za:5060) Running State Change CS_DESTROY (Cur 2 Tot 373                                        76)
284. 2019-06-10 16:33:45.306276 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/202@connec.cpbx.co.za:5060) State DESTROY
285. 2019-06-10 16:33:45.306276 [DEBUG] mod_sofia.c:343 sofia/internal/202@connec.cpbx.co.za:5060 SOFIA DESTROY
286. 2019-06-10 16:33:45.306276 [DEBUG] switch_core_state_machine.c:181 sofia/internal/202@connec.cpbx.co.za:5060 Standard DESTROY
287. 2019-06-10 16:33:45.306276 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/202@connec.cpbx.co.za:5060) State DESTROY going to sleep