[root@router ~]# asterisk -r Asterisk 13.5.0, Copyright (C) 1999 - 2014, Digium, Inc. and others. Created by Mark Spencer Asterisk comes with ABSOLUTELY NO WARRANTY; type 'core show warranty' for details. This is free software, with components licensed under the GNU General Public License version 2 and other licenses; you are welcome to redistribute it under certain conditions. Type 'core show license' for details. ========================================================================= Connected to Asterisk 13.5.0 currently running on router (pid = 4185) router*CLI> pjsip show registrations ========================================================================================= mango/sip:81.88.86.11 mango Registered router*CLI> pjsip show aors Aor: Contact: ========================================================================================= Aor: 208 1 Aor: 209 1 Aor: 219 1 Aor: mango 0 Contact: mango/sip:vpbx400034059.mangosip.ru:5060 Unavail 0.000 router*CLI> group show channels Channel Group Category 0 active channels router*CLI> pjsip set logger on PJSIP Logging enabled router*CLI> pjsip show auths I/OAuth: ========================================================================================= Auth: 208/208 Auth: 209/209 Auth: 219/219 Auth: mango/asterisk router*CLI> pjsip show contacts Contact: ========================================================================================= Contact: mango/sip:vpbx400034059.mangosip.ru:5060 Unavail 0.000 router*CLI> pjsip show channels No objects found. router*CLI> core show channels Channel Location State Application(Data) 0 active channels 0 active calls 5191 calls processed router*CLI> iax2 show peers Name/Username Host Mask Port Status Description 207 (null) (D) (null) (null) UNKNOWN 206 (null) (D) (null) (null) UNKNOWN 205 (null) (D) (null) (null) UNKNOWN 204 (null) (D) (null) (null) UNKNOWN 203 (null) (D) 255.255.255.255 (null) UNKNOWN 202 (null) (D) 255.255.255.255 (null) UNKNOWN 201 (null) (D) (null) (null) UNKNOWN 216 192.168.0.77 (D) (null) 4569 OK (48 ms) 217 192.168.0.110 (D) (null) 4569 OK (9 ms) 214 (null) (D) (null) (null) UNKNOWN 215 192.168.0.10 (D) (null) 4569 OK (32 ms) 212 192.168.0.94 (D) 255.255.255.255 4569 OK (33 ms) 213 192.168.0.11 (D) 255.255.255.255 4569 OK (26 ms) 211 (null) (D) 255.255.255.255 (null) UNKNOWN 218 (null) (D) (null) (null) UNKNOWN 225 (null) (D) (null) (null) UNKNOWN 224 (null) (D) (null) (null) UNKNOWN 227 (null) (D) (null) (null) UNKNOWN 226 (null) (D) (null) (null) UNKNOWN 221 (null) (D) (null) (null) UNKNOWN 223 (null) (D) (null) (null) UNKNOWN 222 (null) (D) 255.255.255.255 (null) UNKNOWN 229 (null) (D) (null) (null) UNKNOWN 228 (null) (D) (null) (null) UNKNOWN 24 iax2 peers [5 online, 19 offline, 0 unmonitored] router*CLI> core set debug 9 Core debug was OFF and is now 9. [Oct 23 09:24:46] DEBUG[4227]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.77 in 60 seconds [Oct 23 09:24:49] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 1 for 192.168.0.11 [Oct 23 09:24:49] DEBUG[4233]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 2 for 192.168.0.11 [Oct 23 09:24:49] DEBUG[4229]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.11 in 60 seconds [Oct 23 09:24:49] DEBUG[4229]: chan_iax2.c:11157 socket_process_helper: Peer 213: got pong, lastms 26, historicms 26, maxms 2000 [Oct 23 09:24:54] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 2 for 192.168.0.10 [Oct 23 09:24:59] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 2 for 192.168.0.77 [Oct 23 09:25:02] DEBUG[4228]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 3 for 192.168.0.94 [Oct 23 09:25:02] DEBUG[4199]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for IAX2 - 212 [Oct 23 09:25:02] DEBUG[4199]: chan_iax2.c:14472 iax2_devicestate: Checking device state for device 212 [Oct 23 09:25:02] DEBUG[4199]: chan_iax2.c:14481 iax2_devicestate: Found peer. What's device state of 212? addr=192.168.0.94:4569, defaddr=(null) maxms=2000, lastms=33 [Oct 23 09:25:02] DEBUG[4199]: devicestate.c:473 do_state_change: Changing state for IAX2/212 - state 0 (Unknown) [Oct 23 09:25:04] DEBUG[4227]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.94 in 60 seconds [Oct 23 09:25:14] DEBUG[4229]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 3 for 192.168.0.11 [Oct 23 09:25:14] DEBUG[4199]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for IAX2 - 213 [Oct 23 09:25:14] DEBUG[4199]: chan_iax2.c:14472 iax2_devicestate: Checking device state for device 213 [Oct 23 09:25:14] DEBUG[4199]: chan_iax2.c:14481 iax2_devicestate: Found peer. What's device state of 213? addr=192.168.0.11:4569, defaddr=(null) maxms=2000, lastms=26 [Oct 23 09:25:14] DEBUG[4199]: devicestate.c:473 do_state_change: Changing state for IAX2/213 - state 0 (Unknown) [Oct 23 09:25:15] DEBUG[4230]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 3 for 192.168.0.110 [Oct 23 09:25:15] DEBUG[4199]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for IAX2 - 217 [Oct 23 09:25:15] DEBUG[4199]: chan_iax2.c:14472 iax2_devicestate: Checking device state for device 217 [Oct 23 09:25:15] DEBUG[4199]: chan_iax2.c:14481 iax2_devicestate: Found peer. What's device state of 217? addr=192.168.0.110:4569, defaddr=(null) maxms=2000, lastms=9 [Oct 23 09:25:15] DEBUG[4199]: devicestate.c:473 do_state_change: Changing state for IAX2/217 - state 0 (Unknown) [Oct 23 09:25:16] DEBUG[4234]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.11 in 60 seconds [Oct 23 09:25:16] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 2 for 192.168.0.94 [Oct 23 09:25:17] DEBUG[4232]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.110 in 60 seconds [Oct 23 09:25:22] DEBUG[24041]: threadpool.c:1107 worker_idle: Worker thread idle timeout reached. Dying. [Oct 23 09:25:22] DEBUG[24046]: threadpool.c:1107 worker_idle: Worker thread idle timeout reached. Dying. [Oct 23 09:25:22] DEBUG[4207]: threadpool.c:968 worker_thread_destroy: Destroying worker thread 7189 [Oct 23 09:25:22] DEBUG[4186]: threadpool.c:968 worker_thread_destroy: Destroying worker thread 7194 [Oct 23 09:25:22] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 2 for 192.168.0.110 [Oct 23 09:25:22] DEBUG[4227]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 3 for 192.168.0.110 [Oct 23 09:25:22] DEBUG[4233]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.110 in 60 seconds [Oct 23 09:25:22] DEBUG[4233]: chan_iax2.c:11157 socket_process_helper: Peer 217: got pong, lastms 14, historicms 14, maxms 2000 [Oct 23 09:25:27] DEBUG[4226]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 3 for 192.168.0.10 [Oct 23 09:25:27] DEBUG[4199]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for IAX2 - 215 [Oct 23 09:25:27] DEBUG[4199]: chan_iax2.c:14472 iax2_devicestate: Checking device state for device 215 [Oct 23 09:25:27] DEBUG[4199]: chan_iax2.c:14481 iax2_devicestate: Found peer. What's device state of 215? addr=192.168.0.10:4569, defaddr=(null) maxms=2000, lastms=32 [Oct 23 09:25:27] DEBUG[4199]: devicestate.c:473 do_state_change: Changing state for IAX2/215 - state 0 (Unknown) [Oct 23 09:25:28] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 1 for 192.168.0.77 [Oct 23 09:25:28] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 2 for 192.168.0.11 [Oct 23 09:25:28] DEBUG[4228]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 2 for 192.168.0.77 [Oct 23 09:25:28] DEBUG[4232]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.77 in 60 seconds [Oct 23 09:25:28] DEBUG[4232]: chan_iax2.c:11157 socket_process_helper: Peer 216: got pong, lastms 14, historicms 14, maxms 2000 [Oct 23 09:25:29] DEBUG[4231]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.10 in 60 seconds [Oct 23 09:25:30] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 2 for 192.168.0.110 [Oct 23 09:25:32] DEBUG[4230]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 3 for 192.168.0.77 [Oct 23 09:25:32] DEBUG[4199]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for IAX2 - 216 [Oct 23 09:25:32] DEBUG[4199]: chan_iax2.c:14472 iax2_devicestate: Checking device state for device 216 [Oct 23 09:25:32] DEBUG[4199]: chan_iax2.c:14481 iax2_devicestate: Found peer. What's device state of 216? addr=192.168.0.77:4569, defaddr=(null) maxms=2000, lastms=14 [Oct 23 09:25:32] DEBUG[4199]: devicestate.c:473 do_state_change: Changing state for IAX2/216 - state 0 (Unknown) [Oct 23 09:25:33] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 1 for 192.168.0.94 [Oct 23 09:25:33] DEBUG[4226]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 2 for 192.168.0.94 [Oct 23 09:25:33] DEBUG[4234]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.94 in 60 seconds [Oct 23 09:25:33] DEBUG[4234]: chan_iax2.c:11157 socket_process_helper: Peer 212: got pong, lastms 33, historicms 33, maxms 2000 [Oct 23 09:25:34] DEBUG[4227]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.77 in 60 seconds [Oct 23 09:25:41] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 2 for 192.168.0.10 [Oct 23 09:25:41] DEBUG[4229]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 3 for 192.168.0.10 [Oct 23 09:25:41] DEBUG[4235]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.10 in 60 seconds [Oct 23 09:25:41] DEBUG[4235]: chan_iax2.c:11157 socket_process_helper: Peer 215: got pong, lastms 132, historicms 132, maxms 2000 [Oct 23 09:25:41] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 2 for 192.168.0.10 [Oct 23 09:25:46] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 2 for 192.168.0.77 [Oct 23 09:25:49] DEBUG[4232]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 3 for 192.168.0.94 [Oct 23 09:25:49] DEBUG[4199]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for IAX2 - 212 [Oct 23 09:25:49] DEBUG[4199]: chan_iax2.c:14472 iax2_devicestate: Checking device state for device 212 [Oct 23 09:25:49] DEBUG[4199]: chan_iax2.c:14481 iax2_devicestate: Found peer. What's device state of 212? addr=192.168.0.94:4569, defaddr=(null) maxms=2000, lastms=33 [Oct 23 09:25:49] DEBUG[4199]: devicestate.c:473 do_state_change: Changing state for IAX2/212 - state 0 (Unknown) [Oct 23 09:25:49] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 1 for 192.168.0.11 [Oct 23 09:25:49] DEBUG[4227]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 2 for 192.168.0.11 [Oct 23 09:25:49] DEBUG[4233]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.11 in 60 seconds [Oct 23 09:25:49] DEBUG[4233]: chan_iax2.c:11157 socket_process_helper: Peer 213: got pong, lastms 17, historicms 17, maxms 2000 [Oct 23 09:25:51] DEBUG[4230]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.94 in 60 seconds [Oct 23 09:26:01] DEBUG[4228]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 3 for 192.168.0.11 [Oct 23 09:26:01] DEBUG[4199]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for IAX2 - 213 [Oct 23 09:26:01] DEBUG[4199]: chan_iax2.c:14472 iax2_devicestate: Checking device state for device 213 [Oct 23 09:26:01] DEBUG[4199]: chan_iax2.c:14481 iax2_devicestate: Found peer. What's device state of 213? addr=192.168.0.11:4569, defaddr=(null) maxms=2000, lastms=17 [Oct 23 09:26:01] DEBUG[4199]: devicestate.c:473 do_state_change: Changing state for IAX2/213 - state 0 (Unknown) [Oct 23 09:26:02] DEBUG[4227]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 3 for 192.168.0.110 [Oct 23 09:26:02] DEBUG[4199]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for IAX2 - 217 [Oct 23 09:26:02] DEBUG[4199]: chan_iax2.c:14472 iax2_devicestate: Checking device state for device 217 [Oct 23 09:26:02] DEBUG[4199]: chan_iax2.c:14481 iax2_devicestate: Found peer. What's device state of 217? addr=192.168.0.110:4569, defaddr=(null) maxms=2000, lastms=14 [Oct 23 09:26:02] DEBUG[4199]: devicestate.c:473 do_state_change: Changing state for IAX2/217 - state 0 (Unknown) [Oct 23 09:26:03] DEBUG[4231]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.11 in 60 seconds [Oct 23 09:26:04] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 2 for 192.168.0.94 [Oct 23 09:26:04] DEBUG[4235]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.110 in 60 seconds [Oct 23 09:26:14] DEBUG[4234]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 3 for 192.168.0.10 [Oct 23 09:26:14] DEBUG[4199]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for IAX2 - 215 [Oct 23 09:26:14] DEBUG[4199]: chan_iax2.c:14472 iax2_devicestate: Checking device state for device 215 [Oct 23 09:26:14] DEBUG[4199]: chan_iax2.c:14481 iax2_devicestate: Found peer. What's device state of 215? addr=192.168.0.10:4569, defaddr=(null) maxms=2000, lastms=132 [Oct 23 09:26:14] DEBUG[4199]: devicestate.c:473 do_state_change: Changing state for IAX2/215 - state 0 (Unknown) [Oct 23 09:26:16] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 2 for 192.168.0.11 [Oct 23 09:26:16] DEBUG[4227]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.10 in 60 seconds [Oct 23 09:26:17] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 2 for 192.168.0.110 [Oct 23 09:26:19] DEBUG[4231]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 3 for 192.168.0.77 [Oct 23 09:26:19] DEBUG[4199]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for IAX2 - 216 [Oct 23 09:26:19] DEBUG[4199]: chan_iax2.c:14472 iax2_devicestate: Checking device state for device 216 [Oct 23 09:26:19] DEBUG[4199]: chan_iax2.c:14481 iax2_devicestate: Found peer. What's device state of 216? addr=192.168.0.77:4569, defaddr=(null) maxms=2000, lastms=14 [Oct 23 09:26:19] DEBUG[4199]: devicestate.c:473 do_state_change: Changing state for IAX2/216 - state 0 (Unknown) [Oct 23 09:26:21] DEBUG[4235]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.77 in 60 seconds [Oct 23 09:26:22] DEBUG[4207]: threadpool.c:508 grow: Increasing threadpool SIP's size by 5 [Oct 23 09:26:22] DEBUG[24066]: pjsip:0 : endpoint Request msg OPTIONS/cseq=61800 (tdta0xac51508) created. [Oct 23 09:26:22] DEBUG[24066]: config.c:3544 ast_parse_arg: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Oct 23 09:26:22] DEBUG[24066]: config.c:3544 ast_parse_arg: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Oct 23 09:26:22] DEBUG[24066]: config.c:3544 ast_parse_arg: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Oct 23 09:26:22] DEBUG[4186]: threadpool.c:508 grow: Increasing threadpool Sorcery's size by 1 [Oct 23 09:26:22] DEBUG[24066]: res_pjsip.c:3075 endpt_send_request: 0xa72a874: Wrapper created [Oct 23 09:26:22] DEBUG[24066]: res_pjsip.c:3106 endpt_send_request: 0xa72a874: Set timer to 30000 msec [Oct 23 09:26:22] DEBUG[24066]: pjsip:0 : tsx0xac52574 .Transaction created for Request msg OPTIONS/cseq=61800 (tdta0xac51508) [Oct 23 09:26:22] DEBUG[24066]: pjsip:0 : tsx0xac52574 Sending Request msg OPTIONS/cseq=61800 (tdta0xac51508) in state Null [Oct 23 09:26:22] DEBUG[24066]: pjsip:0 : sip_resolve.c .Starting async DNS A query: target=vpbx400034059.mangosip.ru, transport=Unspecified, port=5060 [Oct 23 09:26:22] DEBUG[24066]: pjsip:0 : tsx0xac52574 .State changed from Null to Calling, event=TX_MSG [Oct 23 09:26:22] DEBUG[4230]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 3 for 192.168.0.110 [Oct 23 09:26:22] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 2 for 192.168.0.110 [Oct 23 09:26:22] DEBUG[4234]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.110 in 60 seconds [Oct 23 09:26:22] DEBUG[4234]: chan_iax2.c:11157 socket_process_helper: Peer 217: got pong, lastms 30, historicms 30, maxms 2000 [Oct 23 09:26:28] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 2 for 192.168.0.77 [Oct 23 09:26:28] DEBUG[4227]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 3 for 192.168.0.77 [Oct 23 09:26:28] DEBUG[4233]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.77 in 60 seconds [Oct 23 09:26:28] DEBUG[4233]: chan_iax2.c:11157 socket_process_helper: Peer 216: got pong, lastms 9, historicms 9, maxms 2000 [Oct 23 09:26:29] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 2 for 192.168.0.10 [Oct 23 09:26:33] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 1 for 192.168.0.94 [Oct 23 09:26:33] DEBUG[4230]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 2 for 192.168.0.94 [Oct 23 09:26:33] DEBUG[4226]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.94 in 60 seconds [Oct 23 09:26:33] DEBUG[4226]: chan_iax2.c:11157 socket_process_helper: Peer 212: got pong, lastms 40, historicms 40, maxms 2000 [Oct 23 09:26:34] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 2 for 192.168.0.77 [Oct 23 09:26:36] DEBUG[4227]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 3 for 192.168.0.94 [Oct 23 09:26:36] DEBUG[4199]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for IAX2 - 212 [Oct 23 09:26:36] DEBUG[4199]: chan_iax2.c:14472 iax2_devicestate: Checking device state for device 212 [Oct 23 09:26:36] DEBUG[4199]: chan_iax2.c:14481 iax2_devicestate: Found peer. What's device state of 212? addr=192.168.0.94:4569, defaddr=(null) maxms=2000, lastms=40 [Oct 23 09:26:36] DEBUG[4199]: devicestate.c:473 do_state_change: Changing state for IAX2/212 - state 0 (Unknown) [Oct 23 09:26:38] DEBUG[4231]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.94 in 60 seconds [Oct 23 09:26:41] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 1 for 192.168.0.10 [Oct 23 09:26:41] DEBUG[4229]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 2 for 192.168.0.10 [Oct 23 09:26:41] DEBUG[4235]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.10 in 60 seconds [Oct 23 09:26:41] DEBUG[4235]: chan_iax2.c:11157 socket_process_helper: Peer 215: got pong, lastms 9, historicms 9, maxms 2000 [Oct 23 09:26:48] DEBUG[4232]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 3 for 192.168.0.11 [Oct 23 09:26:48] DEBUG[4199]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for IAX2 - 213 [Oct 23 09:26:48] DEBUG[4199]: chan_iax2.c:14472 iax2_devicestate: Checking device state for device 213 [Oct 23 09:26:48] DEBUG[4199]: chan_iax2.c:14481 iax2_devicestate: Found peer. What's device state of 213? addr=192.168.0.11:4569, defaddr=(null) maxms=2000, lastms=17 [Oct 23 09:26:48] DEBUG[4199]: devicestate.c:473 do_state_change: Changing state for IAX2/213 - state 0 (Unknown) [Oct 23 09:26:49] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 2 for 192.168.0.11 [Oct 23 09:26:49] DEBUG[4227]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 3 for 192.168.0.11 [Oct 23 09:26:49] DEBUG[4233]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.11 in 60 seconds [Oct 23 09:26:49] DEBUG[4233]: chan_iax2.c:11157 socket_process_helper: Peer 213: got pong, lastms 32, historicms 32, maxms 2000 [Oct 23 09:26:49] DEBUG[4235]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 3 for 192.168.0.110 [Oct 23 09:26:49] DEBUG[4199]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for IAX2 - 217 [Oct 23 09:26:49] DEBUG[4199]: chan_iax2.c:14472 iax2_devicestate: Checking device state for device 217 [Oct 23 09:26:49] DEBUG[4199]: chan_iax2.c:14481 iax2_devicestate: Found peer. What's device state of 217? addr=192.168.0.110:4569, defaddr=(null) maxms=2000, lastms=30 [Oct 23 09:26:49] DEBUG[4199]: devicestate.c:473 do_state_change: Changing state for IAX2/217 - state 0 (Unknown) [Oct 23 09:26:50] DEBUG[4234]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.11 in 60 seconds [Oct 23 09:26:51] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 2 for 192.168.0.94 [Oct 23 09:26:51] DEBUG[4232]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.110 in 60 seconds [Oct 23 09:27:01] DEBUG[4231]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 3 for 192.168.0.10 [Oct 23 09:27:01] DEBUG[4199]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for IAX2 - 215 [Oct 23 09:27:01] DEBUG[4199]: chan_iax2.c:14472 iax2_devicestate: Checking device state for device 215 [Oct 23 09:27:01] DEBUG[4199]: chan_iax2.c:14481 iax2_devicestate: Found peer. What's device state of 215? addr=192.168.0.10:4569, defaddr=(null) maxms=2000, lastms=9 [Oct 23 09:27:01] DEBUG[4199]: devicestate.c:473 do_state_change: Changing state for IAX2/215 - state 0 (Unknown) [Oct 23 09:27:02] DEBUG[4230]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 1 for 192.168.0.75 -- Registered IAX2 '211' (UNAUTHENTICATED) at 192.168.0.75:4569 [Oct 23 09:27:02] DEBUG[4230]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 2 for 192.168.0.75 [Oct 23 09:27:02] DEBUG[4199]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for IAX2 - 211 [Oct 23 09:27:02] DEBUG[4199]: chan_iax2.c:14472 iax2_devicestate: Checking device state for device 211 [Oct 23 09:27:02] DEBUG[4199]: chan_iax2.c:14481 iax2_devicestate: Found peer. What's device state of 211? addr=192.168.0.75:4569, defaddr=(null) maxms=2000, lastms=0 [Oct 23 09:27:02] DEBUG[4199]: devicestate.c:473 do_state_change: Changing state for IAX2/211 - state 0 (Unknown) [Oct 23 09:27:02] DEBUG[4199]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for IAX2 - 211 [Oct 23 09:27:02] DEBUG[4199]: chan_iax2.c:14472 iax2_devicestate: Checking device state for device 211 [Oct 23 09:27:02] DEBUG[4199]: chan_iax2.c:14481 iax2_devicestate: Found peer. What's device state of 211? addr=192.168.0.75:4569, defaddr=(null) maxms=2000, lastms=0 [Oct 23 09:27:02] DEBUG[4199]: devicestate.c:473 do_state_change: Changing state for IAX2/211 - state 0 (Unknown) [Oct 23 09:27:02] DEBUG[4187]: threadpool.c:508 grow: Increasing threadpool stasis-core's size by 1 [Oct 23 09:27:02] DEBUG[4242]: app_queue.c:2374 device_state_cb: Device 'IAX2/211' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Oct 23 09:27:02] DEBUG[4226]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.75 in 60 seconds [Oct 23 09:27:02] DEBUG[4226]: chan_iax2.c:11157 socket_process_helper: Peer 211: got pong, lastms 9, historicms 9, maxms 2000 [Oct 23 09:27:03] DEBUG[4227]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.10 in 60 seconds [Oct 23 09:27:03] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 2 for 192.168.0.11 [Oct 23 09:27:04] DEBUG[4231]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.75 in 60 seconds [Oct 23 09:27:04] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 2 for 192.168.0.110 [Oct 23 09:27:06] DEBUG[4235]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 3 for 192.168.0.77 [Oct 23 09:27:06] DEBUG[4199]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for IAX2 - 216 [Oct 23 09:27:06] DEBUG[4199]: chan_iax2.c:14472 iax2_devicestate: Checking device state for device 216 [Oct 23 09:27:06] DEBUG[4199]: chan_iax2.c:14481 iax2_devicestate: Found peer. What's device state of 216? addr=192.168.0.77:4569, defaddr=(null) maxms=2000, lastms=9 [Oct 23 09:27:06] DEBUG[4199]: devicestate.c:473 do_state_change: Changing state for IAX2/216 - state 0 (Unknown) [Oct 23 09:27:08] DEBUG[4226]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.77 in 60 seconds [Oct 23 09:27:16] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 2 for 192.168.0.10 [Oct 23 09:27:21] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 2 for 192.168.0.77 [Oct 23 09:27:22] DEBUG[24066]: pjsip:0 : endpoint Request msg OPTIONS/cseq=13390 (tdta0xac52d18) created. [Oct 23 09:27:22] DEBUG[24066]: config.c:3544 ast_parse_arg: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Oct 23 09:27:22] DEBUG[24066]: config.c:3544 ast_parse_arg: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Oct 23 09:27:22] DEBUG[24066]: config.c:3544 ast_parse_arg: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Oct 23 09:27:22] DEBUG[24066]: res_pjsip.c:3075 endpt_send_request: 0xac35be4: Wrapper created [Oct 23 09:27:22] DEBUG[24066]: res_pjsip.c:3106 endpt_send_request: 0xac35be4: Set timer to 30000 msec [Oct 23 09:27:22] DEBUG[24066]: pjsip:0 : tsx0xac550bc .Transaction created for Request msg OPTIONS/cseq=13390 (tdta0xac52d18) [Oct 23 09:27:22] DEBUG[24066]: pjsip:0 : tsx0xac550bc Sending Request msg OPTIONS/cseq=13390 (tdta0xac52d18) in state Null [Oct 23 09:27:22] DEBUG[24066]: pjsip:0 : sip_resolve.c .Starting async DNS A query: target=vpbx400034059.mangosip.ru, transport=Unspecified, port=5060 [Oct 23 09:27:22] DEBUG[24066]: pjsip:0 : tsx0xac550bc .State changed from Null to Calling, event=TX_MSG [Oct 23 09:27:22] DEBUG[24068]: threadpool.c:1107 worker_idle: Worker thread idle timeout reached. Dying. [Oct 23 09:27:22] DEBUG[24069]: threadpool.c:1107 worker_idle: Worker thread idle timeout reached. Dying. [Oct 23 09:27:22] DEBUG[24070]: threadpool.c:1107 worker_idle: Worker thread idle timeout reached. Dying. [Oct 23 09:27:22] DEBUG[24067]: threadpool.c:1107 worker_idle: Worker thread idle timeout reached. Dying. [Oct 23 09:27:22] DEBUG[4207]: threadpool.c:968 worker_thread_destroy: Destroying worker thread 7197 [Oct 23 09:27:22] DEBUG[4207]: threadpool.c:968 worker_thread_destroy: Destroying worker thread 7198 [Oct 23 09:27:22] DEBUG[4207]: threadpool.c:968 worker_thread_destroy: Destroying worker thread 7199 [Oct 23 09:27:22] DEBUG[4207]: threadpool.c:968 worker_thread_destroy: Destroying worker thread 7196 [Oct 23 09:27:22] DEBUG[24072]: threadpool.c:1107 worker_idle: Worker thread idle timeout reached. Dying. [Oct 23 09:27:22] DEBUG[4187]: threadpool.c:968 worker_thread_destroy: Destroying worker thread 7201 [Oct 23 09:27:22] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 1 for 192.168.0.110 [Oct 23 09:27:22] DEBUG[4227]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 2 for 192.168.0.110 [Oct 23 09:27:22] DEBUG[4233]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.110 in 60 seconds [Oct 23 09:27:22] DEBUG[4233]: chan_iax2.c:11157 socket_process_helper: Peer 217: got pong, lastms 35, historicms 35, maxms 2000 [Oct 23 09:27:23] DEBUG[4230]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 3 for 192.168.0.94 [Oct 23 09:27:23] DEBUG[4199]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for IAX2 - 212 [Oct 23 09:27:23] DEBUG[4199]: chan_iax2.c:14472 iax2_devicestate: Checking device state for device 212 [Oct 23 09:27:23] DEBUG[4199]: chan_iax2.c:14481 iax2_devicestate: Found peer. What's device state of 212? addr=192.168.0.94:4569, defaddr=(null) maxms=2000, lastms=40 [Oct 23 09:27:23] DEBUG[4199]: devicestate.c:473 do_state_change: Changing state for IAX2/212 - state 0 (Unknown) [Oct 23 09:27:25] DEBUG[4234]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.94 in 60 seconds [Oct 23 09:27:28] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 1 for 192.168.0.77 [Oct 23 09:27:28] DEBUG[4228]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 2 for 192.168.0.77 [Oct 23 09:27:29] DEBUG[4232]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.77 in 60 seconds [Oct 23 09:27:29] DEBUG[4232]: chan_iax2.c:11157 socket_process_helper: Peer 216: got pong, lastms 30, historicms 30, maxms 2000 [Oct 23 09:27:33] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 2 for 192.168.0.94 [Oct 23 09:27:33] DEBUG[4231]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 3 for 192.168.0.94 [Oct 23 09:27:33] DEBUG[4229]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.94 in 60 seconds [Oct 23 09:27:33] DEBUG[4229]: chan_iax2.c:11157 socket_process_helper: Peer 212: got pong, lastms 16, historicms 16, maxms 2000 [Oct 23 09:27:36] DEBUG[4228]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 3 for 192.168.0.11 [Oct 23 09:27:36] DEBUG[4199]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for IAX2 - 213 [Oct 23 09:27:36] DEBUG[4199]: chan_iax2.c:14472 iax2_devicestate: Checking device state for device 213 [Oct 23 09:27:36] DEBUG[4199]: chan_iax2.c:14481 iax2_devicestate: Found peer. What's device state of 213? addr=192.168.0.11:4569, defaddr=(null) maxms=2000, lastms=32 [Oct 23 09:27:36] DEBUG[4199]: devicestate.c:473 do_state_change: Changing state for IAX2/213 - state 0 (Unknown) [Oct 23 09:27:37] DEBUG[4227]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 3 for 192.168.0.110 [Oct 23 09:27:37] DEBUG[4199]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for IAX2 - 217 [Oct 23 09:27:37] DEBUG[4199]: chan_iax2.c:14472 iax2_devicestate: Checking device state for device 217 [Oct 23 09:27:37] DEBUG[4199]: chan_iax2.c:14481 iax2_devicestate: Found peer. What's device state of 217? addr=192.168.0.110:4569, defaddr=(null) maxms=2000, lastms=35 [Oct 23 09:27:37] DEBUG[4199]: devicestate.c:473 do_state_change: Changing state for IAX2/217 - state 0 (Unknown) [Oct 23 09:27:38] DEBUG[4231]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.11 in 60 seconds [Oct 23 09:27:38] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 2 for 192.168.0.94 [Oct 23 09:27:39] DEBUG[4235]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.110 in 60 seconds [Oct 23 09:27:41] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 1 for 192.168.0.10 [Oct 23 09:27:41] DEBUG[4230]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 2 for 192.168.0.10 [Oct 23 09:27:41] DEBUG[4234]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.10 in 60 seconds [Oct 23 09:27:41] DEBUG[4234]: chan_iax2.c:11157 socket_process_helper: Peer 215: got pong, lastms 50, historicms 50, maxms 2000 [Oct 23 09:27:48] DEBUG[4233]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 3 for 192.168.0.10 [Oct 23 09:27:48] DEBUG[4199]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for IAX2 - 215 [Oct 23 09:27:48] DEBUG[4199]: chan_iax2.c:14472 iax2_devicestate: Checking device state for device 215 [Oct 23 09:27:48] DEBUG[4199]: chan_iax2.c:14481 iax2_devicestate: Found peer. What's device state of 215? addr=192.168.0.10:4569, defaddr=(null) maxms=2000, lastms=50 [Oct 23 09:27:48] DEBUG[4199]: devicestate.c:473 do_state_change: Changing state for IAX2/215 - state 0 (Unknown) [Oct 23 09:27:49] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 2 for 192.168.0.11 [Oct 23 09:27:49] DEBUG[4229]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 3 for 192.168.0.11 [Oct 23 09:27:49] DEBUG[4230]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.11 in 60 seconds [Oct 23 09:27:49] DEBUG[4230]: chan_iax2.c:11157 socket_process_helper: Peer 213: got pong, lastms 37, historicms 37, maxms 2000 [Oct 23 09:27:49] DEBUG[4234]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 3 for 192.168.0.75 [Oct 23 09:27:49] DEBUG[4199]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for IAX2 - 211 [Oct 23 09:27:49] DEBUG[4199]: chan_iax2.c:14472 iax2_devicestate: Checking device state for device 211 [Oct 23 09:27:49] DEBUG[4199]: chan_iax2.c:14481 iax2_devicestate: Found peer. What's device state of 211? addr=192.168.0.75:4569, defaddr=(null) maxms=2000, lastms=9 [Oct 23 09:27:49] DEBUG[4199]: devicestate.c:473 do_state_change: Changing state for IAX2/211 - state 0 (Unknown) [Oct 23 09:27:50] DEBUG[4227]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 4 for 192.168.0.75 -- Accepting UNAUTHENTICATED call from 192.168.0.75:4569: -- > requested format = gsm, -- > requested prefs = (), -- > actual format = gsm, -- > host prefs = (gsm|ulaw|alaw), -- > priority = mine [Oct 23 09:27:50] DEBUG[4187]: threadpool.c:508 grow: Increasing threadpool stasis-core's size by 1 [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Progress' -- Executing [8903XXXXXXX@out:1] Progress("IAX2/211-3750", "") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'EXTEN' is '8903XXXXXXX' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Gosub' -- Executing [8903XXXXXXX@out:2] Gosub("IAX2/211-3750", "init,~~s~~,1(out,8903XXXXXXX)") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: app_stack.c:606 gosub_exec: Channel IAX2/211-3750 has no datastore, so we're allocating one. [Oct 23 09:27:50] DEBUG[24073][C-000006da]: app_stack.c:648 gosub_exec: Setting 'ARG1' to 'out' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: app_stack.c:648 gosub_exec: Setting 'ARG2' to '8903XXXXXXX' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG1' is 'out' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'MSet' -- Executing [~~s~~@init:1] MSet("IAX2/211-3750", "LOCAL(action)=out") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG2' is '8903XXXXXXX' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'MSet' -- Executing [~~s~~@init:2] MSet("IAX2/211-3750", "LOCAL(subject)=8903XXXXXXX") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'EXTEN' is '~~s~~' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'MSet' -- Executing [~~s~~@init:3] MSet("IAX2/211-3750", "LOCAL(~~EXTEN~~)=~~s~~") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of '~~EXTEN~~' is '~~s~~' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'MSet' -- Executing [~~s~~@init:4] MSet("IAX2/211-3750", "LOCAL(~~EXTEN~~)=~~s~~") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'action' is 'out' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Goto' -- Executing [~~s~~@init:5] Goto("IAX2/211-3750", "sw_38_out,10") in new stack -- Goto (init,sw_38_out,10) [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'subject' is '8903XXXXXXX' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '1' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'GotoIf' -- Executing [sw_38_out@init:10] GotoIf("IAX2/211-3750", "1?11:13") in new stack -- Goto (init,sw_38_out,11) [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'subject' is '8903XXXXXXX' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Set' -- Executing [sw_38_out@init:11] Set("IAX2/211-3750", "CDR(Destination)=8903XXXXXXX") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Goto' -- Executing [sw_38_out@init:12] Goto("IAX2/211-3750", "14") in new stack -- Goto (init,sw_38_out,14) [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'NoOp' -- Executing [sw_38_out@init:14] NoOp("IAX2/211-3750", "Finish if_sw_init_default_38_46") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3782 ast_str_retrieve_variable: Result of 'init_uid' is NULL [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '0' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'GotoIf' -- Executing [sw_38_out@init:15] GotoIf("IAX2/211-3750", "0?16:25") in new stack -- Goto (init,sw_38_out,25) [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'NoOp' -- Executing [sw_38_out@init:25] NoOp("IAX2/211-3750", "Finish if_sw_init_default_38_47") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'UNIQUEID' is '1445603270.11002' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Set' -- Executing [sw_38_out@init:26] Set("IAX2/211-3750", "__init_uid=1445603270.11002") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4818 pbx_substitute_variables_helper_full: Function CALLERID(num) result is '211' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Set' -- Executing [sw_38_out@init:27] Set("IAX2/211-3750", "__init_num=211") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4818 pbx_substitute_variables_helper_full: Function CALLERID(name) result is '211' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Set' -- Executing [sw_38_out@init:28] Set("IAX2/211-3750", "__init_name=211") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'action' is 'out' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Gosub' -- Executing [sw_38_out@init:29] Gosub("IAX2/211-3750", "log,~~s~~,1(out,)") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: app_stack.c:648 gosub_exec: Setting 'ARG1' to 'out' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: app_stack.c:648 gosub_exec: Setting 'ARG2' to '' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG1' is 'out' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'MSet' -- Executing [~~s~~@log:1] MSet("IAX2/211-3750", "LOCAL(action)=out") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG2' is '' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'MSet' -- Executing [~~s~~@log:2] MSet("IAX2/211-3750", "LOCAL(subject)=") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'EXTEN' is '~~s~~' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'MSet' -- Executing [~~s~~@log:3] MSet("IAX2/211-3750", "LOCAL(~~EXTEN~~)=~~s~~") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of '~~EXTEN~~' is '~~s~~' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'MSet' -- Executing [~~s~~@log:4] MSet("IAX2/211-3750", "LOCAL(~~EXTEN~~)=~~s~~") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'action' is 'out' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Goto' -- Executing [~~s~~@log:5] Goto("IAX2/211-3750", "sw_70_out,10") in new stack -- Goto (log,sw_70_out,10) [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4818 pbx_substitute_variables_helper_full: Function CDR(Destination) result is '8903XXXXXXX' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4818 pbx_substitute_variables_helper_full: Function CALLERID(all) result is '"211" <211>' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'init_uid' is '1445603270.11002' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Log' -- Executing [sw_70_out@log:10] Log("IAX2/211-3750", "NOTICE,8903XXXXXXX>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>"211" <211> 1445603270.11002") in new stack [Oct 23 09:27:50] NOTICE[24073][C-000006da]: Ext. sw_70_out:10 @ log: 8903XXXXXXX>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>"211" <211> 1445603270.11002 [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Goto' -- Executing [sw_70_out@log:11] Goto("IAX2/211-3750", "~~s~~,6") in new stack -- Goto (log,~~s~~,6) [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'NoOp' -- Executing [~~s~~@log:6] NoOp("IAX2/211-3750", "Finish switch_log_70") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Return' -- Executing [~~s~~@log:7] Return("IAX2/211-3750", "") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'action' is 'out' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '1' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'GotoIf' -- Executing [sw_38_out@init:30] GotoIf("IAX2/211-3750", "1?31:34") in new stack -- Goto (init,sw_38_out,31) [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'init_num' is '211' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Gosub' -- Executing [sw_38_out@init:31] Gosub("IAX2/211-3750", "limit,~~s~~,1(211,internal,2)") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: app_stack.c:648 gosub_exec: Setting 'ARG1' to '211' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: app_stack.c:648 gosub_exec: Setting 'ARG2' to 'internal' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: app_stack.c:648 gosub_exec: Setting 'ARG3' to '2' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG1' is '211' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'MSet' -- Executing [~~s~~@limit:1] MSet("IAX2/211-3750", "LOCAL(subject)=211") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG2' is 'internal' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'MSet' -- Executing [~~s~~@limit:2] MSet("IAX2/211-3750", "LOCAL(cat)=internal") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG3' is '2' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'MSet' -- Executing [~~s~~@limit:3] MSet("IAX2/211-3750", "LOCAL(max)=2") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'subject' is '211' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'cat' is 'internal' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Gosub' -- Executing [~~s~~@limit:4] Gosub("IAX2/211-3750", "grp,~~s~~,1(Check,211,internal)") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: app_stack.c:648 gosub_exec: Setting 'ARG1' to 'Check' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: app_stack.c:648 gosub_exec: Setting 'ARG2' to '211' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: app_stack.c:648 gosub_exec: Setting 'ARG3' to 'internal' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG1' is 'Check' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'MSet' -- Executing [~~s~~@grp:1] MSet("IAX2/211-3750", "LOCAL(action)=Check") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG2' is '211' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'MSet' -- Executing [~~s~~@grp:2] MSet("IAX2/211-3750", "LOCAL(subject)=211") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG3' is 'internal' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'MSet' -- Executing [~~s~~@grp:3] MSet("IAX2/211-3750", "LOCAL(cat)=internal") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'EXTEN' is '~~s~~' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'MSet' -- Executing [~~s~~@grp:4] MSet("IAX2/211-3750", "LOCAL(~~EXTEN~~)=~~s~~") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of '~~EXTEN~~' is '~~s~~' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'MSet' -- Executing [~~s~~@grp:5] MSet("IAX2/211-3750", "LOCAL(~~EXTEN~~)=~~s~~") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'action' is 'Check' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Goto' -- Executing [~~s~~@grp:6] Goto("IAX2/211-3750", "sw_61_Check,10") in new stack -- Goto (grp,sw_61_Check,10) [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'subject' is '211' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'cat' is 'internal' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4818 pbx_substitute_variables_helper_full: Function GROUP_COUNT(211@internal) result is '0' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Set' -- Executing [sw_61_Check@grp:10] Set("IAX2/211-3750", "groupcount=0") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Goto' -- Executing [sw_61_Check@grp:11] Goto("IAX2/211-3750", "~~s~~,7") in new stack -- Goto (grp,~~s~~,7) [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'NoOp' -- Executing [~~s~~@grp:7] NoOp("IAX2/211-3750", "Finish switch_grp_61") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Return' -- Executing [~~s~~@grp:8] Return("IAX2/211-3750", "") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'groupcount' is '0' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'max' is '2' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '0' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'GotoIf' -- Executing [~~s~~@limit:5] GotoIf("IAX2/211-3750", "0?6:12") in new stack -- Goto (limit,~~s~~,12) [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'NoOp' -- Executing [~~s~~@limit:12] NoOp("IAX2/211-3750", "Finish if_limit_62") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Return' -- Executing [~~s~~@limit:13] Return("IAX2/211-3750", "") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'init_num' is '211' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Gosub' -- Executing [sw_38_out@init:32] Gosub("IAX2/211-3750", "grp,~~s~~,1(Set,211,internal)") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: app_stack.c:648 gosub_exec: Setting 'ARG1' to 'Set' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: app_stack.c:648 gosub_exec: Setting 'ARG2' to '211' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: app_stack.c:648 gosub_exec: Setting 'ARG3' to 'internal' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG1' is 'Set' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'MSet' -- Executing [~~s~~@grp:1] MSet("IAX2/211-3750", "LOCAL(action)=Set") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG2' is '211' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'MSet' -- Executing [~~s~~@grp:2] MSet("IAX2/211-3750", "LOCAL(subject)=211") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG3' is 'internal' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'MSet' -- Executing [~~s~~@grp:3] MSet("IAX2/211-3750", "LOCAL(cat)=internal") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'EXTEN' is '~~s~~' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'MSet' -- Executing [~~s~~@grp:4] MSet("IAX2/211-3750", "LOCAL(~~EXTEN~~)=~~s~~") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of '~~EXTEN~~' is '~~s~~' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'MSet' -- Executing [~~s~~@grp:5] MSet("IAX2/211-3750", "LOCAL(~~EXTEN~~)=~~s~~") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'action' is 'Set' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Goto' -- Executing [~~s~~@grp:6] Goto("IAX2/211-3750", "sw_61_Set,10") in new stack -- Goto (grp,sw_61_Set,10) [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'subject' is '211' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'cat' is 'internal' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Set' -- Executing [sw_61_Set@grp:10] Set("IAX2/211-3750", "OUTBOUND_GROUP=211@internal") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Goto' -- Executing [sw_61_Set@grp:11] Goto("IAX2/211-3750", "~~s~~,7") in new stack -- Goto (grp,~~s~~,7) [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'NoOp' -- Executing [~~s~~@grp:7] NoOp("IAX2/211-3750", "Finish switch_grp_61") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Return' -- Executing [~~s~~@grp:8] Return("IAX2/211-3750", "") in new stack [Oct 23 09:27:50] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 2 for 192.168.0.11 [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'init_num' is '211' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Set' -- Executing [sw_38_out@init:33] Set("IAX2/211-3750", "SPYGROUP=211") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'NoOp' -- Executing [sw_38_out@init:34] NoOp("IAX2/211-3750", "Finish if_sw_init_default_38_50") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Goto' -- Executing [sw_38_out@init:35] Goto("IAX2/211-3750", "~~s~~,6") in new stack -- Goto (init,~~s~~,6) [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'NoOp' -- Executing [~~s~~@init:6] NoOp("IAX2/211-3750", "Finish switch_init_38") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Return' -- Executing [~~s~~@init:7] Return("IAX2/211-3750", "") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'REC_MAIN' is '/home/rec/' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Gosub' -- Executing [8903XXXXXXX@out:3] Gosub("IAX2/211-3750", "mix,~~s~~,1(/home/rec/,out,)") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: app_stack.c:648 gosub_exec: Setting 'ARG1' to '/home/rec/' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: app_stack.c:648 gosub_exec: Setting 'ARG2' to 'out' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: app_stack.c:648 gosub_exec: Setting 'ARG3' to '' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG1' is '/home/rec/' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'MSet' -- Executing [~~s~~@mix:1] MSet("IAX2/211-3750", "LOCAL(path)=/home/rec/") in new stack [Oct 23 09:27:50] DEBUG[4235]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.10 in 60 seconds [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG2' is 'out' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'MSet' -- Executing [~~s~~@mix:2] MSet("IAX2/211-3750", "LOCAL(descr)=out") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG3' is '' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'MSet' -- Executing [~~s~~@mix:3] MSet("IAX2/211-3750", "LOCAL(path_add)=") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'path' is '/home/rec/' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'EPOCH' is '1445603270' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4818 pbx_substitute_variables_helper_full: Function STRFTIME(1445603270,,%Y) result is '2015' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'EPOCH' is '1445603270' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4818 pbx_substitute_variables_helper_full: Function STRFTIME(1445603270,,%m) result is '10' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'EPOCH' is '1445603270' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4818 pbx_substitute_variables_helper_full: Function STRFTIME(1445603270,,%d) result is '23' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'path_add' is '' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'EPOCH' is '1445603270' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4818 pbx_substitute_variables_helper_full: Function STRFTIME(1445603270,,%Y-%m-%d_%H-%M-%S) result is '2015-10-23_09-27-50' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'descr' is 'out' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'init_num' is '211' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4818 pbx_substitute_variables_helper_full: Function CDR(Destination) result is '8903XXXXXXX' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'init_uid' is '1445603270.11002' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'MixMonitor' -- Executing [~~s~~@mix:4] MixMonitor("IAX2/211-3750", "/home/rec/2015/10/23/2015-10-23_09-27-50_out_from_211_to_8903XXXXXXX_1445603270.11002.wav49") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: autochan.c:58 ast_autochan_setup: Created autochan 0xa874c50 to hold channel IAX2/211-3750 (0xb74302bc) [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Return' -- Executing [~~s~~@mix:5] Return("IAX2/211-3750", "") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'EXTEN' is '8903XXXXXXX' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Goto' -- Executing [8903XXXXXXX@out:4] Goto("IAX2/211-3750", "p8903XXXXXXX,1") in new stack -- Goto (out,p8903XXXXXXX,1) [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'EXTEN' is 'p8903XXXXXXX' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Goto' -- Executing [p8903XXXXXXX@out:1] Goto("IAX2/211-3750", "out-patterns,8903XXXXXXX,1") in new stack -- Goto (out-patterns,8903XXXXXXX,1) [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Set' -- Executing [8903XXXXXXX@out-patterns:1] Set("IAX2/211-3750", "CDR(OutRoute)=ip-mango") in new stack [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'EXTEN' is '8903XXXXXXX' [Oct 23 09:27:50] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Dial' -- Executing [8903XXXXXXX@out-patterns:2] Dial("IAX2/211-3750", "Local/8903XXXXXXX@dial-ip-mango/n,,r") in new stack == Begin MixMonitor Recording IAX2/211-3750 [Oct 23 09:27:50] DEBUG[24075][C-000006da]: audiohook.c:271 audiohook_read_frame_both: Read factory 0xac60c8c and write factory 0xac616ac both fail to provide 160 samples [Oct 23 09:27:50] DEBUG[24073][C-000006da]: channel_internal_api.c:933 ast_channel_callid_set: Channel Call ID changing from [C-000006da] to [C-000006da] [Oct 23 09:27:50] DEBUG[24073][C-000006da]: channel.c:6458 ast_channel_inherit_variables: Inheriting variable __init_name from IAX2/211-3750 to Local/8903XXXXXXX@dial-ip-mango-00000d76;1. [Oct 23 09:27:50] DEBUG[24073][C-000006da]: channel.c:6458 ast_channel_inherit_variables: Inheriting variable __init_num from IAX2/211-3750 to Local/8903XXXXXXX@dial-ip-mango-00000d76;1. [Oct 23 09:27:50] DEBUG[24073][C-000006da]: channel.c:6458 ast_channel_inherit_variables: Inheriting variable __init_uid from IAX2/211-3750 to Local/8903XXXXXXX@dial-ip-mango-00000d76;1. -- Called Local/8903XXXXXXX@dial-ip-mango/n [Oct 23 09:27:50] DEBUG[24076][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'EXTEN' is '8903XXXXXXX' [Oct 23 09:27:50] DEBUG[24076][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Goto' -- Executing [8903XXXXXXX@dial-ip-mango:1] Goto("Local/8903XXXXXXX@dial-ip-mango-00000d76;2", "7903XXXXXXX,1") in new stack -- Goto (dial-ip-mango,7903XXXXXXX,1) [Oct 23 09:27:50] DEBUG[24076][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'EXTEN' is '7903XXXXXXX' [Oct 23 09:27:50] DEBUG[24076][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Dial' -- Executing [7903XXXXXXX@dial-ip-mango:1] Dial("Local/8903XXXXXXX@dial-ip-mango-00000d76;2", "PJSIP/7903XXXXXXX@mango,,T") in new stack [Oct 23 09:27:50] DEBUG[24066]: pjsip:0 : dlg0xac621b4 UAC dialog created [Oct 23 09:27:50] DEBUG[24066]: pjsip:0 : dlg0xac621b4 Module Outbound INVITE Auth added as dialog usage, data=(nil) [Oct 23 09:27:50] DEBUG[24066]: pjsip:0 : dlg0xac621b4 Module mod-invite added as dialog usage, data=0xac6d914 [Oct 23 09:27:50] DEBUG[24066]: pjsip:0 : dlg0xac621b4 .Session count inc to 2 by mod-invite [Oct 23 09:27:50] DEBUG[24066]: pjsip:0 : dlg0xac621b4 Module mod-100rel added as dialog usage, data=0xac6da14 [Oct 23 09:27:50] DEBUG[24066]: pjsip:0 : dlg0xac621b4 100rel module attached [Oct 23 09:27:50] DEBUG[24066]: pjsip:0 : inv0xac621b4 UAC invite session created for dialog dlg0xac621b4 [Oct 23 09:27:50] DEBUG[24066]: pjsip:0 : dlg0xac621b4 .Session count inc to 2 by Session Module [Oct 23 09:27:50] DEBUG[24066]: pjsip:0 : dlg0xac621b4 Module Session Module added as dialog usage, data=(nil) [Oct 23 09:27:50] DEBUG[24076][C-000006da]: rtp_engine.c:1158 ast_rtp_instance_early_bridge_make_compatible: Can't find native functions for channel 'Local/8903XXXXXXX@dial-ip-mango-00000d76;2' [Oct 23 09:27:50] DEBUG[24076][C-000006da]: channel.c:6458 ast_channel_inherit_variables: Inheriting variable __init_name from Local/8903XXXXXXX@dial-ip-mango-00000d76;2 to PJSIP/mango-00000c4d. [Oct 23 09:27:50] DEBUG[24076][C-000006da]: channel.c:6458 ast_channel_inherit_variables: Inheriting variable __init_num from Local/8903XXXXXXX@dial-ip-mango-00000d76;2 to PJSIP/mango-00000c4d. [Oct 23 09:27:50] DEBUG[24076][C-000006da]: channel.c:6458 ast_channel_inherit_variables: Inheriting variable __init_uid from Local/8903XXXXXXX@dial-ip-mango-00000d76;2 to PJSIP/mango-00000c4d. [Oct 23 09:27:50] DEBUG[24066]: rtp_engine.c:425 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0xac50d64' [Oct 23 09:27:50] DEBUG[24066]: res_rtp_asterisk.c:2489 ast_rtp_new: Allocated port 29566 for RTP instance '0xac50d64' [Oct 23 09:27:50] DEBUG[24066]: pjsip:0 : icess0xac72b84 ICE session created, comp_cnt=2, role is Unknown agent [Oct 23 09:27:50] DEBUG[24066]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '178.XX.XXX.XXX' into... [Oct 23 09:27:50] DEBUG[24066]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '178.XX.XXX.XXX' and port ''. [Oct 23 09:27:50] DEBUG[24066]: pjsip:0 : icess0xac72b84 Candidate 0 added: comp_id=1, type=host, foundation=Hb213f2a9, addr=178.XX.XXX.XXX:29566, base=178.XX.XXX.XXX:29566, prio=0x7effffff (2130706431) [Oct 23 09:27:50] DEBUG[24066]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.0.254' into... [Oct 23 09:27:50] DEBUG[24066]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.0.254' and port ''. [Oct 23 09:27:50] DEBUG[24066]: pjsip:0 : icess0xac72b84 Candidate 1 added: comp_id=1, type=host, foundation=Hc0a800fe, addr=192.168.0.254:29566, base=192.168.0.254:29566, prio=0x7effffff (2130706431) [Oct 23 09:27:50] DEBUG[24066]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '172.16.0.1' into... [Oct 23 09:27:50] DEBUG[24066]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '172.16.0.1' and port ''. [Oct 23 09:27:50] DEBUG[24066]: pjsip:0 : icess0xac72b84 Candidate 2 added: comp_id=1, type=host, foundation=Hac100001, addr=172.16.0.1:29566, base=172.16.0.1:29566, prio=0x7effffff (2130706431) [Oct 23 09:27:50] DEBUG[24066]: rtp_engine.c:434 ast_rtp_instance_new: RTP instance '0xac50d64' is setup and ready to go [Oct 23 09:27:50] DEBUG[24066]: res_rtp_asterisk.c:4721 ast_rtp_prop_set: Setup RTCP on RTP instance '0xac50d64' [Oct 23 09:27:50] DEBUG[24066]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '178.XX.XXX.XXX' into... [Oct 23 09:27:50] DEBUG[24066]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '178.XX.XXX.XXX' and port ''. [Oct 23 09:27:50] DEBUG[24066]: pjsip:0 : icess0xac72b84 Candidate 3 added: comp_id=2, type=host, foundation=Hb213f2a9, addr=178.XX.XXX.XXX:29567, base=178.XX.XXX.XXX:29567, prio=0x7efffffe (2130706430) [Oct 23 09:27:50] DEBUG[24066]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.0.254' into... [Oct 23 09:27:50] DEBUG[24066]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.0.254' and port ''. [Oct 23 09:27:50] DEBUG[24066]: pjsip:0 : icess0xac72b84 Candidate 4 added: comp_id=2, type=host, foundation=Hc0a800fe, addr=192.168.0.254:29567, base=192.168.0.254:29567, prio=0x7efffffe (2130706430) [Oct 23 09:27:50] DEBUG[24066]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '172.16.0.1' into... [Oct 23 09:27:50] DEBUG[24066]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '172.16.0.1' and port ''. [Oct 23 09:27:50] DEBUG[24066]: pjsip:0 : icess0xac72b84 Candidate 5 added: comp_id=2, type=host, foundation=Hac100001, addr=172.16.0.1:29567, base=172.16.0.1:29567, prio=0x7efffffe (2130706430) [Oct 23 09:27:50] DEBUG[24066]: pjsip:0 : icess0xac72b84 Destroying ICE session 0xac72b84 [Oct 23 09:27:50] DEBUG[24066]: pjsip:0 : stuse0xac74580 STUN session 0xac7499c destroy request, ref_cnt=4 [Oct 23 09:27:50] DEBUG[24066]: pjsip:0 : stuse0xac75568 STUN session 0xac75984 destroy request, ref_cnt=3 [Oct 23 09:27:50] DEBUG[24066]: pjsip:0 : ice_session.c ICE session 0xac72b84 destroyed [Oct 23 09:27:50] DEBUG[24066]: pjsip:0 : stun_session.c STUN session 0xac7499c destroyed [Oct 23 09:27:50] DEBUG[24066]: pjsip:0 : stun_session.c STUN session 0xac75984 destroyed -- Called PJSIP/7903XXXXXXX@mango [Oct 23 09:27:50] DEBUG[24076][C-000006da]: channel.c:5490 set_format: Channel PJSIP/mango-00000c4d setting read format path: gsm -> gsm [Oct 23 09:27:50] DEBUG[24076][C-000006da]: channel.c:5490 set_format: Channel PJSIP/mango-00000c4d setting write format path: gsm -> gsm [Oct 23 09:27:50] DEBUG[24066]: pjsip:0 : endpoint Request msg INVITE/cseq=15840 (tdta0xac73420) created. [Oct 23 09:27:50] DEBUG[24066]: res_pjsip_session.c:2236 handle_outgoing_request: Method is INVITE [Oct 23 09:27:50] DEBUG[24066]: pjsip:0 : dlg0xac621b4 Module NAT added as dialog usage, data=(nil) [Oct 23 09:27:50] DEBUG[24066]: pjsip:0 : inv0xac621b4 .Sending Request msg INVITE/cseq=15840 (tdta0xac73420) [Oct 23 09:27:50] DEBUG[24066]: pjsip:0 : dlg0xac621b4 ..Sending Request msg INVITE/cseq=15840 (tdta0xac73420) [Oct 23 09:27:50] DEBUG[24073][C-000006da]: chan_iax2.c:5759 iax2_indicate: Callno 3750: Config blocked sending control frame 22. [Oct 23 09:27:50] DEBUG[24066]: pjsip:0 : tsx0xac7676c ...Transaction created for Request msg INVITE/cseq=15839 (tdta0xac73420) [Oct 23 09:27:50] DEBUG[24066]: pjsip:0 : tsx0xac7676c ..Sending Request msg INVITE/cseq=15839 (tdta0xac73420) in state Null [Oct 23 09:27:50] DEBUG[24066]: pjsip:0 : sip_resolve.c ...Starting async DNS A query: target=vpbx400034059.mangosip.ru, transport=Unspecified, port=5060 [Oct 23 09:27:50] DEBUG[24066]: pjsip:0 : tsx0xac7676c ...State changed from Null to Calling, event=TX_MSG [Oct 23 09:27:50] DEBUG[24066]: pjsip:0 : dlg0xac621b4 ....Transaction tsx0xac7676c state changed to Calling [Oct 23 09:27:50] DEBUG[24066]: res_pjsip_session.c:2143 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [Oct 23 09:27:50] DEBUG[24066]: res_pjsip_session.c:2155 __print_debug_details: The state change pertains to the endpoint 'mango(PJSIP/mango-00000c4d)' [Oct 23 09:27:50] DEBUG[24066]: res_pjsip_session.c:2160 __print_debug_details: The inv session still has an invite_tsx (0xac7676c) [Oct 23 09:27:50] DEBUG[24066]: res_pjsip_session.c:2175 __print_debug_details: There is no transaction involved in this state change [Oct 23 09:27:50] DEBUG[24066]: res_pjsip_session.c:2177 __print_debug_details: The current inv state is CALLING [Oct 23 09:27:50] DEBUG[24066]: res_pjsip_session.c:2333 session_inv_on_state_changed: Source of transaction state change is TX_MSG [Oct 23 09:27:50] DEBUG[24066]: res_pjsip_session.c:2263 handle_outgoing: Sending request [Oct 23 09:27:50] DEBUG[24066]: res_pjsip_session.c:2236 handle_outgoing_request: Method is INVITE [Oct 23 09:27:50] DEBUG[24066]: res_pjsip_session.c:2143 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Oct 23 09:27:50] DEBUG[24066]: res_pjsip_session.c:2155 __print_debug_details: The state change pertains to the endpoint 'mango(PJSIP/mango-00000c4d)' [Oct 23 09:27:50] DEBUG[24066]: res_pjsip_session.c:2160 __print_debug_details: The inv session still has an invite_tsx (0xac7676c) [Oct 23 09:27:50] DEBUG[24066]: res_pjsip_session.c:2166 __print_debug_details: The UAC INVITE transaction involved in this state change is 0xac7676c [Oct 23 09:27:50] DEBUG[24066]: res_pjsip_session.c:2170 __print_debug_details: The current transaction state is Calling [Oct 23 09:27:50] DEBUG[24066]: res_pjsip_session.c:2172 __print_debug_details: The transaction state change event is TX_MSG [Oct 23 09:27:50] DEBUG[24066]: res_pjsip_session.c:2177 __print_debug_details: The current inv state is CALLING [Oct 23 09:27:50] DEBUG[24066]: res_pjsip_session.c:2263 handle_outgoing: Sending request [Oct 23 09:27:50] DEBUG[24066]: res_pjsip_session.c:2236 handle_outgoing_request: Method is INVITE [Oct 23 09:27:51] DEBUG[4234]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.75 in 60 seconds [Oct 23 09:27:51] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 2 for 192.168.0.110 [Oct 23 09:27:53] DEBUG[4231]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 3 for 192.168.0.77 [Oct 23 09:27:53] DEBUG[4199]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for IAX2 - 216 [Oct 23 09:27:53] DEBUG[4199]: chan_iax2.c:14472 iax2_devicestate: Checking device state for device 216 [Oct 23 09:27:53] DEBUG[4199]: chan_iax2.c:14481 iax2_devicestate: Found peer. What's device state of 216? addr=192.168.0.77:4569, defaddr=(null) maxms=2000, lastms=30 [Oct 23 09:27:53] DEBUG[4199]: devicestate.c:473 do_state_change: Changing state for IAX2/216 - state 0 (Unknown) [Oct 23 09:27:55] DEBUG[4235]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.77 in 60 seconds [Oct 23 09:28:02] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 3 for 192.168.0.75 [Oct 23 09:28:02] DEBUG[4227]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 4 for 192.168.0.75 [Oct 23 09:28:02] DEBUG[4233]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.75 in 60 seconds [Oct 23 09:28:02] DEBUG[4233]: chan_iax2.c:11157 socket_process_helper: Peer 211: got pong, lastms 13, historicms 13, maxms 2000 [Oct 23 09:28:03] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 2 for 192.168.0.10 [Oct 23 09:28:04] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 3 for 192.168.0.75 [Oct 23 09:28:08] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 2 for 192.168.0.77 [Oct 23 09:28:10] DEBUG[24074]: threadpool.c:1107 worker_idle: Worker thread idle timeout reached. Dying. [Oct 23 09:28:10] DEBUG[4187]: threadpool.c:968 worker_thread_destroy: Destroying worker thread 7202 [Oct 23 09:28:10] DEBUG[4227]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 3 for 192.168.0.94 [Oct 23 09:28:10] DEBUG[4199]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for IAX2 - 212 [Oct 23 09:28:10] DEBUG[4199]: chan_iax2.c:14472 iax2_devicestate: Checking device state for device 212 [Oct 23 09:28:10] DEBUG[4199]: chan_iax2.c:14481 iax2_devicestate: Found peer. What's device state of 212? addr=192.168.0.94:4569, defaddr=(null) maxms=2000, lastms=16 [Oct 23 09:28:10] DEBUG[4199]: devicestate.c:473 do_state_change: Changing state for IAX2/212 - state 0 (Unknown) [Oct 23 09:28:11] DEBUG[4231][C-000006da]: chan_iax2.c:9684 log_jitterstats: JB STATS:IAX2/211-3750 ping=4 ljitterms=-1 ljbdelayms=0 ltotlost=-1 lrecentlosspct=-1 ldropped=0 looo=-1 lrecvd=-1 rjitterms=0 rjbdelayms=0 rtotlost=0 rrecentlosspct=0 rdropped=0 rooo=0 rrecvd=0 [Oct 23 09:28:13] DEBUG[4226]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.94 in 60 seconds [Oct 23 09:28:14] DEBUG[4228][C-000006da]: chan_iax2.c:10951 socket_process_helper: Immediately destroying 3750, having received hangup [Oct 23 09:28:14] DEBUG[24073][C-000006da]: channel.c:2682 ast_hangup: Hanging up channel 'Local/8903XXXXXXX@dial-ip-mango-00000d76;1' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: app_dial.c:3060 dial_exec_full: Exiting with DIALSTATUS=CANCEL. [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:6511 __ast_pbx_run: Spawn extension (out-patterns,8903XXXXXXX,2) exited non-zero on 'IAX2/211-3750' == Spawn extension (out-patterns, 8903XXXXXXX, 2) exited non-zero on 'IAX2/211-3750' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: channel.c:2533 ast_softhangup_nolock: Soft-Hanging (0x10) up channel 'IAX2/211-3750' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: channel.c:2533 ast_softhangup_nolock: Soft-Hanging (0x80) up channel 'IAX2/211-3750' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Gosub' -- Executing [h@out-patterns:1] Gosub("IAX2/211-3750", "init,~~s~~,1(Terminate,out)") in new stack [Oct 23 09:28:14] DEBUG[24073][C-000006da]: app_stack.c:648 gosub_exec: Setting 'ARG1' to 'Terminate' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: app_stack.c:648 gosub_exec: Setting 'ARG2' to 'out' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG1' is 'Terminate' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'MSet' -- Executing [~~s~~@init:1] MSet("IAX2/211-3750", "LOCAL(action)=Terminate") in new stack [Oct 23 09:28:14] DEBUG[4200]: cdr.c:1276 cdr_object_finalize: Finalized CDR for IAX2/211-3750 - start 1445603270.748770 answer 0.000000 end 1445603294.663168 dispo NO ANSWER [Oct 23 09:28:14] DEBUG[4200]: cdr.c:1276 cdr_object_finalize: Finalized CDR for Local/8903XXXXXXX@dial-ip-mango-00000d76;1 - start 1445603270.868880 answer 0.000000 end 1445603294.663219 dispo FAILED [Oct 23 09:28:14] DEBUG[4187]: threadpool.c:508 grow: Increasing threadpool stasis-core's size by 1 [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG2' is 'out' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'MSet' -- Executing [~~s~~@init:2] MSet("IAX2/211-3750", "LOCAL(subject)=out") in new stack [Oct 23 09:28:14] DEBUG[4200]: cdr.c:1104 cdr_object_create_public_records: CDR for Local/8903XXXXXXX@dial-ip-mango-00000d76;1 is dialed and has no Party B; discarding [Oct 23 09:28:14] DEBUG[24076][C-000006da]: channel.c:2682 ast_hangup: Hanging up channel 'PJSIP/mango-00000c4d' [Oct 23 09:28:14] DEBUG[24076][C-000006da]: chan_pjsip.c:1702 hangup_cause2sip: AST hangup cause 0 (no match found in PJSIP) [Oct 23 09:28:14] DEBUG[24076][C-000006da]: app_dial.c:3060 dial_exec_full: Exiting with DIALSTATUS=CANCEL. [Oct 23 09:28:14] DEBUG[24076][C-000006da]: pbx.c:6511 __ast_pbx_run: Spawn extension (dial-ip-mango,7903XXXXXXX,1) exited non-zero on 'Local/8903XXXXXXX@dial-ip-mango-00000d76;2' == Spawn extension (dial-ip-mango, 7903XXXXXXX, 1) exited non-zero on 'Local/8903XXXXXXX@dial-ip-mango-00000d76;2' [Oct 23 09:28:14] DEBUG[24076][C-000006da]: channel.c:2533 ast_softhangup_nolock: Soft-Hanging (0x10) up channel 'Local/8903XXXXXXX@dial-ip-mango-00000d76;2' [Oct 23 09:28:14] DEBUG[24076][C-000006da]: channel.c:2682 ast_hangup: Hanging up channel 'Local/8903XXXXXXX@dial-ip-mango-00000d76;2' [Oct 23 09:28:14] DEBUG[24066]: pjsip:0 : inv0xac621b4 .Delaying CANCEL since no provisional response is received yet [Oct 23 09:28:14] DEBUG[4199]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for Local - 8903XXXXXXX@dial-ip-mango [Oct 23 09:28:14] DEBUG[4199]: core_local.c:315 local_devicestate: Checking if extension 8903XXXXXXX@dial-ip-mango exists (devicestate) [Oct 23 09:28:14] DEBUG[4199]: devicestate.c:473 do_state_change: Changing state for Local/8903XXXXXXX@dial-ip-mango - state 1 (Not in use) [Oct 23 09:28:14] DEBUG[4242]: app_queue.c:2374 device_state_cb: Device 'Local/8903XXXXXXX@dial-ip-mango' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Oct 23 09:28:14] DEBUG[4200]: cdr.c:1276 cdr_object_finalize: Finalized CDR for Local/8903XXXXXXX@dial-ip-mango-00000d76;2 - start 1445603270.869221 answer 0.000000 end 1445603294.667278 dispo NO ANSWER [Oct 23 09:28:14] DEBUG[4187]: threadpool.c:508 grow: Increasing threadpool stasis-core's size by 1 [Oct 23 09:28:14] DEBUG[4199]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for Local - 8903XXXXXXX@dial-ip-mango [Oct 23 09:28:14] DEBUG[4199]: core_local.c:315 local_devicestate: Checking if extension 8903XXXXXXX@dial-ip-mango exists (devicestate) [Oct 23 09:28:14] DEBUG[4199]: devicestate.c:473 do_state_change: Changing state for Local/8903XXXXXXX@dial-ip-mango - state 1 (Not in use) [Oct 23 09:28:14] DEBUG[4199]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for PJSIP - mango [Oct 23 09:28:14] DEBUG[4199]: devicestate.c:473 do_state_change: Changing state for PJSIP/mango - state 5 (Unavailable) [Oct 23 09:28:14] DEBUG[4242]: app_queue.c:2374 device_state_cb: Device 'Local/8903XXXXXXX@dial-ip-mango' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Oct 23 09:28:14] DEBUG[4200]: cdr.c:1276 cdr_object_finalize: Finalized CDR for PJSIP/mango-00000c4d - start 1445603270.880327 answer 0.000000 end 1445603294.671129 dispo FAILED [Oct 23 09:28:14] DEBUG[4200]: cdr.c:1104 cdr_object_create_public_records: CDR for PJSIP/mango-00000c4d is dialed and has no Party B; discarding [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'EXTEN' is '~~s~~' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'MSet' -- Executing [~~s~~@init:3] MSet("IAX2/211-3750", "LOCAL(~~EXTEN~~)=~~s~~") in new stack [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of '~~EXTEN~~' is '~~s~~' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'MSet' -- Executing [~~s~~@init:4] MSet("IAX2/211-3750", "LOCAL(~~EXTEN~~)=~~s~~") in new stack [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'action' is 'Terminate' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Goto' -- Executing [~~s~~@init:5] Goto("IAX2/211-3750", "sw_38_Terminate,10") in new stack -- Goto (init,sw_38_Terminate,10) [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'subject' is 'out' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Goto' -- Executing [sw_38_Terminate@init:10] Goto("IAX2/211-3750", "sw_40_out,10") in new stack -- Goto (init,sw_40_out,10) [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'subject' is 'out' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Gosub' -- Executing [sw_40_out@init:10] Gosub("IAX2/211-3750", "cdr,~~s~~,1(General,out)") in new stack [Oct 23 09:28:14] DEBUG[24073][C-000006da]: app_stack.c:648 gosub_exec: Setting 'ARG1' to 'General' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: app_stack.c:648 gosub_exec: Setting 'ARG2' to 'out' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG1' is 'General' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'MSet' -- Executing [~~s~~@cdr:1] MSet("IAX2/211-3750", "LOCAL(action)=General") in new stack [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG2' is 'out' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'MSet' -- Executing [~~s~~@cdr:2] MSet("IAX2/211-3750", "LOCAL(subject)=out") in new stack [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'EXTEN' is '~~s~~' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'MSet' -- Executing [~~s~~@cdr:3] MSet("IAX2/211-3750", "LOCAL(~~EXTEN~~)=~~s~~") in new stack [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of '~~EXTEN~~' is '~~s~~' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'MSet' -- Executing [~~s~~@cdr:4] MSet("IAX2/211-3750", "LOCAL(~~EXTEN~~)=~~s~~") in new stack [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'action' is 'General' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Goto' -- Executing [~~s~~@cdr:5] Goto("IAX2/211-3750", "sw_37_General,10") in new stack -- Goto (cdr,sw_37_General,10) [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'CMD_CURL' is '/usr/bin/curl --silent --ipv4 --connect-timeout 3 --max-time 3 --insecure -X POST -H "Content-Type: application/json"' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'init_uid' is '1445603270.11002' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'subject' is 'out' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'init_num' is '211' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:4818 pbx_substitute_variables_helper_full: Function CDR(Destination) result is '8903XXXXXXX' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:4818 pbx_substitute_variables_helper_full: Function CDR(disposition) result is 'NO ANSWER' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:4818 pbx_substitute_variables_helper_full: Function CDR(start) result is '2015-10-23 09:27:50' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:4818 pbx_substitute_variables_helper_full: Function CDR(answer) result is '' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:4818 pbx_substitute_variables_helper_full: Function CDR(end) result is '2015-10-23 09:28:14' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:4818 pbx_substitute_variables_helper_full: Function CDR(duration) result is '23' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:4818 pbx_substitute_variables_helper_full: Function CDR(billsec) result is '0' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:4818 pbx_substitute_variables_helper_full: Function CDR(OutRoute) result is 'ip-mango' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:4818 pbx_substitute_variables_helper_full: Function CDR(QueueDate) result is '' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'MIXMONITOR_FILENAME' is '/home/rec/2015/10/23/2015-10-23_09-27-50_out_from_211_to_8903XXXXXXX_1445603270.11002.wav49' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'System' -- Executing [sw_37_General@cdr:10] System("IAX2/211-3750", "/usr/bin/curl --silent --ipv4 --connect-timeout 3 --max-time 3 --insecure -X POST -H "Content-Type: application/json" -d '{"uid":"1445603270.11002","generalRoute":"out","generalFrom":"211","generalTo":"8903XXXXXXX","generalDisposition":"NO ANSWER","geeralTimeStart":"2015-10-23 09:27:50","generalTimeAnswer":"","generalTimeEnd":"2015-10-23 09:28:14","generalDurationTotal":"23","generalDurationBill":"0","generalOutRoute":"ip-mango","generalInTime":"","generalMix":"/home/rec/2015/10/23/2015-10-23_09-27-50_out_from_211_to_8903XXXXXXX_1445603270.11002.wav49"}' http:/example.com/asterisk/cdr") in new stack [Oct 23 09:28:14] DEBUG[4227]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 4 for 192.168.0.75 [Oct 23 09:28:14] DEBUG[4227]: chan_iax2.c:2617 peercnt_modify: peercnt entry 192.168.0.75 modified limit:2048 registered:0â–’Unregistered IAX2 '211' (UNAUTHENTICATED) [Oct 23 09:28:14] DEBUG[4199]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for IAX2 - 211 [Oct 23 09:28:14] DEBUG[4199]: chan_iax2.c:14472 iax2_devicestate: Checking device state for device 211 [Oct 23 09:28:14] DEBUG[4199]: chan_iax2.c:14481 iax2_devicestate: Found peer. What's device state of 211? addr=(null), defaddr=(null) maxms=2000, lastms=13 [Oct 23 09:28:14] DEBUG[4199]: devicestate.c:473 do_state_change: Changing state for IAX2/211 - state 5 (Unavailable) [Oct 23 09:28:14] DEBUG[4242]: app_queue.c:2374 device_state_cb: Device 'IAX2/211' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue. [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Goto' -- Executing [sw_37_General@cdr:11] Goto("IAX2/211-3750", "~~s~~,6") in new stack -- Goto (cdr,~~s~~,6) [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'NoOp' -- Executing [~~s~~@cdr:6] NoOp("IAX2/211-3750", "Finish switch_cdr_37") in new stack [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Return' -- Executing [~~s~~@cdr:7] Return("IAX2/211-3750", "") in new stack [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'subject' is 'out' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Gosub' -- Executing [sw_40_out@init:11] Gosub("IAX2/211-3750", "log,~~s~~,1(out-term,)") in new stack [Oct 23 09:28:14] DEBUG[24073][C-000006da]: app_stack.c:648 gosub_exec: Setting 'ARG1' to 'out-term' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: app_stack.c:648 gosub_exec: Setting 'ARG2' to '' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG1' is 'out-term' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'MSet' -- Executing [~~s~~@log:1] MSet("IAX2/211-3750", "LOCAL(action)=out-term") in new stack [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG2' is '' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'MSet' -- Executing [~~s~~@log:2] MSet("IAX2/211-3750", "LOCAL(subject)=") in new stack [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'EXTEN' is '~~s~~' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'MSet' -- Executing [~~s~~@log:3] MSet("IAX2/211-3750", "LOCAL(~~EXTEN~~)=~~s~~") in new stack [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of '~~EXTEN~~' is '~~s~~' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'MSet' -- Executing [~~s~~@log:4] MSet("IAX2/211-3750", "LOCAL(~~EXTEN~~)=~~s~~") in new stack [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'action' is 'out-term' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Goto' -- Executing [~~s~~@log:5] Goto("IAX2/211-3750", "sw_70_out-term,10") in new stack -- Goto (log,sw_70_out-term,10) [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:4818 pbx_substitute_variables_helper_full: Function CDR(Destination) result is '8903XXXXXXX' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:4818 pbx_substitute_variables_helper_full: Function CALLERID(all) result is '"211" <211>' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:3785 ast_str_retrieve_variable: Result of 'init_uid' is '1445603270.11002' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Log' -- Executing [sw_70_out-term@log:10] Log("IAX2/211-3750", "NOTICE,8903XXXXXXX-------------------------------------->>"211" <211> 1445603270.11002") in new stack [Oct 23 09:28:14] NOTICE[24073][C-000006da]: Ext. sw_70_out-term:10 @ log: 8903XXXXXXX-------------------------------------->>"211" <211> 1445603270.11002 [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Goto' -- Executing [sw_70_out-term@log:11] Goto("IAX2/211-3750", "~~s~~,6") in new stack -- Goto (log,~~s~~,6) [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'NoOp' -- Executing [~~s~~@log:6] NoOp("IAX2/211-3750", "Finish switch_log_70") in new stack [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Return' -- Executing [~~s~~@log:7] Return("IAX2/211-3750", "") in new stack [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Goto' -- Executing [sw_40_out@init:12] Goto("IAX2/211-3750", "sw_38_Terminate,11") in new stack -- Goto (init,sw_38_Terminate,11) [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'NoOp' -- Executing [sw_38_Terminate@init:11] NoOp("IAX2/211-3750", "Finish switch_sw_init_Terminate_38_40") in new stack [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Goto' -- Executing [sw_38_Terminate@init:12] Goto("IAX2/211-3750", "~~s~~,6") in new stack -- Goto (init,~~s~~,6) [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'NoOp' -- Executing [~~s~~@init:6] NoOp("IAX2/211-3750", "Finish switch_init_38") in new stack [Oct 23 09:28:14] DEBUG[24073][C-000006da]: pbx.c:4983 pbx_extension_helper: Launching 'Return' -- Executing [~~s~~@init:7] Return("IAX2/211-3750", "") in new stack [Oct 23 09:28:14] DEBUG[24073][C-000006da]: channel.c:2682 ast_hangup: Hanging up channel 'IAX2/211-3750' [Oct 23 09:28:14] DEBUG[24073][C-000006da]: chan_iax2.c:5298 iax2_hangup: We're hanging up IAX2/211-3750 now... [Oct 23 09:28:14] DEBUG[24073][C-000006da]: chan_iax2.c:5315 iax2_hangup: Really destroying IAX2/211-3750 now... [Oct 23 09:28:14] DEBUG[24073][C-000006da]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.75 in 60 seconds -- Hungup 'IAX2/211-3750' [Oct 23 09:28:14] DEBUG[24075][C-000006da]: autochan.c:71 ast_autochan_destroy: Removed autochan 0xa874c50 from the list, about to free it == MixMonitor close filestream (mixed) == End MixMonitor Recording IAX2/211-3750 [Oct 23 09:28:14] DEBUG[24075][C-000006da]: app_mixmonitor.c:776 mixmonitor_thread: No recipients to forward monitor to, moving on. [Oct 23 09:28:14] DEBUG[4199]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for IAX2 - 211 [Oct 23 09:28:14] DEBUG[4199]: chan_iax2.c:14472 iax2_devicestate: Checking device state for device 211 [Oct 23 09:28:14] DEBUG[4199]: chan_iax2.c:14481 iax2_devicestate: Found peer. What's device state of 211? addr=(null), defaddr=(null) maxms=2000, lastms=0 [Oct 23 09:28:14] DEBUG[4199]: devicestate.c:473 do_state_change: Changing state for IAX2/211 - state 5 (Unavailable) [Oct 23 09:28:14] DEBUG[4242]: app_queue.c:2374 device_state_cb: Device 'IAX2/211' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue. [Oct 23 09:28:16] DEBUG[4231]: chan_iax2.c:11504 socket_process_helper: Immediately destroying 6221, having received INVAL [Oct 23 09:28:16] DEBUG[4231]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.75 in 60 seconds [Oct 23 09:28:16] DEBUG[4231]: chan_iax2.c:11506 socket_process_helper: Destroying call 6221 [Oct 23 09:28:22] DEBUG[24066]: pjsip:0 : endpoint Request msg OPTIONS/cseq=61009 (tdta0xac57390) created. [Oct 23 09:28:22] DEBUG[24066]: config.c:3544 ast_parse_arg: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Oct 23 09:28:22] DEBUG[24066]: config.c:3544 ast_parse_arg: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Oct 23 09:28:22] DEBUG[24066]: config.c:3544 ast_parse_arg: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Oct 23 09:28:22] DEBUG[24066]: res_pjsip.c:3075 endpt_send_request: 0xac3f9ac: Wrapper created [Oct 23 09:28:22] DEBUG[24066]: res_pjsip.c:3106 endpt_send_request: 0xac3f9ac: Set timer to 30000 msec [Oct 23 09:28:22] DEBUG[24066]: pjsip:0 : tsx0xac5415c .Transaction created for Request msg OPTIONS/cseq=61009 (tdta0xac57390) [Oct 23 09:28:22] DEBUG[24066]: pjsip:0 : tsx0xac5415c Sending Request msg OPTIONS/cseq=61009 (tdta0xac57390) in state Null [Oct 23 09:28:22] DEBUG[24066]: pjsip:0 : sip_resolve.c .Starting async DNS A query: target=vpbx400034059.mangosip.ru, transport=Unspecified, port=5060 [Oct 23 09:28:22] DEBUG[24066]: pjsip:0 : tsx0xac5415c .State changed from Null to Calling, event=TX_MSG [Oct 23 09:28:22] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 1 for 192.168.0.110 [Oct 23 09:28:22] DEBUG[4229]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 2 for 192.168.0.110 [Oct 23 09:28:22] DEBUG[4235]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.110 in 60 seconds [Oct 23 09:28:22] DEBUG[4235]: chan_iax2.c:11157 socket_process_helper: Peer 217: got pong, lastms 8, historicms 8, maxms 2000 [Oct 23 09:28:23] DEBUG[4232]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 3 for 192.168.0.11 [Oct 23 09:28:23] DEBUG[4199]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for IAX2 - 213 [Oct 23 09:28:23] DEBUG[4199]: chan_iax2.c:14472 iax2_devicestate: Checking device state for device 213 [Oct 23 09:28:23] DEBUG[4199]: chan_iax2.c:14481 iax2_devicestate: Found peer. What's device state of 213? addr=192.168.0.11:4569, defaddr=(null) maxms=2000, lastms=37 [Oct 23 09:28:23] DEBUG[4199]: devicestate.c:473 do_state_change: Changing state for IAX2/213 - state 0 (Unknown) [Oct 23 09:28:24] DEBUG[4233]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 3 for 192.168.0.110 [Oct 23 09:28:24] DEBUG[4199]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for IAX2 - 217 [Oct 23 09:28:24] DEBUG[4199]: chan_iax2.c:14472 iax2_devicestate: Checking device state for device 217 [Oct 23 09:28:24] DEBUG[4199]: chan_iax2.c:14481 iax2_devicestate: Found peer. What's device state of 217? addr=192.168.0.110:4569, defaddr=(null) maxms=2000, lastms=8 [Oct 23 09:28:24] DEBUG[4199]: devicestate.c:473 do_state_change: Changing state for IAX2/217 - state 0 (Unknown) [Oct 23 09:28:25] DEBUG[4229]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.11 in 60 seconds [Oct 23 09:28:25] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 2 for 192.168.0.94 [Oct 23 09:28:26] DEBUG[4230]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.110 in 60 seconds [Oct 23 09:28:29] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 1 for 192.168.0.77 [Oct 23 09:28:29] DEBUG[4234]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 2 for 192.168.0.77 [Oct 23 09:28:29] DEBUG[4228]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.77 in 60 seconds [Oct 23 09:28:29] DEBUG[4228]: chan_iax2.c:11157 socket_process_helper: Peer 216: got pong, lastms 8, historicms 8, maxms 2000 [Oct 23 09:28:33] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 1 for 192.168.0.94 [Oct 23 09:28:33] DEBUG[4233]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 2 for 192.168.0.94 [Oct 23 09:28:33] DEBUG[4231]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.94 in 60 seconds [Oct 23 09:28:33] DEBUG[4231]: chan_iax2.c:11157 socket_process_helper: Peer 212: got pong, lastms 21, historicms 21, maxms 2000 [Oct 23 09:28:34] DEBUG[24079]: threadpool.c:1107 worker_idle: Worker thread idle timeout reached. Dying. [Oct 23 09:28:34] DEBUG[4187]: threadpool.c:968 worker_thread_destroy: Destroying worker thread 7204 [Oct 23 09:28:34] DEBUG[24078]: threadpool.c:1107 worker_idle: Worker thread idle timeout reached. Dying. [Oct 23 09:28:34] DEBUG[4187]: threadpool.c:968 worker_thread_destroy: Destroying worker thread 7203 [Oct 23 09:28:36] DEBUG[4234]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 3 for 192.168.0.10 [Oct 23 09:28:36] DEBUG[4199]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for IAX2 - 215 [Oct 23 09:28:36] DEBUG[4199]: chan_iax2.c:14472 iax2_devicestate: Checking device state for device 215 [Oct 23 09:28:36] DEBUG[4199]: chan_iax2.c:14481 iax2_devicestate: Found peer. What's device state of 215? addr=192.168.0.10:4569, defaddr=(null) maxms=2000, lastms=50 [Oct 23 09:28:36] DEBUG[4199]: devicestate.c:473 do_state_change: Changing state for IAX2/215 - state 0 (Unknown) [Oct 23 09:28:38] DEBUG[4227]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.10 in 60 seconds [Oct 23 09:28:38] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 2 for 192.168.0.11 [Oct 23 09:28:38] DEBUG[4231]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 1 for 192.168.0.66 -- Registered IAX2 '222' (UNAUTHENTICATED) at 192.168.0.66:4569 [Oct 23 09:28:38] DEBUG[4199]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for IAX2 - 222 [Oct 23 09:28:38] DEBUG[4199]: chan_iax2.c:14472 iax2_devicestate: Checking device state for device 222 [Oct 23 09:28:38] DEBUG[4199]: chan_iax2.c:14481 iax2_devicestate: Found peer. What's device state of 222? addr=192.168.0.66:4569, defaddr=(null) maxms=2000, lastms=0 [Oct 23 09:28:38] DEBUG[4199]: devicestate.c:473 do_state_change: Changing state for IAX2/222 - state 0 (Unknown) [Oct 23 09:28:38] DEBUG[4231]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 2 for 192.168.0.66 [Oct 23 09:28:38] DEBUG[4199]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for IAX2 - 222 [Oct 23 09:28:38] DEBUG[4199]: chan_iax2.c:14472 iax2_devicestate: Checking device state for device 222 [Oct 23 09:28:38] DEBUG[4199]: chan_iax2.c:14481 iax2_devicestate: Found peer. What's device state of 222? addr=192.168.0.66:4569, defaddr=(null) maxms=2000, lastms=0 [Oct 23 09:28:38] DEBUG[4199]: devicestate.c:473 do_state_change: Changing state for IAX2/222 - state 0 (Unknown) [Oct 23 09:28:38] DEBUG[4187]: threadpool.c:508 grow: Increasing threadpool stasis-core's size by 1 [Oct 23 09:28:38] DEBUG[4242]: app_queue.c:2374 device_state_cb: Device 'IAX2/222' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Oct 23 09:28:38] DEBUG[4229]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.66 in 60 seconds [Oct 23 09:28:38] DEBUG[4229]: chan_iax2.c:11157 socket_process_helper: Peer 222: got pong, lastms 30, historicms 30, maxms 2000 [Oct 23 09:28:39] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 2 for 192.168.0.110 [Oct 23 09:28:40] DEBUG[4234]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.66 in 60 seconds [Oct 23 09:28:40] DEBUG[4232]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 3 for 192.168.0.77 [Oct 23 09:28:40] DEBUG[4199]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for IAX2 - 216 [Oct 23 09:28:40] DEBUG[4199]: chan_iax2.c:14472 iax2_devicestate: Checking device state for device 216 [Oct 23 09:28:40] DEBUG[4199]: chan_iax2.c:14481 iax2_devicestate: Found peer. What's device state of 216? addr=192.168.0.77:4569, defaddr=(null) maxms=2000, lastms=8 [Oct 23 09:28:40] DEBUG[4199]: devicestate.c:473 do_state_change: Changing state for IAX2/216 - state 0 (Unknown) [Oct 23 09:28:41] DEBUG[4223]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 2 for 192.168.0.10 [Oct 23 09:28:41] DEBUG[4227]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 3 for 192.168.0.10 [Oct 23 09:28:41] DEBUG[4233]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.10 in 60 seconds [Oct 23 09:28:41] DEBUG[4233]: chan_iax2.c:11157 socket_process_helper: Peer 215: got pong, lastms 34, historicms 34, maxms 2000 [Oct 23 09:28:42] DEBUG[4230]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.77 in 60 seconds [Oct 23 09:28:47] DEBUG[4228]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 3 for 192.168.0.66 [Oct 23 09:28:47] DEBUG[4228]: chan_iax2.c:2617 peercnt_modify: peercnt entry 192.168.0.66 modified limit:2048 registered:0â–’Unregistered IAX2 '222' (UNAUTHENTICATED) [Oct 23 09:28:47] DEBUG[4199]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for IAX2 - 222 [Oct 23 09:28:47] DEBUG[4199]: chan_iax2.c:14472 iax2_devicestate: Checking device state for device 222 [Oct 23 09:28:47] DEBUG[4199]: chan_iax2.c:14481 iax2_devicestate: Found peer. What's device state of 222? addr=(null), defaddr=(null) maxms=2000, lastms=0 [Oct 23 09:28:47] DEBUG[4199]: devicestate.c:473 do_state_change: Changing state for IAX2/222 - state 5 (Unavailable) [Oct 23 09:28:47] DEBUG[4242]: app_queue.c:2374 device_state_cb: Device 'IAX2/222' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue. router*CLI> pjsip show channels No objects found. router*CLI> core show channels Channel Location State Application(Data) 0 active channels 0 active calls 5193 calls processed router*CLI> exit Asterisk cleanly ending (0). Executing last minute cleanups [root@router ~]#