15:07:35.156[app:dbg]Q:NONE
15:07:35.156[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:(
(nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
15:07:35.156[app:dbg]self_on_set_media() SLIC 6: no such call / hold call! 0x206
0025
15:07:35.156[app:dbg]vapi_proc_event: VAPI_CB
15:07:35.156[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x00000401 result 0x00000000
15:07:35.156[app:dbg]vapi: conn 6. RTCP disabled
15:07:35.156[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x000004ff
15:07:35.166[app:dbg]vapi_proc_event: VAPI_CB
15:07:35.166[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x000004ff result 0x00000000
15:07:35.166[app:dbg]Conn 6: Set voice mode successeful
15:07:35.166[app:dbg]Stop all medias on chan 6
15:07:35.166[app:dbg]Mute all RX-TX medias on SLIC 6
15:07:35.166[app:dbg]Port 6: check vapi queue ('busy''set voice') at vapi_next_o
ps:2532
15:07:35.166[app:dbg]Port 6 get cmd 'destroy' from queue at (vapi_next_ops:2551)
15:07:35.166[app:dbg]VQ Conn 6 + 01  :       'destroy' (hold) + <-get_ptr
15:07:35.166[app:dbg]Port 6: check vapi queue ('free') at vapi_destroy_chan:890
15:07:35.166[app:dbg]Destroying connection 6...
15:07:35.166[app:dbg]Chan 6: current state is CREATED
15:07:35.166[app:dbg]Port 6: set vapi queue MSP to 'busy' with 'destroy' at vapi
_destroy_chan:916
15:07:35.166[app:dbg]VQ Conn 6 = MSP :       'destroy' =
15:07:35.166[app:dbg]VQ Conn 6 + 01  :       'destroy' (hold) + <-get_ptr
15:07:35.166[app:dbg]Chan 6: CREATED -> DESTROYING
15:07:35.166[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x0000014b
15:07:35.176[app:dbg]Delete all RX-TX medias from SLIC 6
15:07:35.176[app:dbg]ITC: [msg_clear] -> pbx
15:07:35.176[app:dbg]dump_port_calls() SLIC 7:
15:07:35.176[app:dbg]Q:(0x32d000,0x02070004,(nil))
15:07:35.176[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:(
(nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
15:07:35.176[app:dbg]SLIC 7: peer cleared(02070004)
15:07:35.176[app:dbg]SLIC 7: current call cleared
15:07:35.176[app:dbg]SLIC 7: -> busy - no hold call, no wait call
15:07:35.176[app:info]SLIC 7: from state 'talking' to state 'busy'
15:07:35.196[app:dbg]port_start_tone(7 22 0 0)
15:07:35.196[app:dbg]CMD_START_TONE: port = 7
15:07:35.196[app:dbg]Port 7: check vapi queue ('free') at vapi_start_tone_chan:1
384
15:07:35.196[app:dbg]Chan 7: current state is CREATED
15:07:35.196[app:dbg]Port 7: set vapi queue MSP to 'busy' with 'start_tone' at v
api_start_tone_chan:1421
15:07:35.196[app:dbg]VQ Conn 7 = MSP :    'start_tone' =
15:07:35.196[app:dbg]chan 7 start tone, id=22, direction=TDM
15:07:35.196[app:dbg]Port 7: user port 1, old state busy, new state
15:07:35.196[app:dbg]Set port 7 led to state 'LED_ON'
15:07:35.196[app:dbg]pbx -[msg_fxs_state]-> group
15:07:35.196[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x00000922
15:07:35.196[app:dbg]ITC: [msg_fxs_state] -> group
15:07:35.196[app:dbg]-----[GM] self_fxs_state()
15:07:35.196[app:dbg]Port 7: new state is busy
15:07:35.216[app:dbg]vapi: chan 7: connection STATISTIC
15:07:35.216[app:dbg]vapi: chan 7: Rx_pack = 98
15:07:35.216[app:dbg]vapi: chan 7: Rx_oct  = 16538
15:07:35.216[app:dbg]vapi: chan 7: Lost_pack  = 0
15:07:35.216[app:dbg]vapi: chan 7: Tx_pack = 127
15:07:35.216[app:dbg]vapi: chan 7: Tx_oct  = 21844
15:07:35.216[app:dbg]vapi: chan 7: peak_jiter = 11
15:07:35.216[app:dbg]SLIC 7: Common port statistic
15:07:35.216[app:dbg]SLIC 7: Rx_pack = 282999
15:07:35.216[app:dbg]SLIC 7: Rx_oct  = 47329150
15:07:35.216[app:dbg]SLIC 7: Lost_pack  = 498
15:07:35.216[app:dbg]SLIC 7: Tx_pack = 198482
15:07:35.216[app:dbg]SLIC 7: Tx_oct  = 30448561
15:07:35.216[app:dbg]SLIC 7: peak_jiter = 11
15:07:35.216[app:dbg]SLIC 7: reset call 0x02070004 (active)
15:07:35.216[app:dbg]CMD_SET_VOICE: port = 7
15:07:35.216[app:dbg]Port 7: check vapi queue ('busy''start_tone') at vapi_start
_stop_chan:1623
15:07:35.216[app:dbg]Port 7 put cmd 'set voice',cur 'start_tone' to queue at (va
pi_start_stop_chan:1630)
15:07:35.216[app:dbg]VQ Conn 7 = MSP :    'start_tone' =
15:07:35.216[app:dbg]VQ Conn 7 + 03  :     'set voice'  + <-get_ptr
15:07:35.216[app:dbg]incom_calls_set_media_started() call 0x02070004, group -1,
task <sip> media stopped
15:07:35.236[app:dbg]incom_calls_rem() rem call 0x02070004, group -1, task <sip>
 from list
15:07:35.236[app:dbg]dump_port_calls() SLIC 7:
15:07:35.236[app:dbg]Q:NONE
15:07:35.236[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:(
(nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
15:07:35.236[app:dbg]vapi_proc_event: VAPI_CB
15:07:35.236[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x0000014b result 0x00000000
15:07:35.236[app:dbg]Delete all RX-TX medias from SLIC 7
15:07:35.236[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x00000103
15:07:35.246[app:dbg]vapi_proc_event: VAPI_CB
15:07:35.246[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x00000922 result 0x00000000
15:07:35.246[app:dbg]Conn 7: Start tone - Successfull
15:07:35.246[app:dbg]Port 7: check vapi queue ('busy''start_tone') at vapi_next_
ops:2532
15:07:35.246[app:dbg]Port 7 get cmd 'set voice' from queue at (vapi_next_ops:255
1)
15:07:35.246[app:dbg]Port 7: check vapi queue ('free') at vapi_start_stop_chan:1
623
15:07:35.246[app:dbg]Chan 7: current state is CREATED
15:07:35.246[app:dbg]vapi: Conn 7. start_stop voice chan, TX stop, RX stop
15:07:35.246[app:dbg]Port 7: set vapi queue MSP to 'busy' with 'set voice' at va
pi_start_stop_chan:1666
15:07:35.246[app:dbg]VQ Conn 7 = MSP :     'set voice' =
15:07:35.246[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x00000401
15:07:35.256[app:dbg]vapi_proc_event: VAPI_CB
15:07:35.256[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x00000103 result 0x00000000
15:07:35.256[app:dbg]Conn 6 destroyed
15:07:35.256[app:dbg]Chan 6: DESTROYING -> INITIAL
15:07:35.256[app:dbg]Port 6: check vapi queue ('busy''destroy') at vapi_next_ops
:2532
15:07:35.256[app:dbg]Port 6 get cmd 'destroy' from queue at (vapi_next_ops:2551)
15:07:35.256[app:dbg]Port 6: check vapi queue ('free') at vapi_destroy_chan:890
15:07:35.256[app:dbg]Destroying connection 14...
15:07:35.256[app:dbg]Chan 14: current state is CREATED
15:07:35.256[app:dbg]Port 6: set vapi queue MSP to 'busy' with 'destroy' at vapi
_destroy_chan:916
15:07:35.256[app:dbg]VQ Conn 14 = MSP :       'destroy' =
15:07:35.256[app:dbg]Chan 14: CREATED -> DESTROYING
15:07:35.256[app:dbg]Delete all RX-TX medias from SLIC 14
15:07:35.256[app:dbg]vapi_cb_req: 14 0 result 0x00000000 requid 0x0000014b
15:07:35.266[app:dbg]vapi_proc_event: VAPI_CB
15:07:35.266[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x00000401 result 0x00000000
15:07:35.266[app:dbg]vapi: conn 7. RTCP disabled
15:07:35.266[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x000004ff
15:07:35.276[app:dbg]vapi_proc_event: VAPI_CB
15:07:35.276[app:dbg]vapi_cb_chan: chan 14 reqest_id 0x0000014b result 0x0000000
0
15:07:35.276[app:dbg]vapi_cb_req: 14 0 result 0x00000000 requid 0x00000103
15:07:35.286[app:dbg]vapi_proc_event: VAPI_CB
15:07:35.286[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x000004ff result 0x00000000
15:07:35.286[app:dbg]Conn 7: Set voice mode successeful
15:07:35.286[app:dbg]Stop all medias on chan 7
15:07:35.286[app:dbg]Port 7: check vapi queue ('busy''set voice') at vapi_next_o
ps:2532
15:07:35.286[app:dbg]Mute all RX-TX medias on SLIC 7
15:07:35.296[app:dbg]vapi_proc_event: VAPI_CB
15:07:35.296[app:dbg]vapi_cb_chan: chan 14 reqest_id 0x00000103 result 0x0000000
0
15:07:35.296[app:dbg]Conn 14 destroyed
15:07:35.296[app:dbg]Chan 14: DESTROYING -> INITIAL
15:07:35.296[app:dbg]Port 6: check vapi queue ('busy''destroy') at vapi_next_ops
:2532
15:07:36.996[sip]nta: timer I fired, terminate 200 response
15:07:36.996[sip]nta_incoming_timer: 0/0 resent, 0/0 tout, 1/3 term, 1/3 free
15:07:39.076[app:dbg]slic7. Event 8.
15:07:39.076[app:dbg]slic 7. Pre-On-hook event
15:07:39.076[app:dbg]HIO: preonhook TDM port '7', port enabled 1
15:07:39.076[app:dbg]CMD_STOP_TONE: port = 7
15:07:39.076[app:dbg]Port 7: check vapi queue ('free') at vapi_stop_tone_chan:14
74
15:07:39.076[app:dbg]Chan 7: current state is CREATED
15:07:39.076[app:dbg]Port 7: set vapi queue MSP to 'busy' with 'stop_tone' at va
pi_stop_tone_chan:1520
15:07:39.076[app:dbg]VQ Conn 7 = MSP :     'stop_tone' =
15:07:39.076[app:dbg]chan 7 stop tone
15:07:39.086[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x00000923
15:07:39.086[app:dbg]vapi_proc_event: VAPI_CB
15:07:39.086[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x00000923 result 0x00000000
15:07:39.086[app:dbg]Conn 7: Stop tone - Successfull
15:07:39.086[app:dbg]Port 7: check vapi queue ('busy''stop_tone') at vapi_next_o
ps:2532
15:07:39.096[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, co
nn 7
15:07:39.966[app:dbg]slic7. Event 1.
15:07:39.966[app:dbg]slic 7. On-hook event
15:07:39.966[app:dbg]Set port 7 led to state 'LED_OFF'
15:07:39.966[app:dbg]HIO: onhook TDM port '7', port enabled 1
15:07:39.966[app:dbg]SLIC 7 (102): onhook state: busy
15:07:39.966[app:dbg]regex ID 7: dial reset
15:07:39.966[app:info]SLIC 7: from state 'busy' to state 'hangup'
15:07:39.966[app:dbg]CMD_STOP_TONE: port = 7
15:07:39.966[app:dbg]Port 7: check vapi queue ('free') at vapi_stop_tone_chan:14
74
15:07:39.966[app:dbg]Chan 7: current state is CREATED
15:07:39.966[app:ERR]chan 7: no generated tones!
15:07:39.966[app:dbg]vapi_chan.c:1510: conn 7 peek cmd 'no event' from queue
15:07:39.966[app:dbg]Port 7: check vapi queue ('free') at __cmd_engine:320
15:07:39.966[app:dbg]Port 7: check vapi queue ('free') at vapi_next_ops:2532
15:07:39.966[app:dbg]SLIC 7: reset
15:07:39.966[app:dbg]dump_port_calls() SLIC 7:
15:07:39.966[app:dbg]Q:NONE
15:07:39.966[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:(
(nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
15:07:39.966[app:dbg]Delete all RX-TX medias from SLIC 7
15:07:39.966[app:dbg]free_final_mx: final_mx was NULL for SLIC 7
15:07:39.966[app:dbg]CMD_DESTROY_CONN: port = 7
15:07:39.966[app:dbg]Port 7: check vapi queue ('free') at vapi_destroy_chan:890
15:07:39.966[app:dbg]Destroying connection 7...
15:07:39.966[app:dbg]Chan 7: current state is CREATED
15:07:39.966[app:dbg]Port 7: set vapi queue MSP to 'busy' with 'destroy' at vapi
_destroy_chan:916
15:07:39.966[app:dbg]VQ Conn 7 = MSP :       'destroy' =
15:07:39.966[app:dbg]Chan 7: CREATED -> DESTROYING
15:07:39.966[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x0000014b
15:07:39.966[app:dbg]CMD_DESTROY_IPONLY_CONN: port = 7
15:07:39.966[app:dbg]Port 7: check vapi queue ('busy''destroy') at vapi_destroy_
chan:890
15:07:39.966[app:dbg]Clear vapi queue of Port 7/chan 15
15:07:39.966[app:dbg]Port 7 put cmd 'destroy',cur 'destroy' to queue at (vapi_de
stroy_chan:897)
15:07:39.966[app:dbg]VQ Conn 15 = MSP :       'destroy' =
15:07:39.966[app:dbg]VQ Conn 15 + 00  :       'destroy' (hold) + <-get_ptr
15:07:39.966[app:dbg]Port 7: user port 1, old state hangup, new state
15:07:39.966[app:dbg]Set port 7 led to state 'LED_OFF'
15:07:39.966[app:dbg]pbx -[msg_fxs_state]-> group
15:07:39.966[app:dbg]ITC: [msg_fxs_state] -> group
15:07:39.966[app:dbg]-----[GM] self_fxs_state()
15:07:39.966[app:dbg]Port 7: new state is hangup
15:07:39.976[app:dbg]Delete all RX-TX medias from SLIC 15
15:07:39.986[app:dbg]Delete all RX-TX medias from SLIC 7
15:07:39.986[app:dbg]dump_port_calls() SLIC 7:
15:07:39.986[app:dbg]Q:NONE
15:07:39.986[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:(
(nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
15:07:39.986[app:dbg]Set port 7 led to state 'LED_OFF'
15:07:39.996[app:dbg]vapi_proc_event: VAPI_CB
15:07:39.996[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x0000014b result 0x00000000
15:07:39.996[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x00000103
15:07:40.006[app:dbg]vapi_proc_event: VAPI_CB
15:07:40.006[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x00000103 result 0x00000000
15:07:40.006[app:dbg]Conn 7 destroyed
15:07:40.006[app:dbg]Chan 7: DESTROYING -> INITIAL
15:07:40.006[app:dbg]Port 7: check vapi queue ('busy''destroy') at vapi_next_ops
:2532
15:07:40.006[app:dbg]Port 7 get cmd 'destroy' from queue at (vapi_next_ops:2551)
15:07:40.006[app:dbg]Port 7: check vapi queue ('free') at vapi_destroy_chan:890
15:07:40.006[app:dbg]Destroying connection 15...
15:07:40.006[app:dbg]Chan 15: current state is INITIAL
15:07:40.006[app:ERR]vapi_destroy_chan() chan 15: current state initial: duplica
te destroying connection!
15:07:40.006[app:dbg]Port 7: check vapi queue ('free') at vapi_next_ops:2694
15:07:40.006[app:dbg]Port 7: check vapi queue ('free') at vapi_next_ops:2532
15:07:40.026[sip]nta: timer K fired, terminate REFER (477657)
15:07:40.026[sip]nta_outgoing_timer: 0/0 resent, 0/2 tout, 1/5 term, 1/7 free
15:07:40.106[sip]nta: timer K fired, terminate BYE (477658)
15:07:40.106[sip]nta_outgoing_timer: 0/0 resent, 0/2 tout, 1/4 term, 1/6 free
15:07:40.146[sip]nta: timer K fired, terminate BYE (477660)
15:07:40.146[sip]nta_outgoing_timer: 0/0 resent, 0/2 tout, 1/3 term, 1/5 free
15:07:46.216[sip]nta_agent: received garbage from udp/80.75.132.66:5060/sip
15:07:53.036[sip]nta: timer D fired, terminate INVITE (477656)
15:07:53.036[sip]nta: timer F fired, terminating ACK (477656)
15:07:53.036[sip]nta_outgoing_timer: 0/0 resent, 1/2 tout, 1/2 term, 2/4 free
15:07:57.346[sip]nta: timer J fired, terminate 200 response
15:07:57.346[sip]nta_incoming_timer: 0/0 resent, 0/0 tout, 1/2 term, 1/2 free
15:08:01.216[sip]nta_agent: received garbage from udp/80.75.132.66:5060/sip
15:08:03.946[sip]nta: timer D fired, terminate INVITE (477658)
15:08:03.946[sip]nta_outgoing_timer: 0/0 resent, 0/1 tout, 1/1 term, 1/2 free
15:08:03.976[sip]nta: timer F fired, terminating ACK (477658)
15:08:03.976[sip]nta_outgoing_timer: 0/0 resent, 1/1 tout, 0/0 term, 1/1 free
15:08:07.126[sip]nta: timer J fired, terminate 200 response
15:08:07.126[sip]nta_incoming_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/1 free
15:08:16.216[sip]nta_agent: received garbage from udp/80.75.132.66:5060/sip
15:08:21.996[sip]send 773 bytes to udp/[80.75.132.66]:5060 at 01:22:54.270000:
15:08:21.996[sip]   ------------------------------------------------------------
------------
15:08:21.996[sip]   REGISTER sip:80.75.132.66 SIP/2.0
15:08:21.996[sip]   Via: SIP/2.0/UDP 192.168.1.36;rport;branch=z9hG4bK81cXBFKeaj
Ugg
15:08:21.996[sip]   Max-Forwards: 70
15:08:21.996[sip]   From: <sip:883140776145071@voip.mtt.ru>;tag=H5FDUm3752eap
15:08:21.996[sip]   To: <sip:883140776145071@voip.mtt.ru>
15:08:21.996[sip]   Call-ID: 9824bf11-6107-1234-42ba-a8f94b093d27
15:08:21.996[sip]   CSeq: 417588 REGISTER
15:08:21.996[sip]   Contact: <sip:883140776145071@94.159.5.238:5060>
15:08:21.996[sip]   Expires: 300
15:08:21.996[sip]   User-Agent: TAU-8.IP/2.0.0 SN/VI33008455 sofia-sip/1.12.10
15:08:21.996[sip]   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SU
BSCRIBE, NOTIFY, REFER, UPDATE, INFO
15:08:21.996[sip]   Supported: 100rel, replaces, path
15:08:21.996[sip]   Authorization: Digest username="883140776145071", realm="80.
75.132.66", nonce="1457698021:742063111f4322e9bae9cbc8311b6021", algorithm=MD5,
uri="sip:80.75.132.66", response="e5dd97990005dcde589dbe3fb27f6c65"
15:08:21.996[sip]   Content-Length: 0
15:08:21.996[sip]
15:08:21.996[sip]   ------------------------------------------------------------
------------
15:08:21.996[sip]nta: sent REGISTER (417588) to udp/80.75.132.66:5060/sip
15:08:22.036[sip]recv 478 bytes from udp/[80.75.132.66]:5060 at 01:22:54.310000:
15:08:22.036[sip]   ------------------------------------------------------------
------------
15:08:22.036[sip]   SIP/2.0 200 OK
15:08:22.046[sip]   Via: SIP/2.0/UDP 192.168.1.36;rport=5060;branch=z9hG4bK81cXB
FKeajUgg;received=94.159.5.238
15:08:22.046[sip]   Contact: <sip:883140776145071@94.159.5.238:5060;transport=UD
P>;expires=300
15:08:22.046[sip]   To: <sip:883140776145071@voip.mtt.ru>;tag=57798979
15:08:22.046[sip]   From: <sip:883140776145071@voip.mtt.ru>;tag=H5FDUm3752eap
15:08:22.046[sip]   Call-ID: 9824bf11-6107-1234-42ba-a8f94b093d27
15:08:22.046[sip]   CSeq: 417588 REGISTER
15:08:22.046[sip]   Date: Fri, 11 Mar 2016 12:08:22 GMT
15:08:22.046[sip]   PortaBilling: available-funds:6065.44010 currency:RUB
15:08:22.046[sip]   Content-Length: 0
15:08:22.046[sip]
15:08:22.046[sip]   ------------------------------------------------------------
------------
15:08:22.046[sip]nta: received 200 OK for REGISTER (417588)
15:08:22.046[sip]nta: 200 OK is going to a transaction
15:08:22.046[sip]nua(0x339a00): event r_register 200 OK
15:08:22.046[app:dbg]got nua_r_register : 200(OK)
15:08:22.046[app:dbg]sip: group 0: REGISTER: 200 OK
15:08:22.046[app:dbg]sip: group 0: successfully registered
