08:47:48.315[sip]nta: sent ACK (34711) to */192.168.0.101:5060
08:47:48.315[sip]nua(0x36b500): call state changed: completing -> ready
08:47:48.315[sip]nua(0x36b500): event i_state 200 ACK sent
08:47:48.315[sip]nua(0x36b500): event i_active 200 Call active
08:47:48.315[app:dbg]got nua_r_set_params : 200(OK)
08:47:48.315[app:dbg]NO SIP IN nua_r_set_params == 200 : OK
08:47:48.315[app:dbg]got nua_i_state : 200(ACK sent)
08:47:48.315[app:dbg]NO SIP IN nua_i_state == 200 : ACK sent
08:47:48.315[app:dbg]self_i_state(): call state 8: : : sdp_init have_oc
08:47:48.315[app:dbg]sip: call 00040005: ACK from sip:218@192.168.0.101
08:47:48.315[app:dbg]got nua_i_active : 200(Call active)
08:47:48.315[app:dbg]NO SIP IN nua_i_active == 200 : Call active
08:47:48.315[app:dbg]vapi_proc_event: VAPI_CB
08:47:48.315[app:dbg]vapi_cb_chan: chan 5 reqest_id 0x00000510 result 0x00000000
08:47:48.315[app:dbg]VOIP_SET_PACKET2: chan = 5
08:47:48.315[app:dbg]vapi_cb_setchan: chan 5 deactivate 0
08:47:48.315[app:dbg]chan 5. vapi_cb_setchan: VOIP_SET_PACKET2
08:47:48.315[app:dbg]SET RX PT: 101
08:47:48.325[app:dbg]vapi_cb_req: 5 0 result 0x00000000 requid 0x00000513
08:47:48.325[app:dbg]vapi_proc_event: VAPI_CB
08:47:48.325[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000502 result 0x00000000
08:47:48.325[app:dbg]VOIP_DISABLE: chan = 4
08:47:48.325[app:dbg]vapi_cb_setchan: chan 4 deactivate 0
08:47:48.325[app:dbg]vapi: create: TDM channel 4 Set SSRC to 5CB59595
08:47:48.325[app:dbg]vapi: Conn 4. Set src/dst eth mac - Ok
08:47:48.325[app:dbg]Reserved IP: 192.168.253.1
08:47:48.325[app:dbg]vapi_cb_setchan: ch4. msp_ip = 192.168.253.2
08:47:48.325[app:dbg]IP PARAMS: 1FDA8C0 30152 2FDA8C0 30152
08:47:48.325[app:dbg]vapi: Conn 4. Set src/dst ip addr - ok
08:47:48.325[app:dbg]vapi_proc_event: VAPI_CB
08:47:48.325[app:dbg]vapi_cb_chan: chan 5 reqest_id 0x00000513 result 0x00000000
08:47:48.325[app:dbg]VOIP_SET_DTMFOPT: chan = 5
08:47:48.325[app:dbg]vapi_cb_setchan: chan 5 deactivate 0
08:47:48.325[app:dbg]vapi: Chan 5 set chach (packet mode)
08:47:48.325[app:dbg]chan 5. vapi_cb_setchan: VOIP_SET_DTMFOPT dtmf 1, pt 101
08:47:48.325[app:dbg]Enable RFC2833 events
08:47:48.325[app:dbg]Set RFC2833 PT: 101(01A6, 65FF)
08:47:48.325[app:dbg]chan 5. vapi_cb_setchan: VOIP_SET_DTMFOPT2
08:47:48.325[app:dbg]chan 5. vapi_cb_setchan: VOIP_SET_PT2
08:47:48.325[app:dbg]vapi: Conn 5. Enable RTP indication
08:47:48.325[app:dbg]chan 5. vapi_cb_setchan: VOIP_ENABLE_RTP_IND
08:47:48.325[app:dbg]chan 5: set jitter buffer options
08:47:48.325[app:dbg]Conn 5, JB it not MFPT, set delay to [0;200]ms, mode soft th 500
08:47:48.325[app:dbg]chan 5. vapi_cb_setchan: VOIP_SET_INDCTL
08:47:48.325[app:dbg]chan 5. vapi_cb_setchan: VOIP_SET_JBOPT
08:47:48.325[app:dbg]vapi: Conn 5. Set tone ctl options
08:47:48.325[app:dbg]chan 5. vapi_cb_setchan: VOIP_SET_VLAN
08:47:48.325[app:dbg]VAD: 1 CNG: 0 PTE: 20
08:47:48.335[app:dbg]Create RX-TX media for SLIC 4(sendonly: 0, rtcp: 0)
08:47:48.335[app:dbg]FORCE_BIND; bind msp_sock
08:47:48.335[app:dbg]bind net_sock addr = 192.168.253.1 port = 51317
08:47:48.335[app:dbg]FORCE_BIND; bind net_sock
08:47:48.335[app:dbg]bind net_sock addr = 192.168.0.217 port = 28762
08:47:48.335[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000508
08:47:48.335[app:dbg]vapi_cb_req: 5 0 result 0x00000000 requid 0x00000516
08:47:48.335[app:dbg]vapi_proc_event: VAPI_CB
08:47:48.335[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000508 result 0x00000000
08:47:48.335[app:dbg]VOIP_SET_IP: chan = 4
08:47:48.335[app:dbg]vapi_cb_setchan: chan 4 deactivate 0
08:47:48.335[app:dbg]chan 4. vapi_cb_setchan: configure ecan on
08:47:48.335[app:dbg]vapi_passthru_echocan_cb() NLP, DCRF enabled, session 0, on 1, tail 32ms, value 0x8003
08:47:48.335[app:dbg]vapi_proc_event: VAPI_CB
08:47:48.335[app:dbg]vapi_cb_chan: chan 5 reqest_id 0x00000516 result 0x00000000
08:47:48.335[app:dbg]VOIP_SET_VCEOPT: chan = 5
08:47:48.335[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000547
08:47:48.335[app:dbg]vapi_cb_setchan: chan 5 deactivate 0
08:47:48.335[app:dbg]chan 5. vapi_cb_setchan: VOIP_SET_VCEOPT
08:47:48.335[app:dbg]vapi_cb_req: 5 0 result 0x00000000 requid 0x00000518
08:47:48.335[app:dbg]vapi_proc_event: VAPI_CB
08:47:48.335[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000547 result 0x00000000
08:47:48.335[app:dbg]VOIP_SSRC_FILT: chan = 4
08:47:48.335[app:dbg]vapi_cb_setchan: chan 4 deactivate 0
08:47:48.335[app:dbg]chan 4. vapi_cb_setchan: VOIP_SSRC_FILT
08:47:48.335[app:dbg]vapi_cb_setchan: ch4. msp_ip = 192.168.253.2
08:47:48.335[app:dbg]RTCP IP PARAMS: 1FDA8C0 30153 2FDA8C0 30153
08:47:48.335[app:dbg]vapi_proc_event: VAPI_CB
08:47:48.335[app:dbg]vapi_cb_chan: chan 5 reqest_id 0x00000518 result 0x00000000
08:47:48.335[app:dbg]VOIP_SET_VOICE: chan = 5
08:47:48.335[app:dbg]vapi_cb_setchan: chan 5 deactivate 0
08:47:48.335[app:dbg]vapi_cb_setchan() Conn 5: set eActive state ok
08:47:48.335[app:dbg]Port 5: check vapi queue ('busy''start voice') at vapi_next_ops:2599
08:47:48.345[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x0000052b
08:47:48.345[app:dbg]vapi_proc_event: VAPI_CB
08:47:48.345[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x0000052b result 0x00000000
08:47:48.345[app:dbg]VOIP_SET_IP2: chan = 4
08:47:48.345[app:dbg]vapi_cb_setchan: chan 4 deactivate 0
08:47:48.345[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_PT
08:47:48.345[app:dbg]for chan <4> set codec type = 5 'G711A'
08:47:48.355[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x0000054e
08:47:48.355[app:dbg]vapi_proc_event: VAPI_CB
08:47:48.355[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x0000054e result 0x00000000
08:47:48.355[app:dbg]VOIP_SET_ADAPTATION_CODEC: chan = 4
08:47:48.355[app:dbg]vapi_cb_setchan: chan 4 deactivate 0
08:47:48.355[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_CODEC
08:47:48.355[app:dbg]set_packet_interval = 20
08:47:48.355[app:dbg]vapi: Conn 4. Set 'Packet interval' 20
08:47:48.355[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_PACKET
08:47:48.355[app:dbg]SET TX PT: 101
08:47:48.355[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000510
08:47:48.355[app:dbg]vapi_proc_event: VAPI_CB
08:47:48.355[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000510 result 0x00000000
08:47:48.355[app:dbg]VOIP_SET_PACKET2: chan = 4
08:47:48.355[app:dbg]vapi_cb_setchan: chan 4 deactivate 0
08:47:48.355[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_PACKET2
08:47:48.355[app:dbg]SET RX PT: 101
08:47:48.355[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000513
08:47:48.355[app:dbg]vapi_proc_event: VAPI_CB
08:47:48.355[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000513 result 0x00000000
08:47:48.355[app:dbg]VOIP_SET_DTMFOPT: chan = 4
08:47:48.355[app:dbg]vapi_cb_setchan: chan 4 deactivate 0
08:47:48.355[app:dbg]vapi: Chan 4 set chach (packet mode)
08:47:48.355[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_DTMFOPT dtmf 1, pt 101
08:47:48.355[app:dbg]Enable RFC2833 events
08:47:48.355[app:dbg]Set RFC2833 PT: 101(01A6, 65FF)
08:47:48.355[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_DTMFOPT2
08:47:48.355[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_PT2
08:47:48.355[app:dbg]vapi: Conn 4. Enable RTP indication
08:47:48.355[app:dbg]chan 4. vapi_cb_setchan: VOIP_ENABLE_RTP_IND
08:47:48.355[app:dbg]chan 4: set jitter buffer options
08:47:48.355[app:dbg]Conn 4, JB it not MFPT, set delay to [0;200]ms, mode soft th 500
08:47:48.355[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_INDCTL
08:47:48.355[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_JBOPT
08:47:48.355[app:dbg]vapi: Conn 4. Set tone ctl options
08:47:48.355[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_VLAN
08:47:48.355[app:dbg]VAD: 1 CNG: 0 PTE: 20
08:47:48.355[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000516
08:47:48.355[app:dbg]vapi_proc_event: VAPI_CB
08:47:48.355[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000516 result 0x00000000
08:47:48.365[app:dbg]VOIP_SET_VCEOPT: chan = 4
08:47:48.365[app:dbg]vapi_cb_setchan: chan 4 deactivate 0
08:47:48.365[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_VCEOPT
08:47:48.365[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000518
08:47:48.365[app:dbg]vapi_proc_event: VAPI_CB
08:47:48.365[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000518 result 0x00000000
08:47:48.365[app:dbg]VOIP_SET_VOICE: chan = 4
08:47:48.365[app:dbg]vapi_cb_setchan: chan 4 deactivate 0
08:47:48.365[app:dbg]vapi_cb_setchan() Conn 4: set eActive state ok
08:47:48.365[app:dbg]Port 4: check vapi queue ('busy''start voice') at vapi_next_ops:2599
08:47:48.365[app:dbg]VQ Conn 4 + 06  :     'stop_tone'  + <-get_ptr 
08:47:48.375[app:dbg]Port 4 get cmd 'stop_tone' from queue at (vapi_next_ops:2618)
08:47:48.375[app:dbg]Port 4: check vapi queue ('free') at vapi_stop_tone_chan:1503
08:47:48.375[app:dbg]Chan 4: current state is CREATED
08:47:48.375[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'stop_tone' at vapi_stop_tone_chan:1549
08:47:48.375[app:dbg]VQ Conn 4 = MSP :     'stop_tone' =
08:47:48.375[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000923
08:47:48.375[app:dbg]chan 4 stop tone
08:47:48.375[app:dbg]vapi: Conn 4. event 'RTP Monitor Ind': Start RTP stream , PT 0x0008 'PCM-A', silence 0
08:47:48.375[app:dbg]vapi: generic event, code 5 <SSRC change>, conn 0
08:47:48.375[app:dbg]vapi_proc_event: VAPI_CB
08:47:48.375[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000923 result 0x00000000
08:47:48.375[app:dbg]Conn 4: Stop tone - Successfull
08:47:48.375[app:dbg]Port 4: check vapi queue ('busy''stop_tone') at vapi_next_ops:2599
08:47:48.415[app:dbg]vapi: Conn 5. event 'RTP Monitor Ind': Start RTP stream , PT 0x0008 'PCM-A', silence 0
08:47:48.415[app:dbg]vapi: generic event, code 5 <SSRC change>, conn 0
08:47:50.185[app:dbg]slic4. Event 8.
08:47:50.185[app:dbg]slic 4. Pre-On-hook event
08:47:50.185[app:dbg]HIO: preonhook TDM port '4', port enabled 1
08:47:51.115[app:dbg]slic4. Event 1.
08:47:51.115[app:dbg]slic 4. On-hook event
08:47:51.115[app:dbg]Set port 4 led to state 'LED_OFF'
08:47:51.115[app:dbg]HIO: onhook TDM port '4', port enabled 1
08:47:51.115[app:dbg]SLIC 4 (218): onhook state: talking
08:47:51.115[app:dbg]regex ID 4: dial reset
08:47:51.115[app:WARN]SLIC 4: onhook in talking -> connect A & C!
08:47:51.115[app:dbg]SLIC 4: hold current call
08:47:51.115[app:dbg]is_local_call: check call 02040004(333@192.168.0.101)
08:47:51.115[app:dbg]is_local_call: check call 00040005(219@)
08:47:51.115[app:dbg]pbx -[msg_flash]-> sip
08:47:51.115[app:dbg]ITC: [msg_flash] -> sip
08:47:51.115[app:dbg]sip: call 00040005: endpoint 4: flash
08:47:51.115[app:info]SLIC 4: from state 'talking' to state 'dvo'
08:47:51.115[app:dbg]Port 4: user port 2, old state holding, new state dvo
08:47:51.115[app:dbg]Set port 4 led to state 'LED_ON'
08:47:51.115[app:dbg]pbx -[msg_fxs_state]-> group
08:47:51.115[app:dbg]ITC: [msg_fxs_state] -> group
08:47:51.115[app:dbg]-----[GM] self_fxs_state()
08:47:51.115[app:dbg]Port 4: new state is dvo
08:47:51.115[app:dbg]SLIC 4: -> transfer call to sip/:0/219, pt 20
08:47:51.115[app:dbg]is_local_call: check call 02040004(333@192.168.0.101)
08:47:51.115[app:dbg]is_local_call: check call 00040005(219@)
08:47:51.115[app:dbg]pbx -[msg_transfer]-> sip
08:47:51.115[app:dbg]ITC: [msg_transfer] -> sip
08:47:51.115[app:dbg]sip: transfer call 02040004 from endpoint 4
08:47:51.115[app:dbg]sip_params_create() normal - using cur proxy [192.168.0.101:5060] if proxy call
08:47:51.115[app:dbg]stun_get_public_ip(port = 8000)
08:47:51.115[app:dbg]stun_get_public_ip: Always using local IP
08:47:51.115[app:dbg]sip: to host is <(null)> - should not have port; to user is <(null)>, use proxy - yes
08:47:51.115[app:dbg]sip -[msg_set_media]-> pbx
08:47:51.115[app:dbg]sip: call 02040004: REFER to sip:192.168.0.101:5060?Replaces=888c97e7-e062-1234-c2b8-a8
f94b0e6be9%3bto-tag%3d15988%3bfrom-tag%3dN0mgg8NB18DNF
08:47:51.115[sip]nua(0x396a00): recv signal r_refer
08:47:51.115[sip]nua(0x396a00): adding subscribe usage with event refer
08:47:51.115[sip]send 725 bytes to udp/[192.168.0.101]:5060 at 19:17:05.730000:
08:47:51.115[sip]   ------------------------------------------------------------------------
08:47:51.115[sip]   REFER sip:192.168.0.101:5060 SIP/2.0
08:47:51.115[sip]   Via: SIP/2.0/UDP 192.168.0.217;rport;branch=z9hG4bK4Dr4Q37aKv3pa
08:47:51.115[sip]   Max-Forwards: 70
08:47:51.115[sip]   From: <sip:218@192.168.0.101>;tag=mQUQeD573ZQ2K
08:47:51.115[sip]   To: "Zakurakin" <sip:333@192.168.0.101>;tag=24653
08:47:51.115[sip]   Call-ID: 000071fe-35218c5e43d710009c860080f0a4b6a0@192.168.0.101
08:47:51.115[sip]   CSeq: 34710 REFER
08:47:51.115[sip]   Contact: <sip:218@192.168.0.217:5060>
08:47:51.115[sip]   User-Agent: TAU-8.IP/2.1.0 SN/VI33023837 sofia-sip/1.12.10
08:47:51.115[sip]   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDA
TE, INFO
08:47:51.115[sip]   Supported: timer, 100rel, replaces
08:47:51.125[sip]   Refer-To: <sip:192.168.0.101:5060?Replaces=888c97e7-e062-1234-c2b8-a8f94b0e6be9%3bto-tag
%3d15988%3bfrom-tag%3dN0mgg8NB18DNF>
08:47:51.125[sip]   Referred-By: <sip:218@192.168.0.101>
08:47:51.125[sip]   Content-Length: 0
08:47:51.125[sip]   
08:47:51.125[sip]   ------------------------------------------------------------------------
08:47:51.125[sip]nta: sent REFER (34710) to */192.168.0.101:5060
08:47:51.125[sip]nua(0x396a00): event r_refer 100 Trying
08:47:51.125[app:dbg]got nua_r_refer : 100(Trying)
08:47:51.125[app:dbg]NO SIP IN nua_r_refer == 100 : Trying
08:47:51.125[app:WARN]sip: call 02040004: REFER: 100 Trying
08:47:51.125[app:dbg]sip: call 02040004: Proxy 100 wait 202 Accepted
08:47:51.135[app:info]SLIC 4: from state 'dvo' to state 'hangup'
08:47:51.135[app:dbg]CMD_STOP_TONE: port = 4
08:47:51.135[app:dbg]Port 4: check vapi queue ('free') at vapi_stop_tone_chan:1503
08:47:51.135[app:dbg]Chan 4: current state is CREATED
08:47:51.135[app:ERR]chan 4: no generated tones!
08:47:51.135[app:dbg]vapi_chan.c:1539: conn 4 peek cmd 'no event' from queue
08:47:51.135[app:dbg]Port 4: check vapi queue ('free') at __cmd_engine:321
08:47:51.135[app:dbg]Port 4: check vapi queue ('free') at vapi_next_ops:2599
08:47:51.135[app:dbg]SLIC 4: reset
08:47:51.135[app:dbg]dump_port_calls() SLIC 4:
08:47:51.135[app:dbg]Q:(0x31a800,0x00040005,(nil))
08:47:51.135[app:dbg]H:(0x31cc00,0x02040004,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H
2:((nil),0x00000000,(nil))
08:47:51.135[app:dbg]vapi: chan 4: connection STATISTIC
08:47:51.135[app:dbg]vapi: chan 4: Rx_pack = 37
08:47:51.135[app:dbg]vapi: chan 4: Rx_oct  = 5410
08:47:51.135[app:dbg]vapi: chan 4: Lost_pack  = 0
08:47:51.135[app:dbg]vapi: chan 4: Tx_pack = 80
08:47:51.135[app:dbg]vapi: chan 4: Tx_oct  = 13283
08:47:51.135[app:dbg]vapi: chan 4: peak_jiter = 10
08:47:51.135[app:dbg]SLIC 4: Common port statistic
08:47:51.135[app:dbg]SLIC 4: Rx_pack = 10055
08:47:51.135[app:dbg]SLIC 4: Rx_oct  = 1718171
08:47:51.135[app:dbg]SLIC 4: Lost_pack  = 0
08:47:51.135[app:dbg]SLIC 4: Tx_pack = 7895
08:47:51.135[app:dbg]SLIC 4: Tx_oct  = 1264307
08:47:51.135[app:dbg]SLIC 4: peak_jiter = 10
08:47:51.135[app:dbg]SLIC 4: reset call 0x00040005 (active)
08:47:51.135[app:dbg]CMD_SET_VOICE: port = 4
08:47:51.135[app:dbg]Port 4: check vapi queue ('free') at vapi_start_stop_chan:1652
08:47:51.135[app:dbg]Chan 4: current state is CREATED
08:47:51.135[app:dbg]vapi: Conn 4. start_stop voice chan, TX stop, RX stop
08:47:51.135[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'set voice' at vapi_start_stop_chan:1695
08:47:51.135[app:dbg]VQ Conn 4 = MSP :     'set voice' =
08:47:51.135[app:dbg]vapi: chan 4: connection STATISTIC
08:47:51.135[app:dbg]vapi: chan 4: Rx_pack = 549
08:47:51.135[app:dbg]vapi: chan 4: Rx_oct  = 94428
08:47:51.135[app:dbg]vapi: chan 4: Lost_pack  = 0
08:47:51.135[app:dbg]vapi: chan 4: Tx_pack = 736
08:47:51.135[app:dbg]vapi: chan 4: Tx_oct  = 123094
08:47:51.135[app:dbg]vapi: chan 4: peak_jiter = 24
08:47:51.135[app:dbg]SLIC 4: Common port statistic
08:47:51.135[app:dbg]SLIC 4: Rx_pack = 10604
08:47:51.135[app:dbg]SLIC 4: Rx_oct  = 1812599
08:47:51.135[app:dbg]SLIC 4: Lost_pack  = 0
08:47:51.135[app:dbg]SLIC 4: Tx_pack = 8631
08:47:51.135[app:dbg]SLIC 4: Tx_oct  = 1387401
08:47:51.135[app:dbg]SLIC 4: peak_jiter = 24
08:47:51.135[app:dbg]SLIC 4: reset call 0x02040004 (hold)
08:47:51.135[app:dbg]CMD_SET_IPONLY_VOICE: port = 4
08:47:51.135[app:dbg]Port 4: check vapi queue ('busy''set voice') at vapi_start_stop_chan:1652
08:47:51.135[app:dbg]Port 4 put cmd 'set voice',cur 'set voice' to queue at (vapi_start_stop_chan:1659)
08:47:51.135[app:dbg]VQ Conn 12 = MSP :     'set voice' =
08:47:51.135[app:dbg]VQ Conn 12 + 07  :     'set voice' (hold) + <-get_ptr 
08:47:51.135[app:dbg]incom_calls_set_media_started() call 0x02040004, group -1, task <sip> media stopped
08:47:51.135[app:dbg]CMD_DESTROY_IPONLY_CONN: port = 4
08:47:51.135[app:dbg]Port 4: check vapi queue ('busy''set voice') at vapi_destroy_chan:895
08:47:51.135[app:dbg]Clear vapi queue of Port 4/chan 12
08:47:51.135[app:dbg]Port 4 put cmd 'destroy',cur 'set voice' to queue at (vapi_destroy_chan:902)
08:47:51.135[app:dbg]VQ Conn 12 = MSP :     'set voice' =
08:47:51.135[app:dbg]VQ Conn 12 + 00  :       'destroy' (hold) + <-get_ptr 
08:47:51.135[app:dbg]incom_calls_rem() rem call 0x02040004, group -1, task <sip> from list
08:47:51.135[app:dbg]free_final_mx: final_mx was NULL for SLIC 4
08:47:51.135[app:dbg]CMD_DESTROY_CONN: port = 4
08:47:51.135[app:dbg]Port 4: check vapi queue ('busy''set voice') at vapi_destroy_chan:895
08:47:51.135[app:dbg]Clear vapi queue of Port 4/chan 4
08:47:51.135[app:dbg]Port 4 put cmd 'destroy',cur 'set voice' to queue at (vapi_destroy_chan:902)
08:47:51.135[app:dbg]VQ Conn 4 = MSP :     'set voice' =
08:47:51.135[app:dbg]VQ Conn 4 + 00  :       'destroy' (hold) + <-get_ptr 
08:47:51.135[app:dbg]VQ Conn 4 + 01  :       'destroy'  +  
08:47:51.135[app:dbg]CMD_DESTROY_IPONLY_CONN: port = 4
08:47:51.135[app:dbg]Port 4: check vapi queue ('busy''set voice') at vapi_destroy_chan:895
08:47:51.135[app:dbg]Clear vapi queue of Port 4/chan 12
08:47:51.135[app:dbg]Port 4 put cmd 'destroy',cur 'set voice' to queue at (vapi_destroy_chan:902)
08:47:51.135[app:dbg]VQ Conn 12 = MSP :     'set voice' =
08:47:51.135[app:dbg]VQ Conn 12 + 00  :       'destroy'  + <-get_ptr 
08:47:51.135[app:dbg]VQ Conn 12 + 01  :       'destroy' (hold) +  
08:47:51.135[app:dbg]Port 4: user port 2, old state hangup, new state 
08:47:51.135[app:dbg]Set port 4 led to state 'LED_OFF'
08:47:51.135[app:dbg]pbx -[msg_fxs_state]-> group
08:47:51.135[app:dbg]dump_port_calls() SLIC 4:
08:47:51.135[app:dbg]Q:NONE
08:47:51.135[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:(
(nil),0x00000000,(nil))
08:47:51.145[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000401
08:47:51.145[app:dbg]ITC: [msg_fxs_state] -> group
08:47:51.145[app:dbg]-----[GM] self_fxs_state()
08:47:51.145[app:dbg]Port 4: new state is hangup
08:47:51.145[app:dbg]Delete all RX-TX medias from SLIC 4
08:47:51.145[app:dbg]Set port 4 led to state 'LED_OFF'
08:47:51.145[app:dbg]ITC: [msg_set_media] -> pbx
08:47:51.145[app:dbg]self_on_set_media: call id 0x02040004 tx/rx 0/-1
08:47:51.145[app:dbg]dump_port_calls() SLIC 4:
08:47:51.145[app:dbg]Q:NONE
08:47:51.145[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:(
(nil),0x00000000,(nil))
08:47:51.145[app:dbg]self_on_set_media() SLIC 4: no such call / hold call! 0x2040004
08:47:51.145[app:dbg]vapi_proc_event: VAPI_CB
08:47:51.145[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000401 result 0x00000000
08:47:51.145[app:dbg]vapi: conn 4. RTCP disabled
08:47:51.145[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x000004ff
08:47:51.145[app:dbg]vapi_proc_event: VAPI_CB
08:47:51.145[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x000004ff result 0x00000000
08:47:51.145[app:dbg]Conn 4: Set voice mode successeful
08:47:51.145[app:dbg]Stop all medias on chan 4
08:47:51.145[app:dbg]Port 4: check vapi queue ('busy''set voice') at vapi_next_ops:2599
08:47:51.145[app:dbg]Port 4 get cmd 'destroy' from queue at (vapi_next_ops:2618)
08:47:51.145[app:dbg]VQ Conn 4 + 01  :       'destroy' (hold) + <-get_ptr 
08:47:51.145[app:dbg]Port 4: check vapi queue ('free') at vapi_destroy_chan:895
08:47:51.145[app:dbg]Destroying connection 4...
08:47:51.145[app:dbg]Chan 4: current state is CREATED
08:47:51.145[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'destroy' at vapi_destroy_chan:921
08:47:51.145[app:dbg]VQ Conn 4 = MSP :       'destroy' =
08:47:51.145[app:dbg]VQ Conn 4 + 01  :       'destroy' (hold) + <-get_ptr 
08:47:51.145[app:dbg]Chan 4: CREATED -> DESTROYING
08:47:51.155[app:dbg]Delete all RX-TX medias from SLIC 12
08:47:51.155[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x0000014b
08:47:51.155[sip]recv 304 bytes from udp/[192.168.0.101]:5060 at 19:17:05.770000:
08:47:51.155[sip]   ------------------------------------------------------------------------
08:47:51.155[sip]   SIP/2.0 501 Not Implemented
08:47:51.155[sip]   Via: SIP/2.0/UDP 192.168.0.217;branch=z9hG4bK4Dr4Q37aKv3pa;rport=5060
08:47:51.155[sip]   To: "Zakurakin" <sip:333@192.168.0.101>;tag=24653
08:47:51.155[sip]   From: sip:218@192.168.0.101;tag=mQUQeD573ZQ2K
08:47:51.155[sip]   Call-ID: 000071fe-35218c5e43d710009c860080f0a4b6a0@192.168.0.101
08:47:51.155[sip]   CSeq: 34710 REFER
08:47:51.155[sip]   Content-Length: 0
08:47:51.155[sip]   
08:47:51.155[sip]   ------------------------------------------------------------------------
08:47:51.155[sip]nta: received 501 Not Implemented for REFER (34710)
08:47:51.155[sip]nta: 501 Not Implemented is going to a transaction
08:47:51.155[sip]nua(0x396a00): event r_refer 501 Not Implemented
08:47:51.155[sip]nua(0x396a00): removing subscribe usage with event refer
08:47:51.155[sip]nua(0x396a00): handle with session and 
08:47:51.155[app:dbg]got nua_r_refer : 501(Not Implemented)
08:47:51.155[app:WARN]sip: call 02040004: REFER: 501 Not Implemented
08:47:51.155[app:WARN]sip: call 02040004: Transfer failed
08:47:51.155[app:dbg]sip: call ffffffff: BYE to sip:218@192.168.0.101
08:47:51.155[sip]nua: nua_r_bye with invalid handle 0x302600
08:47:51.155[app:dbg]sip: call ffffffff: BYE to sip:218@192.168.0.101
08:47:51.155[sip]nua: nua_r_bye with invalid handle 0x333f00
08:47:51.155[app:dbg]sip: call ffffffff: BYE to sip:218@192.168.0.101
08:47:51.155[sip]nua: nua_r_bye with invalid handle 0x395400
08:47:51.155[app:dbg]sip: call ffffffff: BYE to sip:218@192.168.0.101
08:47:51.155[sip]nua: nua_r_bye with invalid handle 0x36ea00
08:47:51.155[app:dbg]sip: call ffffffff: BYE to sip:218@192.168.0.101
08:47:51.155[sip]nua: nua_r_bye with invalid handle 0x331b00
08:47:51.155[app:dbg]sip: call ffffffff: BYE to sip:218@192.168.0.101
08:47:51.155[app:dbg]sip: call 02040004: BYE to sip:333@192.168.0.101
08:47:51.155[app:dbg]sip: call 00040005: BYE to sip:219@192.168.0.101
08:47:51.165[app:dbg]vapi_proc_event: VAPI_CB
08:47:51.165[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x0000014b result 0x00000000
08:47:51.165[sip]nua(0x391500): recv signal r_bye
08:47:51.165[sip]nua(0x391500): event r_bye 900 Invalid handle for BYE
08:47:51.165[app:dbg]got nua_r_bye : 900(Invalid handle for BYE)
08:47:51.165[app:dbg]NO SIP IN nua_r_bye == 900 : Invalid handle for BYE
08:47:51.165[app:dbg]sip: call ffffffff: BYE/INFO: 900 Invalid handle for BYE
08:47:51.165[sip]nua(0x396a00): recv signal r_bye
08:47:51.165[sip]send 671 bytes to udp/[192.168.0.101]:5060 at 19:17:05.780000:
08:47:51.165[sip]   ------------------------------------------------------------------------
08:47:51.165[sip]   BYE sip:192.168.0.101:5060 SIP/2.0
08:47:51.165[sip]   Via: SIP/2.0/UDP 192.168.0.217;rport;branch=z9hG4bK5pHXSyreg5S9N
08:47:51.165[sip]   Max-Forwards: 70
08:47:51.165[sip]   From: <sip:218@192.168.0.101>;tag=mQUQeD573ZQ2K
08:47:51.165[sip]   To: "Zakurakin" <sip:333@192.168.0.101>;tag=24653
08:47:51.165[sip]   Call-ID: 000071fe-35218c5e43d710009c860080f0a4b6a0@192.168.0.101
08:47:51.165[sip]   CSeq: 34711 BYE
08:47:51.165[sip]   Contact: <sip:218@192.168.0.217:5060>
08:47:51.165[sip]   User-Agent: TAU-8.IP/2.1.0 SN/VI33023837 sofia-sip/1.12.10
08:47:51.165[sip]   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDA
TE, INFO
08:47:51.165[sip]   Supported: timer, 100rel, replaces
08:47:51.165[sip]   Reason: Q.850;cause=16;text="Normal call clearing"
08:47:51.165[sip]   Content-Length: 0
08:47:51.165[sip]   P-RTP-Stat: PS=682, OS=113806, PR=549, OR=94428, PL=0, JI=24
08:47:51.165[sip]   
08:47:51.165[sip]   ------------------------------------------------------------------------
08:47:51.165[sip]nta: sent BYE (34711) to */192.168.0.101:5060
08:47:51.165[sip]nua(0x36b500): recv signal r_bye
08:47:51.175[app:dbg]Mute all RX-TX medias on SLIC 4
08:47:51.165[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000103
08:47:51.175[app:dbg]vapi_proc_event: VAPI_CB
08:47:51.175[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000103 result 0x00000000
08:47:51.175[app:dbg]Conn 4 destroyed
08:47:51.175[app:dbg]Chan 4: DESTROYING -> INITIAL
08:47:51.175[app:dbg]Port 4: check vapi queue ('busy''destroy') at vapi_next_ops:2599
08:47:51.175[app:dbg]Port 4 get cmd 'destroy' from queue at (vapi_next_ops:2618)
08:47:51.175[app:dbg]Port 4: check vapi queue ('free') at vapi_destroy_chan:895
08:47:51.175[app:dbg]Destroying connection 12...
08:47:51.175[app:dbg]Chan 12: current state is CREATED
08:47:51.175[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'destroy' at vapi_destroy_chan:921
08:47:51.175[app:dbg]VQ Conn 12 = MSP :       'destroy' =
08:47:51.175[app:dbg]Chan 12: CREATED -> DESTROYING
08:47:51.175[sip]send 844 bytes to udp/[192.168.0.101]:5060 at 19:17:05.790000:
08:47:51.175[sip]   ------------------------------------------------------------------------
08:47:51.175[sip]   BYE sip:192.168.0.101:5060 SIP/2.0
08:47:51.175[sip]   Via: SIP/2.0/UDP 192.168.0.217;rport;branch=z9hG4bK6ZapUS9HDegvH
08:47:51.175[sip]   Max-Forwards: 70
08:47:51.175[sip]   From: "218" <sip:218@192.168.0.101>;tag=N0mgg8NB18DNF
08:47:51.175[sip]   To: <sip:219@192.168.0.101>;tag=15988
08:47:51.175[sip]   Call-ID: 888c97e7-e062-1234-c2b8-a8f94b0e6be9
08:47:51.175[sip]   CSeq: 34712 BYE
08:47:51.175[sip]   Contact: <sip:218@192.168.0.217:5060>
08:47:51.175[sip]   User-Agent: TAU-8.IP/2.1.0 SN/VI33023837 sofia-sip/1.12.10
08:47:51.175[sip]   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDA
TE, INFO
08:47:51.175[sip]   Supported: timer, 100rel, replaces
08:47:51.175[sip]   Proxy-Authorization: Digest username="218", realm="Registered Users", nonce="c3860c19326
4c89123468d1a3468d1a2", algorithm=MD5, uri="sip:192.168.0.101:5060", response="8456555d848a7d50a8e5a795036bb
b2b"
08:47:51.175[sip]   Reason: Q.850;cause=16;text="Normal call clearing"
08:47:51.175[sip]   Content-Length: 0
08:47:51.175[sip]   P-RTP-Stat: PS=80, OS=13283, PR=37, OR=5410, PL=0, JI=10
08:47:51.175[sip]   
08:47:51.175[sip]   ------------------------------------------------------------------------
08:47:51.175[sip]nta: sent BYE (34712) to */192.168.0.101:5060
08:47:51.185[app:dbg]Delete all RX-TX medias from SLIC 4
08:47:51.185[app:dbg]vapi_cb_req: 12 0 result 0x00000000 requid 0x0000014b
08:47:51.185[app:dbg]vapi_proc_event: VAPI_CB
08:47:51.185[app:dbg]vapi_cb_chan: chan 12 reqest_id 0x0000014b result 0x00000000
08:47:51.185[app:dbg]vapi_cb_req: 12 0 result 0x00000000 requid 0x00000103
08:47:51.185[app:dbg]vapi_proc_event: VAPI_CB
08:47:51.185[app:dbg]vapi_cb_chan: chan 12 reqest_id 0x00000103 result 0x00000000
08:47:51.185[app:dbg]Conn 12 destroyed
08:47:51.185[app:dbg]Chan 12: DESTROYING -> INITIAL
08:47:51.185[app:dbg]Port 4: check vapi queue ('busy''destroy') at vapi_next_ops:2599
08:47:51.195[app:dbg]Delete all RX-TX medias from SLIC 12
08:47:51.195[sip]recv 289 bytes from udp/[192.168.0.101]:5060 at 19:17:05.810000:
08:47:51.195[sip]   ------------------------------------------------------------------------
08:47:51.195[sip]   SIP/2.0 200 OK
08:47:51.195[sip]   Via: SIP/2.0/UDP 192.168.0.217;branch=z9hG4bK5pHXSyreg5S9N;rport=5060
08:47:51.195[sip]   To: "Zakurakin" <sip:333@192.168.0.101>;tag=24653
08:47:51.195[sip]   From: sip:218@192.168.0.101;tag=mQUQeD573ZQ2K
08:47:51.195[sip]   Call-ID: 000071fe-35218c5e43d710009c860080f0a4b6a0@192.168.0.101
08:47:51.195[sip]   CSeq: 34711 BYE
08:47:51.195[sip]   Content-Length: 0
08:47:51.195[sip]   
08:47:51.195[sip]   ------------------------------------------------------------------------
08:47:51.195[sip]nta: received 200 OK for BYE (34711)
08:47:51.195[sip]nta: 200 OK is going to a transaction
08:47:51.195[sip]nua(0x396a00): event r_bye 200 OK
08:47:51.195[app:dbg]got nua_r_bye : 200(OK)
08:47:51.195[app:dbg]sip: call 02040004: BYE/INFO: 200 OK
08:47:51.195[sip]nua(0x396a00): call state changed: terminating -> terminated
08:47:51.195[sip]nua(0x396a00): event i_state 200 to BYE
08:47:51.195[app:dbg]got nua_i_state : 200(to BYE)
08:47:51.195[app:dbg]NO SIP IN nua_i_state == 200 : to BYE
08:47:51.195[app:dbg]self_i_state(): call state 10: : : sdp_init have_oc
08:47:51.195[app:dbg]sip: call 02040004: terminated
08:47:51.195[app:dbg]self_callstate_terminated: call id = 02040004 need_exchange_at_answer = 0
08:47:51.195[sip]nua(0x396a00): event i_terminated 200 to BYE
08:47:51.195[sip]nua(0x396a00): removing session usage
08:47:51.195[sip]nua: terminated session 0x396a00
08:47:51.195[sip]nua(0x396a00): recv signal r_destroy
08:47:51.215[sip]recv 264 bytes from udp/[192.168.0.101]:5060 at 19:17:05.830000:
08:47:51.215[sip]   ------------------------------------------------------------------------
08:47:51.215[sip]   SIP/2.0 200 OK
08:47:51.215[sip]   Via: SIP/2.0/UDP 192.168.0.217;branch=z9hG4bK6ZapUS9HDegvH;rport=5060
08:47:51.215[sip]   To: sip:219@192.168.0.101;tag=15988
08:47:51.215[sip]   From: "218" <sip:218@192.168.0.101>;tag=N0mgg8NB18DNF
08:47:51.215[sip]   Call-ID: 888c97e7-e062-1234-c2b8-a8f94b0e6be9
08:47:51.215[sip]   CSeq: 34712 BYE
08:47:51.215[sip]   Content-Length: 0
08:47:51.215[sip]   
08:47:51.215[sip]   ------------------------------------------------------------------------
08:47:51.215[sip]nta: received 200 OK for BYE (34712)
08:47:51.215[sip]nta: 200 OK is going to a transaction
08:47:51.215[sip]nua(0x36b500): event r_bye 200 OK
08:47:51.215[app:dbg]got nua_r_bye : 200(OK)
08:47:51.215[app:dbg]sip: call 00040005: BYE/INFO: 200 OK
08:47:51.215[sip]nua(0x36b500): call state changed: terminating -> terminated
08:47:51.215[sip]nua(0x36b500): event i_state 200 to BYE
08:47:51.215[app:dbg]got nua_i_state : 200(to BYE)
08:47:51.215[app:dbg]NO SIP IN nua_i_state == 200 : to BYE
08:47:51.215[app:dbg]self_i_state(): call state 10: : : sdp_init have_oc
08:47:51.215[app:dbg]sip: call 00040005: terminated
08:47:51.215[app:dbg]self_callstate_terminated: call id = 00040005 need_exchange_at_answer = 0
08:47:51.215[sip]nua(0x36b500): event i_terminated 200 to BYE
08:47:51.215[sip]nua(0x36b500): removing session usage
08:47:51.215[sip]nua: terminated session 0x36b500
08:47:51.215[sip]nua(0x36b500): recv signal r_destroy
08:47:51.225[sip]recv 354 bytes from udp/[192.168.0.101]:5060 at 19:17:05.840000:
08:47:51.225[sip]   ------------------------------------------------------------------------
08:47:51.225[sip]   BYE sip:219@192.168.0.217:5060 SIP/2.0
08:47:51.225[sip]   Via: SIP/2.0/UDP 192.168.0.101:5060;branch=z9hG4bK000030eb
08:47:51.225[sip]   Max-Forwards: 70
08:47:51.225[sip]   To: sip:219@192.168.0.101;tag=Qj71KyQjUtttp
08:47:51.225[sip]   From: "Potapova" <sip:218@192.168.0.101>;tag=31432
08:47:51.225[sip]   Call-ID: 00005ec7-35218c5e2abe10009c870080f0a4b6a0@192.168.0.101
08:47:51.225[sip]   CSeq: 3 BYE
08:47:51.225[sip]   Allow: INVITE,ACK,CANCEL,BYE,REGISTER
08:47:51.225[sip]   Content-Length: 0
08:47:51.225[sip]   
08:47:51.225[sip]   ------------------------------------------------------------------------
08:47:51.225[sip]nta: received BYE sip:219@192.168.0.217:5060 SIP/2.0 (CSeq 3)
08:47:51.225[sip]nta: BYE (3) going to existing leg
08:47:51.225[sip]nua(0x331a00): event i_bye 100 Trying
08:47:51.225[app:dbg]got nua_i_bye : 100(Trying)
08:47:51.225[sip]nua(0x331a00): recv signal r_respond 200 OK
08:47:51.225[sip]send 524 bytes to udp/[192.168.0.101]:5060 at 19:17:05.840000:
08:47:51.225[sip]   ------------------------------------------------------------------------
08:47:51.225[sip]   SIP/2.0 200 OK
08:47:51.225[sip]   Via: SIP/2.0/UDP 192.168.0.101:5060;branch=z9hG4bK000030eb
08:47:51.225[sip]   From: "Potapova" <sip:218@192.168.0.101>;tag=31432
08:47:51.225[sip]   To: sip:219@192.168.0.101;tag=Qj71KyQjUtttp
08:47:51.225[sip]   Call-ID: 00005ec7-35218c5e2abe10009c870080f0a4b6a0@192.168.0.101
08:47:51.225[sip]   CSeq: 3 BYE
08:47:51.225[sip]   User-Agent: TAU-8.IP/2.1.0 SN/VI33023837 sofia-sip/1.12.10
08:47:51.225[sip]   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDA
TE, INFO
08:47:51.225[sip]   Supported: timer, 100rel, replaces
08:47:51.225[sip]   Content-Length: 0
08:47:51.225[sip]   P-RTP-Stat: PS=40, OS=5926, PR=82, OR=13627, PL=0, JI=0
08:47:51.225[sip]   
08:47:51.225[sip]   ------------------------------------------------------------------------
08:47:51.225[sip]nta: sent 200 OK for BYE (3)
08:47:51.225[sip]nua(0x331a00): removing session usage
08:47:51.225[sip]nua(0x331a00): call state changed: ready -> terminated
08:47:51.225[sip]nua(0x331a00): event i_state 200 Session Terminated
08:47:51.225[app:dbg]got nua_i_state : 200(Session Terminated)
08:47:51.225[app:dbg]NO SIP IN nua_i_state == 200 : Session Terminated
08:47:51.225[app:dbg]self_i_state(): call state 10: : : sdp_init have_oc
08:47:51.235[app:dbg]sip: call 02050000: terminated
08:47:51.235[app:dbg]7336: endpoint 5 set to busy
08:47:51.235[app:dbg]sip -[msg_clear]-> pbx
08:47:51.235[app:dbg]ITC: [msg_clear] -> pbx
08:47:51.235[app:dbg]dump_port_calls() SLIC 5:
08:47:51.235[app:dbg]Q:(0x31d800,0x02050000,(nil))
08:47:51.235[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:(
(nil),0x00000000,(nil))
08:47:51.235[app:dbg]SLIC 5: peer cleared(02050000)
08:47:51.235[app:dbg]SLIC 5: current call cleared
08:47:51.235[app:dbg]SLIC 5: -> busy - no hold call, no wait call
08:47:51.235[app:info]SLIC 5: from state 'talking' to state 'busy'
08:47:51.235[app:dbg]port_start_tone(5 22 0 0)
08:47:51.235[app:dbg]CMD_START_TONE: port = 5
08:47:51.235[app:dbg]Port 5: check vapi queue ('free') at vapi_start_tone_chan:1412
08:47:51.235[app:dbg]Chan 5: current state is CREATED
08:47:51.235[app:dbg]Port 5: set vapi queue MSP to 'busy' with 'start_tone' at vapi_start_tone_chan:1449
08:47:51.235[app:dbg]VQ Conn 5 = MSP :    'start_tone' =
08:47:51.235[app:dbg]Conn 5, tone config: tone_high: 425Hz, tone_low: 0Hz, tone_t_on1: 330ms, tone_t_off1: 3
30ms, tone_t_on2: 0ms, tone_t_off2: 0ms
08:47:51.235[app:dbg]chan 5 start tone, id=22, direction=TDM
08:47:51.235[app:dbg]Port 5: user port 3, old state busy, new state 
08:47:51.235[app:dbg]Set port 5 led to state 'LED_ON'
08:47:51.235[app:dbg]pbx -[msg_fxs_state]-> group
08:47:51.235[app:dbg]vapi: chan 5: connection STATISTIC
08:47:51.235[app:dbg]vapi: chan 5: Rx_pack = 82
08:47:51.235[app:dbg]vapi: chan 5: Rx_oct  = 13627
08:47:51.235[app:dbg]vapi: chan 5: Lost_pack  = 0
08:47:51.235[app:dbg]vapi: chan 5: Tx_pack = 40
08:47:51.235[app:dbg]vapi: chan 5: Tx_oct  = 5926
08:47:51.235[app:dbg]vapi: chan 5: peak_jiter = 0
08:47:51.235[app:dbg]SLIC 5: Common port statistic
08:47:51.235[app:dbg]SLIC 5: Rx_pack = 11352
08:47:51.235[app:dbg]SLIC 5: Rx_oct  = 1938870
08:47:51.235[app:dbg]SLIC 5: Lost_pack  = 0
08:47:51.235[app:dbg]SLIC 5: Tx_pack = 13940
08:47:51.235[app:dbg]SLIC 5: Tx_oct  = 2181953
08:47:51.235[app:dbg]SLIC 5: peak_jiter = 0
08:47:51.235[app:dbg]SLIC 5: reset call 0x02050000 (active)
08:47:51.235[app:dbg]CMD_SET_VOICE: port = 5
08:47:51.235[app:dbg]Port 5: check vapi queue ('busy''start_tone') at vapi_start_stop_chan:1652
08:47:51.235[app:dbg]Port 5 put cmd 'set voice',cur 'start_tone' to queue at (vapi_start_stop_chan:1659)
08:47:51.235[app:dbg]VQ Conn 5 = MSP :    'start_tone' =
08:47:51.235[app:dbg]VQ Conn 5 + 01  :     'set voice'  + <-get_ptr 
08:47:51.235[app:dbg]incom_calls_set_media_started() call 0x02050000, group -1, task <sip> media stopped
08:47:51.235[app:dbg]incom_calls_rem() rem call 0x02050000, group -1, task <sip> from list
08:47:51.235[app:dbg]dump_port_calls() SLIC 5:
08:47:51.235[app:dbg]Q:NONE
08:47:51.235[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:(
(nil),0x00000000,(nil))
08:47:51.235[app:dbg]vapi_cb_req: 5 0 result 0x00000000 requid 0x00000922
08:47:51.235[app:dbg]ITC: [msg_fxs_state] -> group
08:47:51.235[app:dbg]-----[GM] self_fxs_state()
08:47:51.235[app:dbg]Port 5: new state is busy
08:47:51.235[app:dbg]Delete all RX-TX medias from SLIC 5
08:47:51.235[app:dbg]vapi_proc_event: VAPI_CB
08:47:51.235[app:dbg]vapi_cb_chan: chan 5 reqest_id 0x00000922 result 0x00000000
08:47:51.235[app:dbg]Conn 5: Start tone - Successfull
08:47:51.235[app:dbg]Port 5: check vapi queue ('busy''start_tone') at vapi_next_ops:2599
08:47:51.245[sip]nua(0x331a00): event i_terminated 200 Session Terminated
08:47:51.245[app:dbg]self_callstate_terminated: call id = 02050000 need_exchange_at_answer = 0
08:47:51.245[sip]nua(0x331a00): recv signal r_destroy
08:47:51.235[app:dbg]Port 5 get cmd 'set voice' from queue at (vapi_next_ops:2618)
08:47:51.245[app:dbg]Port 5: check vapi queue ('free') at vapi_start_stop_chan:1652
08:47:51.245[app:dbg]Chan 5: current state is CREATED
08:47:51.245[app:dbg]vapi: Conn 5. start_stop voice chan, TX stop, RX stop
08:47:51.245[app:dbg]Port 5: set vapi queue MSP to 'busy' with 'set voice' at vapi_start_stop_chan:1695
08:47:51.245[app:dbg]VQ Conn 5 = MSP :     'set voice' =
08:47:51.245[app:dbg]vapi_cb_req: 5 0 result 0x00000000 requid 0x00000401
08:47:51.245[app:dbg]vapi_proc_event: VAPI_CB
08:47:51.245[app:dbg]vapi_cb_chan: chan 5 reqest_id 0x00000401 result 0x00000000
08:47:51.245[app:dbg]vapi: conn 5. RTCP disabled
08:47:51.245[app:dbg]vapi_cb_req: 5 0 result 0x00000000 requid 0x000004ff
08:47:51.245[app:dbg]vapi_proc_event: VAPI_CB
08:47:51.245[app:dbg]vapi_cb_chan: chan 5 reqest_id 0x000004ff result 0x00000000
08:47:51.245[app:dbg]Conn 5: Set voice mode successeful
08:47:51.245[app:dbg]Stop all medias on chan 5
08:47:51.245[app:dbg]Mute all RX-TX medias on SLIC 5
08:47:51.245[app:dbg]Port 5: check vapi queue ('busy''set voice') at vapi_next_ops:2599
08:47:51.865[sip]nta: timer I fired, terminate 422 response
08:47:51.865[sip]nta_incoming_timer: 0/0 resent, 0/0 tout, 1/3 term, 1/3 free
08:47:53.285[sip]nta: timer I fired, terminate 200 response
08:47:53.285[sip]nta_incoming_timer: 0/0 resent, 0/0 tout, 1/2 term, 1/2 free
08:47:53.705[app:dbg]slic5. Event 8.
08:47:53.705[app:dbg]slic 5. Pre-On-hook event
08:47:53.705[app:dbg]HIO: preonhook TDM port '5', port enabled 1
08:47:53.705[app:dbg]CMD_STOP_TONE: port = 5
08:47:53.705[app:dbg]Port 5: check vapi queue ('free') at vapi_stop_tone_chan:1503
08:47:53.705[app:dbg]Chan 5: current state is CREATED
08:47:53.705[app:dbg]Port 5: set vapi queue MSP to 'busy' with 'stop_tone' at vapi_stop_tone_chan:1549
08:47:53.705[app:dbg]VQ Conn 5 = MSP :     'stop_tone' =
08:47:53.705[app:dbg]chan 5 stop tone
08:47:53.715[app:dbg]vapi_cb_req: 5 0 result 0x00000000 requid 0x00000923
08:47:53.715[app:dbg]vapi_proc_event: VAPI_CB
08:47:53.715[app:dbg]vapi_cb_chan: chan 5 reqest_id 0x00000923 result 0x00000000
08:47:53.715[app:dbg]Conn 5: Stop tone - Successfull
08:47:53.715[app:dbg]Port 5: check vapi queue ('busy''stop_tone') at vapi_next_ops:2599
08:47:53.715[app:dbg]Port 5: check vapi queue ('free') at vapi_cid_dtmf_chan:3088
08:47:53.715[app:dbg]Chan 5: current state is CREATED
08:47:53.715[app:dbg]Port 5: set vapi queue MSP to 'busy' with 'cid_dtmf_event' at vapi_cid_dtmf_chan:3117
08:47:53.715[app:dbg]VQ Conn 5 = MSP : 'cid_dtmf_event' =
08:47:53.715[app:info]Generating Caller-ID DTMF tone '2'
08:47:53.715[app:dbg]chan 5 start tone, id=1, direction=TDM
08:47:53.715[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, conn 5
08:47:53.725[app:dbg]vapi_cb_req: 5 0 result 0x00000000 requid 0x00000948
08:47:53.725[app:dbg]vapi_proc_event: VAPI_CB
08:47:53.725[app:dbg]vapi_cb_chan: chan 5 reqest_id 0x00000948 result 0x00000000
08:47:53.725[app:dbg]Conn 5: Caller Id DTMF tone - Successfull
08:47:53.725[app:dbg]Port 5: check vapi queue ('busy''cid_dtmf_event') at vapi_next_ops:2599
08:47:53.865[app:dbg]Port 5: check vapi queue ('free') at vapi_cid_dtmf_chan:3088
08:47:53.865[app:dbg]Chan 5: current state is CREATED
08:47:53.865[app:dbg]Port 5: set vapi queue MSP to 'busy' with 'cid_dtmf_event' at vapi_cid_dtmf_chan:3117
08:47:53.865[app:dbg]VQ Conn 5 = MSP : 'cid_dtmf_event' =
08:47:53.865[app:info]Generating Caller-ID DTMF tone '1'
08:47:53.865[app:dbg]chan 5 start tone, id=0, direction=TDM
08:47:53.865[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, conn 5
08:47:53.875[app:dbg]vapi_cb_req: 5 0 result 0x00000000 requid 0x00000948
08:47:53.875[app:dbg]vapi_proc_event: VAPI_CB
08:47:53.875[app:dbg]vapi_cb_chan: chan 5 reqest_id 0x00000948 result 0x00000000
08:47:53.875[app:dbg]Conn 5: Caller Id DTMF tone - Successfull
08:47:53.875[app:dbg]Port 5: check vapi queue ('busy''cid_dtmf_event') at vapi_next_ops:2599
08:47:54.025[app:dbg]Port 5: check vapi queue ('free') at vapi_cid_dtmf_chan:3088
08:47:54.025[app:dbg]Chan 5: current state is CREATED
08:47:54.025[app:dbg]Port 5: set vapi queue MSP to 'busy' with 'cid_dtmf_event' at vapi_cid_dtmf_chan:3117
08:47:54.025[app:dbg]VQ Conn 5 = MSP : 'cid_dtmf_event' =
08:47:54.025[app:info]Generating Caller-ID DTMF tone '8'
08:47:54.025[app:dbg]chan 5 start tone, id=7, direction=TDM
08:47:54.025[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, conn 5
08:47:54.035[app:dbg]vapi_cb_req: 5 0 result 0x00000000 requid 0x00000948
08:47:54.035[app:dbg]vapi_proc_event: VAPI_CB
08:47:54.035[app:dbg]vapi_cb_chan: chan 5 reqest_id 0x00000948 result 0x00000000
08:47:54.035[app:dbg]Conn 5: Caller Id DTMF tone - Successfull
08:47:54.035[app:dbg]Port 5: check vapi queue ('busy''cid_dtmf_event') at vapi_next_ops:2599
08:47:54.185[app:dbg]Port 5: check vapi queue ('free') at vapi_cid_dtmf_chan:3088
08:47:54.185[app:dbg]Chan 5: current state is CREATED
08:47:54.185[app:dbg]Port 5: set vapi queue MSP to 'busy' with 'cid_dtmf_event' at vapi_cid_dtmf_chan:3117
08:47:54.185[app:dbg]VQ Conn 5 = MSP : 'cid_dtmf_event' =
08:47:54.185[app:info]Generating Caller-ID DTMF tone 'C'
08:47:54.185[app:dbg]chan 5 start tone, id=11, direction=TDM
08:47:54.185[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, conn 5
08:47:54.195[app:dbg]vapi_cb_req: 5 0 result 0x00000000 requid 0x00000948
08:47:54.195[app:dbg]vapi_proc_event: VAPI_CB
08:47:54.195[app:dbg]vapi_cb_chan: chan 5 reqest_id 0x00000948 result 0x00000000
08:47:54.195[app:dbg]Conn 5: Caller Id DTMF tone - Successfull
08:47:54.195[app:dbg]Port 5: check vapi queue ('busy''cid_dtmf_event') at vapi_next_ops:2599
08:47:54.345[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, conn 5
08:47:54.615[app:dbg]slic5. Event 1.
08:47:54.615[app:dbg]slic 5. On-hook event
08:47:54.615[app:dbg]Set port 5 led to state 'LED_OFF'
08:47:54.615[app:dbg]HIO: onhook TDM port '5', port enabled 1
08:47:54.615[app:dbg]SLIC 5 (219): onhook state: busy
08:47:54.615[app:dbg]regex ID 5: dial reset
08:47:54.615[app:info]SLIC 5: from state 'busy' to state 'hangup'
08:47:54.615[app:dbg]CMD_STOP_TONE: port = 5
08:47:54.615[app:dbg]Port 5: check vapi queue ('free') at vapi_stop_tone_chan:1503
08:47:54.615[app:dbg]Chan 5: current state is CREATED
08:47:54.615[app:ERR]chan 5: no generated tones!
08:47:54.615[app:dbg]vapi_chan.c:1539: conn 5 peek cmd 'no event' from queue
08:47:54.615[app:dbg]Port 5: check vapi queue ('free') at __cmd_engine:321
08:47:54.615[app:dbg]Port 5: check vapi queue ('free') at vapi_next_ops:2599
08:47:54.615[app:dbg]SLIC 5: reset
08:47:54.615[app:dbg]dump_port_calls() SLIC 5:
08:47:54.615[app:dbg]Q:NONE
08:47:54.615[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:(
(nil),0x00000000,(nil))
08:47:54.615[app:dbg]Delete all RX-TX medias from SLIC 5
08:47:54.615[app:dbg]free_final_mx: final_mx was NULL for SLIC 5
08:47:54.615[app:dbg]CMD_DESTROY_CONN: port = 5
08:47:54.615[app:dbg]Port 5: check vapi queue ('free') at vapi_destroy_chan:895
08:47:54.615[app:dbg]Destroying connection 5...
08:47:54.615[app:dbg]Chan 5: current state is CREATED
08:47:54.615[app:dbg]Port 5: set vapi queue MSP to 'busy' with 'destroy' at vapi_destroy_chan:921
08:47:54.615[app:dbg]VQ Conn 5 = MSP :       'destroy' =
08:47:54.615[app:dbg]Chan 5: CREATED -> DESTROYING
08:47:54.615[app:dbg]vapi_cb_req: 5 0 result 0x00000000 requid 0x0000014b
08:47:54.615[app:dbg]CMD_DESTROY_IPONLY_CONN: port = 5
08:47:54.615[app:dbg]Port 5: check vapi queue ('busy''destroy') at vapi_destroy_chan:895
08:47:54.615[app:dbg]Clear vapi queue of Port 5/chan 13
08:47:54.615[app:dbg]Port 5 put cmd 'destroy',cur 'destroy' to queue at (vapi_destroy_chan:902)
08:47:54.615[app:dbg]VQ Conn 13 = MSP :       'destroy' =
08:47:54.615[app:dbg]VQ Conn 13 + 00  :       'destroy' (hold) + <-get_ptr 
08:47:54.615[app:dbg]Port 5: user port 3, old state hangup, new state 
08:47:54.615[app:dbg]Set port 5 led to state 'LED_OFF'
08:47:54.615[app:dbg]pbx -[msg_fxs_state]-> group
08:47:54.615[app:dbg]ITC: [msg_fxs_state] -> group
08:47:54.615[app:dbg]-----[GM] self_fxs_state()
08:47:54.615[app:dbg]Port 5: new state is hangup
08:47:54.615[app:dbg]dump_port_calls() SLIC 5:
08:47:54.615[app:dbg]Q:NONE
08:47:54.615[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:(
(nil),0x00000000,(nil))
08:47:54.615[app:dbg]Set port 5 led to state 'LED_OFF'
08:47:54.615[app:dbg]vapi_proc_event: VAPI_CB
08:47:54.615[app:dbg]vapi_cb_chan: chan 5 reqest_id 0x0000014b result 0x00000000
08:47:54.615[app:dbg]vapi_cb_req: 5 0 result 0x00000000 requid 0x00000103
08:47:54.615[app:dbg]vapi_proc_event: VAPI_CB
08:47:54.615[app:dbg]vapi_cb_chan: chan 5 reqest_id 0x00000103 result 0x00000000
08:47:54.615[app:dbg]Conn 5 destroyed
08:47:54.615[app:dbg]Chan 5: DESTROYING -> INITIAL
08:47:54.625[app:dbg]Delete all RX-TX medias from SLIC 13
08:47:54.615[app:dbg]Port 5: check vapi queue ('busy''destroy') at vapi_next_ops:2599
08:47:54.625[app:dbg]Port 5 get cmd 'destroy' from queue at (vapi_next_ops:2618)
08:47:54.625[app:dbg]Port 5: check vapi queue ('free') at vapi_destroy_chan:895
08:47:54.625[app:dbg]Destroying connection 13...
08:47:54.625[app:dbg]Chan 13: current state is INITIAL
08:47:54.625[app:ERR]vapi_destroy_chan() chan 13: current state initial: duplicate destroying connection!
08:47:54.625[app:dbg]Port 5: check vapi queue ('free') at vapi_next_ops:2761
08:47:54.625[app:dbg]Port 5: check vapi queue ('free') at vapi_next_ops:2599
08:47:54.635[app:dbg]Delete all RX-TX medias from SLIC 5
08:47:55.605[sip]send 381 bytes to udp/[192.168.0.101]:5060 at 19:17:10.220000:
08:47:55.605[sip]   ------------------------------------------------------------------------
08:47:55.605[sip]   OPTIONS sip:224@192.168.0.101 SIP/2.0
08:47:55.605[sip]   Via: SIP/2.0/UDP 192.168.0.217;rport;branch=z9hG4bK783eXmtNaQ6eD
08:47:55.605[sip]   Max-Forwards: 70
08:47:55.605[sip]   From: "224" <sip:224@192.168.0.101>;tag=3XDjg16BN8v4e
08:47:55.605[sip]   To: "224" <sip:224@192.168.0.101>
08:47:55.605[sip]   Call-ID: 2273d048-e062-1234-c1b8-a8f94b0e6be9
08:47:55.605[sip]   CSeq: 6857 OPTIONS
08:47:55.605[sip]   Subject: KEEPALIVE
08:47:55.605[sip]   User-Agent: TAU-8.IP/2.1.0 SN/VI33023837 sofia-sip/1.12.10
08:47:55.605[sip]   Content-Length: 0
08:47:55.605[sip]   
08:47:55.605[sip]   ------------------------------------------------------------------------
08:47:55.605[sip]nta: sent OPTIONS (6857) to */192.168.0.101:5060
08:47:55.625[sip]recv 287 bytes from udp/[192.168.0.101]:5060 at 19:17:10.240000:
08:47:55.625[sip]   ------------------------------------------------------------------------
08:47:55.625[sip]   SIP/2.0 501 Not Implemented
08:47:55.625[sip]   Via: SIP/2.0/UDP 192.168.0.217;branch=z9hG4bK783eXmtNaQ6eD;rport=5060
08:47:55.625[sip]   To: "224" <sip:224@192.168.0.101>;tag=4504
08:47:55.625[sip]   From: "224" <sip:224@192.168.0.101>;tag=3XDjg16BN8v4e
08:47:55.625[sip]   Call-ID: 2273d048-e062-1234-c1b8-a8f94b0e6be9
08:47:55.625[sip]   CSeq: 6857 OPTIONS
08:47:55.625[sip]   Content-Length: 0
08:47:55.625[sip]   
08:47:55.625[sip]   ------------------------------------------------------------------------
08:47:55.625[sip]nta: received 501 Not Implemented for OPTIONS (6857)
08:47:55.625[sip]nta: 501 Not Implemented is going to a transaction
08:47:56.165[sip]nta: timer K fired, terminate REFER (34710)
08:47:56.165[sip]nta_outgoing_timer: 0/0 resent, 0/2 tout, 1/7 term, 1/9 free
08:47:56.205[sip]nta: timer K fired, terminate BYE (34711)
08:47:56.205[sip]nta_outgoing_timer: 0/0 resent, 0/2 tout, 1/6 term, 1/8 free
08:47:56.225[sip]nta: timer K fired, terminate BYE (34712)
08:47:56.225[sip]nta_outgoing_timer: 0/0 resent, 0/2 tout, 1/5 term, 1/7 free
08:47:58.315[sip]send 381 bytes to udp/[192.168.0.101]:5060 at 19:17:12.930000:
08:47:58.315[sip]   ------------------------------------------------------------------------
08:47:58.315[sip]   OPTIONS sip:218@192.168.0.101 SIP/2.0
08:47:58.315[sip]   Via: SIP/2.0/UDP 192.168.0.217;rport;branch=z9hG4bK8HX7yFBS7Zv1r
08:47:58.315[sip]   Max-Forwards: 70
08:47:58.315[sip]   From: "218" <sip:218@192.168.0.101>;tag=gKpm701SFvyQN
08:47:58.315[sip]   To: "218" <sip:218@192.168.0.101>
08:47:58.315[sip]   Call-ID: 59c3f847-e062-1234-c2b8-a8f94b0e6be9
08:47:58.315[sip]   CSeq: 6861 OPTIONS
08:47:58.315[sip]   Subject: KEEPALIVE
08:47:58.315[sip]   User-Agent: TAU-8.IP/2.1.0 SN/VI33023837 sofia-sip/1.12.10
08:47:58.315[sip]   Content-Length: 0
08:47:58.315[sip]   
08:47:58.315[sip]   ------------------------------------------------------------------------
08:47:58.315[sip]nta: sent OPTIONS (6861) to */192.168.0.101:5060
08:47:58.335[sip]recv 288 bytes from udp/[192.168.0.101]:5060 at 19:17:12.950000:
08:47:58.335[sip]   ------------------------------------------------------------------------
08:47:58.335[sip]   SIP/2.0 501 Not Implemented
08:47:58.335[sip]   Via: SIP/2.0/UDP 192.168.0.217;branch=z9hG4bK8HX7yFBS7Zv1r;rport=5060
08:47:58.335[sip]   To: "218" <sip:218@192.168.0.101>;tag=21341
08:47:58.335[sip]   From: "218" <sip:218@192.168.0.101>;tag=gKpm701SFvyQN
08:47:58.335[sip]   Call-ID: 59c3f847-e062-1234-c2b8-a8f94b0e6be9
08:47:58.335[sip]   CSeq: 6861 OPTIONS
08:47:58.335[sip]   Content-Length: 0
08:47:58.335[sip]   
08:47:58.335[sip]   ------------------------------------------------------------------------
08:47:58.335[sip]nta: received 501 Not Implemented for OPTIONS (6861)
08:47:58.335[sip]nta: 501 Not Implemented is going to a transaction
08:47:58.405[sip]send 381 bytes to udp/[192.168.0.101]:5060 at 19:17:13.020000:
08:47:58.405[sip]   ------------------------------------------------------------------------
08:47:58.405[sip]   OPTIONS sip:217@192.168.0.101 SIP/2.0
08:47:58.405[sip]   Via: SIP/2.0/UDP 192.168.0.217;rport;branch=z9hG4bK9tp00avv48jmm
08:47:58.405[sip]   Max-Forwards: 70
08:47:58.405[sip]   From: "217" <sip:217@192.168.0.101>;tag=9K56t3B13X2mm
08:47:58.405[sip]   To: "217" <sip:217@192.168.0.101>
08:47:58.405[sip]   Call-ID: 59d1b3e7-e062-1234-c2b8-a8f94b0e6be9
08:47:58.405[sip]   CSeq: 6862 OPTIONS
08:47:58.405[sip]   Subject: KEEPALIVE
08:47:58.405[sip]   User-Agent: TAU-8.IP/2.1.0 SN/VI33023837 sofia-sip/1.12.10
08:47:58.405[sip]   Content-Length: 0
08:47:58.405[sip]   
08:47:58.405[sip]   ------------------------------------------------------------------------
08:47:58.405[sip]nta: sent OPTIONS (6862) to */192.168.0.101:5060
08:47:58.425[sip]recv 288 bytes from udp/[192.168.0.101]:5060 at 19:17:13.040000:
08:47:58.425[sip]   ------------------------------------------------------------------------
08:47:58.425[sip]   SIP/2.0 501 Not Implemented
08:47:58.425[sip]   Via: SIP/2.0/UDP 192.168.0.217;branch=z9hG4bK9tp00avv48jmm;rport=5060
08:47:58.425[sip]   To: "217" <sip:217@192.168.0.101>;tag=27354
08:47:58.425[sip]   From: "217" <sip:217@192.168.0.101>;tag=9K56t3B13X2mm
08:47:58.425[sip]   Call-ID: 59d1b3e7-e062-1234-c2b8-a8f94b0e6be9
08:47:58.425[sip]   CSeq: 6862 OPTIONS
08:47:58.425[sip]   Content-Length: 0
08:47:58.425[sip]   
08:47:58.425[sip]   ------------------------------------------------------------------------
08:47:58.425[sip]nta: received 501 Not Implemented for OPTIONS (6862)
08:47:58.425[sip]nta: 501 Not Implemented is going to a transaction
08:47:59.675[sip]send 381 bytes to udp/[192.168.0.101]:5060 at 19:17:14.290000:
08:47:59.675[sip]   ------------------------------------------------------------------------
08:47:59.675[sip]   OPTIONS sip:223@192.168.0.101 SIP/2.0
08:47:59.675[sip]   Via: SIP/2.0/UDP 192.168.0.217;rport;branch=z9hG4bKa4FS25c01H96F
08:47:59.675[sip]   Max-Forwards: 70
08:47:59.675[sip]   From: "223" <sip:223@192.168.0.101>;tag=2mmSe6N8QZ6HK
08:47:59.675[sip]   To: "223" <sip:223@192.168.0.101>
08:47:59.675[sip]   Call-ID: 6c79b428-e062-1234-c2b8-a8f94b0e6be9
08:47:59.675[sip]   CSeq: 6863 OPTIONS
08:47:59.675[sip]   Subject: KEEPALIVE
08:47:59.675[sip]   User-Agent: TAU-8.IP/2.1.0 SN/VI33023837 sofia-sip/1.12.10
08:47:59.675[sip]   Content-Length: 0
08:47:59.675[sip]   
08:47:59.675[sip]   ------------------------------------------------------------------------
08:47:59.675[sip]nta: sent OPTIONS (6863) to */192.168.0.101:5060
08:47:59.695[sip]recv 287 bytes from udp/[192.168.0.101]:5060 at 19:17:14.310000:
08:47:59.695[sip]   ------------------------------------------------------------------------
08:47:59.695[sip]   SIP/2.0 501 Not Implemented
08:47:59.695[sip]   Via: SIP/2.0/UDP 192.168.0.217;branch=z9hG4bKa4FS25c01H96F;rport=5060
08:47:59.695[sip]   To: "223" <sip:223@192.168.0.101>;tag=7389
08:47:59.695[sip]   From: "223" <sip:223@192.168.0.101>;tag=2mmSe6N8QZ6HK
08:47:59.695[sip]   Call-ID: 6c79b428-e062-1234-c2b8-a8f94b0e6be9
08:47:59.695[sip]   CSeq: 6863 OPTIONS
08:47:59.695[sip]   Content-Length: 0
08:47:59.695[sip]   
08:47:59.695[sip]   ------------------------------------------------------------------------
08:47:59.695[sip]nta: received 501 Not Implemented for OPTIONS (6863)
08:47:59.695[sip]nta: 501 Not Implemented is going to a transaction
08:48:00.635[sip]nta: timer K fired, terminate OPTIONS (6857)
08:48:00.635[sip]nta_outgoing_timer: 0/0 resent, 0/2 tout, 1/7 term, 1/9 free
08:48:03.345[sip]nta: timer K fired, terminate OPTIONS (6861)
08:48:03.345[sip]nta_outgoing_timer: 0/0 resent, 0/2 tout, 1/6 term, 1/8 free
08:48:03.435[sip]nta: timer K fired, terminate OPTIONS (6862)
08:48:03.435[sip]nta_outgoing_timer: 0/0 resent, 0/2 tout, 1/5 term, 1/7 free
08:48:04.705[sip]send 381 bytes to udp/[192.168.0.101]:5060 at 19:17:19.320000:
08:48:04.705[sip]   ------------------------------------------------------------------------
08:48:04.705[sip]   OPTIONS sip:221@192.168.0.101 SIP/2.0
08:48:04.705[sip]   Via: SIP/2.0/UDP 192.168.0.217;rport;branch=z9hG4bKBD9H40X3ytZSB
08:48:04.705[sip]   Max-Forwards: 70
08:48:04.705[sip]   From: "221" <sip:221@192.168.0.101>;tag=5F03KQ8jFt99N
08:48:04.705[sip]   To: "221" <sip:221@192.168.0.101>
08:48:04.705[sip]   Call-ID: 6f7abf28-e062-1234-c2b8-a8f94b0e6be9
08:48:04.705[sip]   CSeq: 6864 OPTIONS
08:48:04.705[sip]   Subject: KEEPALIVE
08:48:04.705[sip]   User-Agent: TAU-8.IP/2.1.0 SN/VI33023837 sofia-sip/1.12.10
08:48:04.705[sip]   Content-Length: 0
08:48:04.705[sip]   
08:48:04.705[sip]   ------------------------------------------------------------------------
08:48:04.705[sip]nta: sent OPTIONS (6864) to */192.168.0.101:5060
08:48:04.705[sip]nta: timer K fired, terminate OPTIONS (6863)
08:48:04.705[sip]nta_outgoing_timer: 0/1 resent, 0/3 tout, 1/4 term, 1/7 free
08:48:04.725[sip]recv 288 bytes from udp/[192.168.0.101]:5060 at 19:17:19.340000:
08:48:04.725[sip]   ------------------------------------------------------------------------
08:48:04.725[sip]   SIP/2.0 501 Not Implemented
08:48:04.725[sip]   Via: SIP/2.0/UDP 192.168.0.217;branch=z9hG4bKBD9H40X3ytZSB;rport=5060
08:48:04.725[sip]   To: "221" <sip:221@192.168.0.101>;tag=11385
08:48:04.725[sip]   From: "221" <sip:221@192.168.0.101>;tag=5F03KQ8jFt99N
08:48:04.725[sip]   Call-ID: 6f7abf28-e062-1234-c2b8-a8f94b0e6be9
08:48:04.725[sip]   CSeq: 6864 OPTIONS
08:48:04.725[sip]   Content-Length: 0
08:48:04.725[sip]   
08:48:04.725[sip]   ------------------------------------------------------------------------
08:48:04.725[sip]nta: received 501 Not Implemented for OPTIONS (6864)
08:48:04.725[sip]nta: 501 Not Implemented is going to a transaction
08:48:04.925[sip]send 381 bytes to udp/[192.168.0.101]:5060 at 19:17:19.540000:
08:48:04.925[sip]   ------------------------------------------------------------------------
08:48:04.925[sip]   OPTIONS sip:220@192.168.0.101 SIP/2.0
08:48:04.925[sip]   Via: SIP/2.0/UDP 192.168.0.217;rport;branch=z9hG4bKcp2a6Ue7U3NcQ
08:48:04.925[sip]   Max-Forwards: 70
08:48:04.925[sip]   From: "220" <sip:220@192.168.0.101>;tag=466ajvQFjHKQa
08:48:04.925[sip]   To: "220" <sip:220@192.168.0.101>
08:48:04.925[sip]   Call-ID: 39e9ac47-e062-1234-c1b8-a8f94b0e6be9
08:48:04.925[sip]   CSeq: 6860 OPTIONS
08:48:04.925[sip]   Subject: KEEPALIVE
08:48:04.925[sip]   User-Agent: TAU-8.IP/2.1.0 SN/VI33023837 sofia-sip/1.12.10
08:48:04.925[sip]   Content-Length: 0
08:48:04.925[sip]   
08:48:04.925[sip]   ------------------------------------------------------------------------
08:48:04.925[sip]nta: sent OPTIONS (6860) to */192.168.0.101:5060
08:48:04.945[sip]recv 287 bytes from udp/[192.168.0.101]:5060 at 19:17:19.560000:
08:48:04.945[sip]   ------------------------------------------------------------------------
08:48:04.945[sip]   SIP/2.0 501 Not Implemented
08:48:04.945[sip]   Via: SIP/2.0/UDP 192.168.0.217;branch=z9hG4bKcp2a6Ue7U3NcQ;rport=5060
08:48:04.945[sip]   To: "220" <sip:220@192.168.0.101>;tag=4185
08:48:04.945[sip]   From: "220" <sip:220@192.168.0.101>;tag=466ajvQFjHKQa
08:48:04.945[sip]   Call-ID: 39e9ac47-e062-1234-c1b8-a8f94b0e6be9
08:48:04.945[sip]   CSeq: 6860 OPTIONS
08:48:04.945[sip]   Content-Length: 0
08:48:04.945[sip]   
08:48:04.945[sip]   ------------------------------------------------------------------------
08:48:04.945[sip]nta: received 501 Not Implemented for OPTIONS (6860)
08:48:04.945[sip]nta: 501 Not Implemented is going to a transaction
08:48:05.965[sip]send 381 bytes to udp/[192.168.0.101]:5060 at 19:17:20.580000:
08:48:05.965[sip]   ------------------------------------------------------------------------
08:48:05.965[sip]   OPTIONS sip:219@192.168.0.101 SIP/2.0
08:48:05.965[sip]   Via: SIP/2.0/UDP 192.168.0.217;rport;branch=z9hG4bKDZU37pZaSccZj
08:48:05.965[sip]   Max-Forwards: 70
08:48:05.965[sip]   From: "219" <sip:219@192.168.0.101>;tag=71jNQDat9BpFD
08:48:05.965[sip]   To: "219" <sip:219@192.168.0.101>
08:48:05.965[sip]   Call-ID: 821fb228-e062-1234-c2b8-a8f94b0e6be9
08:48:05.965[sip]   CSeq: 6866 OPTIONS
08:48:05.965[sip]   Subject: KEEPALIVE
08:48:05.965[sip]   User-Agent: TAU-8.IP/2.1.0 SN/VI33023837 sofia-sip/1.12.10
08:48:05.965[sip]   Content-Length: 0
08:48:05.965[sip]   
08:48:05.965[sip]   ------------------------------------------------------------------------
08:48:05.965[sip]nta: sent OPTIONS (6866) to */192.168.0.101:5060
08:48:05.985[sip]recv 288 bytes from udp/[192.168.0.101]:5060 at 19:17:20.600000:
08:48:05.985[sip]   ------------------------------------------------------------------------
08:48:05.985[sip]   SIP/2.0 501 Not Implemented
08:48:05.985[sip]   Via: SIP/2.0/UDP 192.168.0.217;branch=z9hG4bKDZU37pZaSccZj;rport=5060
08:48:05.985[sip]   To: "219" <sip:219@192.168.0.101>;tag=16561
08:48:05.985[sip]   From: "219" <sip:219@192.168.0.101>;tag=71jNQDat9BpFD
08:48:05.985[sip]   Call-ID: 821fb228-e062-1234-c2b8-a8f94b0e6be9
08:48:05.985[sip]   CSeq: 6866 OPTIONS
08:48:05.985[sip]   Content-Length: 0
08:48:05.985[sip]   
08:48:05.985[sip]   ------------------------------------------------------------------------
08:48:05.985[sip]nta: received 501 Not Implemented for OPTIONS (6866)
08:48:05.985[sip]nta: 501 Not Implemented is going to a transaction
08:48:09.735[sip]nta: timer K fired, terminate OPTIONS (6864)
08:48:09.735[sip]nta_outgoing_timer: 0/0 resent, 0/2 tout, 1/6 term, 1/8 free
08:48:09.955[sip]nta: timer K fired, terminate OPTIONS (6860)
08:48:09.955[sip]nta_outgoing_timer: 0/0 resent, 0/2 tout, 1/5 term, 1/7 free
08:48:10.995[sip]nta: timer K fired, terminate OPTIONS (6866)
08:48:10.995[sip]nta_outgoing_timer: 0/0 resent, 0/2 tout, 1/4 term, 1/6 free
08:48:11.775[sip]send 381 bytes to udp/[192.168.0.101]:5060 at 19:17:26.390000:
08:48:11.775[sip]   ------------------------------------------------------------------------
08:48:11.775[sip]   OPTIONS sip:216@192.168.0.101 SIP/2.0
08:48:11.775[sip]   Via: SIP/2.0/UDP 192.168.0.217;rport;branch=z9hG4bKe8mv9HgepN2He
08:48:11.775[sip]   Max-Forwards: 70
08:48:11.775[sip]   From: "216" <sip:216@192.168.0.101>;tag=8aceS8tX6mc2r
08:48:11.775[sip]   To: "216" <sip:216@192.168.0.101>
08:48:11.775[sip]   Call-ID: 73b00467-e062-1234-c2b8-a8f94b0e6be9
08:48:11.775[sip]   CSeq: 6865 OPTIONS
08:48:11.775[sip]   Subject: KEEPALIVE
08:48:11.775[sip]   User-Agent: TAU-8.IP/2.1.0 SN/VI33023837 sofia-sip/1.12.10
08:48:11.775[sip]   Content-Length: 0
08:48:11.775[sip]   
08:48:11.775[sip]   ------------------------------------------------------------------------
08:48:11.775[sip]nta: sent OPTIONS (6865) to */192.168.0.101:5060
08:48:11.795[sip]recv 288 bytes from udp/[192.168.0.101]:5060 at 19:17:26.410000:
08:48:11.795[sip]   ------------------------------------------------------------------------
08:48:11.795[sip]   SIP/2.0 501 Not Implemented
08:48:11.795[sip]   Via: SIP/2.0/UDP 192.168.0.217;branch=z9hG4bKe8mv9HgepN2He;rport=5060
08:48:11.795[sip]   To: "216" <sip:216@192.168.0.101>;tag=19682
08:48:11.795[sip]   From: "216" <sip:216@192.168.0.101>;tag=8aceS8tX6mc2r
08:48:11.795[sip]   Call-ID: 73b00467-e062-1234-c2b8-a8f94b0e6be9
08:48:11.795[sip]   CSeq: 6865 OPTIONS
08:48:11.795[sip]   Content-Length: 0
08:48:11.795[sip]   
08:48:11.795[sip]   ------------------------------------------------------------------------
08:48:11.795[sip]nta: received 501 Not Implemented for OPTIONS (6865)
08:48:11.795[sip]nta: 501 Not Implemented is going to a transaction
08:48:16.345[sip]nta: timer D fired, terminate INVITE (34709)
08:48:16.345[sip]nta: timer F fired, terminating ACK (34709)
08:48:16.345[sip]nta_outgoing_timer: 0/0 resent, 1/2 tout, 1/4 term, 2/6 free
08:48:16.805[sip]nta: timer K fired, terminate OPTIONS (6865)
08:48:16.805[sip]nta_outgoing_timer: 0/0 resent, 0/1 tout, 1/3 term, 1/4 free
08:48:17.315[app:dbg]app: REINIT
08:48:17.315[app:ERR]pbx: select Interrupted system call

