FreeSWITCH Pastebin

Untitled

From Paltry Penguin, 5 Years ago, written in FreeSWITCH.
- view diff
URL https://pastebin.freeswitch.org/view/b88d1696
Embed
Download Paste or View Raw
  1. span style="color: goldenrod; font-weight: bold;"> 2018-12-27 08:33:52.671968 [DEBUG] sofia.c:2442 Re-attaching to session 388e8344-12cf-4951-844c-d632471081ed
  2. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  3. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  4. 2018-12-27 08:33:52.671968 [DEBUG] sofia.c:9873 sofia/default/9921646958@fs.telicom.co.za receiving invite from 169.255.170.11:64474 version: 1.6.19 git 7a77e0b 2017-07-13 12:01:45Z 64bit
  5. 2018-12-27 08:33:52.671968 [DEBUG] sofia.c:10044 IP 169.255.170.11 Rejected by acl "default". Falling back to Digest auth.
  6. nua.c:610 nua_set_hparams() nua: nua_set_hparams: entering
  7. nua.c:610 nua_set_hparams() nua: nua_r_set_params with invalid handle (nil)
  8. 2018-12-27 08:33:52.671968 [DEBUG] sofia.c:11168 Setting NAT mode based on via port
  9. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  10. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  11. 2018-12-27 08:33:52.671968 [DEBUG] sofia.c:7084 Channel sofia/default/9921646958@fs.telicom.co.za entering state [received][100]
  12. 2018-12-27 08:33:52.671968 [DEBUG] sofia.c:7094 Remote SDP:
  13. v=0
  14. o=Z 0 0 IN IP4 169.255.170.11
  15. s=Z
  16. c=IN IP4 169.255.170.11
  17. t=0 0
  18. m=audio 8000 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-16
  23.  
  24. 2018-12-27 08:33:52.671968 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[G729:18:8000:20:8000:1]
  25. 2018-12-27 08:33:52.671968 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [G729:18:8000:20:8000:1] ++++ is saved as a match
  26. 2018-12-27 08:33:52.671968 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
  27. 2018-12-27 08:33:52.671968 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
  28. 2018-12-27 08:33:52.671968 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 101@8000
  29. 2018-12-27 08:33:52.671968 [DEBUG] switch_core_media.c:3061 Set Codec sofia/default/9921646958@fs.telicom.co.za G729/8000 20 ms 160 samples 8000 bits 1 channels
  30. 2018-12-27 08:33:52.671968 [DEBUG] switch_core_codec.c:111 sofia/default/9921646958@fs.telicom.co.za Original read codec set to G729:18
  31. 2018-12-27 08:33:52.671968 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 101@8000
  32. 2018-12-27 08:33:52.671968 [DEBUG] switch_core_media.c:4767 sofia/default/9921646958@fs.telicom.co.za Set 2833 dtmf send payload to 101 recv payload to 101
  33. 2018-12-27 08:33:52.671968 [DEBUG] sofia.c:7507 (sofia/default/9921646958@fs.telicom.co.za) State Change CS_NEW -> CS_INIT
  34. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  35. 2018-12-27 08:33:52.671968 [DEBUG] switch_core_state_machine.c:584 (sofia/default/9921646958@fs.telicom.co.za) Running State Change CS_INIT (Cur 3 Tot 94)
  36. 2018-12-27 08:33:52.671968 [DEBUG] switch_core_state_machine.c:627 (sofia/default/9921646958@fs.telicom.co.za) State INIT
  37. 2018-12-27 08:33:52.671968 [DEBUG] mod_sofia.c:90 sofia/default/9921646958@fs.telicom.co.za SOFIA INIT
  38. 2018-12-27 08:33:52.671968 [DEBUG] switch_core_state_machine.c:40 sofia/default/9921646958@fs.telicom.co.za Standard INIT
  39. 2018-12-27 08:33:52.671968 [DEBUG] switch_core_state_machine.c:48 (sofia/default/9921646958@fs.telicom.co.za) State Change CS_INIT -> CS_ROUTING
  40. 2018-12-27 08:33:52.671968 [DEBUG] switch_core_state_machine.c:627 (sofia/default/9921646958@fs.telicom.co.za) State INIT going to sleep
  41. 2018-12-27 08:33:52.671968 [DEBUG] switch_core_state_machine.c:584 (sofia/default/9921646958@fs.telicom.co.za) Running State Change CS_ROUTING (Cur 3 Tot 94)
  42. 2018-12-27 08:33:52.671968 [DEBUG] switch_channel.c:2249 (sofia/default/9921646958@fs.telicom.co.za) Callstate Change DOWN -> RINGING
  43. 2018-12-27 08:33:52.671968 [DEBUG] switch_core_state_machine.c:643 (sofia/default/9921646958@fs.telicom.co.za) State ROUTING
  44. 2018-12-27 08:33:52.671968 [DEBUG] mod_sofia.c:143 sofia/default/9921646958@fs.telicom.co.za SOFIA ROUTING
  45. 2018-12-27 08:33:52.671968 [DEBUG] switch_core_state_machine.c:236 sofia/default/9921646958@fs.telicom.co.za Standard ROUTING
  46. 2018-12-27 08:33:52.671968 [INFO] mod_dialplan_xml.c:637 Processing 9921646958 <9921646958>->0215082222 in context default
  47. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 407 reply
  48. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/163.172.251.49:52466
  49. tport.c:4046 tport_resolve() tport_resolve addrinfo = 163.172.251.49:52466
  50. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/163.172.251.49:52466
  51. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 765 bytes of 765 to udp/163.172.251.49:52466
  52. tport.c:3492 tport_send_msg() tport_vsend returned 765
  53. nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7f1b708d0c60)
  54. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/7 resent, 0/7 tout, 0/16 term, 1/25 free
  55. nta.c:1296 agent_timer() nta: timer set next to 603 ms
  56. 2018-12-27 08:33:52.671968 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7f1b641dab30 Connected.
  57. 2018-12-27 08:33:52.671968 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [LOAD_CONF] Query :SELECT name,value FROM system WHERE group_title IN ('global','opensips','callingcard')
  58. 2018-12-27 08:33:52.691946 [NOTICE] switch_cpp.cpp:1365 [ASTPP] [xml_handler] Params:
  59. 'Event-Name: REQUEST_PARAMS
  60. Core-UUID: f497a5fa-9d26-464a-b04b-40dc1cbba922
  61. FreeSWITCH-Hostname: fs
  62. FreeSWITCH-Switchname: fs
  63. FreeSWITCH-IPv4: 172.235.171.624
  64. FreeSWITCH-IPv6: %3A%3A1
  65. Event-Date-Local: 2018-12-27%2008%3A33%3A52
  66. Event-Date-GMT: Thu,%2027%20Dec%202018%2006%3A33%3A52%20GMT
  67. Event-Date-Timestamp: 1545892432671968
  68. Event-Calling-File: mod_dialplan_xml.c
  69. Event-Calling-Function: dialplan_xml_locate
  70. Event-Calling-Line-Number: 608
  71. Event-Sequence: 7057
  72. Channel-State: CS_ROUTING
  73. Channel-Call-State: RINGING
  74. Channel-State-Number: 2
  75. Channel-Name: sofia/default/9921646958%40fs.telicom.co.za
  76. Unique-ID: 388e8344-12cf-4951-844c-d632471081ed
  77. Call-Direction: inbound
  78. Presence-Call-Direction: inbound
  79. Channel-HIT-Dialplan: true
  80. Channel-Presence-ID: 9921646958%40fs.telicom.co.za
  81. Channel-Call-UUID: 388e8344-12cf-4951-844c-d632471081ed
  82. Answer-State: ringing
  83. Channel-Read-Codec-Name: G729
  84. Channel-Read-Codec-Rate: 8000
  85. Channel-Read-Codec-Bit-Rate: 8000
  86. Channel-Write-Codec-Name: G729
  87. Channel-Write-Codec-Rate: 8000
  88. Channel-Write-Codec-Bit-Rate: 8000
  89. Caller-Direction: inbound
  90. Caller-Logical-Direction: inbound
  91. Caller-Username: 9921646958
  92. Caller-Dialplan: XML
  93. Caller-Caller-ID-Name: 9921646958
  94. Caller-Caller-ID-Number: 9921646958
  95. Caller-Orig-Caller-ID-Name: 9921646958
  96. Caller-Orig-Caller-ID-Number: 9921646958
  97. Caller-Network-Addr: 169.255.170.11
  98. Caller-ANI: 9921646958
  99. Caller-Destination-Number: 0215082222
  100. Caller-Unique-ID: 388e8344-12cf-4951-844c-d632471081ed
  101. Caller-Source: mod_sofia
  102. Caller-Context: default
  103. Caller-Channel-Name: sofia/default/9921646958%40fs.telicom.co.za
  104. Caller-Profile-Index: 1
  105. Caller-Profile-Created-Time: 1545892432671968
  106. Caller-Channel-Created-Time: 1545892432671968
  107. Caller-Channel-Answered-Time: 0
  108. Caller-Channel-Progress-Time: 0
  109. Caller-Channel-Progress-Media-Time: 0
  110. Caller-Channel-Hangup-Time: 0
  111. Caller-Channel-Transfer-Time: 0
  112. Caller-Channel-Resurrect-Time: 0
  113. Caller-Channel-Bridged-Time: 0
  114. Caller-Channel-Last-Hold: 0
  115. Caller-Channel-Hold-Accum: 0
  116. Caller-Screen-Bit: true
  117. Caller-Privacy-Hide-Name: false
  118. Caller-Privacy-Hide-Number: false
  119. variable_direction: inbound
  120. variable_uuid: 388e8344-12cf-4951-844c-d632471081ed
  121. variable_session_id: 94
  122. variable_sip_from_params: transport%3DTCP
  123. variable_sip_from_user: 9921646958
  124. variable_sip_from_uri: 9921646958%40fs.telicom.co.za
  125. variable_sip_from_host: fs.telicom.co.za
  126. variable_video_media_flow: sendrecv
  127. variable_channel_name: sofia/default/9921646958%40fs.telicom.co.za
  128. variable_sip_call_id: zFmXly0qj9O7r1b-Tg06nQ..
  129. variable_ep_codec_string: mod_com_g729.G729%408000h%4020i%408000b
  130. variable_sip_local_network_addr: 172.235.171.624
  131. variable_sip_network_ip: 169.255.170.11
  132. variable_sip_network_port: 64474
  133. variable_sip_invite_stamp: 1545892432671968
  134. variable_sip_received_ip: 169.255.170.11
  135. variable_sip_received_port: 64474
  136. variable_sip_via_protocol: tcp
  137. variable_sip_authorized: true
  138. variable_Event-Name: REQUEST_PARAMS
  139. variable_Core-UUID: f497a5fa-9d26-464a-b04b-40dc1cbba922
  140. variable_FreeSWITCH-Hostname: fs
  141. variable_FreeSWITCH-Switchname: fs
  142. variable_FreeSWITCH-IPv4: 172.235.171.624
  143. variable_FreeSWITCH-IPv6: %3A%3A1
  144. variable_Event-Date-Local: 2018-12-27%2008%3A33%3A52
  145. variable_Event-Date-GMT: Thu,%2027%20Dec%202018%2006%3A33%3A52%20GMT
  146. variable_Event-Date-Timestamp: 1545892432671968
  147. variable_Event-Calling-File: sofia.c
  148. variable_Event-Calling-Function: sofia_handle_sip_i_invite
  149. variable_Event-Calling-Line-Number: 10096
  150. variable_Event-Sequence: 7048
  151. variable_sip_number_alias: 9921646958
  152. variable_sip_auth_username: 9921646958
  153. variable_sip_auth_realm: fs.telicom.co.za
  154. variable_number_alias: 9921646958
  155. variable_requested_user_name: 9921646958
  156. variable_requested_domain_name: fs.telicom.co.za
  157. variable_effective_caller_id_name: 0218643997
  158. variable_effective_caller_id_number: 0218643997
  159. variable_sipcall: true
  160. variable_accountcode: 9921646958
  161. variable_user_name: 9921646958
  162. variable_domain_name: fs.telicom.co.za
  163. variable_sip_from_user_stripped: 9921646958
  164. variable_sip_from_tag: 7c1d0045
  165. variable_sofia_profile_name: default
  166. variable_recovery_profile_name: default
  167. variable_sip_full_via: SIP/2.0/TCP%20169.255.170.11%3A43653%3Bbranch%3Dz9hG4bK-524287-1---e1480dab6fd2e528%3Brport%3D64474
  168. variable_sip_recover_via: SIP/2.0/TCP%20169.255.170.11%3A43653%3Bbranch%3Dz9hG4bK-524287-1---e1480dab6fd2e528%3Brport%3D64474
  169. variable_sip_full_from: %3Csip%3A9921646958%40fs.telicom.co.za%3Btransport%3DTCP%3E%3Btag%3D7c1d0045
  170. variable_sip_full_to: %3Csip%3A0215082222%40fs.telicom.co.za%3Btransport%3DTCP%3E
  171. variable_sip_allow: INVITE,%20ACK,%20CANCEL,%20BYE,%20NOTIFY,%20REFER,%20MESSAGE,%20OPTIONS,%20INFO,%20SUBSCRIBE
  172. variable_sip_req_params: transport%3DTCP
  173. variable_sip_req_user: 0215082222
  174. variable_sip_req_uri: 0215082222%40fs.telicom.co.za
  175. variable_sip_req_host: fs.telicom.co.za
  176. variable_sip_to_params: transport%3DTCP
  177. variable_sip_to_user: 0215082222
  178. variable_sip_to_uri: 0215082222%40fs.telicom.co.za
  179. variable_sip_to_host: fs.telicom.co.za
  180. variable_sip_contact_params: transport%3DTCP
  181. variable_sip_contact_user: 9921646958
  182. variable_sip_contact_port: 43653
  183. variable_sip_contact_uri: 9921646958%40169.255.170.11%3A43653
  184. variable_sip_contact_host: 169.255.170.11
  185. variable_sip_user_agent: Z%205.2.19%20rv2.8.99
  186. variable_sip_via_host: 169.255.170.11
  187. variable_sip_via_port: 43653
  188. variable_sip_via_rport: 64474
  189. variable_max_forwards: 70
  190. variable_presence_id: 9921646958%40fs.telicom.co.za
  191. variable_sip_nat_detected: true
  192. variable_switch_r_sdp: v%3D0%0D%0Ao%3DZ%200%200%20IN%20IP4%20169.255.170.11%0D%0As%3DZ%0D%0Ac%3DIN%20IP4%20169.255.170.11%0D%0At%3D0%200%0D%0Am%3Daudio%208000%20RTP/AVP%2018%20101%0D%0Aa%3Drtpmap%3A18%20G729/8000%0D%0Aa%3Dfmtp%3A18%20annexb%3Dno%0D%0Aa%3Drtpmap%3A101%20telephone-event/8000%0D%0Aa%3Dfmtp%3A101%200-16%0D%0A
  193. variable_rtp_use_codec_string: G729,PCMA,PCMU
  194. variable_audio_media_flow: sendrecv
  195. variable_remote_media_ip: 169.255.170.11
  196. variable_remote_media_port: 8000
  197. variable_rtp_audio_recv_pt: 18
  198. variable_rtp_use_codec_name: G729
  199. variable_rtp_use_codec_fmtp: annexb%3Dno
  200. variable_rtp_use_codec_rate: 8000
  201. variable_rtp_use_codec_ptime: 20
  202. variable_rtp_use_codec_channels: 1
  203. variable_rtp_last_audio_codec_string: G729%408000h%4020i%401c
  204. variable_read_codec: G729
  205. variable_original_read_codec: G729
  206. variable_read_rate: 8000
  207. variable_original_read_rate: 8000
  208. variable_write_codec: G729
  209. variable_write_rate: 8000
  210. variable_dtmf_type: rfc2833
  211. variable_endpoint_disposition: RECEIVED
  212. variable_call_uuid: 388e8344-12cf-4951-844c-d632471081ed
  213. Hunt-Direction: inbound
  214. Hunt-Logical-Direction: inbound
  215. Hunt-Username: 9921646958
  216. Hunt-Dialplan: XML
  217. Hunt-Caller-ID-Name: 9921646958
  218. Hunt-Caller-ID-Number: 9921646958
  219. Hunt-Orig-Caller-ID-Name: 9921646958
  220. Hunt-Orig-Caller-ID-Number: 9921646958
  221. Hunt-Network-Addr: 169.255.170.11
  222. Hunt-ANI: 9921646958
  223. Hunt-Destination-Number: 0215082222
  224. Hunt-Unique-ID: 388e8344-12cf-4951-844c-d632471081ed
  225. Hunt-Source: mod_sofia
  226. Hunt-Context: default
  227. Hunt-Channel-Name: sofia/default/9921646958%40fs.telicom.co.za
  228. Hunt-Profile-Index: 1
  229. Hunt-Profile-Created-Time: 1545892432671968
  230. Hunt-Channel-Created-Time: 1545892432671968
  231. Hunt-Channel-Answered-Time: 0
  232. Hunt-Channel-Progress-Time: 0
  233. Hunt-Channel-Progress-Media-Time: 0
  234. Hunt-Channel-Hangup-Time: 0
  235. Hunt-Channel-Transfer-Time: 0
  236. Hunt-Channel-Resurrect-Time: 0
  237. Hunt-Channel-Bridged-Time: 0
  238. Hunt-Channel-Last-Hold: 0
  239. Hunt-Channel-Hold-Accum: 0
  240. Hunt-Screen-Bit: true
  241. Hunt-Privacy-Hide-Name: false
  242. Hunt-Privacy-Hide-Number: false
  243.  
  244. '
  245. 2018-12-27 08:33:52.691946 [INFO] switch_cpp.cpp:1365 [ASTPP] [xml_REQUEST] tag_name:
  246. 2018-12-27 08:33:52.691946 [INFO] switch_cpp.cpp:1365 [ASTPP] [xml_REQUEST] key_name:
  247. 2018-12-27 08:33:52.691946 [INFO] switch_cpp.cpp:1365 [ASTPP] [xml_REQUEST] key_value:
  248. 2018-12-27 08:33:52.691946 [INFO] switch_cpp.cpp:1365 [ASTPP] [xml_REQUEST] section: dialplan
  249. 2018-12-27 08:33:52.691946 [INFO] switch_cpp.cpp:1365 [ASTPP] [Dialplan] Dialed number : 0215082222
  250. 2018-12-27 08:33:52.691946 [WARNING] switch_cpp.cpp:1365 [ASTPP] [FAXER] in custom Caller ID
  251. 2018-12-27 08:33:52.691946 [INFO] switch_cpp.cpp:1365 [ASTPP] [Dialplan] Caller Id name / number  : 0218643997 / 0218643997
  252. 2018-12-27 08:33:52.691946 [WARNING] switch_cpp.cpp:1365 [ASTPP] [DONUMBERTRANSLATION] Before number translation : 0215082222
  253. 2018-12-27 08:33:52.691946 [WARNING] switch_cpp.cpp:1365 [ASTPP] [DONUMBERTRANSLATION] After  number translation : 27215082222
  254. 2018-12-27 08:33:52.691946 [WARNING] switch_cpp.cpp:1365 [ASTPP] [DONUMBERTRANSLATION] Before number translation : 27215082222
  255. 2018-12-27 08:33:52.691946 [WARNING] switch_cpp.cpp:1365 [ASTPP] [DONUMBERTRANSLATION] After  number translation : 27215082222
  256. 2018-12-27 08:33:52.691946 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [CHECK_DID] Query :SELECT A.id as id,B.id as accountid,B.number as account_code,B.did_cid_translation as did_cid_translation,A.number as  did_number,A.connectcost,A.includedseconds,A.cost,A.inc,A.extensions,A.maxchannels,A.call_type,A.city,A.province,A.init_inc,A.leg_timeout FROM dids AS A,accounts AS B WHERE A.status=0 AND B.status=0 AND B.deleted=0 AND B.id=A.accountid AND A.number ="27215082222" LIMIT 1
  257. 2018-12-27 08:33:52.691946 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [CHECK_LOCAL_CALL] Query :SELECT sip_devices.id as sip_id,sip_devices.username as username,accounts.number as accountcode,sip_devices.accountid as accountid,accounts.did_cid_translation as did_cid_translation FROM sip_devices as sip_devices,accounts as  accounts WHERE accounts.status=0 AND accounts.deleted=0 AND accounts.id=sip_devices.accountid AND sip_devices.username="0215082222" limit 1
  258. 2018-12-27 08:33:52.691946 [INFO] switch_cpp.cpp:1365 [ASTPP] [Dialplan] Call direction : outbound
  259. 2018-12-27 08:33:52.691946 [NOTICE] switch_cpp.cpp:1365 [ASTPP] [Accountcode : 9921646958]
  260. 2018-12-27 08:33:52.691946 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_PRICELIST_ROUTING_INFO] Query :select id,routing_prefix,pricelist_id_admin from pricelists WHERE (routing_prefix = '0215082222' OR routing_prefix = '021508222' OR routing_prefix = '02150822' OR routing_prefix = '0215082' OR routing_prefix = '021508' OR routing_prefix = '02150' OR routing_prefix = '0215' OR routing_prefix = '021' OR routing_prefix = '02' OR routing_prefix = '0' OR routing_prefix ='--') AND status = 0 limit 1
  261. 2018-12-27 08:33:52.691946 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [DOAUTHORIZATION] Query :SELECT * FROM accounts WHERE (number = "9921646958" OR id="9921646958") AND status=0 AND deleted=0 AND (expiry >= '2018-12-27 06:33:52' OR expiry = '0000-00-00 00:00:00') limit 1
  262. 2018-12-27 08:33:52.711949 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [CHECK_BLOCKED_PREFIX] Query :SELECT * FROM block_patterns WHERE (blocked_patterns = '^0215082222.*' OR blocked_patterns = '^021508222.*' OR blocked_patterns = '^02150822.*' OR blocked_patterns = '^0215082.*' OR blocked_patterns = '^021508.*' OR blocked_patterns = '^02150.*' OR blocked_patterns = '^0215.*' OR blocked_patterns = '^021.*' OR blocked_patterns = '^02.*' OR blocked_patterns = '^0.*' OR blocked_patterns ='--') AND accountid = 56 limit 1
  263. 2018-12-27 08:33:52.711949 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_CALLERID_NUMBER] CALLERID :0218643997
  264. 2018-12-27 08:33:52.711949 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_CUSTOMER_ID] USERID :56
  265. 2018-12-27 08:33:52.711949 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_CIDPOOL] CIDPOOL :0
  266. 2018-12-27 08:33:52.711949 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_PACKAGE_INFO] Query :SELECT * FROM packages  as P inner join package_patterns as PKGPTR on P.id = PKGPTR.package_id WHERE (patterns = '^0215082222.*' OR patterns = '^021508222.*' OR patterns = '^02150822.*' OR patterns = '^0215082.*' OR patterns = '^021508.*' OR patterns = '^02150.*' OR patterns = '^0215.*' OR patterns = '^021.*' OR patterns = '^02.*' OR patterns = '^0.*' OR patterns ='--') AND status = 0 AND pricelist_id = 4 ORDER BY LENGTH(PKGPTR.patterns) DESC LIMIT 1
  267. 2018-12-27 08:33:52.711949 [INFO] switch_cpp.cpp:1365 [ASTPP] =============== Account Information ===================
  268. 2018-12-27 08:33:52.711949 [INFO] switch_cpp.cpp:1365 [ASTPP] User id : 56
  269. 2018-12-27 08:33:52.711949 [INFO] switch_cpp.cpp:1365 [ASTPP] Account code : 9921646958
  270. 2018-12-27 08:33:52.711949 [INFO] switch_cpp.cpp:1365 [ASTPP] Type : 1 [0:prepaid,1:postpaid]
  271. 2018-12-27 08:33:52.711949 [INFO] switch_cpp.cpp:1365 [ASTPP] Ratecard id : 4
  272. 2018-12-27 08:33:52.711949 [INFO] switch_cpp.cpp:1365 [ASTPP] ========================================================
  273. 2018-12-27 08:33:52.711949 [WARNING] switch_cpp.cpp:1365 [ASTPP] [DONUMBERTRANSLATION] Before number translation : 0215082222
  274. 2018-12-27 08:33:52.711949 [WARNING] switch_cpp.cpp:1365 [ASTPP] [DONUMBERTRANSLATION] After  number translation : 27215082222
  275. 2018-12-27 08:33:52.711949 [WARNING] switch_cpp.cpp:1365 [ASTPP] [DONUMBERTRANSLATION] Before number translation : 27215082222
  276. 2018-12-27 08:33:52.711949 [WARNING] switch_cpp.cpp:1365 [ASTPP] [DONUMBERTRANSLATION] After  number translation : 27215082222
  277. 2018-12-27 08:33:52.711949 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_PRICELIST_INFO] Query :select * from pricelists WHERE id = 4 AND status = 0
  278. 2018-12-27 08:33:52.711949 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_RATES] Query :SELECT * FROM routes WHERE (pattern = '^27215082222.*' OR pattern = '^2721508222.*' OR pattern = '^272150822.*' OR pattern = '^27215082.*' OR pattern = '^2721508.*' OR pattern = '^272150.*' OR pattern = '^27215.*' OR pattern = '^2721.*' OR pattern = '^272.*' OR pattern = '^27.*' OR pattern = '^2.*' OR pattern ='--') AND status = 0 AND pricelist_id = 4  ORDER BY LENGTH(pattern) DESC,cost DESC LIMIT 1
  279. 2018-12-27 08:33:52.711949 [INFO] switch_cpp.cpp:1365 [ASTPP] =============== Rates Information ===================
  280. 2018-12-27 08:33:52.711949 [INFO] switch_cpp.cpp:1365 [ASTPP] ID : 18194
  281. 2018-12-27 08:33:52.711949 [INFO] switch_cpp.cpp:1365 [ASTPP] Connectcost : 0.00000
  282. 2018-12-27 08:33:52.711949 [INFO] switch_cpp.cpp:1365 [ASTPP] Includedseconds : 0
  283. 2018-12-27 08:33:52.711949 [INFO] switch_cpp.cpp:1365 [ASTPP] Cost : 0.00000
  284. 2018-12-27 08:33:52.711949 [INFO] switch_cpp.cpp:1365 [ASTPP] comment : South Africa
  285. 2018-12-27 08:33:52.711949 [INFO] switch_cpp.cpp:1365 [ASTPP] Accid : 56
  286. 2018-12-27 08:33:52.711949 [INFO] switch_cpp.cpp:1365 [ASTPP] Trunk ID: 1
  287. 2018-12-27 08:33:52.711949 [INFO] switch_cpp.cpp:1365 [ASTPP] Routing type:
  288. 2018-12-27 08:33:52.711949 [INFO] switch_cpp.cpp:1365 [ASTPP] ================================================================
  289. 2018-12-27 08:33:52.711949 [INFO] switch_cpp.cpp:1365 [ASTPP] [FIND_MAXLENGTH] Call is free - assigning max length!!! :: 100
  290. 2018-12-27 08:33:52.711949 [INFO] switch_cpp.cpp:1365 [ASTPP] Call Max length duration : 100 minutes
  291. 2018-12-27 08:33:52.711949 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [Dialplan] Routing Type : 0
  292. 2018-12-27 08:33:52.711949 [INFO] switch_cpp.cpp:1365 [ASTPP] [DIALPLAN] User Rate ID : 18194
  293. 2018-12-27 08:33:52.711949 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_CARRIER_RATES_TRUNKS] Trunk ids 1111******************:1
  294. 2018-12-27 08:33:52.711949 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_COUNTER_INFO] force_trunk_type here :1
  295. 2018-12-27 08:33:52.711949 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_CARRIER_RATES]1111122222 Query :SELECT TK.id as trunk_id,TK.codec,GW.name as path,GW.dialplan_variable,TK.provider_id,TR.init_inc,TK.status,TK.cid_translation,TK.leg_timeout,TK.dialed_modify,TK.maxchannels,TR.pattern,TR.id as outbound_route_id,TR.connectcost,TR.comment,TR.includedseconds,TR.cost,TR.inc,TR.prepend,TR.strip,(select percentage from routing where routes_id=(select id from routes where (pattern = '^27215082222.*' OR pattern = '^2721508222.*' OR pattern = '^272150822.*' OR pattern = '^27215082.*' OR pattern = '^2721508.*' OR pattern = '^272150.*' OR pattern = '^27215.*' OR pattern = '^2721.*' OR pattern = '^272.*' OR pattern = '^27.*' OR pattern = '^2.*' OR pattern ='--') and pricelist_id=4  ORDER BY LENGTH(pattern) DESC,cost DESC limit 1) AND trunk_id = TR.trunk_id limit 1) as percentage,(select call_count from routing where routes_id=(select id from routes where (pattern = '^27215082222.*' OR pattern = '^2721508222.*' OR pattern = '^272150822.*' OR pattern = '^27215082.*' OR pattern = '^2721508.*' OR pattern = '^272150.*' OR pattern = '^27215.*' OR pattern = '^2721.*' OR pattern = '^272.*' OR pattern = '^27.*' OR pattern = '^2.*' OR pattern ='--') and pricelist_id=4  ORDER BY LENGTH(pattern) DESC,cost DESC limit 1) AND trunk_id = TR.trunk_id) as trunk_count,(select call_count from routes where (pattern = '^27215082222.*' OR pattern = '^2721508222.*' OR pattern = '^272150822.*' OR pattern = '^27215082.*' OR pattern = '^2721508.*' OR pattern = '^272150.*' OR pattern = '^27215.*' OR pattern = '^2721.*' OR pattern = '^272.*' OR pattern = '^27.*' OR pattern = '^2.*' OR pattern ='--') and pricelist_id=4  ORDER BY LENGTH(pattern) DESC,cost DESC limit 1 ) as routes_count,100 * (select call_count from routing where routes_id=(select id from routes where (pattern = '^27215082222.*' OR pattern = '^2721508222.*' OR pattern = '^272150822.*' OR pattern = '^27215082.*' OR pattern = '^2721508.*' OR pattern = '^272150.*' OR pattern = '^27215.*' OR pattern = '^2721.*' OR pattern = '^272.*' OR pattern = '^27.*' OR pattern = '^2.*' OR pattern ='--') and pricelist_id=4  ORDER BY LENGTH(pattern) DESC,cost DESC limit 1) AND trunk_id = TR.trunk_id) / (select call_count from routes where (pattern = '^27215082222.*' OR pattern = '^2721508222.*' OR pattern = '^272150822.*' OR pattern = '^27215082.*' OR pattern = '^2721508.*' OR pattern = '^272150.*' OR pattern = '^27215.*' OR pattern = '^2721.*' OR pattern = '^272.*' OR pattern = '^27.*' OR pattern = '^2.*' OR pattern ='--') and pricelist_id=4  ORDER BY LENGTH(pattern) DESC,cost DESC limit 1 ) AS percent_atual,(select name from gateways where status=0 AND id = TK.failover_gateway_id) as path1,(select name from gateways where status=0 AND id = TK.failover_gateway_id1) as path2 FROM outbound_routes as TR,trunks as TK,gateways as GW WHERE GW.status=0 AND GW.id= TK.gateway_id AND TK.status=0 AND TK.id= TR.trunk_id AND (pattern = '^27215082222.*' OR pattern = '^2721508222.*' OR pattern = '^272150822.*' OR pattern = '^27215082.*' OR pattern = '^2721508.*' OR pattern = '^272150.*' OR pattern = '^27215.*' OR pattern = '^2721.*' OR pattern = '^272.*' OR pattern = '^27.*' OR pattern = '^2.*' OR pattern ='--') AND TR.status = 0  AND TR.trunk_id IN (1)
  296. 2018-12-27 08:33:52.711949 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_CARRIER_RATES_TRUNKS] Trunk ids ******************:1
  297. 2018-12-27 08:33:52.711949 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_ROUTING_TYPE] Routing type ******************:0
  298. 2018-12-27 08:33:52.711949 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_CARRIER_RATES] Query :SELECT TK.id as trunk_id,TK.codec,GW.name as path,GW.dialplan_variable,TK.provider_id,TR.init_inc,TK.status,TK.cid_translation,TK.leg_timeout,TK.dialed_modify,TK.maxchannels,TR.pattern,TR.id as outbound_route_id,TR.connectcost,TR.comment,TR.includedseconds,TR.cost,TR.inc,TR.prepend,TR.strip,(select percentage from routing where routes_id=(select id from routes where (pattern = '^27215082222.*' OR pattern = '^2721508222.*' OR pattern = '^272150822.*' OR pattern = '^27215082.*' OR pattern = '^2721508.*' OR pattern = '^272150.*' OR pattern = '^27215.*' OR pattern = '^2721.*' OR pattern = '^272.*' OR pattern = '^27.*' OR pattern = '^2.*' OR pattern ='--') and pricelist_id=4  ORDER BY LENGTH(pattern) DESC,cost DESC limit 1) AND trunk_id = TR.trunk_id limit 1) as percentage,(select call_count from routing where routes_id=(select id from routes where (pattern = '^27215082222.*' OR pattern = '^2721508222.*' OR pattern = '^272150822.*' OR pattern = '^27215082.*' OR pattern = '^2721508.*' OR pattern = '^272150.*' OR pattern = '^27215.*' OR pattern = '^2721.*' OR pattern = '^272.*' OR pattern = '^27.*' OR pattern = '^2.*' OR pattern ='--') and pricelist_id=4  ORDER BY LENGTH(pattern) DESC,cost DESC limit 1) AND trunk_id = TR.trunk_id) as trunk_count,(select call_count from routes where (pattern = '^27215082222.*' OR pattern = '^2721508222.*' OR pattern = '^272150822.*' OR pattern = '^27215082.*' OR pattern = '^2721508.*' OR pattern = '^272150.*' OR pattern = '^27215.*' OR pattern = '^2721.*' OR pattern = '^272.*' OR pattern = '^27.*' OR pattern = '^2.*' OR pattern ='--') and pricelist_id=4  ORDER BY LENGTH(pattern) DESC,cost DESC limit 1 ) as routes_count,100 * (select call_count from routing where routes_id=(select id from routes where (pattern = '^27215082222.*' OR pattern = '^2721508222.*' OR pattern = '^272150822.*' OR pattern = '^27215082.*' OR pattern = '^2721508.*' OR pattern = '^272150.*' OR pattern = '^27215.*' OR pattern = '^2721.*' OR pattern = '^272.*' OR pattern = '^27.*' OR pattern = '^2.*' OR pattern ='--') and pricelist_id=4  ORDER BY LENGTH(pattern) DESC,cost DESC limit 1) AND trunk_id = TR.trunk_id) / (select call_count from routes where (pattern = '^27215082222.*' OR pattern = '^2721508222.*' OR pattern = '^272150822.*' OR pattern = '^27215082.*' OR pattern = '^2721508.*' OR pattern = '^272150.*' OR pattern = '^27215.*' OR pattern = '^2721.*' OR pattern = '^272.*' OR pattern = '^27.*' OR pattern = '^2.*' OR pattern ='--') and pricelist_id=4  ORDER BY LENGTH(pattern) DESC,cost DESC limit 1 ) AS percent_atual,(select name from gateways where status=0 AND id = TK.failover_gateway_id) as path1,(select name from gateways where status=0 AND id = TK.failover_gateway_id1) as path2 FROM outbound_routes as TR,trunks as TK,gateways as GW WHERE GW.status=0 AND GW.id= TK.gateway_id AND TK.status=0 AND TK.id= TR.trunk_id AND (pattern = '^27215082222.*' OR pattern = '^2721508222.*' OR pattern = '^272150822.*' OR pattern = '^27215082.*' OR pattern = '^2721508.*' OR pattern = '^272150.*' OR pattern = '^27215.*' OR pattern = '^2721.*' OR pattern = '^272.*' OR pattern = '^27.*' OR pattern = '^2.*' OR pattern ='--') AND TR.status = 0  AND TR.trunk_id IN (1)  ORDER by IF( percent_atual >= percentage, percentage, '' ) ASC , IF( percent_atual <= percentage, percentage, '' ) DESC
  299. 2018-12-27 08:33:52.731945 [NOTICE] switch_cpp.cpp:1365 [ASTPP] Bitco: 0.00438 > 0.00000, skipping for loss less routing
  300. 2018-12-27 08:33:52.731945 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_OVERRIDE_CALLERID] Query :SELECT callerid_name as cid_name,callerid_number as cid_number,accountid FROM accounts_callerid WHERE accountid = 56 AND status=0 LIMIT 1
  301. 2018-12-27 08:33:52.731945 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [Functions] [GET_queue_INFO] Query :SELECT id,destination_number,agent_hold_file from pbx_queue WHERE destination_number = 27215082222 and status=0 LIMIT 1
  302. 2018-12-27 08:33:52.731945 [WARNING] switch_cpp.cpp:1365 [ASTPP] [fifo_agent_flag] fifo_agent_flag0
  303. 2018-12-27 08:33:52.731945 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_PRICELIST_INFO] Query :select * from pricelists WHERE id = 4 AND status = 0
  304. 2018-12-27 08:33:52.731945 [INFO] switch_cpp.cpp:1365 [ASTPP] [DIALPLAN] Routing Type11111 : 0
  305. 2018-12-27 08:33:52.731945 [WARNING] switch_cpp.cpp:1365 [ASTPP] [FSXMLOUTBOUND] Caller ID Translation Starts
  306. 2018-12-27 08:33:52.731945 [WARNING] switch_cpp.cpp:1365 [ASTPP] [FSXMLOUTBOUND] Caller ID Translation Ends
  307. 2018-12-27 08:33:52.731945 [WARNING] switch_cpp.cpp:1365 [ASTPP] [DONUMBERTRANSLATION] Before number translation : 27215082222
  308. 2018-12-27 08:33:52.731945 [WARNING] switch_cpp.cpp:1365 [ASTPP] [DONUMBERTRANSLATION] After  number translation : 0215082222
  309. 2018-12-27 08:33:52.731945 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [Dialplan] Generated XML:
  310. <?xml version="1.0" encoding="UTF-8" standalone="no"?>
  311. <document type="freeswitch/xml">
  312. <section name="dialplan" description="ASTPP Dialplan">
  313. <context name="default">
  314. <extension name="27215082222">
  315. <condition field="destination_number" expression="0215082222">
  316. <action application="set" data="effective_destination_number=27215082222"/>
  317. <action application="sched_hangup" data="+6000 normal_clearing"/>
  318. <action application="set" data="callstart=2018-12-27 06:33:52"/>
  319. <action application="set" data="hangup_after_bridge=true"/>
  320. <action application="set" data="continue_on_fail=TRUE"/>
  321. <action application="set" data="account_id=56"/>
  322. <action application="set" data="parent_id=0"/>
  323. <action application="set" data="entity_id=0"/>
  324. <action application="set" data="call_processed=internal"/>
  325. <action application="set" data="call_direction=outbound"/>
  326. <action application="set" data="accountname=default"/>
  327. <action application="export" data="t38_passthru=true"/>
  328. <action application="set" data="fax_enable_t38=true"/>
  329. <action application="set" data="fax_enable_t38_request=true"/>
  330. <action application="set" data="origination_rates=ID:18194|CODE:^2721.*|DESTINATION:South Africa|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.00000|INC:1|INITIALBLOCK:1|RATEGROUP:4|MARKUP:0|ACCID:56"/>
  331. <action application="set" data="original_caller_id_name=0218643997"/>
  332. <action application="set" data="original_caller_id_number=0218643997"/>
  333.  
  334. <action application="set" data="effective_caller_id_name=0218643997"/>
  335. <action application="set" data="effective_caller_id_number=0218643997"/>
  336. <action application="set" data="calltype=STANDARD"/>
  337. <action application="set" data="termination_rates=ID:44749|CODE:^27.*|DESTINATION:South Africa|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.00438|INC:1|INITIALBLOCK:1|TRUNK:1|PROVIDER:5"/>
  338. <action application="set" data="trunk_id=1"/>
  339. <action application="set" data="provider_id=5"/>
  340. <action application="set" data="rate_flag=0"/>
  341. <action application="set" data="force_trunk_flag=18194"/>
  342. <action application="export" data="presence_data=trunk_id=1"/>
  343. <action application="export" data="presence_data=x|||Deon(9921646958)|||^2721.* // South Africa // 0.00000 // trunk_id=1|||trunk_name // ^27.* // South Africa // 0.00438 // trunk_id=1|||STD"/>
  344. <action application="set" data="bridge_pre_execute_bleg_app=system"/>
  345.  <action application="set" data="bridge_pre_execute_bleg_data=/bin/bash /backup/html/ASTPP4_2oct/web_interface/astpp/update_count.sh 1 4 0 18194"/>
  346. <action application="bridge" data="[leg_timeout=30]sofia/gateway/Bitco/0215082222"/>
  347. </condition>
  348. </extension>
  349. </context>
  350. </section>
  351. </document>
  352. 2018-12-27 08:33:52.731945 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7f1b641dab30 released.
  353. Dialplan: sofia/default/9921646958@fs.telicom.co.za parsing [default->27215082222] continue=false
  354. Dialplan: sofia/default/9921646958@fs.telicom.co.za Regex (PASS) [27215082222] destination_number(0215082222) =~ /0215082222/ break=on-false
  355. Dialplan: sofia/default/9921646958@fs.telicom.co.za Action set(effective_destination_number=27215082222)
  356. Dialplan: sofia/default/9921646958@fs.telicom.co.za Action sched_hangup(+6000 normal_clearing)
  357. Dialplan: sofia/default/9921646958@fs.telicom.co.za Action set(callstart=2018-12-27 06:33:52)
  358. Dialplan: sofia/default/9921646958@fs.telicom.co.za Action set(hangup_after_bridge=true)
  359. Dialplan: sofia/default/9921646958@fs.telicom.co.za Action set(continue_on_fail=TRUE)
  360. Dialplan: sofia/default/9921646958@fs.telicom.co.za Action set(account_id=56)
  361. Dialplan: sofia/default/9921646958@fs.telicom.co.za Action set(parent_id=0)
  362. Dialplan: sofia/default/9921646958@fs.telicom.co.za Action set(entity_id=0)
  363. Dialplan: sofia/default/9921646958@fs.telicom.co.za Action set(call_processed=internal)
  364. Dialplan: sofia/default/9921646958@fs.telicom.co.za Action set(call_direction=outbound)
  365. Dialplan: sofia/default/9921646958@fs.telicom.co.za Action set(accountname=default)
  366. Dialplan: sofia/default/9921646958@fs.telicom.co.za Action export(t38_passthru=true)
  367. Dialplan: sofia/default/9921646958@fs.telicom.co.za Action set(fax_enable_t38=true)
  368. Dialplan: sofia/default/9921646958@fs.telicom.co.za Action set(fax_enable_t38_request=true)
  369. Dialplan: sofia/default/9921646958@fs.telicom.co.za Action set(origination_rates=ID:18194|CODE:^2721.*|DESTINATION:South Africa|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.00000|INC:1|INITIALBLOCK:1|RATEGROUP:4|MARKUP:0|ACCID:56)
  370. Dialplan: sofia/default/9921646958@fs.telicom.co.za Action set(original_caller_id_name=0218643997)
  371. Dialplan: sofia/default/9921646958@fs.telicom.co.za Action set(original_caller_id_number=0218643997)
  372. Dialplan: sofia/default/9921646958@fs.telicom.co.za Action set(effective_caller_id_name=0218643997)
  373. Dialplan: sofia/default/9921646958@fs.telicom.co.za Action set(effective_caller_id_number=0218643997)
  374. Dialplan: sofia/default/9921646958@fs.telicom.co.za Action set(calltype=STANDARD)
  375. Dialplan: sofia/default/9921646958@fs.telicom.co.za Action set(termination_rates=ID:44749|CODE:^27.*|DESTINATION:South Africa|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.00438|INC:1|INITIALBLOCK:1|TRUNK:1|PROVIDER:5)
  376. Dialplan: sofia/default/9921646958@fs.telicom.co.za Action set(trunk_id=1)
  377. Dialplan: sofia/default/9921646958@fs.telicom.co.za Action set(provider_id=5)
  378. Dialplan: sofia/default/9921646958@fs.telicom.co.za Action set(rate_flag=0)
  379. Dialplan: sofia/default/9921646958@fs.telicom.co.za Action set(force_trunk_flag=18194)
  380. Dialplan: sofia/default/9921646958@fs.telicom.co.za Action export(presence_data=trunk_id=1)
  381. Dialplan: sofia/default/9921646958@fs.telicom.co.za Action export(presence_data=x|||Deon(9921646958)|||^2721.* // South Africa // 0.00000 // trunk_id=1|||trunk_name // ^27.* // South Africa // 0.00438 // trunk_id=1|||STD)
  382. Dialplan: sofia/default/9921646958@fs.telicom.co.za Action set(bridge_pre_execute_bleg_app=system)
  383. Dialplan: sofia/default/9921646958@fs.telicom.co.za Action set(bridge_pre_execute_bleg_data=/bin/bash /backup/html/ASTPP4_2oct/web_interface/astpp/update_count.sh 1 4 0 18194)
  384. Dialplan: sofia/default/9921646958@fs.telicom.co.za Action bridge([leg_timeout=30]sofia/gateway/Bitco/0215082222)
  385. 2018-12-27 08:33:52.731945 [DEBUG] switch_core_state_machine.c:286 (sofia/default/9921646958@fs.telicom.co.za) State Change CS_ROUTING -> CS_EXECUTE
  386. 2018-12-27 08:33:52.731945 [DEBUG] switch_core_state_machine.c:643 (sofia/default/9921646958@fs.telicom.co.za) State ROUTING going to sleep
  387. 2018-12-27 08:33:52.731945 [DEBUG] switch_core_state_machine.c:584 (sofia/default/9921646958@fs.telicom.co.za) Running State Change CS_EXECUTE (Cur 3 Tot 94)
  388. 2018-12-27 08:33:52.751947 [DEBUG] switch_core_state_machine.c:650 (sofia/default/9921646958@fs.telicom.co.za) State EXECUTE
  389. 2018-12-27 08:33:52.751947 [DEBUG] mod_sofia.c:198 sofia/default/9921646958@fs.telicom.co.za SOFIA EXECUTE
  390. 2018-12-27 08:33:52.751947 [DEBUG] switch_core_state_machine.c:328 sofia/default/9921646958@fs.telicom.co.za Standard EXECUTE
  391. EXECUTE sofia/default/9921646958@fs.telicom.co.za set(effective_destination_number=27215082222)
  392. 2018-12-27 08:33:52.751947 [DEBUG] mod_dptools.c:1548 SET sofia/default/9921646958@fs.telicom.co.za [effective_destination_number]=[27215082222]
  393. EXECUTE sofia/default/9921646958@fs.telicom.co.za sched_hangup(+6000 normal_clearing)
  394. 2018-12-27 08:33:52.751947 [DEBUG] switch_scheduler.c:249 Added task 6 switch_ivr_schedule_hangup (388e8344-12cf-4951-844c-d632471081ed) to run at 1545898432
  395. EXECUTE sofia/default/9921646958@fs.telicom.co.za set(callstart=2018-12-27 06:33:52)
  396. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f1b64027710): events IN
  397. tport.c:2864 tport_recv_event() tport_recv_event(0x7f1b64027710)
  398. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f1b64027710) msg 0x7f1b64135b00 from (udp/172.235.171.624:5060) has 578 bytes, veclen = 1
  399. tport.c:3023 tport_deliver() tport_deliver(0x7f1b64027710): msg 0x7f1b64135b00 (578 bytes) from udp/196.250.140.244:5060/sip next=(nil)
  400. nta.c:2880 agent_recv_request() nta: received REGISTER sip:hpbx58.telicom.co.za:5060 SIP/2.0 (CSeq 1)
  401. nta.c:3174 agent_check_request_via() nta: Via check: received=196.250.140.244
  402. nta.c:3012 agent_recv_request() nta: REGISTER (1) going to existing REGISTER transaction
  403. nta.c:6178 incoming_recv() nta: re-received REGISTER request, retransmitting 401 reply
  404. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/196.250.140.244:5060
  405. tport.c:4046 tport_resolve() tport_resolve addrinfo = 196.250.140.244:5060
  406. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/196.250.140.244:5060
  407. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 597 bytes of 597 to udp/196.250.140.244:5060
  408. tport.c:3492 tport_send_msg() tport_vsend returned 597
  409. 2018-12-27 08:33:52.751947 [DEBUG] mod_dptools.c:1548 SET sofia/default/9921646958@fs.telicom.co.za [callstart]=[2018-12-27 06:33:52]
  410. EXECUTE sofia/default/9921646958@fs.telicom.co.za set(hangup_after_bridge=true)
  411. 2018-12-27 08:33:52.751947 [DEBUG] mod_dptools.c:1548 SET sofia/default/9921646958@fs.telicom.co.za [hangup_after_bridge]=[true]
  412. EXECUTE sofia/default/9921646958@fs.telicom.co.za set(continue_on_fail=TRUE)
  413. 2018-12-27 08:33:52.751947 [DEBUG] mod_dptools.c:1548 SET sofia/default/9921646958@fs.telicom.co.za [continue_on_fail]=[TRUE]
  414. EXECUTE sofia/default/9921646958@fs.telicom.co.za set(account_id=56)
  415. 2018-12-27 08:33:52.751947 [DEBUG] mod_dptools.c:1548 SET sofia/default/9921646958@fs.telicom.co.za [account_id]=[56]
  416. EXECUTE sofia/default/9921646958@fs.telicom.co.za set(parent_id=0)
  417. 2018-12-27 08:33:52.751947 [DEBUG] mod_dptools.c:1548 SET sofia/default/9921646958@fs.telicom.co.za [parent_id]=[0]
  418. EXECUTE sofia/default/9921646958@fs.telicom.co.za set(entity_id=0)
  419. 2018-12-27 08:33:52.751947 [DEBUG] mod_dptools.c:1548 SET sofia/default/9921646958@fs.telicom.co.za [entity_id]=[0]
  420. EXECUTE sofia/default/9921646958@fs.telicom.co.za set(call_processed=internal)
  421. 2018-12-27 08:33:52.751947 [DEBUG] mod_dptools.c:1548 SET sofia/default/9921646958@fs.telicom.co.za [call_processed]=[internal]
  422. EXECUTE sofia/default/9921646958@fs.telicom.co.za set(call_direction=outbound)
  423. 2018-12-27 08:33:52.751947 [DEBUG] mod_dptools.c:1548 SET sofia/default/9921646958@fs.telicom.co.za [call_direction]=[outbound]
  424. EXECUTE sofia/default/9921646958@fs.telicom.co.za set(accountname=default)
  425. 2018-12-27 08:33:52.751947 [DEBUG] mod_dptools.c:1548 SET sofia/default/9921646958@fs.telicom.co.za [accountname]=[default]
  426. EXECUTE sofia/default/9921646958@fs.telicom.co.za export(t38_passthru=true)
  427. 2018-12-27 08:33:52.751947 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [t38_passthru]=[true]
  428. EXECUTE sofia/default/9921646958@fs.telicom.co.za set(fax_enable_t38=true)
  429. 2018-12-27 08:33:52.751947 [DEBUG] mod_dptools.c:1548 SET sofia/default/9921646958@fs.telicom.co.za [fax_enable_t38]=[true]
  430. EXECUTE sofia/default/9921646958@fs.telicom.co.za set(fax_enable_t38_request=true)
  431. 2018-12-27 08:33:52.751947 [DEBUG] mod_dptools.c:1548 SET sofia/default/9921646958@fs.telicom.co.za [fax_enable_t38_request]=[true]
  432. EXECUTE sofia/default/9921646958@fs.telicom.co.za set(origination_rates=ID:18194|CODE:^2721.*|DESTINATION:South Africa|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.00000|INC:1|INITIALBLOCK:1|RATEGROUP:4|MARKUP:0|ACCID:56)
  433. 2018-12-27 08:33:52.751947 [DEBUG] mod_dptools.c:1548 SET sofia/default/9921646958@fs.telicom.co.za [origination_rates]=[ID:18194|CODE:^2721.*|DESTINATION:South Africa|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.00000|INC:1|INITIALBLOCK:1|RATEGROUP:4|MARKUP:0|ACCID:56]
  434. EXECUTE sofia/default/9921646958@fs.telicom.co.za set(original_caller_id_name=0218643997)
  435. 2018-12-27 08:33:52.751947 [DEBUG] mod_dptools.c:1548 SET sofia/default/9921646958@fs.telicom.co.za [original_caller_id_name]=[0218643997]
  436. EXECUTE sofia/default/9921646958@fs.telicom.co.za set(original_caller_id_number=0218643997)
  437. 2018-12-27 08:33:52.751947 [DEBUG] mod_dptools.c:1548 SET sofia/default/9921646958@fs.telicom.co.za [original_caller_id_number]=[0218643997]
  438. EXECUTE sofia/default/9921646958@fs.telicom.co.za set(effective_caller_id_name=0218643997)
  439. 2018-12-27 08:33:52.751947 [DEBUG] mod_dptools.c:1548 SET sofia/default/9921646958@fs.telicom.co.za [effective_caller_id_name]=[0218643997]
  440. EXECUTE sofia/default/9921646958@fs.telicom.co.za set(effective_caller_id_number=0218643997)
  441. 2018-12-27 08:33:52.751947 [DEBUG] mod_dptools.c:1548 SET sofia/default/9921646958@fs.telicom.co.za [effective_caller_id_number]=[0218643997]
  442. EXECUTE sofia/default/9921646958@fs.telicom.co.za set(calltype=STANDARD)
  443. 2018-12-27 08:33:52.751947 [DEBUG] mod_dptools.c:1548 SET sofia/default/9921646958@fs.telicom.co.za [calltype]=[STANDARD]
  444. EXECUTE sofia/default/9921646958@fs.telicom.co.za set(termination_rates=ID:44749|CODE:^27.*|DESTINATION:South Africa|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.00438|INC:1|INITIALBLOCK:1|TRUNK:1|PROVIDER:5)
  445. 2018-12-27 08:33:52.751947 [DEBUG] mod_dptools.c:1548 SET sofia/default/9921646958@fs.telicom.co.za [termination_rates]=[ID:44749|CODE:^27.*|DESTINATION:South Africa|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.00438|INC:1|INITIALBLOCK:1|TRUNK:1|PROVIDER:5]
  446. EXECUTE sofia/default/9921646958@fs.telicom.co.za set(trunk_id=1)
  447. 2018-12-27 08:33:52.751947 [DEBUG] mod_dptools.c:1548 SET sofia/default/9921646958@fs.telicom.co.za [trunk_id]=[1]
  448. EXECUTE sofia/default/9921646958@fs.telicom.co.za set(provider_id=5)
  449. 2018-12-27 08:33:52.751947 [DEBUG] mod_dptools.c:1548 SET sofia/default/9921646958@fs.telicom.co.za [provider_id]=[5]
  450. EXECUTE sofia/default/9921646958@fs.telicom.co.za set(rate_flag=0)
  451. 2018-12-27 08:33:52.751947 [DEBUG] mod_dptools.c:1548 SET sofia/default/9921646958@fs.telicom.co.za [rate_flag]=[0]
  452. EXECUTE sofia/default/9921646958@fs.telicom.co.za set(force_trunk_flag=18194)
  453. 2018-12-27 08:33:52.751947 [DEBUG] mod_dptools.c:1548 SET sofia/default/9921646958@fs.telicom.co.za [force_trunk_flag]=[18194]
  454. EXECUTE sofia/default/9921646958@fs.telicom.co.za export(presence_data=trunk_id=1)
  455. 2018-12-27 08:33:52.751947 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [presence_data]=[trunk_id=1]
  456. EXECUTE sofia/default/9921646958@fs.telicom.co.za export(presence_data=x|||Deon(9921646958)|||^2721.* // South Africa // 0.00000 // trunk_id=1|||trunk_name // ^27.* // South Africa // 0.00438 // trunk_id=1|||STD)
  457. 2018-12-27 08:33:52.751947 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [presence_data]=[x|||Deon(9921646958)|||^2721.* // South Africa // 0.00000 // trunk_id=1|||trunk_name // ^27.* // South Africa // 0.00438 // trunk_id=1|||STD]
  458. EXECUTE sofia/default/9921646958@fs.telicom.co.za set(bridge_pre_execute_bleg_app=system)
  459. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f1b64027710): events ERR
  460. tport_type_udp.c:519 tport_udp_error() tport_udp_error: Connection refused (111) [icmp type=3 code=3]
  461. tport_type_udp.c:524 tport_udp_error()  reported by [196.250.140.244]:0
  462. nta.c:2719 agent_tp_error() nta_agent: tport: 196.250.140.244:5060: Connection refused
  463. 2018-12-27 08:33:52.751947 [DEBUG] mod_dptools.c:1548 SET sofia/default/9921646958@fs.telicom.co.za [bridge_pre_execute_bleg_app]=[system]
  464. EXECUTE sofia/default/9921646958@fs.telicom.co.za set(bridge_pre_execute_bleg_data=/bin/bash /backup/html/ASTPP4_2oct/web_interface/astpp/update_count.sh 1 4 0 18194)
  465. 2018-12-27 08:33:52.751947 [DEBUG] mod_dptools.c:1548 SET sofia/default/9921646958@fs.telicom.co.za [bridge_pre_execute_bleg_data]=[/bin/bash /backup/html/ASTPP4_2oct/web_interface/astpp/update_count.sh 1 4 0 18194]
  466. EXECUTE sofia/default/9921646958@fs.telicom.co.za bridge([leg_timeout=30]sofia/gateway/Bitco/0215082222)
  467. 2018-12-27 08:33:52.751947 [DEBUG] switch_channel.c:1250 sofia/default/9921646958@fs.telicom.co.za EXPORTING[export_vars] [t38_passthru]=[true] to event
  468. 2018-12-27 08:33:52.751947 [DEBUG] switch_channel.c:1250 sofia/default/9921646958@fs.telicom.co.za EXPORTING[export_vars] [presence_data]=[x|||Deon(9921646958)|||^2721.* // South Africa // 0.00000 // trunk_id=1|||trunk_name // ^27.* // South Africa // 0.00438 // trunk_id=1|||STD] to event
  469. 2018-12-27 08:33:52.751947 [DEBUG] switch_channel.c:1250 sofia/default/9921646958@fs.telicom.co.za EXPORTING[export_vars] [presence_data]=[x|||Deon(9921646958)|||^2721.* // South Africa // 0.00000 // trunk_id=1|||trunk_name // ^27.* // South Africa // 0.00438 // trunk_id=1|||STD] to event
  470. 2018-12-27 08:33:52.751947 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
  471. 2018-12-27 08:33:52.751947 [DEBUG] switch_ivr_originate.c:2669 Parsing session specific variables
  472. 2018-12-27 08:33:52.751947 [NOTICE] switch_channel.c:1104 New Channel sofia/default/0215082222 [dcf0b979-33f0-46cc-94e4-7db6877ae6b3]
  473. 2018-12-27 08:33:52.751947 [DEBUG] mod_sofia.c:4819 (sofia/default/0215082222) State Change CS_NEW -> CS_INIT
  474. 2018-12-27 08:33:52.751947 [DEBUG] switch_ivr_originate.c:2963 sofia/default/0215082222 Setting leg timeout to 30
  475. 2018-12-27 08:33:52.751947 [DEBUG] switch_core_state_machine.c:584 (sofia/default/0215082222) Running State Change CS_INIT (Cur 4 Tot 95)
  476. 2018-12-27 08:33:52.751947 [DEBUG] switch_core_state_machine.c:627 (sofia/default/0215082222) State INIT
  477. 2018-12-27 08:33:52.751947 [DEBUG] mod_sofia.c:90 sofia/default/0215082222 SOFIA INIT
  478. nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
  479. nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
  480. 2018-12-27 08:33:52.751947 [DEBUG] sofia_glue.c:1264 sip:197.234.193.20 Setting proxy route to sofia/default/0215082222
  481. 2018-12-27 08:33:52.751947 [DEBUG] sofia_glue.c:1295 sofia/default/0215082222 sending invite version: 1.6.19 git 7a77e0b 2017-07-13 12:01:45Z 64bit
  482. Local SDP:
  483. v=0
  484. o=FreeSWITCH 1545876214 1545876215 IN IP4 172.235.171.624
  485. s=FreeSWITCH
  486. c=IN IP4 172.235.171.624
  487. t=0 0
  488. m=audio 16218 RTP/AVP 18 101
  489. a=rtpmap:18 G729/8000
  490. a=rtpmap:101 telephone-event/8000
  491. a=fmtp:101 0-16
  492. a=ptime:20
  493. a=sendrecv
  494.  
  495. nua.c:633 nua_invite() nua: nua_invite: entering
  496. nua_stack.c:569 nua_stack_signal() nua(0x7f1b64135b00): recv signal r_invite
  497. nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
  498. soa.c:280 soa_clone() soa_clone(static::0x7f1b64025420, 0x7f1b64033e40, 0x7f1b64135b00) called
  499. soa.c:403 soa_set_params() soa_set_params(static::0x7f1b64204820, ...) called
  500. soa.c:403 soa_set_params() soa_set_params(static::0x7f1b64204820, ...) called
  501. soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x7f1b64204820, (nil), 0x7f1b6419619a, -1) called
  502. soa.c:890 soa_set_capability_sdp() soa_set_capability_sdp(static::0x7f1b64204820, (nil), 0x7f1b6419619a, -1) called
  503. nua_dialog.c:338 nua_dialog_usage_add() nua(0x7f1b64135b00): adding session usage
  504. nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x7f1b64230e80)
  505. soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7f1b64204820) called
  506. soa.c:1426 soa_generate_offer() soa_generate_offer(static::0x7f1b64204820, 0) called
  507. soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7f1b64204820, soa_generate_offer): called
  508. soa_static.c:1189 offer_answer_step() soa_static(0x7f1b64204820, soa_generate_offer): generating local description
  509. soa_static.c:1217 offer_answer_step() soa_static(0x7f1b64204820, soa_generate_offer): upgrade with local description
  510. soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7f1b708ceac0, (nil), ""): called
  511. soa_static.c:1446 offer_answer_step() soa_static(0x7f1b64204820, soa_generate_offer): storing local description
  512. soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7f1b64204820, [(nil)], [0x7f1b708d0bf8], [0x7f1b708d0bf4]) called
  513. nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
  514. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/197.234.193.20:5060
  515. tport.c:4046 tport_resolve() tport_resolve addrinfo = 197.234.193.20:5060
  516. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/197.234.193.20:5060
  517. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 1113 bytes of 1113 to udp/197.234.193.20:5060
  518. tport.c:3492 tport_send_msg() tport_vsend returned 1113
  519. nta.c:8304 outgoing_send() nta: sent INVITE (132610152) to UDP/197.234.193.20:5060
  520. tport.c:4160 tport_pend() tport_pend(0x7f1b64027710): pending 0x7f1b64125de0 for udp/172.235.171.624:5060 (already 0)
  521. nua_session.c:4139 signal_call_state_change() nua(0x7f1b64135b00): call state changed: init -> calling, sent offer
  522. soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7f1b64204820, [0x7f1b708d0bd8], [0x7f1b708d0be0], [(nil)]) called
  523. nua_stack.c:269 nua_stack_event() nua(0x7f1b64135b00): event i_state INVITE sent
  524. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  525. nua_stack.c:529 nua_signal() nua(0x7f1b64135b00): sent signal r_invite
  526. 2018-12-27 08:33:52.751947 [DEBUG] switch_core_state_machine.c:40 sofia/default/0215082222 Standard INIT
  527. 2018-12-27 08:33:52.751947 [DEBUG] switch_core_state_machine.c:48 (sofia/default/0215082222) State Change CS_INIT -> CS_ROUTING
  528. 2018-12-27 08:33:52.751947 [DEBUG] switch_core_state_machine.c:627 (sofia/default/0215082222) State INIT going to sleep
  529. 2018-12-27 08:33:52.751947 [DEBUG] switch_core_state_machine.c:584 (sofia/default/0215082222) Running State Change CS_ROUTING (Cur 4 Tot 95)
  530. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  531. 2018-12-27 08:33:52.751947 [DEBUG] sofia.c:7084 Channel sofia/default/0215082222 entering state [calling][0]
  532. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  533. 2018-12-27 08:33:52.751947 [DEBUG] switch_core_state_machine.c:643 (sofia/default/0215082222) State ROUTING
  534. 2018-12-27 08:33:52.751947 [DEBUG] mod_sofia.c:143 sofia/default/0215082222 SOFIA ROUTING
  535. 2018-12-27 08:33:52.751947 [DEBUG] switch_ivr_originate.c:67 (sofia/default/0215082222) State Change CS_ROUTING -> CS_CONSUME_MEDIA
  536. 2018-12-27 08:33:52.751947 [DEBUG] switch_core_state_machine.c:643 (sofia/default/0215082222) State ROUTING going to sleep
  537. 2018-12-27 08:33:52.751947 [DEBUG] switch_core_state_machine.c:584 (sofia/default/0215082222) Running State Change CS_CONSUME_MEDIA (Cur 4 Tot 95)
  538. 2018-12-27 08:33:52.751947 [DEBUG] switch_core_state_machine.c:662 (sofia/default/0215082222) State CONSUME_MEDIA
  539. 2018-12-27 08:33:52.751947 [DEBUG] switch_core_state_machine.c:662 (sofia/default/0215082222) State CONSUME_MEDIA going to sleep
  540. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f1b64027710): events IN
  541. tport.c:2864 tport_recv_event() tport_recv_event(0x7f1b64027710)
  542. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f1b64027710) msg 0x7f1b64142d00 from (udp/172.235.171.624:5060) has 481 bytes, veclen = 1
  543. tport.c:3023 tport_deliver() tport_deliver(0x7f1b64027710): msg 0x7f1b64142d00 (481 bytes) from udp/197.234.193.20:5060/sip next=(nil)
  544. nta.c:3299 agent_recv_response() nta: received 100 Trying for INVITE (132610152)
  545. nta.c:3366 agent_recv_response() nta: 100 Trying is going to a transaction
  546. nta.c:9564 outgoing_estimate_delay() nta_outgoing: RTT is 3.297 ms
  547. tport.c:4222 tport_release() tport_release(0x7f1b64027710): 0x7f1b64125de0 by 0x7f1b6424e940 with 0x7f1b64142d00 (preliminary)
  548. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f1b64027710): events IN
  549. tport.c:2864 tport_recv_event() tport_recv_event(0x7f1b64027710)
  550. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f1b64027710) msg 0x7f1b64142d00 from (udp/172.235.171.624:5060) has 497 bytes, veclen = 1
  551. tport.c:3023 tport_deliver() tport_deliver(0x7f1b64027710): msg 0x7f1b64142d00 (497 bytes) from udp/197.234.193.20:5060/sip next=(nil)
  552. nta.c:3299 agent_recv_response() nta: received 180 Ringing for INVITE (132610152)
  553. nta.c:3366 agent_recv_response() nta: 180 Ringing is going to a transaction
  554. tport.c:4222 tport_release() tport_release(0x7f1b64027710): 0x7f1b64125de0 by 0x7f1b6424e940 with 0x7f1b64142d00 (preliminary)
  555. nua_stack.c:271 nua_stack_event() nua(0x7f1b64135b00): event r_invite 180 Ringing
  556. nua_session.c:4139 signal_call_state_change() nua(0x7f1b64135b00): call state changed: calling -> proceeding
  557. nua_stack.c:271 nua_stack_event() nua(0x7f1b64135b00): event i_state 180 Ringing
  558. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  559. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  560. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  561. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  562. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  563. 2018-12-27 08:33:53.012003 [DEBUG] sofia.c:7084 Channel sofia/default/0215082222 entering state [proceeding][180]
  564. 2018-12-27 08:33:53.012003 [NOTICE] sofia.c:7192 Ring-Ready sofia/default/0215082222!
  565. 2018-12-27 08:33:53.012003 [DEBUG] switch_channel.c:3346 (sofia/default/0215082222) Callstate Change DOWN -> RINGING
  566. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  567. nua.c:879 nua_respond() nua: nua_respond: entering
  568. nua_stack.c:573 nua_stack_signal() nua(0x7f1b6413df30): recv signal r_respond 180 Ringing
  569. nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
  570. soa.c:403 soa_set_params() soa_set_params(static::0x7f1b64155ee0, ...) called
  571. nua_session.c:2320 nua_invite_server_respond() nua: nua_invite_server_respond: entering
  572. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64282a10) tpn = TCP/169.255.170.11:64474
  573. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64282a10): 741 bytes of 741 to tcp/169.255.170.11:64474
  574. tport.c:3492 tport_send_msg() tport_vsend returned 741
  575. tport.c:2296 tport_set_secondary_timer() tport(0x7f1b64282a10): reset timer
  576. nta.c:6791 incoming_reply() nta: sent 180 Ringing for INVITE (2)
  577. nua_session.c:4139 signal_call_state_change() nua(0x7f1b6413df30): call state changed: received -> early
  578. nua_stack.c:271 nua_stack_event() nua(0x7f1b6413df30): event i_state 180 Ringing
  579. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  580. nua_stack.c:529 nua_signal() nua(0x7f1b6413df30): sent signal r_respond
  581. 2018-12-27 08:33:53.012003 [NOTICE] mod_sofia.c:2273 Ring-Ready sofia/default/9921646958@fs.telicom.co.za!
  582. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  583. 2018-12-27 08:33:53.012003 [DEBUG] sofia.c:7084 Channel sofia/default/9921646958@fs.telicom.co.za entering state [early][180]
  584. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  585. 2018-12-27 08:33:53.012003 [NOTICE] switch_ivr_originate.c:525 Ring Ready sofia/default/9921646958@fs.telicom.co.za!
  586. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 407 reply
  587. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/37.49.231.129:50104
  588. tport.c:4046 tport_resolve() tport_resolve addrinfo = 37.49.231.129:50104
  589. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/37.49.231.129:50104
  590. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 762 bytes of 762 to udp/37.49.231.129:50104
  591. tport.c:3492 tport_send_msg() tport_vsend returned 762
  592. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/7 resent, 0/7 tout, 0/16 term, 0/24 free
  593. nta.c:1296 agent_timer() nta: timer set next to 320 ms
  594. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 407 reply
  595. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/37.49.231.204:54643
  596. tport.c:4046 tport_resolve() tport_resolve addrinfo = 37.49.231.204:54643
  597. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/37.49.231.204:54643
  598. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 766 bytes of 766 to udp/37.49.231.204:54643
  599. tport.c:3492 tport_send_msg() tport_vsend returned 766
  600. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/7 resent, 0/7 tout, 0/16 term, 0/24 free
  601. nta.c:1296 agent_timer() nta: timer set next to 431 ms
  602. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f1b64027710): events IN
  603. tport.c:2864 tport_recv_event() tport_recv_event(0x7f1b64027710)
  604. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f1b64027710) msg 0x7f1b64164e70 from (udp/172.235.171.624:5060) has 496 bytes, veclen = 1
  605. tport.c:3023 tport_deliver() tport_deliver(0x7f1b64027710): msg 0x7f1b64164e70 (496 bytes) from udp/196.250.138.210:5060/sip next=(nil)
  606. nta.c:2880 agent_recv_request() nta: received NOTIFY sip:501@172.235.171.624:5060 SIP/2.0 (CSeq 1)
  607. nta.c:3174 agent_check_request_via() nta: Via check: received=196.250.138.210
  608. nta.c:3248 agent_aliases() nta: canonizing sip:501@172.235.171.624:5060 with contact
  609. nta.c:3085 agent_recv_request() nta: NOTIFY (1) going to a default leg
  610. nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
  611. nua_stack.c:899 nh_create() nua: nh_create: entering
  612. nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
  613. nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
  614. soa.c:280 soa_clone() soa_clone(static::0x7f1b64025420, 0x7f1b64033e40, 0x7f1b64175b80) called
  615. soa.c:403 soa_set_params() soa_set_params(static::0x7f1b64176e70, ...) called
  616. nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x7f1b640e9bf0)
  617. nua_dialog.c:338 nua_dialog_usage_add() nua(0x7f1b64175b80): adding subscribe usage with event keep-alive
  618. nua_subnotref.c:638 nua_notify_server_preprocess() nua(0x7f1b64175b80): nua_notify_server_preprocess: terminated ()
  619. nua_stack.c:271 nua_stack_event() nua(0x7f1b64175b80): event i_notify 100 Trying
  620. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  621. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  622. nua.c:879 nua_respond() nua: nua_respond: entering
  623. nua_stack.c:573 nua_stack_signal() nua(0x7f1b64175b80): recv signal r_respond 200 OK
  624. nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
  625. soa.c:403 soa_set_params() soa_set_params(static::0x7f1b64176e70, ...) called
  626. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/196.250.138.210:5060
  627. tport.c:4046 tport_resolve() tport_resolve addrinfo = 196.250.138.210:5060
  628. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/196.250.138.210:5060
  629. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 723 bytes of 723 to udp/196.250.138.210:5060
  630. tport.c:3492 tport_send_msg() tport_vsend returned 723
  631. nta.c:6791 incoming_reply() nta: sent 200 OK for NOTIFY (1)
  632. nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7f1b64175b80): removing subscribe usage with event keep-alive
  633. nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x7f1b640e9bf0)
  634. nua_stack.c:529 nua_signal() nua(0x7f1b64175b80): sent signal r_respond
  635. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  636. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
  637. nua_stack.c:569 nua_stack_signal() nua(0x7f1b64175b80): recv signal r_destroy
  638. nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
  639. soa.c:356 soa_destroy() soa_destroy(static::0x7f1b64176e70) called
  640. nua_stack.c:529 nua_signal() nua(0x7f1b64175b80): sent signal r_destroy
  641. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f1b64027710): events IN
  642. tport.c:2864 tport_recv_event() tport_recv_event(0x7f1b64027710)
  643. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f1b64027710) msg 0x7f1b64132590 from (udp/172.235.171.624:5060) has 4 bytes, veclen = 1
  644. tport.c:3023 tport_deliver() tport_deliver(0x7f1b64027710): bad msg 0x7f1b64132590 (4 bytes) from udp/169.255.170.14:5060/sip next=(nil)
  645. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 407 reply
  646. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/37.49.231.120:50506
  647. tport.c:4046 tport_resolve() tport_resolve addrinfo = 37.49.231.120:50506
  648. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/37.49.231.120:50506
  649. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 764 bytes of 764 to udp/37.49.231.120:50506
  650. tport.c:3492 tport_send_msg() tport_vsend returned 764
  651. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/7 resent, 0/7 tout, 0/17 term, 0/25 free
  652. nta.c:1296 agent_timer() nta: timer set next to 562 ms
  653. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 407 reply
  654. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/37.49.231.129:57611
  655. tport.c:4046 tport_resolve() tport_resolve addrinfo = 37.49.231.129:57611
  656. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/37.49.231.129:57611
  657. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 767 bytes of 767 to udp/37.49.231.129:57611
  658. tport.c:3492 tport_send_msg() tport_vsend returned 767
  659. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/7 resent, 0/7 tout, 0/17 term, 0/25 free
  660. nta.c:1296 agent_timer() nta: timer set next to 454 ms
  661. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f1b64027710): events IN
  662. tport.c:2864 tport_recv_event() tport_recv_event(0x7f1b64027710)
  663. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f1b64027710) msg 0x7f1b64132590 from (udp/172.235.171.624:5060) has 578 bytes, veclen = 1
  664. tport.c:3023 tport_deliver() tport_deliver(0x7f1b64027710): msg 0x7f1b64132590 (578 bytes) from udp/196.250.140.244:5060/sip next=(nil)
  665. nta.c:2880 agent_recv_request() nta: received REGISTER sip:hpbx58.telicom.co.za:5060 SIP/2.0 (CSeq 1)
  666. nta.c:3174 agent_check_request_via() nta: Via check: received=196.250.140.244
  667. nta.c:3012 agent_recv_request() nta: REGISTER (1) going to existing REGISTER transaction
  668. nta.c:6178 incoming_recv() nta: re-received REGISTER request, retransmitting 401 reply
  669. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/196.250.140.244:5060
  670. tport.c:4046 tport_resolve() tport_resolve addrinfo = 196.250.140.244:5060
  671. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/196.250.140.244:5060
  672. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 597 bytes of 597 to udp/196.250.140.244:5060
  673. tport.c:3492 tport_send_msg() tport_vsend returned 597
  674. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f1b64027710): events ERR
  675. tport_type_udp.c:519 tport_udp_error() tport_udp_error: Connection refused (111) [icmp type=3 code=3]
  676. tport_type_udp.c:524 tport_udp_error()  reported by [196.250.140.244]:0
  677. nta.c:2719 agent_tp_error() nta_agent: tport: 196.250.140.244:5060: Connection refused
  678. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f1b64027710): events IN
  679. tport.c:2864 tport_recv_event() tport_recv_event(0x7f1b64027710)
  680. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f1b64027710) msg 0x7f1b64132590 from (udp/172.235.171.624:5060) has 4 bytes, veclen = 1
  681. tport.c:3023 tport_deliver() tport_deliver(0x7f1b64027710): bad msg 0x7f1b64132590 (4 bytes) from udp/169.255.170.14:5060/sip next=(nil)
  682. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 407 reply
  683. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/185.53.88.32:61418
  684. tport.c:4046 tport_resolve() tport_resolve addrinfo = 185.53.88.32:61418
  685. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/185.53.88.32:61418
  686. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 762 bytes of 762 to udp/185.53.88.32:61418
  687. tport.c:3492 tport_send_msg() tport_vsend returned 762
  688. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/7 resent, 0/7 tout, 0/17 term, 0/25 free
  689. nta.c:1296 agent_timer() nta: timer set next to 765 ms
  690. 2018-12-27 08:33:55.231958 [WARNING] switch_core_state_machine.c:687 5909c82b-7b81-4585-a947-066d4f042316 sofia/default/25799@172.235.171.624 Abandoned
  691. 2018-12-27 08:33:55.231958 [NOTICE] switch_core_state_machine.c:690 Hangup sofia/default/25799@172.235.171.624 [CS_NEW] [WRONG_CALL_STATE]
  692. 2018-12-27 08:33:55.231958 [DEBUG] switch_core_state_machine.c:584 (sofia/default/25799@172.235.171.624) Running State Change CS_HANGUP (Cur 4 Tot 95)
  693. 2018-12-27 08:33:55.231958 [DEBUG] switch_core_state_machine.c:850 (sofia/default/25799@172.235.171.624) Callstate Change DOWN -> HANGUP
  694. 2018-12-27 08:33:55.231958 [DEBUG] switch_core_state_machine.c:852 (sofia/default/25799@172.235.171.624) State HANGUP
  695. 2018-12-27 08:33:55.231958 [DEBUG] mod_sofia.c:438 Channel sofia/default/25799@172.235.171.624 hanging up, cause: WRONG_CALL_STATE
  696. 2018-12-27 08:33:55.231958 [DEBUG] switch_core_state_machine.c:60 sofia/default/25799@172.235.171.624 Standard HANGUP, cause: WRONG_CALL_STATE
  697. 2018-12-27 08:33:55.231958 [DEBUG] switch_core_state_machine.c:852 (sofia/default/25799@172.235.171.624) State HANGUP going to sleep
  698. 2018-12-27 08:33:55.231958 [DEBUG] switch_core_state_machine.c:619 (sofia/default/25799@172.235.171.624) State Change CS_HANGUP -> CS_REPORTING
  699. 2018-12-27 08:33:55.231958 [DEBUG] switch_core_state_machine.c:584 (sofia/default/25799@172.235.171.624) Running State Change CS_REPORTING (Cur 4 Tot 95)
  700. 2018-12-27 08:33:55.231958 [DEBUG] switch_core_state_machine.c:938 (sofia/default/25799@172.235.171.624) State REPORTING
  701. 2018-12-27 08:33:55.231958 [DEBUG] switch_core_state_machine.c:174 sofia/default/25799@172.235.171.624 Standard REPORTING, cause: WRONG_CALL_STATE
  702. 2018-12-27 08:33:55.231958 [DEBUG] switch_core_state_machine.c:938 (sofia/default/25799@172.235.171.624) State REPORTING going to sleep
  703. 2018-12-27 08:33:55.231958 [DEBUG] switch_core_state_machine.c:610 (sofia/default/25799@172.235.171.624) State Change CS_REPORTING -> CS_DESTROY
  704. 2018-12-27 08:33:55.231958 [DEBUG] switch_core_session.c:1665 Session 92 (sofia/default/25799@172.235.171.624) Locked, Waiting on external entities
  705. 2018-12-27 08:33:55.231958 [NOTICE] switch_core_session.c:1683 Session 92 (sofia/default/25799@172.235.171.624) Ended
  706. 2018-12-27 08:33:55.231958 [NOTICE] switch_core_session.c:1687 Close Channel sofia/default/25799@172.235.171.624 [CS_DESTROY]
  707. 2018-12-27 08:33:55.231958 [DEBUG] switch_core_state_machine.c:741 (sofia/default/25799@172.235.171.624) Running State Change CS_DESTROY (Cur 3 Tot 95)
  708. 2018-12-27 08:33:55.231958 [DEBUG] switch_core_state_machine.c:751 (sofia/default/25799@172.235.171.624) State DESTROY
  709. 2018-12-27 08:33:55.231958 [DEBUG] mod_sofia.c:343 sofia/default/25799@172.235.171.624 SOFIA DESTROY
  710. 2018-12-27 08:33:55.231958 [DEBUG] switch_core_state_machine.c:181 sofia/default/25799@172.235.171.624 Standard DESTROY
  711. 2018-12-27 08:33:55.231958 [DEBUG] switch_core_state_machine.c:751 (sofia/default/25799@172.235.171.624) State DESTROY going to sleep
  712. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f1b64027710): events IN
  713. tport.c:2864 tport_recv_event() tport_recv_event(0x7f1b64027710)
  714. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f1b64027710) msg 0x7f1b641896d0 from (udp/172.235.171.624:5060) has 4 bytes, veclen = 1
  715. tport.c:3023 tport_deliver() tport_deliver(0x7f1b64027710): bad msg 0x7f1b641896d0 (4 bytes) from udp/192.168.2.180:5060/sip next=(nil)
  716. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f1b64027710): events IN
  717. tport.c:2864 tport_recv_event() tport_recv_event(0x7f1b64027710)
  718. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f1b64027710) msg 0x7f1b64132590 from (udp/172.235.171.624:5060) has 777 bytes, veclen = 1
  719. tport.c:3023 tport_deliver() tport_deliver(0x7f1b64027710): msg 0x7f1b64132590 (777 bytes) from udp/197.234.193.20:5060/sip next=(nil)
  720. nta.c:3299 agent_recv_response() nta: received 183 Session Progress for INVITE (132610152)
  721. nta.c:3366 agent_recv_response() nta: 183 Session Progress is going to a transaction
  722. tport.c:4222 tport_release() tport_release(0x7f1b64027710): 0x7f1b64125de0 by 0x7f1b6424e940 with 0x7f1b64132590 (preliminary)
  723. soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x7f1b64204820, (nil), 0x7f1b640e9b5b, 238) called
  724. soa.c:1595 soa_process_answer() soa_process_answer(static::0x7f1b64204820) called
  725. soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7f1b64204820, soa_process_answer): called
  726. soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7f1b64231180, 0x7f1b64230a20, ""): called
  727. soa_static.c:1304 offer_answer_step() soa_static(0x7f1b64204820, soa_process_answer): upgrade codecs with remote description
  728. soa.c:1730 soa_activate() soa_activate(static::0x7f1b64204820, (nil)) called
  729. nua_session.c:988 nua_session_client_response() nua(0x7f1b64135b00): INVITE: processed SDP answer in 183 Session Progress
  730. nua_stack.c:271 nua_stack_event() nua(0x7f1b64135b00): event r_invite 183 Session Progress
  731. nua_session.c:4139 signal_call_state_change() nua(0x7f1b64135b00): call state changed: proceeding -> proceeding, received answer
  732. soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x7f1b64204820, [0x7f1b708d0648], [0x7f1b708d0650], [(nil)]) called
  733. soa.c:616 soa_get_params() soa_get_params(static::0x7f1b64204820, ...) called
  734. nua_stack.c:271 nua_stack_event() nua(0x7f1b64135b00): event i_state 183 Session Progress
  735. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  736. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  737. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  738. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  739. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  740. 2018-12-27 08:33:55.551996 [DEBUG] sofia.c:7084 Channel sofia/default/0215082222 entering state [proceeding][183]
  741. 2018-12-27 08:33:55.551996 [DEBUG] sofia.c:7094 Remote SDP:
  742. v=0
  743. o=root 3028 3028 IN IP4 197.234.193.20
  744. s=session
  745. c=IN IP4 197.234.193.20
  746. t=0 0
  747. m=audio 15514 RTP/AVP 18 101
  748. a=rtpmap:18 G729/8000
  749. a=fmtp:18 annexb=no
  750. a=rtpmap:101 telephone-event/8000
  751. a=fmtp:101 0-16
  752. a=ptime:20
  753.  
  754. 2018-12-27 08:33:55.551996 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[G729:18:8000:20:8000:1]
  755. 2018-12-27 08:33:55.551996 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [G729:18:8000:20:8000:1] ++++ is saved as a match
  756. 2018-12-27 08:33:55.551996 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 101@8000
  757. 2018-12-27 08:33:55.551996 [DEBUG] switch_core_media.c:3061 Set Codec sofia/default/0215082222 G729/8000 20 ms 160 samples 8000 bits 1 channels
  758. 2018-12-27 08:33:55.551996 [DEBUG] switch_core_codec.c:111 sofia/default/0215082222 Original read codec set to G729:18
  759. 2018-12-27 08:33:55.551996 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 101@8000
  760. 2018-12-27 08:33:55.551996 [DEBUG] switch_core_media.c:4767 sofia/default/0215082222 Set 2833 dtmf send payload to 101 recv payload to 101
  761. 2018-12-27 08:33:55.551996 [DEBUG] switch_core_media.c:6878 AUDIO RTP [sofia/default/0215082222] 172.235.171.624 port 16218 -> 197.234.193.20 port 15514 codec: 18 ms: 20
  762. 2018-12-27 08:33:55.551996 [DEBUG] switch_rtp.c:4111 Starting timer [soft] 160 bytes per 20ms
  763. 2018-12-27 08:33:55.551996 [DEBUG] switch_core_media.c:7179 sofia/default/0215082222 Set 2833 dtmf send payload to 101
  764. 2018-12-27 08:33:55.551996 [DEBUG] switch_core_media.c:7186 sofia/default/0215082222 Set 2833 dtmf receive payload to 101
  765. 2018-12-27 08:33:55.551996 [DEBUG] switch_core_media.c:7209 sofia/default/0215082222 Set rtp dtmf delay to 40
  766. 2018-12-27 08:33:55.551996 [NOTICE] sofia_media.c:92 Pre-Answer sofia/default/0215082222!
  767. 2018-12-27 08:33:55.551996 [DEBUG] switch_channel.c:3474 (sofia/default/0215082222) Callstate Change RINGING -> EARLY
  768. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  769. 2018-12-27 08:33:55.571956 [INFO] switch_ivr_originate.c:3654 Sending early media
  770. 2018-12-27 08:33:55.571956 [DEBUG] switch_core_media.c:6878 AUDIO RTP [sofia/default/9921646958@fs.telicom.co.za] 172.235.171.624 port 19796 -> 169.255.170.11 port 8000 codec: 18 ms: 20
  771. 2018-12-27 08:33:55.571956 [DEBUG] switch_rtp.c:4111 Starting timer [soft] 160 bytes per 20ms
  772. 2018-12-27 08:33:55.571956 [DEBUG] switch_core_media.c:7179 sofia/default/9921646958@fs.telicom.co.za Set 2833 dtmf send payload to 101
  773. 2018-12-27 08:33:55.571956 [DEBUG] switch_core_media.c:7186 sofia/default/9921646958@fs.telicom.co.za Set 2833 dtmf receive payload to 101
  774. 2018-12-27 08:33:55.571956 [DEBUG] switch_core_media.c:7209 sofia/default/9921646958@fs.telicom.co.za Set rtp dtmf delay to 40
  775. 2018-12-27 08:33:55.571956 [DEBUG] mod_sofia.c:2364 Ring SDP:
  776. v=0
  777. o=FreeSWITCH 1545872639 1545872640 IN IP4 172.235.171.624
  778. s=FreeSWITCH
  779. c=IN IP4 172.235.171.624
  780. t=0 0
  781. m=audio 19796 RTP/AVP 18 101
  782. a=rtpmap:18 G729/8000
  783. a=fmtp:18 annexb=no
  784. a=rtpmap:101 telephone-event/8000
  785. a=fmtp:101 0-16
  786. a=ptime:20
  787. a=sendrecv
  788.  
  789. 2018-12-27 08:33:55.571956 [NOTICE] mod_sofia.c:2367 Pre-Answer sofia/default/9921646958@fs.telicom.co.za!
  790. 2018-12-27 08:33:55.571956 [DEBUG] switch_channel.c:3474 (sofia/default/9921646958@fs.telicom.co.za) Callstate Change RINGING -> EARLY
  791. nua.c:879 nua_respond() nua: nua_respond: entering
  792. nua_stack.c:573 nua_stack_signal() nua(0x7f1b6413df30): recv signal r_respond 183 Session Progress
  793. nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
  794. soa.c:403 soa_set_params() soa_set_params(static::0x7f1b64155ee0, ...) called
  795. soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x7f1b64155ee0, (nil), 0x7f1b6418998b, -1) called
  796. soa.c:890 soa_set_capability_sdp() soa_set_capability_sdp(static::0x7f1b64155ee0, (nil), 0x7f1b6418998b, -1) called
  797. nua_session.c:2320 nua_invite_server_respond() nua: nua_invite_server_respond: entering
  798. soa.c:1515 soa_generate_answer() soa_generate_answer(static::0x7f1b64155ee0) called
  799. soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7f1b64155ee0, soa_generate_answer): called
  800. soa_static.c:1189 offer_answer_step() soa_static(0x7f1b64155ee0, soa_generate_answer): generating local description
  801. soa_static.c:1230 offer_answer_step() soa_static(0x7f1b64155ee0, soa_generate_answer): upgrade with remote description
  802. soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7f1b708ceb00, 0x7f1b640aeab0, ""): called
  803. soa_static.c:1446 offer_answer_step() soa_static(0x7f1b64155ee0, soa_generate_answer): storing local description
  804. soa.c:1730 soa_activate() soa_activate(static::0x7f1b64155ee0, (nil)) called
  805. soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7f1b64155ee0, [(nil)], [0x7f1b708d0c38], [0x7f1b708d0c34]) called
  806. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64282a10) tpn = TCP/169.255.170.11:64474
  807. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64282a10): 1037 bytes of 1037 to tcp/169.255.170.11:64474
  808. tport.c:3492 tport_send_msg() tport_vsend returned 1037
  809. tport.c:2296 tport_set_secondary_timer() tport(0x7f1b64282a10): reset timer
  810. nta.c:6791 incoming_reply() nta: sent 183 Session Progress for INVITE (2)
  811. nua_session.c:4139 signal_call_state_change() nua(0x7f1b6413df30): call state changed: early -> early, sent answer
  812. soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7f1b64155ee0, [0x7f1b708d0ce8], [0x7f1b708d0cf0], [(nil)]) called
  813. soa.c:616 soa_get_params() soa_get_params(static::0x7f1b64155ee0, ...) called
  814. nua_stack.c:271 nua_stack_event() nua(0x7f1b6413df30): event i_state 183 Session Progress
  815. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  816. nua_stack.c:529 nua_signal() nua(0x7f1b6413df30): sent signal r_respond
  817. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  818. 2018-12-27 08:33:55.571956 [DEBUG] sofia.c:7084 Channel sofia/default/9921646958@fs.telicom.co.za entering state [early][183]
  819. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  820. 2018-12-27 08:33:55.571956 [DEBUG] switch_ivr_originate.c:3705 Originate Resulted in Success: [sofia/default/0215082222]
  821. 2018-12-27 08:33:55.571956 [DEBUG] switch_ivr_bridge.c:1614 (sofia/default/0215082222) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
  822. 2018-12-27 08:33:55.571956 [DEBUG] switch_core_state_machine.c:584 (sofia/default/0215082222) Running State Change CS_EXCHANGE_MEDIA (Cur 3 Tot 95)
  823. 2018-12-27 08:33:55.571956 [DEBUG] switch_core_state_machine.c:653 (sofia/default/0215082222) State EXCHANGE_MEDIA
  824. 2018-12-27 08:33:55.571956 [DEBUG] mod_sofia.c:631 SOFIA EXCHANGE_MEDIA
  825. 2018-12-27 08:33:55.612004 [DEBUG] switch_rtp.c:7271 Correct audio ip/port confirmed.
  826. 2018-12-27 08:33:55.631954 [DEBUG] switch_rtp.c:7271 Correct audio ip/port confirmed.
  827. 2018-12-27 08:33:55.751998 [DEBUG] switch_ivr_bridge.c:546 sofia/default/0215082222 Bridge execute app system(/bin/bash /backup/html/ASTPP4_2oct/web_interface/astpp/update_count.sh 1 4 0 18194)
  828. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f1b64027710): events IN
  829. tport.c:2864 tport_recv_event() tport_recv_event(0x7f1b64027710)
  830. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f1b64027710) msg 0x7f1b640ddc20 from (udp/172.235.171.624:5060) has 4 bytes, veclen = 1
  831. tport.c:3023 tport_deliver() tport_deliver(0x7f1b64027710): bad msg 0x7f1b640ddc20 (4 bytes) from udp/169.255.170.14:5060/sip next=(nil)
  832. 2018-12-27 08:33:55.771992 [DEBUG] switch_ivr.c:623 sofia/default/0215082222 Command Execute system(/bin/bash /backup/html/ASTPP4_2oct/web_interface/astpp/update_count.sh 1 4 0 18194)
  833. EXECUTE sofia/default/0215082222 system(/bin/bash /backup/html/ASTPP4_2oct/web_interface/astpp/update_count.sh 1 4 0 18194)
  834. 2018-12-27 08:33:55.771992 [NOTICE] mod_dptools.c:2120 Executing command: /bin/bash /backup/html/ASTPP4_2oct/web_interface/astpp/update_count.sh 1 4 0 18194
  835. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 407 reply
  836. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/37.49.231.129:51317
  837. tport.c:4046 tport_resolve() tport_resolve addrinfo = 37.49.231.129:51317
  838. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/37.49.231.129:51317
  839. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 765 bytes of 765 to udp/37.49.231.129:51317
  840. tport.c:3492 tport_send_msg() tport_vsend returned 765
  841. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/7 resent, 0/7 tout, 0/17 term, 0/25 free
  842. nta.c:1296 agent_timer() nta: timer set next to 66 ms
  843. 2018-12-27 08:33:55.831944 [WARNING] switch_core_state_machine.c:687 319dbb0c-d2dd-4a88-9f55-206ebcf1661d sofia/default/10011@172.235.171.624 Abandoned
  844. 2018-12-27 08:33:55.831944 [NOTICE] switch_core_state_machine.c:690 Hangup sofia/default/10011@172.235.171.624 [CS_NEW] [WRONG_CALL_STATE]
  845. 2018-12-27 08:33:55.831944 [DEBUG] switch_core_state_machine.c:584 (sofia/default/10011@172.235.171.624) Running State Change CS_HANGUP (Cur 3 Tot 95)
  846. 2018-12-27 08:33:55.831944 [DEBUG] switch_core_state_machine.c:850 (sofia/default/10011@172.235.171.624) Callstate Change DOWN -> HANGUP
  847. 2018-12-27 08:33:55.831944 [DEBUG] switch_core_state_machine.c:852 (sofia/default/10011@172.235.171.624) State HANGUP
  848. 2018-12-27 08:33:55.831944 [DEBUG] mod_sofia.c:438 Channel sofia/default/10011@172.235.171.624 hanging up, cause: WRONG_CALL_STATE
  849. 2018-12-27 08:33:55.831944 [DEBUG] switch_core_state_machine.c:60 sofia/default/10011@172.235.171.624 Standard HANGUP, cause: WRONG_CALL_STATE
  850. 2018-12-27 08:33:55.831944 [DEBUG] switch_core_state_machine.c:852 (sofia/default/10011@172.235.171.624) State HANGUP going to sleep
  851. 2018-12-27 08:33:55.831944 [DEBUG] switch_core_state_machine.c:619 (sofia/default/10011@172.235.171.624) State Change CS_HANGUP -> CS_REPORTING
  852. 2018-12-27 08:33:55.831944 [DEBUG] switch_core_state_machine.c:584 (sofia/default/10011@172.235.171.624) Running State Change CS_REPORTING (Cur 3 Tot 95)
  853. 2018-12-27 08:33:55.831944 [DEBUG] switch_core_state_machine.c:938 (sofia/default/10011@172.235.171.624) State REPORTING
  854. 2018-12-27 08:33:55.831944 [DEBUG] switch_core_state_machine.c:174 sofia/default/10011@172.235.171.624 Standard REPORTING, cause: WRONG_CALL_STATE
  855. 2018-12-27 08:33:55.831944 [DEBUG] switch_core_state_machine.c:938 (sofia/default/10011@172.235.171.624) State REPORTING going to sleep
  856. 2018-12-27 08:33:55.831944 [DEBUG] switch_core_state_machine.c:610 (sofia/default/10011@172.235.171.624) State Change CS_REPORTING -> CS_DESTROY
  857. 2018-12-27 08:33:55.831944 [DEBUG] switch_core_session.c:1665 Session 93 (sofia/default/10011@172.235.171.624) Locked, Waiting on external entities
  858. 2018-12-27 08:33:55.831944 [NOTICE] switch_core_session.c:1683 Session 93 (sofia/default/10011@172.235.171.624) Ended
  859. 2018-12-27 08:33:55.831944 [NOTICE] switch_core_session.c:1687 Close Channel sofia/default/10011@172.235.171.624 [CS_DESTROY]
  860. 2018-12-27 08:33:55.831944 [DEBUG] switch_core_state_machine.c:741 (sofia/default/10011@172.235.171.624) Running State Change CS_DESTROY (Cur 2 Tot 95)
  861. 2018-12-27 08:33:55.831944 [DEBUG] switch_core_state_machine.c:751 (sofia/default/10011@172.235.171.624) State DESTROY
  862. 2018-12-27 08:33:55.831944 [DEBUG] mod_sofia.c:343 sofia/default/10011@172.235.171.624 SOFIA DESTROY
  863. 2018-12-27 08:33:55.831944 [DEBUG] switch_core_state_machine.c:181 sofia/default/10011@172.235.171.624 Standard DESTROY
  864. 2018-12-27 08:33:55.831944 [DEBUG] switch_core_state_machine.c:751 (sofia/default/10011@172.235.171.624) State DESTROY going to sleep
  865. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f1b64027710): events IN
  866. tport.c:2864 tport_recv_event() tport_recv_event(0x7f1b64027710)
  867. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f1b64027710) msg 0x7f1b641c7a80 from (udp/172.235.171.624:5060) has 763 bytes, veclen = 1
  868. tport.c:3023 tport_deliver() tport_deliver(0x7f1b64027710): msg 0x7f1b641c7a80 (763 bytes) from udp/197.234.193.20:5060/sip next=(nil)
  869. nta.c:3299 agent_recv_response() nta: received 200 OK for INVITE (132610152)
  870. nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction
  871. tport.c:4222 tport_release() tport_release(0x7f1b64027710): 0x7f1b64125de0 by 0x7f1b6424e940 with 0x7f1b641c7a80
  872. soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x7f1b64204820, (nil), 0x7f1b6415be8d, 238) called
  873. soa.c:1595 soa_process_answer() soa_process_answer(static::0x7f1b64204820) called
  874. nua_session.c:978 nua_session_client_response() nua(0x7f1b64135b00): INVITE: error processing SDP answer in 200 OK
  875. nua_stack.c:271 nua_stack_event() nua(0x7f1b64135b00): event r_invite 200 OK
  876. nua_session.c:4139 signal_call_state_change() nua(0x7f1b64135b00): call state changed: proceeding -> completing, received answer
  877. soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x7f1b64204820, [0x7f1b708d07d8], [0x7f1b708d07e0], [(nil)]) called
  878. soa.c:616 soa_get_params() soa_get_params(static::0x7f1b64204820, ...) called
  879. nua_stack.c:271 nua_stack_event() nua(0x7f1b64135b00): event i_state 200 OK
  880. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  881. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  882. nta.c:7159 _nta_incoming_timer() nta: timer J fired, terminate 200 response
  883. nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7f1b708d0c60)
  884. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 0/7 resent, 0/7 tout, 1/17 term, 1/25 free
  885. nta.c:1296 agent_timer() nta: timer set next to 432 ms
  886. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f1b64027710): events IN
  887. tport.c:2864 tport_recv_event() tport_recv_event(0x7f1b64027710)
  888. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f1b64027710) msg 0x7f1b641682f0 from (udp/172.235.171.624:5060) has 763 bytes, veclen = 1
  889. tport.c:3023 tport_deliver() tport_deliver(0x7f1b64027710): msg 0x7f1b641682f0 (763 bytes) from udp/197.234.193.20:5060/sip next=(nil)
  890. nta.c:3299 agent_recv_response() nta: received 200 OK for INVITE (132610152)
  891. nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction
  892. nta.c:9596 outgoing_duplicate() nta: 200 OK is duplicate response to 132610152 INVITE
  893. nta.c:9603 outgoing_duplicate()         Via: SIP/2.0/UDP 172.235.171.624 ;received=172.235.171.624 ;branch=z9hG4bK67jap81HS3HQK
  894. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  895. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  896. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  897. 2018-12-27 08:33:56.231949 [DEBUG] sofia.c:7084 Channel sofia/default/0215082222 entering state [completing][200]
  898. 2018-12-27 08:33:56.231949 [DEBUG] sofia.c:7094 Remote SDP:
  899. v=0
  900. o=root 3028 3029 IN IP4 197.234.193.20
  901. s=session
  902. c=IN IP4 197.234.193.20
  903. t=0 0
  904. m=audio 15514 RTP/AVP 18 101
  905. a=rtpmap:18 G729/8000
  906. a=fmtp:18 annexb=no
  907. a=rtpmap:101 telephone-event/8000
  908. a=fmtp:101 0-16
  909. a=ptime:20
  910.  
  911. nua.c:639 nua_ack() nua: nua_ack: entering
  912. nua_stack.c:569 nua_stack_signal() nua(0x7f1b64135b00): recv signal r_ack
  913. nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
  914. soa.c:403 soa_set_params() soa_set_params(static::0x7f1b64204820, ...) called
  915. soa.c:1730 soa_activate() soa_activate(static::0x7f1b64204820, (nil)) called
  916. nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
  917. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/197.234.193.20:5060
  918. tport.c:4046 tport_resolve() tport_resolve addrinfo = 197.234.193.20:5060
  919. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/197.234.193.20:5060
  920. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 410 bytes of 410 to udp/197.234.193.20:5060
  921. tport.c:3492 tport_send_msg() tport_vsend returned 410
  922. nta.c:8304 outgoing_send() nta: sent ACK (132610152) to UDP/197.234.193.20:5060
  923. nua_session.c:4139 signal_call_state_change() nua(0x7f1b64135b00): call state changed: completing -> ready
  924. nua_stack.c:271 nua_stack_event() nua(0x7f1b64135b00): event i_state 200 ACK sent
  925. nua_stack.c:271 nua_stack_event() nua(0x7f1b64135b00): event i_active 200 Call active
  926. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  927. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  928. nua_stack.c:529 nua_signal() nua(0x7f1b64135b00): sent signal r_ack
  929. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  930. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  931. 2018-12-27 08:33:56.231949 [DEBUG] sofia.c:7084 Channel sofia/default/0215082222 entering state [ready][200]
  932. 2018-12-27 08:33:56.231949 [NOTICE] sofia.c:8159 Channel [sofia/default/0215082222] has been answered
  933. 2018-12-27 08:33:56.231949 [DEBUG] switch_channel.c:3773 (sofia/default/0215082222) Callstate Change EARLY -> ACTIVE
  934. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  935. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  936. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  937. 2018-12-27 08:33:56.231949 [DEBUG] switch_core_media.c:6861 Audio params are unchanged for sofia/default/9921646958@fs.telicom.co.za.
  938. 2018-12-27 08:33:56.231949 [DEBUG] mod_sofia.c:850 Local SDP sofia/default/9921646958@fs.telicom.co.za:
  939. v=0
  940. o=FreeSWITCH 1545872639 1545872641 IN IP4 172.235.171.624
  941. s=FreeSWITCH
  942. c=IN IP4 172.235.171.624
  943. t=0 0
  944. m=audio 19796 RTP/AVP 18 101
  945. a=rtpmap:18 G729/8000
  946. a=fmtp:18 annexb=no
  947. a=rtpmap:101 telephone-event/8000
  948. a=fmtp:101 0-16
  949. a=ptime:20
  950. a=sendrecv
  951.  
  952. nua.c:879 nua_respond() nua: nua_respond: entering
  953. nua_stack.c:573 nua_stack_signal() nua(0x7f1b6413df30): recv signal r_respond 200 OK
  954. nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
  955. soa.c:403 soa_set_params() soa_set_params(static::0x7f1b64155ee0, ...) called
  956. soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x7f1b64155ee0, (nil), 0x7f1b64230bbb, -1) called
  957. nua_session.c:2320 nua_invite_server_respond() nua: nua_invite_server_respond: entering
  958. soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7f1b64155ee0, [(nil)], [0x7f1b708d0c38], [0x7f1b708d0c34]) called
  959. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64282a10) tpn = TCP/169.255.170.11:64474
  960. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64282a10): 1023 bytes of 1023 to tcp/169.255.170.11:64474
  961. tport.c:3492 tport_send_msg() tport_vsend returned 1023
  962. tport.c:2296 tport_set_secondary_timer() tport(0x7f1b64282a10): reset timer
  963. nta.c:6791 incoming_reply() nta: sent 200 OK for INVITE (2)
  964. nua_session.c:4139 signal_call_state_change() nua(0x7f1b6413df30): call state changed: early -> completed, sent answer
  965. soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7f1b64155ee0, [0x7f1b708d0ce8], [0x7f1b708d0cf0], [(nil)]) called
  966. soa.c:616 soa_get_params() soa_get_params(static::0x7f1b64155ee0, ...) called
  967. nua_stack.c:271 nua_stack_event() nua(0x7f1b6413df30): event i_state 200 OK
  968. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  969. nua_stack.c:529 nua_signal() nua(0x7f1b6413df30): sent signal r_respond
  970. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  971. 2018-12-27 08:33:56.231949 [DEBUG] sofia.c:7084 Channel sofia/default/9921646958@fs.telicom.co.za entering state [completed][200]
  972. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  973. 2018-12-27 08:33:56.231949 [NOTICE] switch_ivr_bridge.c:623 Channel [sofia/default/9921646958@fs.telicom.co.za] has been answered
  974. 2018-12-27 08:33:56.231949 [DEBUG] switch_channel.c:3773 (sofia/default/9921646958@fs.telicom.co.za) Callstate Change EARLY -> ACTIVE
  975. tport.c:2773 tport_wakeup() tport_wakeup(0x7f1b64282a10): events IN
  976. tport.c:2864 tport_recv_event() tport_recv_event(0x7f1b64282a10)
  977. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f1b64282a10) msg 0x7f1b641682f0 from (tcp/169.255.170.11:64474) has 478 bytes, veclen = 1
  978. tport.c:3023 tport_deliver() tport_deliver(0x7f1b64282a10): msg 0x7f1b641682f0 (478 bytes) from tcp/169.255.170.11:64474/sip next=(nil)
  979. nta.c:2880 agent_recv_request() nta: received ACK sip:0215082222@172.235.171.624:5060;transport=tcp SIP/2.0 (CSeq 2)
  980. nta.c:3019 agent_recv_request() nta: ACK (2) is going to INVITE (2)
  981. nua_session.c:2569 process_ack_or_cancel() nua: process_ack_or_cancel: entering
  982. soa.c:1214 soa_clear_remote_sdp() soa_clear_remote_sdp(static::0x7f1b64155ee0) called
  983. nua_stack.c:271 nua_stack_event() nua(0x7f1b6413df30): event i_ack 200 OK
  984. nua_session.c:4139 signal_call_state_change() nua(0x7f1b6413df30): call state changed: completed -> ready
  985. nua_stack.c:271 nua_stack_event() nua(0x7f1b6413df30): event i_state 200 OK
  986. nua_stack.c:271 nua_stack_event() nua(0x7f1b6413df30): event i_active 200 Call active
  987. nta.c:5744 incoming_free() nta: incoming_free(0x7f1b64164ba0)
  988. tport.c:2296 tport_set_secondary_timer() tport(0x7f1b64282a10): reset timer
  989. tport.c:2296 tport_set_secondary_timer() tport(0x7f1b64282a10): reset timer
  990. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  991. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  992. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  993. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  994. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  995. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  996. 2018-12-27 08:33:56.252018 [DEBUG] sofia.c:7084 Channel sofia/default/9921646958@fs.telicom.co.za entering state [ready][200]
  997. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  998. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  999. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1000. 2018-12-27 08:33:56.271969 [DEBUG] switch_rtp.c:7271 Correct audio ip/port confirmed.
  1001. 2018-12-27 08:33:56.271969 [DEBUG] switch_rtp.c:7271 Correct audio ip/port confirmed.
  1002. nta.c:7105 _nta_incoming_timer() nta: timer H fired, timeout and terminate 407 response
  1003. nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7f1b708d0c60)
  1004. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 0/7 resent, 1/7 tout, 1/16 term, 1/23 free
  1005. nta.c:1296 agent_timer() nta: timer set next to 366 ms
  1006. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 407 reply
  1007. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/163.172.251.49:52466
  1008. tport.c:4046 tport_resolve() tport_resolve addrinfo = 163.172.251.49:52466
  1009. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/163.172.251.49:52466
  1010. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 765 bytes of 765 to udp/163.172.251.49:52466
  1011. tport.c:3492 tport_send_msg() tport_vsend returned 765
  1012. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/6 resent, 0/6 tout, 0/16 term, 0/22 free
  1013. nta.c:1296 agent_timer() nta: timer set next to 603 ms
  1014. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f1b64027710): events IN
  1015. tport.c:2864 tport_recv_event() tport_recv_event(0x7f1b64027710)
  1016. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f1b64027710) msg 0x7f1b64070740 from (udp/172.235.171.624:5060) has 734 bytes, veclen = 1
  1017. tport.c:3023 tport_deliver() tport_deliver(0x7f1b64027710): msg 0x7f1b64070740 (734 bytes) from udp/37.49.231.129:5060/sip next=(nil)
  1018. nta.c:2880 agent_recv_request() nta: received INVITE sip:1348222081916@172.235.171.624 SIP/2.0 (CSeq 1)
  1019. nta.c:3248 agent_aliases() nta: canonizing sip:1348222081916@172.235.171.624 with contact
  1020. nta.c:3085 agent_recv_request() nta: INVITE (1) going to a default leg
  1021. nta.c:1348 set_timeout() nta: timer shortened to 200 ms
  1022. nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
  1023. nua_stack.c:899 nh_create() nua: nh_create: entering
  1024. nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
  1025. nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
  1026. soa.c:280 soa_clone() soa_clone(static::0x7f1b64025420, 0x7f1b64033e40, 0x7f1b641a1d90) called
  1027. soa.c:403 soa_set_params() soa_set_params(static::0x7f1b641ed840, ...) called
  1028. nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x7f1b64152810)
  1029. soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7f1b641ed840) called
  1030. soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x7f1b641ed840, (nil), 0x7f1b641d266d, 209) called
  1031. nua_dialog.c:338 nua_dialog_usage_add() nua(0x7f1b641a1d90): adding session usage
  1032. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/37.49.231.129:56862
  1033. tport.c:4046 tport_resolve() tport_resolve addrinfo = 37.49.231.129:56862
  1034. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/37.49.231.129:56862
  1035. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 272 bytes of 272 to udp/37.49.231.129:56862
  1036. tport.c:3492 tport_send_msg() tport_vsend returned 272
  1037. nta.c:6791 incoming_reply() nta: sent 100 Trying for INVITE (1)
  1038. nua_stack.c:271 nua_stack_event() nua(0x7f1b641a1d90): event i_invite 100 Trying
  1039. nua_session.c:4139 signal_call_state_change() nua(0x7f1b641a1d90): call state changed: init -> received, received offer
  1040. soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x7f1b641ed840, [0x7f1b708d08c8], [0x7f1b708d08d0], [(nil)]) called
  1041. nua_stack.c:271 nua_stack_event() nua(0x7f1b641a1d90): event i_state 100 Trying
  1042. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  1043. nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
  1044. 2018-12-27 08:33:56.692004 [NOTICE] switch_channel.c:1104 New Channel sofia/default/10011@172.235.171.624 [e196f3b3-8fe1-44ad-adec-fe3659bf8cfc]
  1045. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  1046. 2018-12-27 08:33:56.692004 [DEBUG] switch_core_state_machine.c:584 (sofia/default/10011@172.235.171.624) Running State Change CS_NEW (Cur 3 Tot 96)
  1047. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1048. 2018-12-27 08:33:56.692004 [DEBUG] sofia.c:9873 sofia/default/10011@172.235.171.624 receiving invite from 37.49.231.129:56862 version: 1.6.19 git 7a77e0b 2017-07-13 12:01:45Z 64bit
  1049. 2018-12-27 08:33:56.692004 [DEBUG] sofia.c:10044 IP 37.49.231.129 Rejected by acl "default". Falling back to Digest auth.
  1050. nua.c:879 nua_respond() nua: nua_respond: entering
  1051. nua_stack.c:573 nua_stack_signal() nua(0x7f1b641a1d90): recv signal r_respond 407 Proxy Authentication Required
  1052. nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
  1053. soa.c:403 soa_set_params() soa_set_params(static::0x7f1b641ed840, ...) called
  1054. nua_session.c:2320 nua_invite_server_respond() nua: nua_invite_server_respond: entering
  1055. soa.c:1214 soa_clear_remote_sdp() soa_clear_remote_sdp(static::0x7f1b641ed840) called
  1056. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/37.49.231.129:56862
  1057. tport.c:4046 tport_resolve() tport_resolve addrinfo = 37.49.231.129:56862
  1058. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/37.49.231.129:56862
  1059. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 764 bytes of 764 to udp/37.49.231.129:56862
  1060. tport.c:3492 tport_send_msg() tport_vsend returned 764
  1061. nta.c:6791 incoming_reply() nta: sent 407 Proxy Authentication Required for INVITE (1)
  1062. nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7f1b641a1d90): removing session usage
  1063. nua_session.c:4139 signal_call_state_change() nua(0x7f1b641a1d90): call state changed: received -> terminated
  1064. nua_stack.c:271 nua_stack_event() nua(0x7f1b641a1d90): event i_state 407 Proxy Authentication Required
  1065. nua_stack.c:271 nua_stack_event() nua(0x7f1b641a1d90): event i_terminated 407 Proxy Authentication Required
  1066. soa.c:356 soa_destroy() soa_destroy(static::0x7f1b641ed840) called
  1067. nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x7f1b64152810)
  1068. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  1069. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  1070. 2018-12-27 08:33:56.692004 [DEBUG] sofia.c:2334 detaching session e196f3b3-8fe1-44ad-adec-fe3659bf8cfc
  1071. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
  1072. nua_stack.c:529 nua_signal() nua(0x7f1b641a1d90): sent signal r_destroy
  1073. nua_stack.c:569 nua_stack_signal() nua(0x7f1b641a1d90): recv signal r_destroy
  1074. nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
  1075. nua_stack.c:529 nua_signal() nua(0x7f1b641a1d90): sent signal r_respond
  1076. 2018-12-27 08:33:56.692004 [WARNING] sofia_reg.c:1792 SIP auth challenge (INVITE) on sofia profile 'default' for [1348222081916@172.235.171.624] from ip 37.49.231.129
  1077. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1078. nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
  1079. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
  1080. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1081. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1082. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
  1083. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1084. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1085. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
  1086. 2018-12-27 08:33:56.692004 [DEBUG] switch_core_state_machine.c:603 (sofia/default/10011@172.235.171.624) State NEW
  1087. 2018-12-27 08:33:56.692004 [WARNING] switch_core_media.c:2480 [CBR]: Asynchronous PTIME not supported, changing our end from 20 to 60
  1088. 2018-12-27 08:33:56.711951 [DEBUG] switch_core_media.c:2959 Changing Codec from G729@20ms@8000hz to G729@60ms@8000hz
  1089. 2018-12-27 08:33:56.752008 [DEBUG] switch_rtp.c:3986 RE-Starting timer [soft] 480 bytes per 60ms
  1090. 2018-12-27 08:33:56.752008 [DEBUG] switch_core_media.c:3061 Set Codec sofia/default/0215082222 G729/8000 60 ms 480 samples 8000 bits 1 channels
  1091. 2018-12-27 08:33:56.752008 [DEBUG] switch_core_codec.c:123 sofia/default/0215082222 Original read codec replaced with G729:18
  1092. 2018-12-27 08:33:56.772009 [INFO] mod_com_g729.c:164 DECODER LICENSE ALLOCATED--->0x7f1b6c19a230 0x7f1b6c19a238
  1093. 2018-12-27 08:33:56.772009 [INFO] mod_com_g729.c:171 DECODER CREATED------------->0x7f1b6c19a230 0x7f1b6c19a238
  1094. 2018-12-27 08:33:56.772009 [DEBUG] switch_core_io.c:1448 Engaging Write Buffer at 960 bytes to accommodate 320->960
  1095. 2018-12-27 08:33:56.811983 [INFO] mod_com_g729.c:126 ENCODER LICENSE ALLOCATED--->0x7f1b64098bd0 0x7f1b64098bd0
  1096. 2018-12-27 08:33:56.811983 [INFO] mod_com_g729.c:133 ENCODER CREATED------------->0x7f1b64098bd0 0x7f1b64098bd0
  1097. 2018-12-27 08:33:56.872003 [INFO] mod_com_g729.c:164 DECODER LICENSE ALLOCATED--->0x7f1b64098b50 0x7f1b64098b58
  1098. 2018-12-27 08:33:56.872003 [INFO] mod_com_g729.c:171 DECODER CREATED------------->0x7f1b64098b50 0x7f1b64098b58
  1099. 2018-12-27 08:33:56.872003 [DEBUG] switch_core_io.c:1448 Engaging Write Buffer at 320 bytes to accommodate 960->320
  1100. 2018-12-27 08:33:56.872003 [INFO] mod_com_g729.c:126 ENCODER LICENSE ALLOCATED--->0x7f1b6c19a2b0 0x7f1b6c19a2b0
  1101. 2018-12-27 08:33:56.872003 [INFO] mod_com_g729.c:133 ENCODER CREATED------------->0x7f1b6c19a2b0 0x7f1b6c19a2b0
  1102. nta.c:1296 agent_timer() nta: timer set next to 301 ms
  1103. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 407 reply
  1104. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/37.49.231.129:56862
  1105. tport.c:4046 tport_resolve() tport_resolve addrinfo = 37.49.231.129:56862
  1106. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/37.49.231.129:56862
  1107. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 764 bytes of 764 to udp/37.49.231.129:56862
  1108. tport.c:3492 tport_send_msg() tport_vsend returned 764
  1109. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/7 resent, 0/7 tout, 0/16 term, 0/23 free
  1110. nta.c:1296 agent_timer() nta: timer set next to 84 ms
  1111. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 407 reply
  1112. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/37.49.231.129:50104
  1113. tport.c:4046 tport_resolve() tport_resolve addrinfo = 37.49.231.129:50104
  1114. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/37.49.231.129:50104
  1115. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 762 bytes of 762 to udp/37.49.231.129:50104
  1116. tport.c:3492 tport_send_msg() tport_vsend returned 762
  1117. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/7 resent, 0/7 tout, 0/16 term, 0/23 free
  1118. nta.c:1296 agent_timer() nta: timer set next to 320 ms
  1119. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 407 reply
  1120. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/37.49.231.204:54643
  1121. tport.c:4046 tport_resolve() tport_resolve addrinfo = 37.49.231.204:54643
  1122. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/37.49.231.204:54643
  1123. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 766 bytes of 766 to udp/37.49.231.204:54643
  1124. tport.c:3492 tport_send_msg() tport_vsend returned 766
  1125. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/7 resent, 0/7 tout, 0/16 term, 0/23 free
  1126. nta.c:1296 agent_timer() nta: timer set next to 431 ms
  1127. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 407 reply
  1128. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/37.49.231.120:50506
  1129. tport.c:4046 tport_resolve() tport_resolve addrinfo = 37.49.231.120:50506
  1130. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/37.49.231.120:50506
  1131. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 764 bytes of 764 to udp/37.49.231.120:50506
  1132. tport.c:3492 tport_send_msg() tport_vsend returned 764
  1133. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/7 resent, 0/7 tout, 0/16 term, 0/23 free
  1134. nta.c:1296 agent_timer() nta: timer set next to 164 ms
  1135. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 407 reply
  1136. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/37.49.231.129:56862
  1137. tport.c:4046 tport_resolve() tport_resolve addrinfo = 37.49.231.129:56862
  1138. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/37.49.231.129:56862
  1139. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 764 bytes of 764 to udp/37.49.231.129:56862
  1140. tport.c:3492 tport_send_msg() tport_vsend returned 764
  1141. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/7 resent, 0/7 tout, 0/16 term, 0/23 free
  1142. nta.c:1296 agent_timer() nta: timer set next to 327 ms
  1143. nta.c:7105 _nta_incoming_timer() nta: timer H fired, timeout and terminate 407 response
  1144. nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7f1b708d0c60)
  1145. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 0/7 resent, 1/7 tout, 1/16 term, 1/23 free
  1146. nta.c:1296 agent_timer() nta: timer set next to 70 ms
  1147. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 407 reply
  1148. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/37.49.231.129:57611
  1149. tport.c:4046 tport_resolve() tport_resolve addrinfo = 37.49.231.129:57611
  1150. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/37.49.231.129:57611
  1151. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 767 bytes of 767 to udp/37.49.231.129:57611
  1152. tport.c:3492 tport_send_msg() tport_vsend returned 767
  1153. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/6 resent, 0/6 tout, 0/16 term, 0/22 free
  1154. nta.c:1296 agent_timer() nta: timer set next to 455 ms
  1155. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f1b64027710): events IN
  1156. tport.c:2864 tport_recv_event() tport_recv_event(0x7f1b64027710)
  1157. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f1b64027710) msg 0x7f1b64237060 from (udp/172.235.171.624:5060) has 578 bytes, veclen = 1
  1158. tport.c:3023 tport_deliver() tport_deliver(0x7f1b64027710): msg 0x7f1b64237060 (578 bytes) from udp/196.250.140.244:5060/sip next=(nil)
  1159. nta.c:2880 agent_recv_request() nta: received REGISTER sip:hpbx58.telicom.co.za:5060 SIP/2.0 (CSeq 1)
  1160. nta.c:3174 agent_check_request_via() nta: Via check: received=196.250.140.244
  1161. nta.c:3012 agent_recv_request() nta: REGISTER (1) going to existing REGISTER transaction
  1162. nta.c:6178 incoming_recv() nta: re-received REGISTER request, retransmitting 401 reply
  1163. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/196.250.140.244:5060
  1164. tport.c:4046 tport_resolve() tport_resolve addrinfo = 196.250.140.244:5060
  1165. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/196.250.140.244:5060
  1166. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 597 bytes of 597 to udp/196.250.140.244:5060
  1167. tport.c:3492 tport_send_msg() tport_vsend returned 597
  1168. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f1b64027710): events ERR
  1169. tport_type_udp.c:519 tport_udp_error() tport_udp_error: Connection refused (111) [icmp type=3 code=3]
  1170. tport_type_udp.c:524 tport_udp_error()  reported by [196.250.140.244]:0
  1171. nta.c:2719 agent_tp_error() nta_agent: tport: 196.250.140.244:5060: Connection refused
  1172. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 407 reply
  1173. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/185.53.88.32:61418
  1174. tport.c:4046 tport_resolve() tport_resolve addrinfo = 185.53.88.32:61418
  1175. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/185.53.88.32:61418
  1176. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 762 bytes of 762 to udp/185.53.88.32:61418
  1177. tport.c:3492 tport_send_msg() tport_vsend returned 762
  1178. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/6 resent, 0/6 tout, 0/16 term, 0/22 free
  1179. nta.c:1296 agent_timer() nta: timer set next to 1147 ms
  1180. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f1b64027710): events IN
  1181. tport.c:2864 tport_recv_event() tport_recv_event(0x7f1b64027710)
  1182. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f1b64027710) msg 0x7f1b641682f0 from (udp/172.235.171.624:5060) has 4 bytes, veclen = 1
  1183. tport.c:3023 tport_deliver() tport_deliver(0x7f1b64027710): bad msg 0x7f1b641682f0 (4 bytes) from udp/213.172.151.31:5060/sip next=(nil)
  1184. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f1b64027710): events IN
  1185. tport.c:2864 tport_recv_event() tport_recv_event(0x7f1b64027710)
  1186. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f1b64027710) msg 0x7f1b6411d580 from (udp/172.235.171.624:5060) has 703 bytes, veclen = 1
  1187. tport.c:3023 tport_deliver() tport_deliver(0x7f1b64027710): msg 0x7f1b6411d580 (703 bytes) from udp/37.49.231.204:5060/sip next=(nil)
  1188. nta.c:2880 agent_recv_request() nta: received INVITE sip:00441224928884@172.235.171.624 SIP/2.0 (CSeq 1)
  1189. nta.c:3248 agent_aliases() nta: canonizing sip:00441224928884@172.235.171.624 with contact
  1190. nta.c:3085 agent_recv_request() nta: INVITE (1) going to a default leg
  1191. nta.c:1348 set_timeout() nta: timer shortened to 200 ms
  1192. nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
  1193. nua_stack.c:899 nh_create() nua: nh_create: entering
  1194. nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
  1195. nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
  1196. soa.c:280 soa_clone() soa_clone(static::0x7f1b64025420, 0x7f1b64033e40, 0x7f1b641a1d90) called
  1197. soa.c:403 soa_set_params() soa_set_params(static::0x7f1b64189820, ...) called
  1198. nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x7f1b6414dff0)
  1199. soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7f1b64189820) called
  1200. soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x7f1b64189820, (nil), 0x7f1b641c53fe, 209) called
  1201. nua_dialog.c:338 nua_dialog_usage_add() nua(0x7f1b641a1d90): adding session usage
  1202. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/37.49.231.204:55683
  1203. tport.c:4046 tport_resolve() tport_resolve addrinfo = 37.49.231.204:55683
  1204. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/37.49.231.204:55683
  1205. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 272 bytes of 272 to udp/37.49.231.204:55683
  1206. tport.c:3492 tport_send_msg() tport_vsend returned 272
  1207. nta.c:6791 incoming_reply() nta: sent 100 Trying for INVITE (1)
  1208. nua_stack.c:271 nua_stack_event() nua(0x7f1b641a1d90): event i_invite 100 Trying
  1209. nua_session.c:4139 signal_call_state_change() nua(0x7f1b641a1d90): call state changed: init -> received, received offer
  1210. soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x7f1b64189820, [0x7f1b708d08c8], [0x7f1b708d08d0], [(nil)]) called
  1211. nua_stack.c:271 nua_stack_event() nua(0x7f1b641a1d90): event i_state 100 Trying
  1212. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  1213. nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
  1214. 2018-12-27 08:33:59.092029 [NOTICE] switch_channel.c:1104 New Channel sofia/default/13760@172.235.171.624 [d8d28df7-26ba-4012-9aa8-a2be15c918a0]
  1215. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  1216. 2018-12-27 08:33:59.092029 [DEBUG] switch_core_state_machine.c:584 (sofia/default/13760@172.235.171.624) Running State Change CS_NEW (Cur 4 Tot 97)
  1217. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1218. 2018-12-27 08:33:59.092029 [DEBUG] sofia.c:9873 sofia/default/13760@172.235.171.624 receiving invite from 37.49.231.204:55683 version: 1.6.19 git 7a77e0b 2017-07-13 12:01:45Z 64bit
  1219. 2018-12-27 08:33:59.092029 [DEBUG] sofia.c:10044 IP 37.49.231.204 Rejected by acl "default". Falling back to Digest auth.
  1220. nua.c:879 nua_respond() nua: nua_respond: entering
  1221. nua_stack.c:573 nua_stack_signal() nua(0x7f1b641a1d90): recv signal r_respond 407 Proxy Authentication Required
  1222. nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
  1223. soa.c:403 soa_set_params() soa_set_params(static::0x7f1b64189820, ...) called
  1224. nua_session.c:2320 nua_invite_server_respond() nua: nua_invite_server_respond: entering
  1225. soa.c:1214 soa_clear_remote_sdp() soa_clear_remote_sdp(static::0x7f1b64189820) called
  1226. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/37.49.231.204:55683
  1227. tport.c:4046 tport_resolve() tport_resolve addrinfo = 37.49.231.204:55683
  1228. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/37.49.231.204:55683
  1229. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 764 bytes of 764 to udp/37.49.231.204:55683
  1230. tport.c:3492 tport_send_msg() tport_vsend returned 764
  1231. nta.c:6791 incoming_reply() nta: sent 407 Proxy Authentication Required for INVITE (1)
  1232. nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7f1b641a1d90): removing session usage
  1233. nua_session.c:4139 signal_call_state_change() nua(0x7f1b641a1d90): call state changed: received -> terminated
  1234. nua_stack.c:271 nua_stack_event() nua(0x7f1b641a1d90): event i_state 407 Proxy Authentication Required
  1235. nua_stack.c:271 nua_stack_event() nua(0x7f1b641a1d90): event i_terminated 407 Proxy Authentication Required
  1236. soa.c:356 soa_destroy() soa_destroy(static::0x7f1b64189820) called
  1237. nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x7f1b6414dff0)
  1238. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  1239. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  1240. 2018-12-27 08:33:59.092029 [DEBUG] sofia.c:2334 detaching session d8d28df7-26ba-4012-9aa8-a2be15c918a0
  1241. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
  1242. nua_stack.c:529 nua_signal() nua(0x7f1b641a1d90): sent signal r_destroy
  1243. nua_stack.c:569 nua_stack_signal() nua(0x7f1b641a1d90): recv signal r_destroy
  1244. nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
  1245. nua_stack.c:529 nua_signal() nua(0x7f1b641a1d90): sent signal r_respond
  1246. 2018-12-27 08:33:59.092029 [WARNING] sofia_reg.c:1792 SIP auth challenge (INVITE) on sofia profile 'default' for [00441224928884@172.235.171.624] from ip 37.49.231.204
  1247. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1248. nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
  1249. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
  1250. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1251. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1252. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
  1253. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1254. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1255. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
  1256. 2018-12-27 08:33:59.092029 [DEBUG] switch_core_state_machine.c:603 (sofia/default/13760@172.235.171.624) State NEW
  1257. nta.c:1296 agent_timer() nta: timer set next to 301 ms
  1258. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 407 reply
  1259. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/37.49.231.204:55683
  1260. tport.c:4046 tport_resolve() tport_resolve addrinfo = 37.49.231.204:55683
  1261. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/37.49.231.204:55683
  1262. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 764 bytes of 764 to udp/37.49.231.204:55683
  1263. tport.c:3492 tport_send_msg() tport_vsend returned 764
  1264. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/7 resent, 0/7 tout, 0/16 term, 0/23 free
  1265. nta.c:1296 agent_timer() nta: timer set next to 611 ms
  1266. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 407 reply
  1267. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/37.49.231.129:56862
  1268. tport.c:4046 tport_resolve() tport_resolve addrinfo = 37.49.231.129:56862
  1269. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/37.49.231.129:56862
  1270. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 764 bytes of 764 to udp/37.49.231.129:56862
  1271. tport.c:3492 tport_send_msg() tport_vsend returned 764
  1272. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/7 resent, 0/7 tout, 0/16 term, 0/23 free
  1273. nta.c:1296 agent_timer() nta: timer set next to 388 ms
  1274. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 407 reply
  1275. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/37.49.231.204:55683
  1276. tport.c:4046 tport_resolve() tport_resolve addrinfo = 37.49.231.204:55683
  1277. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/37.49.231.204:55683
  1278. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 764 bytes of 764 to udp/37.49.231.204:55683
  1279. tport.c:3492 tport_send_msg() tport_vsend returned 764
  1280. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/7 resent, 0/7 tout, 0/16 term, 0/23 free
  1281. nta.c:1296 agent_timer() nta: timer set next to 92 ms
  1282. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 407 reply
  1283. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/163.172.251.49:52466
  1284. tport.c:4046 tport_resolve() tport_resolve addrinfo = 163.172.251.49:52466
  1285. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/163.172.251.49:52466
  1286. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 765 bytes of 765 to udp/163.172.251.49:52466
  1287. tport.c:3492 tport_send_msg() tport_vsend returned 765
  1288. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/7 resent, 0/7 tout, 0/16 term, 0/23 free
  1289. nta.c:1296 agent_timer() nta: timer set next to 602 ms
  1290. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f1b64027710): events IN
  1291. tport.c:2864 tport_recv_event() tport_recv_event(0x7f1b64027710)
  1292. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f1b64027710) msg 0x7f1b641682f0 from (udp/172.235.171.624:5060) has 4 bytes, veclen = 1
  1293. tport.c:3023 tport_deliver() tport_deliver(0x7f1b64027710): bad msg 0x7f1b641682f0 (4 bytes) from udp/169.255.170.14:5060/sip next=(nil)
  1294. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 407 reply
  1295. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/37.49.231.129:50104
  1296. tport.c:4046 tport_resolve() tport_resolve addrinfo = 37.49.231.129:50104
  1297. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/37.49.231.129:50104
  1298. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 762 bytes of 762 to udp/37.49.231.129:50104
  1299. tport.c:3492 tport_send_msg() tport_vsend returned 762
  1300. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/7 resent, 0/7 tout, 0/16 term, 0/23 free
  1301. nta.c:1296 agent_timer() nta: timer set next to 320 ms
  1302. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f1b64027710): events IN
  1303. tport.c:2864 tport_recv_event() tport_recv_event(0x7f1b64027710)
  1304. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f1b64027710) msg 0x7f1b641682f0 from (udp/172.235.171.624:5060) has 4 bytes, veclen = 1
  1305. tport.c:3023 tport_deliver() tport_deliver(0x7f1b64027710): bad msg 0x7f1b641682f0 (4 bytes) from udp/196.250.130.209:5060/sip next=(nil)
  1306. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 407 reply
  1307. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/37.49.231.204:54643
  1308. tport.c:4046 tport_resolve() tport_resolve addrinfo = 37.49.231.204:54643
  1309. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/37.49.231.204:54643
  1310. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 766 bytes of 766 to udp/37.49.231.204:54643
  1311. tport.c:3492 tport_send_msg() tport_vsend returned 766
  1312. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/7 resent, 0/7 tout, 0/16 term, 0/23 free
  1313. nta.c:1296 agent_timer() nta: timer set next to 499 ms
  1314. nta.c:7105 _nta_incoming_timer() nta: timer H fired, timeout and terminate 407 response
  1315. nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7f1b708d0c60)
  1316. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 0/7 resent, 1/7 tout, 1/16 term, 1/23 free
  1317. nta.c:1296 agent_timer() nta: timer set next to 486 ms
  1318. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 407 reply
  1319. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/37.49.231.204:55683
  1320. tport.c:4046 tport_resolve() tport_resolve addrinfo = 37.49.231.204:55683
  1321. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/37.49.231.204:55683
  1322. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 764 bytes of 764 to udp/37.49.231.204:55683
  1323. tport.c:3492 tport_send_msg() tport_vsend returned 764
  1324. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/6 resent, 0/6 tout, 0/16 term, 0/22 free
  1325. nta.c:1296 agent_timer() nta: timer set next to 8 ms
  1326. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 407 reply
  1327. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/37.49.231.129:57611
  1328. tport.c:4046 tport_resolve() tport_resolve addrinfo = 37.49.231.129:57611
  1329. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/37.49.231.129:57611
  1330. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 767 bytes of 767 to udp/37.49.231.129:57611
  1331. tport.c:3492 tport_send_msg() tport_vsend returned 767
  1332. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/6 resent, 0/6 tout, 0/16 term, 0/22 free
  1333. nta.c:1296 agent_timer() nta: timer set next to 455 ms
  1334. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f1b64027710): events IN
  1335. tport.c:2864 tport_recv_event() tport_recv_event(0x7f1b64027710)
  1336. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f1b64027710) msg 0x7f1b641682f0 from (udp/172.235.171.624:5060) has 578 bytes, veclen = 1
  1337. tport.c:3023 tport_deliver() tport_deliver(0x7f1b64027710): msg 0x7f1b641682f0 (578 bytes) from udp/196.250.140.244:5060/sip next=(nil)
  1338. nta.c:2880 agent_recv_request() nta: received REGISTER sip:hpbx58.telicom.co.za:5060 SIP/2.0 (CSeq 1)
  1339. nta.c:3174 agent_check_request_via() nta: Via check: received=196.250.140.244
  1340. nta.c:3012 agent_recv_request() nta: REGISTER (1) going to existing REGISTER transaction
  1341. nta.c:6178 incoming_recv() nta: re-received REGISTER request, retransmitting 401 reply
  1342. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/196.250.140.244:5060
  1343. tport.c:4046 tport_resolve() tport_resolve addrinfo = 196.250.140.244:5060
  1344. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/196.250.140.244:5060
  1345. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 597 bytes of 597 to udp/196.250.140.244:5060
  1346. tport.c:3492 tport_send_msg() tport_vsend returned 597
  1347. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f1b64027710): events ERR
  1348. tport_type_udp.c:519 tport_udp_error() tport_udp_error: Connection refused (111) [icmp type=3 code=3]
  1349. tport_type_udp.c:524 tport_udp_error()  reported by [196.250.140.244]:0
  1350. nta.c:2719 agent_tp_error() nta_agent: tport: 196.250.140.244:5060: Connection refused
  1351. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 407 reply
  1352. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/185.53.88.32:61418
  1353. tport.c:4046 tport_resolve() tport_resolve addrinfo = 185.53.88.32:61418
  1354. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/185.53.88.32:61418
  1355. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 762 bytes of 762 to udp/185.53.88.32:61418
  1356. tport.c:3492 tport_send_msg() tport_vsend returned 762
  1357. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/6 resent, 0/6 tout, 0/16 term, 0/22 free
  1358. nta.c:1296 agent_timer() nta: timer set next to 490 ms
  1359. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f1b64027710): events IN
  1360. tport.c:2864 tport_recv_event() tport_recv_event(0x7f1b64027710)
  1361. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f1b64027710) msg 0x7f1b64135120 from (udp/172.235.171.624:5060) has 508 bytes, veclen = 1
  1362. tport.c:3023 tport_deliver() tport_deliver(0x7f1b64027710): msg 0x7f1b64135120 (508 bytes) from udp/196.250.134.134:5060/sip next=(nil)
  1363. nta.c:2880 agent_recv_request() nta: received NOTIFY sip:1195573632@172.235.171.624:5060 SIP/2.0 (CSeq 1)
  1364. nta.c:3174 agent_check_request_via() nta: Via check: received=196.250.134.134
  1365. nta.c:3248 agent_aliases() nta: canonizing sip:1195573632@172.235.171.624:5060 with contact
  1366. nta.c:3085 agent_recv_request() nta: NOTIFY (1) going to a default leg
  1367. nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
  1368. nua_stack.c:899 nh_create() nua: nh_create: entering
  1369. nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
  1370. nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
  1371. soa.c:280 soa_clone() soa_clone(static::0x7f1b64025420, 0x7f1b64033e40, 0x7f1b6420c500) called
  1372. soa.c:403 soa_set_params() soa_set_params(static::0x7f1b64189820, ...) called
  1373. nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x7f1b641c83c0)
  1374. nua_dialog.c:338 nua_dialog_usage_add() nua(0x7f1b6420c500): adding subscribe usage with event keep-alive
  1375. nua_subnotref.c:638 nua_notify_server_preprocess() nua(0x7f1b6420c500): nua_notify_server_preprocess: terminated ()
  1376. nua_stack.c:271 nua_stack_event() nua(0x7f1b6420c500): event i_notify 100 Trying
  1377. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  1378. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1379. nua.c:879 nua_respond() nua: nua_respond: entering
  1380. nua_stack.c:573 nua_stack_signal() nua(0x7f1b6420c500): recv signal r_respond 200 OK
  1381. nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
  1382. soa.c:403 soa_set_params() soa_set_params(static::0x7f1b64189820, ...) called
  1383. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/196.250.134.134:5060
  1384. tport.c:4046 tport_resolve() tport_resolve addrinfo = 196.250.134.134:5060
  1385. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/196.250.134.134:5060
  1386. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 728 bytes of 728 to udp/196.250.134.134:5060
  1387. tport.c:3492 tport_send_msg() tport_vsend returned 728
  1388. nta.c:6791 incoming_reply() nta: sent 200 OK for NOTIFY (1)
  1389. nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7f1b6420c500): removing subscribe usage with event keep-alive
  1390. nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x7f1b641c83c0)
  1391. nua_stack.c:529 nua_signal() nua(0x7f1b6420c500): sent signal r_respond
  1392. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1393. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
  1394. nua_stack.c:569 nua_stack_signal() nua(0x7f1b6420c500): recv signal r_destroy
  1395. nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
  1396. soa.c:356 soa_destroy() soa_destroy(static::0x7f1b64189820) called
  1397. nua_stack.c:529 nua_signal() nua(0x7f1b6420c500): sent signal r_destroy
  1398. nta.c:7105 _nta_incoming_timer() nta: timer H fired, timeout and terminate 407 response
  1399. nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7f1b708d0c60)
  1400. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 0/6 resent, 1/6 tout, 1/17 term, 1/23 free
  1401. nta.c:1296 agent_timer() nta: timer set next to 659 ms
  1402. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 407 reply
  1403. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/37.49.231.129:56862
  1404. tport.c:4046 tport_resolve() tport_resolve addrinfo = 37.49.231.129:56862
  1405. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/37.49.231.129:56862
  1406. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 764 bytes of 764 to udp/37.49.231.129:56862
  1407. tport.c:3492 tport_send_msg() tport_vsend returned 764
  1408. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/5 resent, 0/5 tout, 0/17 term, 0/22 free
  1409. nta.c:1296 agent_timer() nta: timer set next to 478 ms
  1410. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 407 reply
  1411. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/163.172.251.49:52466
  1412. tport.c:4046 tport_resolve() tport_resolve addrinfo = 163.172.251.49:52466
  1413. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/163.172.251.49:52466
  1414. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 765 bytes of 765 to udp/163.172.251.49:52466
  1415. tport.c:3492 tport_send_msg() tport_vsend returned 765
  1416. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/5 resent, 0/5 tout, 0/17 term, 0/22 free
  1417. nta.c:1296 agent_timer() nta: timer set next to 538 ms
  1418. nta.c:7159 _nta_incoming_timer() nta: timer J fired, terminate 200 response
  1419. nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7f1b708d0c60)
  1420. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 0/5 resent, 0/5 tout, 1/17 term, 1/22 free
  1421. nta.c:1296 agent_timer() nta: timer set next to 63 ms
  1422. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f1b64027710): events IN
  1423. tport.c:2864 tport_recv_event() tport_recv_event(0x7f1b64027710)
  1424. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f1b64027710) msg 0x7f1b641682f0 from (udp/172.235.171.624:5060) has 4 bytes, veclen = 1
  1425. tport.c:3023 tport_deliver() tport_deliver(0x7f1b64027710): bad msg 0x7f1b641682f0 (4 bytes) from udp/197.184.54.54:5060/sip next=(nil)
  1426. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 407 reply
  1427. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/37.49.231.129:50104
  1428. tport.c:4046 tport_resolve() tport_resolve addrinfo = 37.49.231.129:50104
  1429. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/37.49.231.129:50104
  1430. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 762 bytes of 762 to udp/37.49.231.129:50104
  1431. tport.c:3492 tport_send_msg() tport_vsend returned 762
  1432. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/5 resent, 0/5 tout, 0/16 term, 0/21 free
  1433. nta.c:1296 agent_timer() nta: timer set next to 447 ms
  1434. nta.c:7159 _nta_incoming_timer() nta: timer J fired, terminate 200 response
  1435. nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7f1b708d0c60)
  1436. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 0/5 resent, 0/5 tout, 1/16 term, 1/21 free
  1437. nta.c:1296 agent_timer() nta: timer set next to 859 ms
  1438. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f1b64027710): events IN
  1439. tport.c:2864 tport_recv_event() tport_recv_event(0x7f1b64027710)
  1440. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f1b64027710) msg 0x7f1b640b4b90 from (udp/172.235.171.624:5060) has 735 bytes, veclen = 1
  1441. tport.c:3023 tport_deliver() tport_deliver(0x7f1b64027710): msg 0x7f1b640b4b90 (735 bytes) from udp/37.49.231.120:5060/sip next=(nil)
  1442. nta.c:2880 agent_recv_request() nta: received INVITE sip:0048221284980@172.235.171.624 SIP/2.0 (CSeq 1)
  1443. nta.c:3248 agent_aliases() nta: canonizing sip:0048221284980@172.235.171.624 with contact
  1444. nta.c:3085 agent_recv_request() nta: INVITE (1) going to a default leg
  1445. nta.c:1348 set_timeout() nta: timer shortened to 200 ms
  1446. nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
  1447. nua_stack.c:899 nh_create() nua: nh_create: entering
  1448. nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
  1449. nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
  1450. soa.c:280 soa_clone() soa_clone(static::0x7f1b64025420, 0x7f1b64033e40, 0x7f1b64272730) called
  1451. soa.c:403 soa_set_params() soa_set_params(static::0x7f1b64189820, ...) called
  1452. nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x7f1b641d0900)
  1453. soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7f1b64189820) called
  1454. soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x7f1b64189820, (nil), 0x7f1b640eb7dd, 210) called
  1455. nua_dialog.c:338 nua_dialog_usage_add() nua(0x7f1b64272730): adding session usage
  1456. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/37.49.231.120:62545
  1457. tport.c:4046 tport_resolve() tport_resolve addrinfo = 37.49.231.120:62545
  1458. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/37.49.231.120:62545
  1459. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 271 bytes of 271 to udp/37.49.231.120:62545
  1460. tport.c:3492 tport_send_msg() tport_vsend returned 271
  1461. nta.c:6791 incoming_reply() nta: sent 100 Trying for INVITE (1)
  1462. nua_stack.c:271 nua_stack_event() nua(0x7f1b64272730): event i_invite 100 Trying
  1463. nua_session.c:4139 signal_call_state_change() nua(0x7f1b64272730): call state changed: init -> received, received offer
  1464. soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x7f1b64189820, [0x7f1b708d08c8], [0x7f1b708d08d0], [(nil)]) called
  1465. nua_stack.c:271 nua_stack_event() nua(0x7f1b64272730): event i_state 100 Trying
  1466. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  1467. nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
  1468. 2018-12-27 08:34:05.751976 [NOTICE] switch_channel.c:1104 New Channel sofia/default/406300@172.235.171.624 [7f0958a5-8f5a-4f89-a33a-23e626d16941]
  1469. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  1470. 2018-12-27 08:34:05.751976 [DEBUG] switch_core_state_machine.c:584 (sofia/default/406300@172.235.171.624) Running State Change CS_NEW (Cur 5 Tot 98)
  1471. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1472. 2018-12-27 08:34:05.751976 [DEBUG] sofia.c:9873 sofia/default/406300@172.235.171.624 receiving invite from 37.49.231.120:62545 version: 1.6.19 git 7a77e0b 2017-07-13 12:01:45Z 64bit
  1473. 2018-12-27 08:34:05.751976 [DEBUG] sofia.c:10044 IP 37.49.231.120 Rejected by acl "default". Falling back to Digest auth.
  1474. nua.c:879 nua_respond() nua: nua_respond: entering
  1475. nua_stack.c:573 nua_stack_signal() nua(0x7f1b64272730): recv signal r_respond 407 Proxy Authentication Required
  1476. nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
  1477. soa.c:403 soa_set_params() soa_set_params(static::0x7f1b64189820, ...) called
  1478. nua_session.c:2320 nua_invite_server_respond() nua: nua_invite_server_respond: entering
  1479. soa.c:1214 soa_clear_remote_sdp() soa_clear_remote_sdp(static::0x7f1b64189820) called
  1480. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/37.49.231.120:62545
  1481. tport.c:4046 tport_resolve() tport_resolve addrinfo = 37.49.231.120:62545
  1482. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/37.49.231.120:62545
  1483. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 763 bytes of 763 to udp/37.49.231.120:62545
  1484. tport.c:3492 tport_send_msg() tport_vsend returned 763
  1485. nta.c:6791 incoming_reply() nta: sent 407 Proxy Authentication Required for INVITE (1)
  1486. nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7f1b64272730): removing session usage
  1487. nua_session.c:4139 signal_call_state_change() nua(0x7f1b64272730): call state changed: received -> terminated
  1488. nua_stack.c:271 nua_stack_event() nua(0x7f1b64272730): event i_state 407 Proxy Authentication Required
  1489. nua_stack.c:271 nua_stack_event() nua(0x7f1b64272730): event i_terminated 407 Proxy Authentication Required
  1490. soa.c:356 soa_destroy() soa_destroy(static::0x7f1b64189820) called
  1491. nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x7f1b641d0900)
  1492. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  1493. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  1494. 2018-12-27 08:34:05.751976 [DEBUG] sofia.c:2334 detaching session 7f0958a5-8f5a-4f89-a33a-23e626d16941
  1495. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
  1496. nua_stack.c:529 nua_signal() nua(0x7f1b64272730): sent signal r_destroy
  1497. nua_stack.c:569 nua_stack_signal() nua(0x7f1b64272730): recv signal r_destroy
  1498. nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
  1499. nua_stack.c:529 nua_signal() nua(0x7f1b64272730): sent signal r_respond
  1500. 2018-12-27 08:34:05.751976 [WARNING] sofia_reg.c:1792 SIP auth challenge (INVITE) on sofia profile 'default' for [0048221284980@172.235.171.624] from ip 37.49.231.120
  1501. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1502. nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
  1503. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
  1504. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1505. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1506. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
  1507. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1508. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1509. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
  1510. 2018-12-27 08:34:05.751976 [DEBUG] switch_core_state_machine.c:603 (sofia/default/406300@172.235.171.624) State NEW
  1511. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f1b64027710): events IN
  1512. tport.c:2864 tport_recv_event() tport_recv_event(0x7f1b64027710)
  1513. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f1b64027710) msg 0x7f1b641682f0 from (udp/172.235.171.624:5060) has 4 bytes, veclen = 1
  1514. tport.c:3023 tport_deliver() tport_deliver(0x7f1b64027710): bad msg 0x7f1b641682f0 (4 bytes) from udp/192.168.2.180:5060/sip next=(nil)
  1515. nta.c:1296 agent_timer() nta: timer set next to 301 ms
  1516. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f1b64027710): events IN
  1517. tport.c:2864 tport_recv_event() tport_recv_event(0x7f1b64027710)
  1518. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f1b64027710) msg 0x7f1b641682f0 from (udp/172.235.171.624:5060) has 8 bytes, veclen = 1
  1519. tport.c:3023 tport_deliver() tport_deliver(0x7f1b64027710): bad msg 0x7f1b641682f0 (0 bytes) from udp/102.141.195.62:5060/sip next=(nil)
  1520. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 407 reply
  1521. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/37.49.231.120:62545
  1522. tport.c:4046 tport_resolve() tport_resolve addrinfo = 37.49.231.120:62545
  1523. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/37.49.231.120:62545
  1524. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 763 bytes of 763 to udp/37.49.231.120:62545
  1525. tport.c:3492 tport_send_msg() tport_vsend returned 763
  1526. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/6 resent, 0/6 tout, 0/15 term, 0/21 free
  1527. nta.c:1296 agent_timer() nta: timer set next to 338 ms
  1528. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f1b64027710): events IN
  1529. tport.c:2864 tport_recv_event() tport_recv_event(0x7f1b64027710)
  1530. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f1b64027710) msg 0x7f1b641682f0 from (udp/172.235.171.624:5060) has 4 bytes, veclen = 1
  1531. tport.c:3023 tport_deliver() tport_deliver(0x7f1b64027710): bad msg 0x7f1b641682f0 (4 bytes) from udp/169.255.170.14:5060/sip next=(nil)
  1532. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 407 reply
  1533. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/37.49.231.204:55683
  1534. tport.c:4046 tport_resolve() tport_resolve addrinfo = 37.49.231.204:55683
  1535. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/37.49.231.204:55683
  1536. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 764 bytes of 764 to udp/37.49.231.204:55683
  1537. tport.c:3492 tport_send_msg() tport_vsend returned 764
  1538. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/6 resent, 0/6 tout, 0/15 term, 0/21 free
  1539. nta.c:1296 agent_timer() nta: timer set next to 8 ms
  1540. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 407 reply
  1541. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/37.49.231.129:57611
  1542. tport.c:4046 tport_resolve() tport_resolve addrinfo = 37.49.231.129:57611
  1543. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/37.49.231.129:57611
  1544. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 767 bytes of 767 to udp/37.49.231.129:57611
  1545. tport.c:3492 tport_send_msg() tport_vsend returned 767
  1546. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/6 resent, 0/6 tout, 0/15 term, 0/21 free
  1547. nta.c:1296 agent_timer() nta: timer set next to 497 ms
  1548. 2018-12-27 08:34:06.731972 [WARNING] switch_core_state_machine.c:687 e196f3b3-8fe1-44ad-adec-fe3659bf8cfc sofia/default/10011@172.235.171.624 Abandoned
  1549. 2018-12-27 08:34:06.731972 [NOTICE] switch_core_state_machine.c:690 Hangup sofia/default/10011@172.235.171.624 [CS_NEW] [WRONG_CALL_STATE]
  1550. 2018-12-27 08:34:06.731972 [DEBUG] switch_core_state_machine.c:584 (sofia/default/10011@172.235.171.624) Running State Change CS_HANGUP (Cur 5 Tot 98)
  1551. 2018-12-27 08:34:06.731972 [DEBUG] switch_core_state_machine.c:850 (sofia/default/10011@172.235.171.624) Callstate Change DOWN -> HANGUP
  1552. 2018-12-27 08:34:06.731972 [DEBUG] switch_core_state_machine.c:852 (sofia/default/10011@172.235.171.624) State HANGUP
  1553. 2018-12-27 08:34:06.731972 [DEBUG] mod_sofia.c:438 Channel sofia/default/10011@172.235.171.624 hanging up, cause: WRONG_CALL_STATE
  1554. 2018-12-27 08:34:06.731972 [DEBUG] switch_core_state_machine.c:60 sofia/default/10011@172.235.171.624 Standard HANGUP, cause: WRONG_CALL_STATE
  1555. 2018-12-27 08:34:06.731972 [DEBUG] switch_core_state_machine.c:852 (sofia/default/10011@172.235.171.624) State HANGUP going to sleep
  1556. 2018-12-27 08:34:06.731972 [DEBUG] switch_core_state_machine.c:619 (sofia/default/10011@172.235.171.624) State Change CS_HANGUP -> CS_REPORTING
  1557. 2018-12-27 08:34:06.731972 [DEBUG] switch_core_state_machine.c:584 (sofia/default/10011@172.235.171.624) Running State Change CS_REPORTING (Cur 5 Tot 98)
  1558. 2018-12-27 08:34:06.731972 [DEBUG] switch_core_state_machine.c:938 (sofia/default/10011@172.235.171.624) State REPORTING
  1559. 2018-12-27 08:34:06.731972 [DEBUG] switch_core_state_machine.c:174 sofia/default/10011@172.235.171.624 Standard REPORTING, cause: WRONG_CALL_STATE
  1560. 2018-12-27 08:34:06.731972 [DEBUG] switch_core_state_machine.c:938 (sofia/default/10011@172.235.171.624) State REPORTING going to sleep
  1561. 2018-12-27 08:34:06.731972 [DEBUG] switch_core_state_machine.c:610 (sofia/default/10011@172.235.171.624) State Change CS_REPORTING -> CS_DESTROY
  1562. 2018-12-27 08:34:06.731972 [DEBUG] switch_core_session.c:1665 Session 96 (sofia/default/10011@172.235.171.624) Locked, Waiting on external entities
  1563. 2018-12-27 08:34:06.731972 [NOTICE] switch_core_session.c:1683 Session 96 (sofia/default/10011@172.235.171.624) Ended
  1564. 2018-12-27 08:34:06.731972 [NOTICE] switch_core_session.c:1687 Close Channel sofia/default/10011@172.235.171.624 [CS_DESTROY]
  1565. 2018-12-27 08:34:06.731972 [DEBUG] switch_core_state_machine.c:741 (sofia/default/10011@172.235.171.624) Running State Change CS_DESTROY (Cur 4 Tot 98)
  1566. 2018-12-27 08:34:06.731972 [DEBUG] switch_core_state_machine.c:751 (sofia/default/10011@172.235.171.624) State DESTROY
  1567. 2018-12-27 08:34:06.731972 [DEBUG] mod_sofia.c:343 sofia/default/10011@172.235.171.624 SOFIA DESTROY
  1568. 2018-12-27 08:34:06.731972 [DEBUG] switch_core_state_machine.c:181 sofia/default/10011@172.235.171.624 Standard DESTROY
  1569. 2018-12-27 08:34:06.731972 [DEBUG] switch_core_state_machine.c:751 (sofia/default/10011@172.235.171.624) State DESTROY going to sleep
  1570. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f1b64027710): events IN
  1571. tport.c:2864 tport_recv_event() tport_recv_event(0x7f1b64027710)
  1572. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f1b64027710) msg 0x7f1b640b1590 from (udp/172.235.171.624:5060) has 578 bytes, veclen = 1
  1573. tport.c:3023 tport_deliver() tport_deliver(0x7f1b64027710): msg 0x7f1b640b1590 (578 bytes) from udp/196.250.140.244:5060/sip next=(nil)
  1574. nta.c:2880 agent_recv_request() nta: received REGISTER sip:hpbx58.telicom.co.za:5060 SIP/2.0 (CSeq 1)
  1575. nta.c:3174 agent_check_request_via() nta: Via check: received=196.250.140.244
  1576. nta.c:3012 agent_recv_request() nta: REGISTER (1) going to existing REGISTER transaction
  1577. nta.c:6178 incoming_recv() nta: re-received REGISTER request, retransmitting 401 reply
  1578. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/196.250.140.244:5060
  1579. tport.c:4046 tport_resolve() tport_resolve addrinfo = 196.250.140.244:5060
  1580. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/196.250.140.244:5060
  1581. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 597 bytes of 597 to udp/196.250.140.244:5060
  1582. tport.c:3492 tport_send_msg() tport_vsend returned 597
  1583. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f1b64027710): events ERR
  1584. tport_type_udp.c:519 tport_udp_error() tport_udp_error: Connection refused (111) [icmp type=3 code=3]
  1585. tport_type_udp.c:524 tport_udp_error()  reported by [196.250.140.244]:0
  1586. nta.c:2719 agent_tp_error() nta_agent: tport: 196.250.140.244:5060: Connection refused
  1587. nta.c:7105 _nta_incoming_timer() nta: timer H fired, timeout and terminate 407 response
  1588. nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7f1b708d0c60)
  1589. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 0/6 resent, 1/6 tout, 1/15 term, 1/21 free
  1590. nta.c:1296 agent_timer() nta: timer set next to 157 ms
  1591. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 407 reply
  1592. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/37.49.231.120:62545
  1593. tport.c:4046 tport_resolve() tport_resolve addrinfo = 37.49.231.120:62545
  1594. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/37.49.231.120:62545
  1595. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 763 bytes of 763 to udp/37.49.231.120:62545
  1596. tport.c:3492 tport_send_msg() tport_vsend returned 763
  1597. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/5 resent, 0/5 tout, 0/15 term, 0/20 free
  1598. nta.c:1296 agent_timer() nta: timer set next to 950 ms
  1599. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f1b64027710): events IN
  1600. tport.c:2864 tport_recv_event() tport_recv_event(0x7f1b64027710)
  1601. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f1b64027710) msg 0x7f1b641682f0 from (udp/172.235.171.624:5060) has 735 bytes, veclen = 1
  1602. tport.c:3023 tport_deliver() tport_deliver(0x7f1b64027710): msg 0x7f1b641682f0 (735 bytes) from udp/37.49.231.129:5060/sip next=(nil)
  1603. nta.c:2880 agent_recv_request() nta: received INVITE sip:1448222081916@172.235.171.624 SIP/2.0 (CSeq 1)
  1604. nta.c:3248 agent_aliases() nta: canonizing sip:1448222081916@172.235.171.624 with contact
  1605. nta.c:3085 agent_recv_request() nta: INVITE (1) going to a default leg
  1606. nta.c:1348 set_timeout() nta: timer shortened to 200 ms
  1607. nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
  1608. nua_stack.c:899 nh_create() nua: nh_create: entering
  1609. nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
  1610. nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
  1611. soa.c:280 soa_clone() soa_clone(static::0x7f1b64025420, 0x7f1b64033e40, 0x7f1b6420c500) called
  1612. soa.c:403 soa_set_params() soa_set_params(static::0x7f1b64147b90, ...) called
  1613. nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x7f1b64187e70)
  1614. soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7f1b64147b90) called
  1615. soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x7f1b64147b90, (nil), 0x7f1b641cb02e, 209) called
  1616. nua_dialog.c:338 nua_dialog_usage_add() nua(0x7f1b6420c500): adding session usage
  1617. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/37.49.231.129:58725
  1618. tport.c:4046 tport_resolve() tport_resolve addrinfo = 37.49.231.129:58725
  1619. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/37.49.231.129:58725
  1620. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 273 bytes of 273 to udp/37.49.231.129:58725
  1621. tport.c:3492 tport_send_msg() tport_vsend returned 273
  1622. nta.c:6791 incoming_reply() nta: sent 100 Trying for INVITE (1)
  1623. nua_stack.c:271 nua_stack_event() nua(0x7f1b6420c500): event i_invite 100 Trying
  1624. nua_session.c:4139 signal_call_state_change() nua(0x7f1b6420c500): call state changed: init -> received, received offer
  1625. soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x7f1b64147b90, [0x7f1b708d08c8], [0x7f1b708d08d0], [(nil)]) called
  1626. nua_stack.c:271 nua_stack_event() nua(0x7f1b6420c500): event i_state 100 Trying
  1627. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  1628. nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
  1629. 2018-12-27 08:34:07.292011 [NOTICE] switch_channel.c:1104 New Channel sofia/default/10011@172.235.171.624 [d32e8add-ac97-490b-ab8b-c219da535b50]
  1630. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  1631. 2018-12-27 08:34:07.292011 [DEBUG] switch_core_state_machine.c:584 (sofia/default/10011@172.235.171.624) Running State Change CS_NEW (Cur 5 Tot 99)
  1632. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1633. 2018-12-27 08:34:07.292011 [DEBUG] sofia.c:9873 sofia/default/10011@172.235.171.624 receiving invite from 37.49.231.129:58725 version: 1.6.19 git 7a77e0b 2017-07-13 12:01:45Z 64bit
  1634. 2018-12-27 08:34:07.292011 [DEBUG] sofia.c:10044 IP 37.49.231.129 Rejected by acl "default". Falling back to Digest auth.
  1635. nua.c:879 nua_respond() nua: nua_respond: entering
  1636. nua_stack.c:573 nua_stack_signal() nua(0x7f1b6420c500): recv signal r_respond 407 Proxy Authentication Required
  1637. nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
  1638. soa.c:403 soa_set_params() soa_set_params(static::0x7f1b64147b90, ...) called
  1639. nua_session.c:2320 nua_invite_server_respond() nua: nua_invite_server_respond: entering
  1640. soa.c:1214 soa_clear_remote_sdp() soa_clear_remote_sdp(static::0x7f1b64147b90) called
  1641. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/37.49.231.129:58725
  1642. tport.c:4046 tport_resolve() tport_resolve addrinfo = 37.49.231.129:58725
  1643. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/37.49.231.129:58725
  1644. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 765 bytes of 765 to udp/37.49.231.129:58725
  1645. tport.c:3492 tport_send_msg() tport_vsend returned 765
  1646. nta.c:6791 incoming_reply() nta: sent 407 Proxy Authentication Required for INVITE (1)
  1647. nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7f1b6420c500): removing session usage
  1648. nua_session.c:4139 signal_call_state_change() nua(0x7f1b6420c500): call state changed: received -> terminated
  1649. nua_stack.c:271 nua_stack_event() nua(0x7f1b6420c500): event i_state 407 Proxy Authentication Required
  1650. nua_stack.c:271 nua_stack_event() nua(0x7f1b6420c500): event i_terminated 407 Proxy Authentication Required
  1651. soa.c:356 soa_destroy() soa_destroy(static::0x7f1b64147b90) called
  1652. nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x7f1b64187e70)
  1653. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  1654. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  1655. 2018-12-27 08:34:07.292011 [DEBUG] sofia.c:2334 detaching session d32e8add-ac97-490b-ab8b-c219da535b50
  1656. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
  1657. nua_stack.c:529 nua_signal() nua(0x7f1b6420c500): sent signal r_destroy
  1658. nua_stack.c:569 nua_stack_signal() nua(0x7f1b6420c500): recv signal r_destroy
  1659. nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
  1660. nua_stack.c:529 nua_signal() nua(0x7f1b6420c500): sent signal r_respond
  1661. 2018-12-27 08:34:07.292011 [WARNING] sofia_reg.c:1792 SIP auth challenge (INVITE) on sofia profile 'default' for [1448222081916@172.235.171.624] from ip 37.49.231.129
  1662. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1663. nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
  1664. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
  1665. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1666. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1667. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
  1668. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1669. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1670. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
  1671. 2018-12-27 08:34:07.292011 [DEBUG] switch_core_state_machine.c:603 (sofia/default/10011@172.235.171.624) State NEW
  1672. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f1b64027710): events IN
  1673. tport.c:2864 tport_recv_event() tport_recv_event(0x7f1b64027710)
  1674. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f1b64027710) msg 0x7f1b640e7a10 from (udp/172.235.171.624:5060) has 4 bytes, veclen = 1
  1675. tport.c:3023 tport_deliver() tport_deliver(0x7f1b64027710): bad msg 0x7f1b640e7a10 (4 bytes) from udp/213.172.151.31:5060/sip next=(nil)
  1676. nta.c:1296 agent_timer() nta: timer set next to 302 ms
  1677. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 407 reply
  1678. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/37.49.231.129:58725
  1679. tport.c:4046 tport_resolve() tport_resolve addrinfo = 37.49.231.129:58725
  1680. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/37.49.231.129:58725
  1681. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 765 bytes of 765 to udp/37.49.231.129:58725
  1682. tport.c:3492 tport_send_msg() tport_vsend returned 765
  1683. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/6 resent, 0/6 tout, 0/15 term, 0/21 free
  1684. nta.c:1296 agent_timer() nta: timer set next to 406 ms
  1685. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 407 reply
  1686. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/37.49.231.129:56862
  1687. tport.c:4046 tport_resolve() tport_resolve addrinfo = 37.49.231.129:56862
  1688. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/37.49.231.129:56862
  1689. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 764 bytes of 764 to udp/37.49.231.129:56862
  1690. tport.c:3492 tport_send_msg() tport_vsend returned 764
  1691. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/6 resent, 0/6 tout, 0/15 term, 0/21 free
  1692. nta.c:1296 agent_timer() nta: timer set next to 477 ms
  1693. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f1b64027710): events IN
  1694. tport.c:2864 tport_recv_event() tport_recv_event(0x7f1b64027710)
  1695. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f1b64027710) msg 0x7f1b64065710 from (udp/172.235.171.624:5060) has 4 bytes, veclen = 1
  1696. tport.c:3023 tport_deliver() tport_deliver(0x7f1b64027710): bad msg 0x7f1b64065710 (4 bytes) from udp/196.250.133.172:5060/sip next=(nil)
  1697. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 407 reply
  1698. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/163.172.251.49:52466
  1699. tport.c:4046 tport_resolve() tport_resolve addrinfo = 163.172.251.49:52466
  1700. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/163.172.251.49:52466
  1701. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 765 bytes of 765 to udp/163.172.251.49:52466
  1702. tport.c:3492 tport_send_msg() tport_vsend returned 765
  1703. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/6 resent, 0/6 tout, 0/15 term, 0/21 free
  1704. nta.c:1296 agent_timer() nta: timer set next to 116 ms
  1705. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f1b64027710): events IN
  1706. tport.c:2864 tport_recv_event() tport_recv_event(0x7f1b64027710)
  1707. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f1b64027710) msg 0x7f1b64151460 from (udp/172.235.171.624:5060) has 4 bytes, veclen = 1
  1708. tport.c:3023 tport_deliver() tport_deliver(0x7f1b64027710): bad msg 0x7f1b64151460 (4 bytes) from udp/196.250.133.172:5060/sip next=(nil)
  1709. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 407 reply
  1710. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/37.49.231.129:58725
  1711. tport.c:4046 tport_resolve() tport_resolve addrinfo = 37.49.231.129:58725
  1712. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/37.49.231.129:58725
  1713. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 765 bytes of 765 to udp/37.49.231.129:58725
  1714. tport.c:3492 tport_send_msg() tport_vsend returned 765
  1715. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/6 resent, 0/6 tout, 0/15 term, 0/21 free
  1716. nta.c:1296 agent_timer() nta: timer set next to 456 ms
  1717. 2018-12-27 08:34:09.111969 [WARNING] switch_core_state_machine.c:687 d8d28df7-26ba-4012-9aa8-a2be15c918a0 sofia/default/13760@172.235.171.624 Abandoned
  1718. 2018-12-27 08:34:09.111969 [NOTICE] switch_core_state_machine.c:690 Hangup sofia/default/13760@172.235.171.624 [CS_NEW] [WRONG_CALL_STATE]
  1719. 2018-12-27 08:34:09.111969 [DEBUG] switch_core_state_machine.c:584 (sofia/default/13760@172.235.171.624) Running State Change CS_HANGUP (Cur 5 Tot 99)
  1720. 2018-12-27 08:34:09.111969 [DEBUG] switch_core_state_machine.c:850 (sofia/default/13760@172.235.171.624) Callstate Change DOWN -> HANGUP
  1721. 2018-12-27 08:34:09.111969 [DEBUG] switch_core_state_machine.c:852 (sofia/default/13760@172.235.171.624) State HANGUP
  1722. 2018-12-27 08:34:09.111969 [DEBUG] mod_sofia.c:438 Channel sofia/default/13760@172.235.171.624 hanging up, cause: WRONG_CALL_STATE
  1723. 2018-12-27 08:34:09.111969 [DEBUG] switch_core_state_machine.c:60 sofia/default/13760@172.235.171.624 Standard HANGUP, cause: WRONG_CALL_STATE
  1724. 2018-12-27 08:34:09.111969 [DEBUG] switch_core_state_machine.c:852 (sofia/default/13760@172.235.171.624) State HANGUP going to sleep
  1725. 2018-12-27 08:34:09.111969 [DEBUG] switch_core_state_machine.c:619 (sofia/default/13760@172.235.171.624) State Change CS_HANGUP -> CS_REPORTING
  1726. 2018-12-27 08:34:09.111969 [DEBUG] switch_core_state_machine.c:584 (sofia/default/13760@172.235.171.624) Running State Change CS_REPORTING (Cur 5 Tot 99)
  1727. 2018-12-27 08:34:09.111969 [DEBUG] switch_core_state_machine.c:938 (sofia/default/13760@172.235.171.624) State REPORTING
  1728. 2018-12-27 08:34:09.111969 [DEBUG] switch_core_state_machine.c:174 sofia/default/13760@172.235.171.624 Standard REPORTING, cause: WRONG_CALL_STATE
  1729. 2018-12-27 08:34:09.111969 [DEBUG] switch_core_state_machine.c:938 (sofia/default/13760@172.235.171.624) State REPORTING going to sleep
  1730. 2018-12-27 08:34:09.111969 [DEBUG] switch_core_state_machine.c:610 (sofia/default/13760@172.235.171.624) State Change CS_REPORTING -> CS_DESTROY
  1731. 2018-12-27 08:34:09.111969 [DEBUG] switch_core_session.c:1665 Session 97 (sofia/default/13760@172.235.171.624) Locked, Waiting on external entities
  1732. 2018-12-27 08:34:09.111969 [NOTICE] switch_core_session.c:1683 Session 97 (sofia/default/13760@172.235.171.624) Ended
  1733. 2018-12-27 08:34:09.111969 [NOTICE] switch_core_session.c:1687 Close Channel sofia/default/13760@172.235.171.624 [CS_DESTROY]
  1734. 2018-12-27 08:34:09.111969 [DEBUG] switch_core_state_machine.c:741 (sofia/default/13760@172.235.171.624) Running State Change CS_DESTROY (Cur 4 Tot 99)
  1735. 2018-12-27 08:34:09.131956 [DEBUG] switch_core_state_machine.c:751 (sofia/default/13760@172.235.171.624) State DESTROY
  1736. 2018-12-27 08:34:09.131956 [DEBUG] mod_sofia.c:343 sofia/default/13760@172.235.171.624 SOFIA DESTROY
  1737. 2018-12-27 08:34:09.131956 [DEBUG] switch_core_state_machine.c:181 sofia/default/13760@172.235.171.624 Standard DESTROY
  1738. 2018-12-27 08:34:09.131956 [DEBUG] switch_core_state_machine.c:751 (sofia/default/13760@172.235.171.624) State DESTROY going to sleep
  1739. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 407 reply
  1740. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/37.49.231.120:62545
  1741. tport.c:4046 tport_resolve() tport_resolve addrinfo = 37.49.231.120:62545
  1742. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/37.49.231.120:62545
  1743. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 763 bytes of 763 to udp/37.49.231.120:62545
  1744. tport.c:3492 tport_send_msg() tport_vsend returned 763
  1745. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/6 resent, 0/6 tout, 0/15 term, 0/21 free
  1746. nta.c:1296 agent_timer() nta: timer set next to 29 ms
  1747. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 407 reply
  1748. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/37.49.231.129:50104
  1749. tport.c:4046 tport_resolve() tport_resolve addrinfo = 37.49.231.129:50104
  1750. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/37.49.231.129:50104
  1751. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 762 bytes of 762 to udp/37.49.231.129:50104
  1752. tport.c:3492 tport_send_msg() tport_vsend returned 762
  1753. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/6 resent, 0/6 tout, 0/15 term, 0/21 free
  1754. nta.c:1296 agent_timer() nta: timer set next to 1306 ms
  1755. tport.c:2773 tport_wakeup() tport_wakeup(0x7f1b64282a10): events IN
  1756. tport.c:2864 tport_recv_event() tport_recv_event(0x7f1b64282a10)
  1757. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f1b64282a10) msg 0x7f1b640e7a10 from (tcp/169.255.170.11:64474) has 780 bytes, veclen = 1
  1758. tport.c:3023 tport_deliver() tport_deliver(0x7f1b64282a10): msg 0x7f1b640e7a10 (780 bytes) from tcp/169.255.170.11:64474/sip next=(nil)
  1759. nta.c:2880 agent_recv_request() nta: received BYE sip:0215082222@172.235.171.624:5060;transport=tcp SIP/2.0 (CSeq 3)
  1760. nta.c:3060 agent_recv_request() nta: BYE (3) going to existing leg
  1761. nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
  1762. nua_stack.c:271 nua_stack_event() nua(0x7f1b6413df30): event i_bye 100 Trying
  1763. tport.c:2296 tport_set_secondary_timer() tport(0x7f1b64282a10): reset timer
  1764. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  1765. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1766. 2018-12-27 08:34:09.392003 [NOTICE] sofia.c:1012 Hangup sofia/default/9921646958@fs.telicom.co.za [CS_EXECUTE] [NORMAL_CLEARING]
  1767. nua.c:879 nua_respond() nua: nua_respond: entering
  1768. nua_stack.c:573 nua_stack_signal() nua(0x7f1b6413df30): recv signal r_respond 200 OK
  1769. nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
  1770. soa.c:403 soa_set_params() soa_set_params(static::0x7f1b64155ee0, ...) called
  1771. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64282a10) tpn = TCP/169.255.170.11:64474
  1772. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64282a10): 475 bytes of 475 to tcp/169.255.170.11:64474
  1773. tport.c:3492 tport_send_msg() tport_vsend returned 475
  1774. tport.c:2296 tport_set_secondary_timer() tport(0x7f1b64282a10): reset timer
  1775. nta.c:6791 incoming_reply() nta: sent 200 OK for BYE (3)
  1776. tport.c:2296 tport_set_secondary_timer() tport(0x7f1b64282a10): reset timer
  1777. nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7f1b6413df30): removing session usage
  1778. nua_session.c:4139 signal_call_state_change() nua(0x7f1b6413df30): call state changed: ready -> terminated
  1779. nua_stack.c:271 nua_stack_event() nua(0x7f1b6413df30): event i_state 200 Session Terminated
  1780. nua_stack.c:271 nua_stack_event() nua(0x7f1b6413df30): event i_terminated 200 Session Terminated
  1781. soa.c:356 soa_destroy() soa_destroy(static::0x7f1b64155ee0) called
  1782. nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x7f1b641654d0)
  1783. nta.c:5744 incoming_free() nta: incoming_free(0x7f1b6418b840)
  1784. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  1785. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  1786. nua_stack.c:529 nua_signal() nua(0x7f1b6413df30): sent signal r_respond
  1787. nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
  1788. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
  1789. nua_stack.c:569 nua_stack_signal() nua(0x7f1b6413df30): recv signal r_destroy
  1790. nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
  1791. nua_stack.c:529 nua_signal() nua(0x7f1b6413df30): sent signal r_destroy
  1792. 2018-12-27 08:34:09.392003 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/default/9921646958@fs.telicom.co.za]
  1793. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1794. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1795. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
  1796. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1797. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1798. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
  1799. 2018-12-27 08:34:09.411949 [DEBUG] switch_ivr_bridge.c:706 sofia/default/9921646958@fs.telicom.co.za ending bridge by request from write function
  1800. 2018-12-27 08:34:09.411949 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/default/0215082222]
  1801. 2018-12-27 08:34:09.411949 [NOTICE] switch_ivr_bridge.c:904 Hangup sofia/default/0215082222 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]
  1802. 2018-12-27 08:34:09.411949 [DEBUG] switch_core_state_machine.c:653 (sofia/default/0215082222) State EXCHANGE_MEDIA going to sleep
  1803. 2018-12-27 08:34:09.411949 [DEBUG] switch_core_state_machine.c:584 (sofia/default/0215082222) Running State Change CS_HANGUP (Cur 4 Tot 99)
  1804. 2018-12-27 08:34:09.411949 [DEBUG] switch_core_state_machine.c:850 (sofia/default/0215082222) Callstate Change ACTIVE -> HANGUP
  1805. 2018-12-27 08:34:09.411949 [DEBUG] switch_core_state_machine.c:852 (sofia/default/0215082222) State HANGUP
  1806. 2018-12-27 08:34:09.411949 [DEBUG] mod_sofia.c:432 sofia/default/0215082222 Overriding SIP cause 480 with 200 from the other leg
  1807. 2018-12-27 08:34:09.411949 [DEBUG] mod_sofia.c:438 Channel sofia/default/0215082222 hanging up, cause: NORMAL_CLEARING
  1808. 2018-12-27 08:34:09.411949 [DEBUG] mod_sofia.c:491 Sending BYE to sofia/default/0215082222
  1809. nua.c:645 nua_bye() nua: nua_bye: entering
  1810. nua_stack.c:569 nua_stack_signal() nua(0x7f1b64135b00): recv signal r_bye
  1811. nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
  1812. soa.c:403 soa_set_params() soa_set_params(static::0x7f1b64204820, ...) called
  1813. soa.c:1784 soa_terminate() soa_terminate(static::0x7f1b64204820) called
  1814. soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7f1b64204820) called
  1815. nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
  1816. tport.c:3257 tport_tsend() tport_tsend(0x7f1b64027710) tpn = UDP/197.234.193.20:5060
  1817. tport.c:4046 tport_resolve() tport_resolve addrinfo = 197.234.193.20:5060
  1818. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f1b64027710): not found by name UDP/197.234.193.20:5060
  1819. tport.c:3594 tport_vsend() tport_vsend(0x7f1b64027710): 537 bytes of 537 to udp/197.234.193.20:5060
  1820. tport.c:3492 tport_send_msg() tport_vsend returned 537
  1821. nta.c:8304 outgoing_send() nta: sent BYE (132610153) to UDP/197.234.193.20:5060
  1822. tport.c:4160 tport_pend() tport_pend(0x7f1b64027710): pending 0x7f1b64065710 for udp/172.235.171.624:5060 (already 0)
  1823. nta.c:1348 set_timeout() nta: timer shortened to 1000 ms
  1824. nua_stack.c:529 nua_signal() nua(0x7f1b64135b00): sent signal r_bye
  1825. 2018-12-27 08:34:09.411949 [DEBUG] switch_core_state_machine.c:60 sofia/default/0215082222 Standard HANGUP, cause: NORMAL_CLEARING
  1826. 2018-12-27 08:34:09.411949 [DEBUG] switch_core_state_machine.c:852 (sofia/default/0215082222) State HANGUP going to sleep
  1827. 2018-12-27 08:34:09.411949 [DEBUG] switch_core_state_machine.c:619 (sofia/default/0215082222) State Change CS_HANGUP -> CS_REPORTING
  1828. 2018-12-27 08:34:09.411949 [DEBUG] switch_core_state_machine.c:584 (sofia/default/0215082222) Running State Change CS_REPORTING (Cur 4 Tot 99)
  1829. 2018-12-27 08:34:09.411949 [DEBUG] switch_core_state_machine.c:938 (sofia/default/0215082222) State REPORTING
  1830. 2018-12-27 08:34:09.411949 [INFO] mod_json_cdr.c:271 Process [dcf0b979-33f0-46cc-94e4-7db6877ae6b3.cdr.json]
  1831. 2018-12-27 08:34:09.411949 [DEBUG] switch_ivr_bridge.c:1712 sofia/default/0215082222 skip receive message [UNBRIDGE] (channel is hungup already)
  1832. 2018-12-27 08:34:09.411949 [DEBUG] switch_ivr_bridge.c:1715 sofia/default/9921646958@fs.telicom.co.za skip receive message [UNBRIDGE] (channel is hungup already)
  1833. 2018-12-27 08:34:09.411949 [DEBUG] switch_core_session.c:2815 sofia/default/9921646958@fs.telicom.co.za skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
  1834. 2018-12-27 08:34:09.411949 [DEBUG] switch_core_state_machine.c:650 (sofia/default/9921646958@fs.telicom.co.za) State EXECUTE going to sleep
  1835. 2018-12-27 08:34:09.411949 [DEBUG] switch_core_state_machine.c:584 (sofia/default/9921646958@fs.telicom.co.za) Running State Change CS_HANGUP (Cur 4 Tot 99)
  1836. 2018-12-27 08:34:09.411949 [DEBUG] switch_core_state_machine.c:850 (sofia/default/9921646958@fs.telicom.co.za) Callstate Change ACTIVE -> HANGUP
  1837. 2018-12-27 08:34:09.411949 [DEBUG] switch_core_state_machine.c:852 (sofia/default/9921646958@fs.telicom.co.za) State HANGUP
  1838. 2018-12-27 08:34:09.411949 [DEBUG] mod_sofia.c:438 Channel sofia/default/9921646958@fs.telicom.co.za hanging up, cause: NORMAL_CLEARING
  1839. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f1b64027710): events IN
  1840. tport.c:2864 tport_recv_event() tport_recv_event(0x7f1b64027710)
  1841. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f1b64027710) msg 0x7f1b641626c0 from (udp/172.235.171.624:5060) has 447 bytes, veclen = 1
  1842. tport.c:3023 tport_deliver() tport_deliver(0x7f1b64027710): msg 0x7f1b641626c0 (447 bytes) from udp/197.234.193.20:5060/sip next=(nil)
  1843. nta.c:3299 agent_recv_response() nta: received 200 OK for BYE (132610153)
  1844. nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction
  1845. nta.c:9564 outgoing_estimate_delay() nta_outgoing: RTT is 2.338 ms
  1846. tport.c:4222 tport_release() tport_release(0x7f1b64027710): 0x7f1b64065710 by 0x7f1b641354d0 with 0x7f1b641626c0
  1847. nua_stack.c:271 nua_stack_event() nua(0x7f1b64135b00): event r_bye 200 OK
  1848. nua_session.c:4139 signal_call_state_change() nua(0x7f1b64135b00): call state changed: terminating -> terminated
  1849. nua_stack.c:271 nua_stack_event() nua(0x7f1b64135b00): event i_state 200 to BYE
  1850. nua_stack.c:271 nua_stack_event() nua(0x7f1b64135b00): event i_terminated 200 to BYE
  1851. nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7f1b64135b00): removing session usage
  1852. soa.c:356 soa_destroy() soa_destroy(static::0x7f1b64204820) called
  1853. nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x7f1b64230e80)
  1854. nua_session.c:351 nua_session_usage_destroy() nua: terminated session 0x7f1b64135b00
  1855. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  1856. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  1857. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  1858. 2018-12-27 08:34:09.411949 [DEBUG] switch_core_state_machine.c:60 sofia/default/9921646958@fs.telicom.co.za Standard HANGUP, cause: NORMAL_CLEARING
  1859. 2018-12-27 08:34:09.411949 [DEBUG] switch_core_state_machine.c:852 (sofia/default/9921646958@fs.telicom.co.za) State HANGUP going to sleep
  1860. 2018-12-27 08:34:09.431945 [DEBUG] switch_core_state_machine.c:619 (sofia/default/9921646958@fs.telicom.co.za) State Change CS_HANGUP -> CS_REPORTING
  1861. 2018-12-27 08:34:09.431945 [DEBUG] switch_core_state_machine.c:584 (sofia/default/9921646958@fs.telicom.co.za) Running State Change CS_REPORTING (Cur 4 Tot 99)
  1862. 2018-12-27 08:34:09.431945 [DEBUG] switch_core_state_machine.c:938 (sofia/default/9921646958@fs.telicom.co.za) State REPORTING
  1863. 2018-12-27 08:34:09.431945 [INFO] mod_json_cdr.c:271 Process [388e8344-12cf-4951-844c-d632471081ed.cdr.json]
  1864. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1865. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1866. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1867. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1868. nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
  1869. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1870. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1871. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
  1872. nua_stack.c:569 nua_stack_signal() nua(0x7f1b64135b00): recv signal r_destroy
  1873. nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
  1874. nua_stack.c:529 nua_signal() nua(0x7f1b64135b00): sent signal r_destroy
  1875. 2018-12-27 08:34:09.431945 [DEBUG] switch_core_state_machine.c:174 sofia/default/0215082222 Standard REPORTING, cause: NORMAL_CLEARING
  1876. 2018-12-27 08:34:09.431945 [DEBUG] switch_core_state_machine.c:938 (sofia/default/0215082222) State REPORTING going to sleep
  1877. 2018-12-27 08:34:09.431945 [DEBUG] switch_core_state_machine.c:610 (sofia/default/0215082222) State Change CS_REPORTING -> CS_DESTROY
  1878. 2018-12-27 08:34:09.431945 [DEBUG] switch_core_session.c:1665 Session 95 (sofia/default/0215082222) Locked, Waiting on external entities
  1879. 2018-12-27 08:34:09.431945 [NOTICE] switch_core_session.c:1683 Session 95 (sofia/default/0215082222) Ended
  1880. 2018-12-27 08:34:09.431945 [NOTICE] switch_core_session.c:1687 Close Channel sofia/default/0215082222 [CS_DESTROY]
  1881. 2018-12-27 08:34:09.431945 [DEBUG] switch_core_state_machine.c:741 (sofia/default/0215082222) Running State Change CS_DESTROY (Cur 3 Tot 99)
  1882. 2018-12-27 08:34:09.431945 [DEBUG] switch_core_state_machine.c:751 (sofia/default/0215082222) State DESTROY
  1883. 2018-12-27 08:34:09.431945 [DEBUG] mod_sofia.c:343 sofia/default/0215082222 SOFIA DESTROY
  1884. 2018-12-27 08:34:09.431945 [INFO] mod_com_g729.c:95 DECODER DESTROYED----------->0x7f1b64098b50 0x7f1b64098b58
  1885. 2018-12-27 08:34:09.431945 [INFO] mod_com_g729.c:98 DECODER LICENSE DEALLOCATED->0x7f1b64098b50 0x7f1b64098b58
  1886. 2018-12-27 08:34:09.431945 [INFO] mod_com_g729.c:84 ENCODER DESTROYED----------->0x7f1b64098bd0 0x7f1b64098bd0
  1887. 2018-12-27 08:34:09.431945 [INFO] mod_com_g729.c:87 ENCODER LICENSE DEALLOCATED->0x7f1b64098bd0 0x7f1b64098bd0
  1888. 2018-12-27 08:34:09.431945 [DEBUG] switch_core_state_machine.c:181 sofia/default/0215082222 Standard DESTROY
  1889. 2018-12-27 08:34:09.431945 [DEBUG] switch_core_state_machine.c:751 (sofia/default/0215082222) State DESTROY going to sleep
  1890. 2018-12-27 08:34:09.431945 [DEBUG] switch_core_state_machine.c:174 sofia/default/9921646958@fs.telicom.co.za Standard REPORTING, cause: NORMAL_CLEARING
  1891. 2018-12-27 08:34:09.431945 [DEBUG] switch_core_state_machine.c:938 (sofia/default/9921646958@fs.telicom.co.za) State REPORTING going to sleep
  1892. 2018-12-27 08:34:09.431945 [DEBUG] switch_core_state_machine.c:610 (sofia/default/9921646958@fs.telicom.co.za) State Change CS_REPORTING -> CS_DESTROY
  1893. 2018-12-27 08:34:09.431945 [DEBUG] switch_core_session.c:1665 Session 94 (sofia/default/9921646958@fs.telicom.co.za) Locked, Waiting on external entities
  1894.  

Reply to "Untitled"