09:22:26.858[app:dbg]Enable RFC2833 events
09:22:26.858[app:dbg]Set RFC2833 PT: 101(01A6, 65FF)
09:22:26.858[app:dbg]chan 5. vapi_cb_setchan: VOIP_SET_DTMFOPT2
09:22:26.858[app:dbg]chan 5. vapi_cb_setchan: VOIP_SET_PT2
09:22:26.858[app:dbg]vapi: Conn 5. Enable RTP indication
09:22:26.858[app:dbg]chan 5. vapi_cb_setchan: VOIP_ENABLE_RTP_IND
09:22:26.858[app:dbg]chan 5: set jitter buffer options
09:22:26.858[app:dbg]Conn 5, JB it not MFPT, set delay to [0;200]ms, mode soft th 500
09:22:26.858[app:dbg]chan 5. vapi_cb_setchan: VOIP_SET_INDCTL
09:22:26.858[app:dbg]chan 5. vapi_cb_setchan: VOIP_SET_JBOPT
09:22:26.858[app:dbg]vapi: Conn 5. Set tone ctl options
09:22:26.858[app:dbg]chan 5. vapi_cb_setchan: VOIP_SET_VLAN
09:22:26.858[app:dbg]VAD: 1 CNG: 0 PTE: 20
09:22:26.868[app:dbg]FORCE_BIND; bind msp_sock
09:22:26.868[app:dbg]bind net_sock addr = 192.168.253.1 port = 120
09:22:26.868[app:dbg]FORCE_BIND; bind net_sock
09:22:26.868[app:dbg]bind net_sock addr = 192.168.0.217 port = 43100
09:22:26.868[sip]recv 313 bytes from udp/[192.168.0.101]:5060 at 19:51:49.860000:
09:22:26.868[sip]   ------------------------------------------------------------------------
09:22:26.868[sip]   ACK sip:219@192.168.0.217:5060 SIP/2.0
09:22:26.868[sip]   Via: SIP/2.0/UDP 192.168.0.101:5060;branch=z9hG4bK0000446a
09:22:26.868[sip]   Max-Forwards: 70
09:22:26.868[sip]   To: sip:219@192.168.0.101;tag=Z2Sj84pN0am2r
09:22:26.868[sip]   From: "Potapova" <sip:218@192.168.0.101>;tag=670
09:22:26.868[sip]   Call-ID: 00007ca2-35218c5e4b4410009d130080f0a4b6a0@192.168.0.101
09:22:26.868[sip]   CSeq: 2 ACK
09:22:26.868[sip]   Content-Length: 0
09:22:26.868[sip]   
09:22:26.868[sip]   ------------------------------------------------------------------------
09:22:26.868[sip]nta: received ACK sip:219@192.168.0.217:5060 SIP/2.0 (CSeq 2)
09:22:26.868[sip]nta: ACK (2) is going to INVITE (2)
09:22:26.868[sip]nua(0x390a00): event i_ack 200 OK
09:22:26.868[sip]nua(0x390a00): call state changed: completed -> ready
09:22:26.868[sip]nua(0x390a00): event i_state 200 OK
09:22:26.868[sip]nua(0x390a00): event i_active 200 Call active
09:22:26.868[sip]recv 644 bytes from udp/[192.168.0.101]:5060 at 19:51:49.870000:
09:22:26.868[sip]   ------------------------------------------------------------------------
09:22:26.868[sip]   SIP/2.0 200 OK
09:22:26.868[sip]   Via: SIP/2.0/UDP 192.168.0.217;branch=z9hG4bKB9v7HZDDUvXgS;rport=5060
09:22:26.868[sip]   To: sip:219@192.168.0.101;tag=28587
09:22:26.868[sip]   From: "218" <sip:218@192.168.0.101>;tag=Xg704eNe6r7vH
09:22:26.868[sip]   Call-ID: de25ec9b-e2c2-1234-17ba-a8f94b0e6be9
09:22:26.868[sip]   CSeq: 165354 INVITE
09:22:26.868[sip]   Contact: sip:192.168.0.101:5060
09:22:26.868[sip]   Require: timer
09:22:26.868[sip]   Supported: timer
09:22:26.868[sip]   Session-Expires: 1800;refresher=uas
09:22:26.868[sip]   Allow: INVITE,ACK,CANCEL,BYE,REGISTER
09:22:26.868[sip]   Content-Type: application/sdp
09:22:26.868[sip]   Content-Length: 200
09:22:26.868[sip]   
09:22:26.868[sip]   v=0
09:22:26.868[sip]   o=- 1 1 IN IP4 192.168.0.217
09:22:26.868[sip]   s=-
09:22:26.868[sip]   c=IN IP4 192.168.0.217
09:22:26.868[sip]   t=0 0
09:22:26.868[sip]   m=audio 23720 RTP/AVP 8 101
09:22:26.868[sip]   a=rtpmap:8 PCMA/8000/1
09:22:26.868[sip]   a=rtpmap:101 telephone-event/8000
09:22:26.868[sip]   a=fmtp:101 0-15
09:22:26.868[sip]   a=sendrecv
09:22:26.868[sip]   a=ptime:20
09:22:26.868[sip]   ------------------------------------------------------------------------
09:22:26.868[sip]nta: received 200 OK for INVITE (165354)
09:22:26.868[sip]nta: 200 OK is going to a transaction
09:22:26.878[app:dbg]got nua_i_ack : 200(OK)
09:22:26.878[sip]nua(0x395500): INVITE: processed SDP answer in 200 OK
09:22:26.878[sip]nua(0x395500): event r_invite 200 OK
09:22:26.878[sip]nua(0x395500): call state changed: proceeding -> completing, received answer
09:22:26.878[sip]nua(0x395500): event i_state 200 OK
09:22:26.888[app:dbg]vapi_cb_req: 5 0 result 0x00000000 requid 0x00000516
09:22:26.888[app:dbg]got nua_i_state : 200(OK)
09:22:26.888[app:dbg]NO SIP IN nua_i_state == 200 : OK
09:22:26.888[app:dbg]self_i_state(): call state 8: : : sdp_init have_oc
09:22:26.888[app:dbg]sip: call 02050005: ACK from sip:218@192.168.0.101
09:22:26.888[app:dbg]sip: call 02050005: ACK from sip:218@192.168.0.101
09:22:26.888[app:dbg]got nua_i_active : 200(Call active)
09:22:26.888[app:dbg]NO SIP IN nua_i_active == 200 : Call active
09:22:26.888[app:dbg]got nua_r_invite : 200(OK)
09:22:26.888[app:dbg]sip: call 0004000a: INVITE: 200 OK
09:22:26.888[app:dbg]attr: name: ptime value: 20
09:22:26.888[app:dbg]sdp_codecs_set_ptime() ptime present : 20
09:22:26.888[app:dbg]sip: call 0004000a: current status (200)
09:22:26.888[app:dbg]got nua_i_state : 200(OK)
09:22:26.888[app:dbg]NO SIP IN nua_i_state == 200 : OK
09:22:26.888[app:dbg]self_i_state(): call state 4: ar : remote sdp : sdp_sent have_oc
09:22:26.888[app:dbg]sip: call 0004000a: SDP answer received
09:22:26.888[app:dbg]sip: call 0004000a: calltype 1, mode_codec 0, codec 0
09:22:26.888[app:dbg]sip: call 0004000a: SDP answer received
09:22:26.888[app:dbg]self_destroy_current_media() nothing to destroy
09:22:26.888[app:dbg]sdp_codecs_get_rfc2833: present=1 pt=101
09:22:26.888[app:dbg]sdp_codecs_set_rfc2833() present pt 101 remote fmtp 0-15, local fmtp 0-15
09:22:26.888[app:dbg]self_start_media: 1. handle call id 0x0004000A, call id 0x0004000A
09:22:26.888[app:dbg]sip: set options: call 0004000a: media stream 0: 192.168.0.217:23716 -> 192.168.0.217:23720: MFPT 0 <drop>
09:22:26.888[app:dbg]self_itc_codec(): payload 8
09:22:26.888[app:dbg]sip_set_rxtx_opts(): check rtpm <PCMA>:8
09:22:26.888[app:dbg]sip_set_rxtx_opts(): check offered 0: 8
09:22:26.888[app:dbg]self_itc_codec(): payload 8
09:22:26.888[app:dbg]Supported codec[0]: <G.711A>:8, vbd off, vad on, ecan on
09:22:26.888[app:dbg]validate_ptime() codec G.711A, ptime 20, check_bigger 1, present 1
09:22:26.888[app:dbg]validate_ptime() using 20
09:22:26.888[app:dbg]sdp_codecs_set_ptime() ptime present : 20
09:22:26.888[app:dbg]sip_set_rxtx_opts(): check rtpm <telephone-event>:101
09:22:26.888[app:dbg]sip_set_rxtx_opts(): check offered 0: 8
09:22:26.888[app:dbg]sip_set_rxtx_opts(): check offered 1: 0
09:22:26.888[app:dbg]sip_set_rxtx_opts(): check offered 2: 18
09:22:26.888[app:dbg]sip_set_rxtx_opts(): check offered 3: 101
09:22:26.888[app:dbg]self_itc_codec(): payload 101
09:22:26.888[app:dbg]validate_ptime() codec G.711A, ptime 20, check_bigger 1, present 1
09:22:26.888[app:dbg]validate_ptime() using 20
09:22:26.888[app:dbg]sdp_codecs_set_ptime() ptime present : 20
09:22:26.888[app:dbg]sdp_codecs_get_rfc2833: present=1 pt=101
09:22:26.888[app:dbg]validate_ptime() codec G.711A, ptime 20, check_bigger 1, present 1
09:22:26.888[app:dbg]validate_ptime() using 20
09:22:26.888[app:dbg]sdp_codecs_set_ptime() ptime present : 20
09:22:26.888[app:dbg]self_start_media: 2. handle call id 0x0004000A, call id 0x0004000A
09:22:26.888[app:dbg]sip -[msg_set_media]-> pbx
09:22:26.888[app:dbg]sip: call 0004000a: call answered
09:22:26.888[app:dbg]sip -[msg_answer]-> pbx
09:22:26.888[app:dbg]sip: call 0004000a: ACK to sip:219@192.168.0.101
09:22:26.888[app:dbg]vapi_proc_event: VAPI_CB
09:22:26.888[app:dbg]vapi_cb_chan: chan 5 reqest_id 0x00000516 result 0x00000000
09:22:26.888[app:dbg]VOIP_SET_VCEOPT: chan = 5
09:22:26.888[app:dbg]vapi_cb_setchan: chan 5 deactivate 0
09:22:26.888[app:dbg]chan 5. vapi_cb_setchan: VOIP_SET_VCEOPT
09:22:26.888[app:dbg]ITC: [msg_set_media] -> pbx
09:22:26.888[app:dbg]self_on_set_media: call id 0x0004000A tx/rx 1/1
09:22:26.888[app:dbg]dump_port_calls() SLIC 4:
09:22:26.898[app:dbg]Q:(0x365400,0x0004000A,(nil))
09:22:26.898[app:dbg]H:(0x364800,0x0204000D,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
09:22:26.898[app:dbg]SLIC 4: TX start / RX start: 192.168.0.217:23716->192.168.0.217:23720, <G.711A:8>
09:22:26.898[app:dbg]SLIC 4: send only 0 vad 1 g723_hr 1 vbd 0, ecan 1 rfc2833 pt 101, NSE pt 0, MFPT 0
09:22:26.898[app:dbg]self_set_media_start(): set ptime to 20
09:22:26.898[app:dbg]port_set_ip_param
09:22:26.898[app:dbg]set media param for '4', 192.168.0.217:23716, mode=local, random 13
09:22:26.898[app:dbg]port_set_ip_param
09:22:26.898[app:dbg]set media param for '4', 192.168.0.217:23720, mode=remote, random 13
09:22:26.898[app:dbg]CMD_CREATE_CONN: port = 4
09:22:26.898[app:dbg]Port 4: check vapi queue ('free') at vapi_create_chan:699
09:22:26.898[app:dbg]Chan 4: current state is CREATED
09:22:26.898[app:dbg]chan 4: no need to create - already exists
09:22:26.898[app:dbg]Port 4: check vapi queue ('free') at __cmd_engine:321
09:22:26.898[app:dbg]Port 4: check vapi queue ('free') at vapi_next_ops:2599
09:22:26.898[app:dbg]SLIC 4: starting media (G.711A) 192.168.0.217:23716 -> 192.168.0.217:23720
09:22:26.898[app:dbg]port 4: start voice - first time
09:22:26.898[app:dbg]port_start_voice() chan 04: remote IP <192.168.0.217> (arp query 0 times)
09:22:26.898[app:dbg]chan 4: get mac succesfull, repeat 0 times
09:22:26.898[app:dbg]CMD_START_VOICE: port = 4
09:22:26.898[app:dbg]vapi_set_chan_param: chan=4 hold=0 deactivate=0
09:22:26.898[app:dbg]Port 4: check vapi queue ('free') at vapi_set_chan_param:2174
09:22:26.898[app:dbg]Chan 4: current state is CREATED
09:22:26.898[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'start voice' at vapi_set_chan_param:2198
09:22:26.898[app:dbg]VQ Conn 4 = MSP :   'start voice' =
09:22:26.898[app:dbg]Conn 4 Eth src=00:00:00:00:00:00, dst=00:00:00:00:00:00
09:22:26.898[app:dbg]Conn 4 IP src=192.168.0.217:23716, dst=192.168.0.217:23720
09:22:26.898[app:dbg]CHECK REQID: 0x00000502(Conn 4)
09:22:26.898[app:dbg]vapi: Conn 4. Disable - Ok
09:22:26.898[app:dbg]ITC: [msg_answer] -> pbx
09:22:26.898[app:dbg]SLIC 4: peer answered
09:22:26.898[app:info]SLIC 4: from state 'ringback' to state 'talking'
09:22:26.898[app:dbg]CMD_STOP_TONE: port = 4
09:22:26.898[app:dbg]Port 4: check vapi queue ('busy''start voice') at vapi_stop_tone_chan:1503
09:22:26.898[app:dbg]Port 4 put cmd 'stop_tone',cur 'start voice' to queue at (vapi_stop_tone_chan:1509)
09:22:26.898[app:dbg]VQ Conn 4 = MSP :   'start voice' =
09:22:26.898[app:dbg]VQ Conn 4 + 05  :     'stop_tone'  + <-get_ptr 
09:22:26.898[app:dbg]Port 4: user port 2, old state holding, new state talking
09:22:26.898[app:dbg]Set port 4 led to state 'LED_ON'
09:22:26.898[app:dbg]pbx -[msg_fxs_state]-> group
09:22:26.898[app:dbg]ITC: [msg_fxs_state] -> group
09:22:26.898[app:dbg]-----[GM] self_fxs_state()
09:22:26.898[app:dbg]Port 4: new state is talking
09:22:26.898[app:dbg]vapi_cb_req: 5 0 result 0x00000000 requid 0x00000518
09:22:26.908[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000502
09:22:26.898[sip]nua(0x395500): recv signal r_set_params
09:22:26.908[sip]nua(0x395500): event r_set_params 200 OK
09:22:26.908[sip]nua(0x395500): recv signal r_ack
09:22:26.908[sip]send 540 bytes to udp/[192.168.0.101]:5060 at 19:51:49.910000:
09:22:26.908[sip]   ------------------------------------------------------------------------
09:22:26.908[sip]   ACK sip:192.168.0.101:5060 SIP/2.0
09:22:26.908[sip]   Via: SIP/2.0/UDP 192.168.0.217;rport;branch=z9hG4bKcjp0Ktygr5K3m
09:22:26.908[sip]   Max-Forwards: 70
09:22:26.908[sip]   From: "218" <sip:218@192.168.0.101>;tag=Xg704eNe6r7vH
09:22:26.908[sip]   To: <sip:219@192.168.0.101>;tag=28587
09:22:26.908[sip]   Call-ID: de25ec9b-e2c2-1234-17ba-a8f94b0e6be9
09:22:26.908[sip]   CSeq: 165354 ACK
09:22:26.908[sip]   Contact: <sip:218@192.168.0.217:5060>
09:22:26.908[sip]   Proxy-Authorization: Digest username="218", realm="Registered Users", nonce="b264c993264c983163c78e1c3972e4c8", algorithm=MD5, uri="sip:219@
192.168.0.101", response="da52b095c189a8b975240e93ae67b5d9"
09:22:26.908[sip]   Content-Length: 0
09:22:26.908[sip]   
09:22:26.908[sip]   ------------------------------------------------------------------------
09:22:26.908[sip]nta: sent ACK (165354) to */192.168.0.101:5060
09:22:26.908[sip]nua(0x395500): call state changed: completing -> ready
09:22:26.908[sip]nua(0x395500): event i_state 200 ACK sent
09:22:26.908[sip]nua(0x395500): event i_active 200 Call active
09:22:26.908[app:dbg]got nua_r_set_params : 200(OK)
09:22:26.908[app:dbg]NO SIP IN nua_r_set_params == 200 : OK
09:22:26.908[app:dbg]got nua_i_state : 200(ACK sent)
09:22:26.908[app:dbg]NO SIP IN nua_i_state == 200 : ACK sent
09:22:26.908[app:dbg]self_i_state(): call state 8: : : sdp_init have_oc
09:22:26.908[app:dbg]sip: call 0004000a: ACK from sip:218@192.168.0.101
09:22:26.908[app:dbg]got nua_i_active : 200(Call active)
09:22:26.908[app:dbg]NO SIP IN nua_i_active == 200 : Call active
09:22:26.908[app:dbg]vapi_proc_event: VAPI_CB
09:22:26.908[app:dbg]vapi_cb_chan: chan 5 reqest_id 0x00000518 result 0x00000000
09:22:26.908[app:dbg]VOIP_SET_VOICE: chan = 5
09:22:26.908[app:dbg]vapi_cb_setchan: chan 5 deactivate 0
09:22:26.908[app:dbg]vapi_cb_setchan() Conn 5: set eActive state ok
09:22:26.908[app:dbg]Port 5: check vapi queue ('busy''start voice') at vapi_next_ops:2599
09:22:26.908[app:dbg]vapi_proc_event: VAPI_CB
09:22:26.908[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000502 result 0x00000000
09:22:26.908[app:dbg]VOIP_DISABLE: chan = 4
09:22:26.908[app:dbg]vapi_cb_setchan: chan 4 deactivate 0
09:22:26.908[app:dbg]vapi: create: TDM channel 4 Set SSRC to 21BE0870
09:22:26.918[app:dbg]vapi: Conn 4. Set src/dst eth mac - Ok
09:22:26.918[app:dbg]Reserved IP: 192.168.253.1
09:22:26.918[app:dbg]vapi_cb_setchan: ch4. msp_ip = 192.168.253.2
09:22:26.918[app:dbg]IP PARAMS: 1FDA8C0 30716 2FDA8C0 30716
09:22:26.918[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000508
09:22:26.918[app:dbg]vapi: Conn 4. Set src/dst ip addr - ok
09:22:26.918[app:dbg]vapi_proc_event: VAPI_CB
09:22:26.918[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000508 result 0x00000000
09:22:26.918[app:dbg]VOIP_SET_IP: chan = 4
09:22:26.918[app:dbg]vapi_cb_setchan: chan 4 deactivate 0
09:22:26.918[app:dbg]chan 4. vapi_cb_setchan: configure ecan on
09:22:26.918[app:dbg]vapi_passthru_echocan_cb() NLP, DCRF enabled, session 0, on 1, tail 32ms, value 0x8003
09:22:26.918[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000547
09:22:26.918[app:dbg]vapi_proc_event: VAPI_CB
09:22:26.918[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000547 result 0x00000000
09:22:26.918[app:dbg]VOIP_SSRC_FILT: chan = 4
09:22:26.918[app:dbg]vapi_cb_setchan: chan 4 deactivate 0
09:22:26.918[app:dbg]chan 4. vapi_cb_setchan: VOIP_SSRC_FILT
09:22:26.918[app:dbg]vapi_cb_setchan: ch4. msp_ip = 192.168.253.2
09:22:26.918[app:dbg]RTCP IP PARAMS: 1FDA8C0 30717 2FDA8C0 30717
09:22:26.918[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x0000052b
09:22:26.918[app:dbg]vapi_proc_event: VAPI_CB
09:22:26.918[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x0000052b result 0x00000000
09:22:26.918[app:dbg]VOIP_SET_IP2: chan = 4
09:22:26.918[app:dbg]vapi_cb_setchan: chan 4 deactivate 0
09:22:26.918[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_PT
09:22:26.918[app:dbg]for chan <4> set codec type = 5 'G711A'
09:22:26.928[app:dbg]Create RX-TX media for SLIC 4(sendonly: 0, rtcp: 0)
09:22:26.928[app:dbg]FORCE_BIND; bind msp_sock
09:22:26.928[app:dbg]bind net_sock addr = 192.168.253.1 port = 64631
09:22:26.928[app:dbg]FORCE_BIND; bind net_sock
09:22:26.928[app:dbg]bind net_sock addr = 192.168.0.217 port = 42076
09:22:26.928[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x0000054e
09:22:26.928[app:dbg]vapi_proc_event: VAPI_CB
09:22:26.928[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x0000054e result 0x00000000
09:22:26.928[app:dbg]VOIP_SET_ADAPTATION_CODEC: chan = 4
09:22:26.928[app:dbg]vapi_cb_setchan: chan 4 deactivate 0
09:22:26.928[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_CODEC
09:22:26.928[app:dbg]set_packet_interval = 20
09:22:26.928[app:dbg]vapi: Conn 4. Set 'Packet interval' 20
09:22:26.928[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_PACKET
09:22:26.928[app:dbg]SET TX PT: 101
09:22:26.928[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000510
09:22:26.928[app:dbg]vapi_proc_event: VAPI_CB
09:22:26.928[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000510 result 0x00000000
09:22:26.928[app:dbg]VOIP_SET_PACKET2: chan = 4
09:22:26.928[app:dbg]vapi_cb_setchan: chan 4 deactivate 0
09:22:26.928[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_PACKET2
09:22:26.928[app:dbg]SET RX PT: 101
09:22:26.938[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000513
09:22:26.938[app:dbg]vapi_proc_event: VAPI_CB
09:22:26.938[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000513 result 0x00000000
09:22:26.938[app:dbg]VOIP_SET_DTMFOPT: chan = 4
09:22:26.938[app:dbg]vapi_cb_setchan: chan 4 deactivate 0
09:22:26.938[app:dbg]vapi: Chan 4 set chach (packet mode)
09:22:26.938[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_DTMFOPT dtmf 1, pt 101
09:22:26.938[app:dbg]Enable RFC2833 events
09:22:26.938[app:dbg]Set RFC2833 PT: 101(01A6, 65FF)
09:22:26.938[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_DTMFOPT2
09:22:26.938[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_PT2
09:22:26.938[app:dbg]vapi: Conn 4. Enable RTP indication
09:22:26.938[app:dbg]chan 4. vapi_cb_setchan: VOIP_ENABLE_RTP_IND
09:22:26.938[app:dbg]chan 4: set jitter buffer options
09:22:26.938[app:dbg]Conn 4, JB it not MFPT, set delay to [0;200]ms, mode soft th 500
09:22:26.938[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_INDCTL
09:22:26.938[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_JBOPT
09:22:26.938[app:dbg]vapi: Conn 4. Set tone ctl options
09:22:26.938[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_VLAN
09:22:26.938[app:dbg]VAD: 1 CNG: 0 PTE: 20
09:22:26.938[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000516
09:22:26.938[app:dbg]vapi_proc_event: VAPI_CB
09:22:26.938[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000516 result 0x00000000
09:22:26.938[app:dbg]VOIP_SET_VCEOPT: chan = 4
09:22:26.938[app:dbg]vapi_cb_setchan: chan 4 deactivate 0
09:22:26.938[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_VCEOPT
09:22:26.938[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000518
09:22:26.938[app:dbg]vapi_proc_event: VAPI_CB
09:22:26.938[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000518 result 0x00000000
09:22:26.938[app:dbg]VOIP_SET_VOICE: chan = 4
09:22:26.938[app:dbg]vapi_cb_setchan: chan 4 deactivate 0
09:22:26.938[app:dbg]vapi_cb_setchan() Conn 4: set eActive state ok
09:22:26.938[app:dbg]Port 4: check vapi queue ('busy''start voice') at vapi_next_ops:2599
09:22:26.938[app:dbg]Port 4 get cmd 'stop_tone' from queue at (vapi_next_ops:2618)
09:22:26.938[app:dbg]Port 4: check vapi queue ('free') at vapi_stop_tone_chan:1503
09:22:26.938[app:dbg]Chan 4: current state is CREATED
09:22:26.938[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'stop_tone' at vapi_stop_tone_chan:1549
09:22:26.938[app:dbg]VQ Conn 4 = MSP :     'stop_tone' =
09:22:26.938[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000923
09:22:26.938[app:dbg]chan 4 stop tone
09:22:26.948[app:dbg]vapi_proc_event: VAPI_CB
09:22:26.948[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000923 result 0x00000000
09:22:26.948[app:dbg]Conn 4: Stop tone - Successfull
09:22:26.948[app:dbg]Port 4: check vapi queue ('busy''stop_tone') at vapi_next_ops:2599
09:22:26.958[app:dbg]vapi: Conn 4. event 'RTP Monitor Ind': Start RTP stream , PT 0x0008 'PCM-A', silence 0
09:22:26.958[app:dbg]vapi: generic event, code 5 <SSRC change>, conn 0
09:22:26.998[app:dbg]vapi: Conn 5. event 'RTP Monitor Ind': Start RTP stream , PT 0x0008 'PCM-A', silence 0
09:22:26.998[app:dbg]vapi: generic event, code 5 <SSRC change>, conn 0
09:22:28.618[sip]nta: timer K fired, terminate REGISTER (149624)
09:22:28.618[sip]nta_outgoing_timer: 0/0 resent, 0/2 tout, 1/6 term, 1/8 free
09:22:28.618[sip]send 755 bytes to udp/[192.168.0.101]:5060 at 19:51:51.620000:
09:22:28.618[sip]   ------------------------------------------------------------------------
09:22:28.618[sip]   REGISTER sip:192.168.0.101:5060 SIP/2.0
09:22:28.618[sip]   Via: SIP/2.0/UDP 192.168.0.217;rport;branch=z9hG4bKDUFSNNFmNeapg
09:22:28.618[sip]   Max-Forwards: 70
09:22:28.618[sip]   From: "218" <sip:218@192.168.0.101>;tag=H4QQFaB48Dvvp
09:22:28.618[sip]   To: "218" <sip:218@192.168.0.101>
09:22:28.618[sip]   Call-ID: b07c6247-e278-1234-eeb9-a8f94b0e6be9
09:22:28.618[sip]   CSeq: 149637 REGISTER
09:22:28.618[sip]   Contact: <sip:218@192.168.0.217:5060>
09:22:28.618[sip]   Expires: 300
09:22:28.618[sip]   User-Agent: TAU-8.IP/2.1.0 SN/VI33023837 sofia-sip/1.12.10
09:22:28.618[sip]   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, INFO
09:22:28.618[sip]   Supported: timer, 100rel, replaces, path
09:22:28.618[sip]   Authorization: Digest username="218", realm="Registered Users", nonce="870e1c3972e4c890204183060c193265", algorithm=MD5, uri="sip:192.168.0.
101:5060", response="7b71516992d04ad5cb50d3df8698bc60"
09:22:28.618[sip]   Content-Length: 0
09:22:28.618[sip]   
09:22:28.618[sip]   ------------------------------------------------------------------------
09:22:28.618[sip]nta: sent REGISTER (149637) to udp/192.168.0.101:5060/sip
09:22:28.638[sip]nta: timer K fired, terminate OPTIONS (20339)
09:22:28.638[sip]nta_outgoing_timer: 0/1 resent, 0/3 tout, 1/5 term, 1/8 free
09:22:28.648[sip]recv 379 bytes from udp/[192.168.0.101]:5060 at 19:51:51.650000:
09:22:28.648[sip]   ------------------------------------------------------------------------
09:22:28.648[sip]   SIP/2.0 200 OK
09:22:28.648[sip]   Via: SIP/2.0/UDP 192.168.0.217;branch=z9hG4bKDUFSNNFmNeapg;rport=5060
09:22:28.648[sip]   To: "218" <sip:218@192.168.0.101>;tag=2570
09:22:28.648[sip]   From: "218" <sip:218@192.168.0.101>;tag=H4QQFaB48Dvvp
09:22:28.648[sip]   Call-ID: b07c6247-e278-1234-eeb9-a8f94b0e6be9
09:22:28.648[sip]   CSeq: 149637 REGISTER
09:22:28.648[sip]   Contact: sip:218@192.168.0.217:5060;expires=300
09:22:28.648[sip]   Expires: 300
09:22:28.648[sip]   Allow: INVITE,ACK,CANCEL,BYE,REGISTER
09:22:28.648[sip]   Content-Length: 0
09:22:28.648[sip]   
09:22:28.648[sip]   ------------------------------------------------------------------------
09:22:28.648[sip]nta: received 200 OK for REGISTER (149637)
09:22:28.648[sip]nta: 200 OK is going to a transaction
09:22:28.648[sip]send 382 bytes to udp/[192.168.0.101]:5060 at 19:51:51.650000:
09:22:28.648[sip]   ------------------------------------------------------------------------
09:22:28.648[sip]   OPTIONS sip:218@192.168.0.101 SIP/2.0
09:22:28.648[sip]   Via: SIP/2.0/UDP 192.168.0.217;rport;branch=z9hG4bKe48HQg0QjQ08B
09:22:28.648[sip]   Max-Forwards: 70
09:22:28.648[sip]   From: "218" <sip:218@192.168.0.101>;tag=H4QQFaB48Dvvp
09:22:28.648[sip]   To: "218" <sip:218@192.168.0.101>
09:22:28.648[sip]   Call-ID: e0b793fb-e2c2-1234-17ba-a8f94b0e6be9
09:22:28.648[sip]   CSeq: 20340 OPTIONS
09:22:28.648[sip]   Subject: KEEPALIVE
09:22:28.648[sip]   User-Agent: TAU-8.IP/2.1.0 SN/VI33023837 sofia-sip/1.12.10
09:22:28.648[sip]   Content-Length: 0
09:22:28.648[sip]   
09:22:28.648[sip]   ------------------------------------------------------------------------
09:22:28.648[sip]nta: sent OPTIONS (20340) to */192.168.0.101:5060
09:22:28.648[sip]nua(0x391000): event r_register 200 OK
09:22:28.648[app:dbg]got nua_r_register : 200(OK)
09:22:28.648[app:dbg]sip: endpoint 4: REGISTER: 200 OK
09:22:28.648[app:dbg]Port 4: user port 2, old state holding, new state talking
09:22:28.648[app:dbg]sip: endpoint 4: successfully registered
09:22:28.668[sip]recv 289 bytes from udp/[192.168.0.101]:5060 at 19:51:51.670000:
09:22:28.668[sip]   ------------------------------------------------------------------------
09:22:28.668[sip]   SIP/2.0 501 Not Implemented
09:22:28.668[sip]   Via: SIP/2.0/UDP 192.168.0.217;branch=z9hG4bKe48HQg0QjQ08B;rport=5060
09:22:28.668[sip]   To: "218" <sip:218@192.168.0.101>;tag=17544
09:22:28.668[sip]   From: "218" <sip:218@192.168.0.101>;tag=H4QQFaB48Dvvp
09:22:28.668[sip]   Call-ID: e0b793fb-e2c2-1234-17ba-a8f94b0e6be9
09:22:28.668[sip]   CSeq: 20340 OPTIONS
09:22:28.668[sip]   Content-Length: 0
09:22:28.668[sip]   
09:22:28.668[sip]   ------------------------------------------------------------------------
09:22:28.668[sip]nta: received 501 Not Implemented for OPTIONS (20340)
09:22:28.668[sip]nta: 501 Not Implemented is going to a transaction
09:22:29.418[sip]send 382 bytes to udp/[192.168.0.101]:5060 at 19:51:52.420000:
09:22:29.418[sip]   ------------------------------------------------------------------------
09:22:29.418[sip]   OPTIONS sip:219@192.168.0.101 SIP/2.0
09:22:29.418[sip]   Via: SIP/2.0/UDP 192.168.0.217;rport;branch=z9hG4bKFD2aSBHUF0pUQ
09:22:29.418[sip]   Max-Forwards: 70
09:22:29.418[sip]   From: "219" <sip:219@192.168.0.101>;tag=jDHgH5U75pjFj
09:22:29.418[sip]   To: "219" <sip:219@192.168.0.101>
09:22:29.418[sip]   Call-ID: cf46db3b-e2c2-1234-17ba-a8f94b0e6be9
09:22:29.418[sip]   CSeq: 20337 OPTIONS
09:22:29.418[sip]   Subject: KEEPALIVE
09:22:29.418[sip]   User-Agent: TAU-8.IP/2.1.0 SN/VI33023837 sofia-sip/1.12.10
09:22:29.418[sip]   Content-Length: 0
09:22:29.418[sip]   
09:22:29.418[sip]   ------------------------------------------------------------------------
09:22:29.418[sip]nta: sent OPTIONS (20337) to */192.168.0.101:5060
09:22:29.418[sip]nta: timer K fired, terminate OPTIONS (20336)
09:22:29.418[sip]nta_outgoing_timer: 0/1 resent, 0/3 tout, 1/6 term, 1/9 free
09:22:29.438[sip]recv 289 bytes from udp/[192.168.0.101]:5060 at 19:51:52.440000:
09:22:29.438[sip]   ------------------------------------------------------------------------
09:22:29.438[sip]   SIP/2.0 501 Not Implemented
09:22:29.438[sip]   Via: SIP/2.0/UDP 192.168.0.217;branch=z9hG4bKFD2aSBHUF0pUQ;rport=5060
09:22:29.438[sip]   To: "219" <sip:219@192.168.0.101>;tag=20125
09:22:29.438[sip]   From: "219" <sip:219@192.168.0.101>;tag=jDHgH5U75pjFj
09:22:29.438[sip]   Call-ID: cf46db3b-e2c2-1234-17ba-a8f94b0e6be9
09:22:29.438[sip]   CSeq: 20337 OPTIONS
09:22:29.438[sip]   Content-Length: 0
09:22:29.438[sip]   
09:22:29.438[sip]   ------------------------------------------------------------------------
09:22:29.438[sip]nta: received 501 Not Implemented for OPTIONS (20337)
09:22:29.438[sip]nta: 501 Not Implemented is going to a transaction
09:22:29.498[sip]nta: timer I fired, terminate 422 response
09:22:29.498[sip]nta_incoming_timer: 0/0 resent, 0/0 tout, 1/2 term, 1/2 free
09:22:29.758[app:dbg]slic4. Event 8.
09:22:29.758[app:dbg]slic 4. Pre-On-hook event
09:22:29.758[app:dbg]HIO: preonhook TDM port '4', port enabled 1
09:22:30.658[app:dbg]slic4. Event 1.
09:22:30.658[app:dbg]slic 4. On-hook event
09:22:30.658[app:dbg]Set port 4 led to state 'LED_OFF'
09:22:30.658[app:dbg]HIO: onhook TDM port '4', port enabled 1
09:22:30.658[app:dbg]SLIC 4 (218): onhook state: talking
09:22:30.658[app:dbg]regex ID 4: dial reset
09:22:30.658[app:WARN]SLIC 4: onhook in talking -> connect A & C!
09:22:30.658[app:dbg]SLIC 4: hold current call
09:22:30.658[app:dbg]is_local_call: check call 0204000D(304@192.168.0.101)
09:22:30.658[app:dbg]is_local_call: check call 0004000A(219@)
09:22:30.658[app:dbg]pbx -[msg_flash]-> sip
09:22:30.658[app:dbg]ITC: [msg_flash] -> sip
09:22:30.658[app:dbg]sip: call 0004000a: endpoint 4: flash
09:22:30.658[app:info]SLIC 4: from state 'talking' to state 'dvo'
09:22:30.658[app:dbg]Port 4: user port 2, old state holding, new state dvo
09:22:30.658[app:dbg]Set port 4 led to state 'LED_ON'
09:22:30.658[app:dbg]pbx -[msg_fxs_state]-> group
09:22:30.658[app:dbg]ITC: [msg_fxs_state] -> group
09:22:30.658[app:dbg]-----[GM] self_fxs_state()
09:22:30.658[app:dbg]Port 4: new state is dvo
09:22:30.658[app:dbg]SLIC 4: -> transfer call to sip/:0/219, pt 20
09:22:30.658[app:dbg]is_local_call: check call 0204000D(304@192.168.0.101)
09:22:30.658[app:dbg]is_local_call: check call 0004000A(219@)
09:22:30.658[app:dbg]pbx -[msg_transfer]-> sip
09:22:30.658[app:dbg]ITC: [msg_transfer] -> sip
09:22:30.658[app:dbg]sip: transfer call 0204000d from endpoint 4
09:22:30.658[app:dbg]sip_params_create() normal - using cur proxy [192.168.0.101:5060] if proxy call
09:22:30.658[app:dbg]stun_get_public_ip(port = 8000)
09:22:30.658[app:dbg]stun_get_public_ip: Always using local IP
09:22:30.658[app:dbg]sip: to host is <(null)> - should not have port; to user is <(null)>, use proxy - yes
09:22:30.658[app:dbg]sip -[msg_set_media]-> pbx
09:22:30.658[app:dbg]sip: call 0204000d: REFER to sip:192.168.0.101:5060?Replaces=de25ec9b-e2c2-1234-17ba-a8f94b0e6be9%3bto-tag%3d28587%3bfrom-tag%3dXg704eNe6r7
vH
09:22:30.658[sip]nua(0x36df00): recv signal r_refer
09:22:30.658[sip]nua(0x36df00): adding subscribe usage with event refer
09:22:30.658[sip]send 714 bytes to udp/[192.168.0.101]:5060 at 19:51:53.660000:
09:22:30.658[sip]   ------------------------------------------------------------------------
09:22:30.658[sip]   REFER sip:192.168.0.101:5060 SIP/2.0
09:22:30.658[sip]   Via: SIP/2.0/UDP 192.168.0.217;rport;branch=z9hG4bKgpU3t61yc9ceK
09:22:30.658[sip]   Max-Forwards: 70
09:22:30.658[sip]   From: <sip:218@192.168.0.101>;tag=v7D82K4a9FHap
09:22:30.658[sip]   To: <sip:304@192.168.0.101>;tag=32223
09:22:30.658[sip]   Call-ID: 000031f0-35218c5e434310009d120080f0a4b6a0@192.168.0.101
09:22:30.658[sip]   CSeq: 165352 REFER
09:22:30.658[sip]   Contact: <sip:218@192.168.0.217:5060>
09:22:30.658[sip]   User-Agent: TAU-8.IP/2.1.0 SN/VI33023837 sofia-sip/1.12.10
09:22:30.658[sip]   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, INFO
09:22:30.658[sip]   Supported: timer, 100rel, replaces
09:22:30.668[sip]   Refer-To: <sip:192.168.0.101:5060?Replaces=de25ec9b-e2c2-1234-17ba-a8f94b0e6be9%3bto-tag%3d28587%3bfrom-tag%3dXg704eNe6r7vH>
09:22:30.668[sip]   Referred-By: <sip:218@192.168.0.101>
09:22:30.668[sip]   Content-Length: 0
09:22:30.668[sip]   
09:22:30.668[sip]   ------------------------------------------------------------------------
09:22:30.668[sip]nta: sent REFER (165352) to */192.168.0.101:5060
09:22:30.668[sip]nua(0x36df00): event r_refer 100 Trying
09:22:30.668[app:dbg]got nua_r_refer : 100(Trying)
09:22:30.668[app:dbg]NO SIP IN nua_r_refer == 100 : Trying
09:22:30.668[app:WARN]sip: call 0204000d: REFER: 100 Trying
09:22:30.668[app:dbg]sip: call 0204000d: Proxy 100 wait 202 Accepted
09:22:30.678[app:info]SLIC 4: from state 'dvo' to state 'hangup'
09:22:30.678[app:dbg]CMD_STOP_TONE: port = 4
09:22:30.678[app:dbg]Port 4: check vapi queue ('free') at vapi_stop_tone_chan:1503
09:22:30.678[app:dbg]Chan 4: current state is CREATED
09:22:30.678[app:ERR]chan 4: no generated tones!
09:22:30.678[app:dbg]vapi_chan.c:1539: conn 4 peek cmd 'no event' from queue
09:22:30.678[app:dbg]Port 4: check vapi queue ('free') at __cmd_engine:321
09:22:30.678[app:dbg]Port 4: check vapi queue ('free') at vapi_next_ops:2599
09:22:30.678[app:dbg]SLIC 4: reset
09:22:30.678[app:dbg]dump_port_calls() SLIC 4:
09:22:30.678[app:dbg]Q:(0x365400,0x0004000A,(nil))
09:22:30.678[app:dbg]H:(0x364800,0x0204000D,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
09:22:30.678[app:dbg]vapi: chan 4: connection STATISTIC
09:22:30.678[app:dbg]vapi: chan 4: Rx_pack = 120
09:22:30.678[app:dbg]vapi: chan 4: Rx_oct  = 19050
09:22:30.678[app:dbg]vapi: chan 4: Lost_pack  = 0
09:22:30.678[app:dbg]vapi: chan 4: Tx_pack = 102
09:22:30.678[app:dbg]vapi: chan 4: Tx_oct  = 15954
09:22:30.678[app:dbg]vapi: chan 4: peak_jiter = 2
09:22:30.678[app:dbg]SLIC 4: Common port statistic
09:22:30.678[app:dbg]SLIC 4: Rx_pack = 47243
09:22:30.678[app:dbg]SLIC 4: Rx_oct  = 8085587
09:22:30.678[app:dbg]SLIC 4: Lost_pack  = 0
09:22:30.678[app:dbg]SLIC 4: Tx_pack = 34248
09:22:30.678[app:dbg]SLIC 4: Tx_oct  = 5464077
09:22:30.678[app:dbg]SLIC 4: peak_jiter = 2
09:22:30.678[app:dbg]SLIC 4: reset call 0x0004000A (active)
09:22:30.678[app:dbg]CMD_SET_VOICE: port = 4
09:22:30.678[app:dbg]Port 4: check vapi queue ('free') at vapi_start_stop_chan:1652
09:22:30.678[app:dbg]Chan 4: current state is CREATED
09:22:30.678[app:dbg]vapi: Conn 4. start_stop voice chan, TX stop, RX stop
09:22:30.678[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'set voice' at vapi_start_stop_chan:1695
09:22:30.678[app:dbg]VQ Conn 4 = MSP :     'set voice' =
09:22:30.678[app:dbg]vapi: chan 4: connection STATISTIC
09:22:30.678[app:dbg]vapi: chan 4: Rx_pack = 72
09:22:30.678[app:dbg]vapi: chan 4: Rx_oct  = 12225
09:22:30.678[app:dbg]vapi: chan 4: Lost_pack  = 0
09:22:30.678[app:dbg]vapi: chan 4: Tx_pack = 428
09:22:30.678[app:dbg]vapi: chan 4: Tx_oct  = 72662
09:22:30.678[app:dbg]vapi: chan 4: peak_jiter = 30
09:22:30.678[app:dbg]SLIC 4: Common port statistic
09:22:30.678[app:dbg]SLIC 4: Rx_pack = 47315
09:22:30.678[app:dbg]SLIC 4: Rx_oct  = 8097812
09:22:30.678[app:dbg]SLIC 4: Lost_pack  = 0
09:22:30.678[app:dbg]SLIC 4: Tx_pack = 34676
09:22:30.678[app:dbg]SLIC 4: Tx_oct  = 5536739
09:22:30.678[app:dbg]SLIC 4: peak_jiter = 30
09:22:30.678[app:dbg]SLIC 4: reset call 0x0204000D (hold)
09:22:30.678[app:dbg]CMD_SET_IPONLY_VOICE: port = 4
09:22:30.678[app:dbg]Port 4: check vapi queue ('busy''set voice') at vapi_start_stop_chan:1652
09:22:30.678[app:dbg]Port 4 put cmd 'set voice',cur 'set voice' to queue at (vapi_start_stop_chan:1659)
09:22:30.678[app:dbg]VQ Conn 12 = MSP :     'set voice' =
09:22:30.678[app:dbg]VQ Conn 12 + 06  :     'set voice' (hold) + <-get_ptr 
09:22:30.678[app:dbg]incom_calls_set_media_started() call 0x0204000D, group -1, task <sip> media stopped
09:22:30.678[app:dbg]CMD_DESTROY_IPONLY_CONN: port = 4
09:22:30.678[app:dbg]Port 4: check vapi queue ('busy''set voice') at vapi_destroy_chan:895
09:22:30.678[app:dbg]Clear vapi queue of Port 4/chan 12
09:22:30.678[app:dbg]Port 4 put cmd 'destroy',cur 'set voice' to queue at (vapi_destroy_chan:902)
09:22:30.678[app:dbg]VQ Conn 12 = MSP :     'set voice' =
09:22:30.678[app:dbg]VQ Conn 12 + 00  :       'destroy' (hold) + <-get_ptr 
09:22:30.678[app:dbg]incom_calls_rem() rem call 0x0204000D, group -1, task <sip> from list
09:22:30.678[app:dbg]free_final_mx: final_mx was NULL for SLIC 4
09:22:30.678[app:dbg]CMD_DESTROY_CONN: port = 4
09:22:30.678[app:dbg]Port 4: check vapi queue ('busy''set voice') at vapi_destroy_chan:895
09:22:30.678[app:dbg]Clear vapi queue of Port 4/chan 4
09:22:30.678[app:dbg]Port 4 put cmd 'destroy',cur 'set voice' to queue at (vapi_destroy_chan:902)
09:22:30.678[app:dbg]VQ Conn 4 = MSP :     'set voice' =
09:22:30.678[app:dbg]VQ Conn 4 + 00  :       'destroy' (hold) + <-get_ptr 
09:22:30.678[app:dbg]VQ Conn 4 + 01  :       'destroy'  +  
09:22:30.678[app:dbg]CMD_DESTROY_IPONLY_CONN: port = 4
09:22:30.678[app:dbg]Port 4: check vapi queue ('busy''set voice') at vapi_destroy_chan:895
09:22:30.678[app:dbg]Clear vapi queue of Port 4/chan 12
09:22:30.678[app:dbg]Port 4 put cmd 'destroy',cur 'set voice' to queue at (vapi_destroy_chan:902)
09:22:30.678[app:dbg]VQ Conn 12 = MSP :     'set voice' =
09:22:30.678[app:dbg]VQ Conn 12 + 00  :       'destroy'  + <-get_ptr 
09:22:30.678[app:dbg]VQ Conn 12 + 01  :       'destroy' (hold) +  
09:22:30.678[app:dbg]Port 4: user port 2, old state hangup, new state 
09:22:30.678[app:dbg]Set port 4 led to state 'LED_OFF'
09:22:30.678[app:dbg]pbx -[msg_fxs_state]-> group
09:22:30.678[app:dbg]dump_port_calls() SLIC 4:
09:22:30.678[app:dbg]Q:NONE
09:22:30.688[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000401
09:22:30.688[app:dbg]ITC: [msg_fxs_state] -> group
09:22:30.688[app:dbg]-----[GM] self_fxs_state()
09:22:30.688[app:dbg]Port 4: new state is hangup
09:22:30.688[app:dbg]Delete all RX-TX medias from SLIC 4
09:22:30.678[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
09:22:30.688[app:dbg]Set port 4 led to state 'LED_OFF'
09:22:30.688[app:dbg]ITC: [msg_set_media] -> pbx
09:22:30.688[app:dbg]self_on_set_media: call id 0x0204000D tx/rx 0/-1
09:22:30.688[app:dbg]dump_port_calls() SLIC 4:
09:22:30.688[app:dbg]Q:NONE
09:22:30.688[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
09:22:30.688[app:dbg]self_on_set_media() SLIC 4: no such call / hold call! 0x204000D
09:22:30.688[app:dbg]vapi_proc_event: VAPI_CB
09:22:30.688[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000401 result 0x00000000
09:22:30.688[app:dbg]vapi: conn 4. RTCP disabled
09:22:30.688[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x000004ff
09:22:30.688[app:dbg]vapi_proc_event: VAPI_CB
09:22:30.688[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x000004ff result 0x00000000
09:22:30.688[app:dbg]Conn 4: Set voice mode successeful
09:22:30.688[app:dbg]Stop all medias on chan 4
09:22:30.688[app:dbg]Port 4: check vapi queue ('busy''set voice') at vapi_next_ops:2599
09:22:30.688[app:dbg]Port 4 get cmd 'destroy' from queue at (vapi_next_ops:2618)
09:22:30.688[app:dbg]VQ Conn 4 + 01  :       'destroy' (hold) + <-get_ptr 
09:22:30.688[app:dbg]Port 4: check vapi queue ('free') at vapi_destroy_chan:895
09:22:30.688[app:dbg]Destroying connection 4...
09:22:30.688[app:dbg]Chan 4: current state is CREATED
09:22:30.688[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'destroy' at vapi_destroy_chan:921
09:22:30.688[app:dbg]VQ Conn 4 = MSP :       'destroy' =
09:22:30.688[app:dbg]VQ Conn 4 + 01  :       'destroy' (hold) + <-get_ptr 
09:22:30.688[app:dbg]Chan 4: CREATED -> DESTROYING
09:22:30.688[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x0000014b
09:22:30.688[app:dbg]vapi_proc_event: VAPI_CB
09:22:30.698[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x0000014b result 0x00000000
09:22:30.698[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000103
09:22:30.698[app:dbg]vapi_proc_event: VAPI_CB
09:22:30.698[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000103 result 0x00000000
09:22:30.698[app:dbg]Conn 4 destroyed
09:22:30.698[app:dbg]Chan 4: DESTROYING -> INITIAL
09:22:30.698[app:dbg]Port 4: check vapi queue ('busy''destroy') at vapi_next_ops:2599
09:22:30.698[app:dbg]Port 4 get cmd 'destroy' from queue at (vapi_next_ops:2618)
09:22:30.698[app:dbg]Port 4: check vapi queue ('free') at vapi_destroy_chan:895
09:22:30.698[app:dbg]Destroying connection 12...
09:22:30.698[app:dbg]Chan 12: current state is CREATED
09:22:30.698[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'destroy' at vapi_destroy_chan:921
09:22:30.698[app:dbg]VQ Conn 12 = MSP :       'destroy' =
09:22:30.698[app:dbg]Chan 12: CREATED -> DESTROYING
09:22:30.698[app:dbg]vapi_cb_req: 12 0 result 0x00000000 requid 0x0000014b
09:22:30.698[app:dbg]vapi_proc_event: VAPI_CB
09:22:30.698[app:dbg]vapi_cb_chan: chan 12 reqest_id 0x0000014b result 0x00000000
09:22:30.698[app:dbg]vapi_cb_req: 12 0 result 0x00000000 requid 0x00000103
09:22:30.698[app:dbg]Delete all RX-TX medias from SLIC 12
09:22:30.698[sip]recv 291 bytes from udp/[192.168.0.101]:5060 at 19:51:53.700000:
09:22:30.708[sip]   ------------------------------------------------------------------------
09:22:30.708[sip]   SIP/2.0 501 Not Implemented
09:22:30.708[sip]   Via: SIP/2.0/UDP 192.168.0.217;branch=z9hG4bKgpU3t61yc9ceK;rport=5060
09:22:30.708[sip]   To: sip:304@192.168.0.101;tag=32223
09:22:30.708[sip]   From: sip:218@192.168.0.101;tag=v7D82K4a9FHap
09:22:30.708[sip]   Call-ID: 000031f0-35218c5e434310009d120080f0a4b6a0@192.168.0.101
09:22:30.708[sip]   CSeq: 165352 REFER
09:22:30.708[sip]   Content-Length: 0
09:22:30.708[sip]   
09:22:30.708[sip]   ------------------------------------------------------------------------
09:22:30.708[sip]nta: received 501 Not Implemented for REFER (165352)
09:22:30.708[sip]nta: 501 Not Implemented is going to a transaction
09:22:30.708[sip]nua(0x36df00): event r_refer 501 Not Implemented
09:22:30.708[sip]nua(0x36df00): removing subscribe usage with event refer
09:22:30.708[sip]nua(0x36df00): handle with session and 
09:22:30.708[app:dbg]got nua_r_refer : 501(Not Implemented)
09:22:30.708[app:WARN]sip: call 0204000d: REFER: 501 Not Implemented
09:22:30.708[app:WARN]sip: call 0204000d: Transfer failed
09:22:30.708[app:dbg]sip: call ffffffff: BYE to sip:218@192.168.0.101
09:22:30.708[sip]nua: nua_r_bye with invalid handle 0x302600
09:22:30.708[app:dbg]sip: call ffffffff: BYE to sip:218@192.168.0.101
09:22:30.708[sip]nua: nua_r_bye with invalid handle 0x333f00
09:22:30.708[app:dbg]sip: call ffffffff: BYE to sip:218@192.168.0.101
09:22:30.708[sip]nua: nua_r_bye with invalid handle 0x395400
09:22:30.708[app:dbg]sip: call ffffffff: BYE to sip:218@192.168.0.101
09:22:30.708[sip]nua: nua_r_bye with invalid handle 0x36ea00
09:22:30.708[app:dbg]sip: call ffffffff: BYE to sip:218@192.168.0.101
09:22:30.708[sip]nua: nua_r_bye with invalid handle 0x331b00
09:22:30.708[app:dbg]sip: call ffffffff: BYE to sip:218@192.168.0.101
09:22:30.708[sip]nua: nua_r_bye with invalid handle 0x391500
09:22:30.708[app:dbg]sip: call ffffffff: BYE to sip:218@192.168.0.101
09:22:30.708[sip]nua: nua_r_bye with invalid handle 0x331200
09:22:30.708[app:dbg]sip: call ffffffff: BYE to sip:218@192.168.0.101
09:22:30.708[sip]nua: nua_r_bye with invalid handle 0x36a100
09:22:30.708[app:dbg]sip: call ffffffff: BYE to sip:218@192.168.0.101
09:22:30.708[sip]nua: nua_r_bye with invalid handle 0x331700
09:22:30.708[app:dbg]sip: call ffffffff: BYE to sip:218@192.168.0.101
09:22:30.708[sip]nua: nua_r_bye with invalid handle 0x3eea00
09:22:30.708[app:dbg]sip: call ffffffff: BYE to sip:218@192.168.0.101
09:22:30.708[app:dbg]sip: call 0204000d: BYE to sip:304@192.168.0.101
09:22:30.708[app:dbg]sip: call 0004000a: BYE to sip:219@192.168.0.101
09:22:30.708[sip]nua(0x391000): recv signal r_bye
09:22:30.708[sip]nua(0x391000): event r_bye 900 Invalid handle for BYE
09:22:30.708[sip]nua(0x36df00): recv signal r_bye
09:22:30.718[app:dbg]got nua_r_bye : 900(Invalid handle for BYE)
09:22:30.718[app:dbg]NO SIP IN nua_r_bye == 900 : Invalid handle for BYE
09:22:30.718[app:dbg]sip: call ffffffff: BYE/INFO: 900 Invalid handle for BYE
09:22:30.718[app:dbg]Mute all RX-TX medias on SLIC 4
09:22:30.718[app:dbg]vapi_proc_event: VAPI_CB
09:22:30.718[app:dbg]vapi_cb_chan: chan 12 reqest_id 0x00000103 result 0x00000000
09:22:30.718[app:dbg]Conn 12 destroyed
09:22:30.718[app:dbg]Chan 12: DESTROYING -> INITIAL
09:22:30.718[app:dbg]Port 4: check vapi queue ('busy''destroy') at vapi_next_ops:2599
09:22:30.718[sip]send 658 bytes to udp/[192.168.0.101]:5060 at 19:51:53.720000:
09:22:30.718[sip]   ------------------------------------------------------------------------
09:22:30.718[sip]   BYE sip:192.168.0.101:5060 SIP/2.0
09:22:30.718[sip]   Via: SIP/2.0/UDP 192.168.0.217;rport;branch=z9hG4bKHZmvv1j29H30e
09:22:30.718[sip]   Max-Forwards: 70
09:22:30.718[sip]   From: <sip:218@192.168.0.101>;tag=v7D82K4a9FHap
09:22:30.718[sip]   To: <sip:304@192.168.0.101>;tag=32223
09:22:30.718[sip]   Call-ID: 000031f0-35218c5e434310009d120080f0a4b6a0@192.168.0.101
09:22:30.718[sip]   CSeq: 165353 BYE
09:22:30.718[sip]   Contact: <sip:218@192.168.0.217:5060>
09:22:30.718[sip]   User-Agent: TAU-8.IP/2.1.0 SN/VI33023837 sofia-sip/1.12.10
09:22:30.718[sip]   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, INFO
09:22:30.718[sip]   Supported: timer, 100rel, replaces
09:22:30.718[sip]   Reason: Q.850;cause=16;text="Normal call clearing"
09:22:30.718[sip]   Content-Length: 0
09:22:30.718[sip]   P-RTP-Stat: PS=428, OS=72662, PR=72, OR=12225, PL=0, JI=30
09:22:30.718[sip]   
09:22:30.718[sip]   ------------------------------------------------------------------------
09:22:30.718[sip]nta: sent BYE (165353) to */192.168.0.101:5060
09:22:30.718[sip]nua(0x395500): recv signal r_bye
09:22:30.728[app:dbg]Delete all RX-TX medias from SLIC 4
09:22:30.728[sip]send 844 bytes to udp/[192.168.0.101]:5060 at 19:51:53.720000:
09:22:30.728[sip]   ------------------------------------------------------------------------
09:22:30.728[sip]   BYE sip:192.168.0.101:5060 SIP/2.0
09:22:30.728[sip]   Via: SIP/2.0/UDP 192.168.0.217;rport;branch=z9hG4bKj8DNyv356tSKa
09:22:30.728[sip]   Max-Forwards: 70
09:22:30.728[sip]   From: "218" <sip:218@192.168.0.101>;tag=Xg704eNe6r7vH
09:22:30.728[sip]   To: <sip:219@192.168.0.101>;tag=28587
09:22:30.728[sip]   Call-ID: de25ec9b-e2c2-1234-17ba-a8f94b0e6be9
09:22:30.728[sip]   CSeq: 165355 BYE
09:22:30.728[sip]   Contact: <sip:218@192.168.0.217:5060>
09:22:30.728[sip]   User-Agent: TAU-8.IP/2.1.0 SN/VI33023837 sofia-sip/1.12.10
09:22:30.728[sip]   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, INFO
09:22:30.728[sip]   Supported: timer, 100rel, replaces
09:22:30.728[sip]   Proxy-Authorization: Digest username="218", realm="Registered Users", nonce="b264c993264c983163c78e1c3972e4c8", algorithm=MD5, uri="sip:192.
168.0.101:5060", response="ff69a20ba1080fb8218e0f220b396beb"
09:22:30.728[sip]   Reason: Q.850;cause=16;text="Normal call clearing"
09:22:30.728[sip]   Content-Length: 0
09:22:30.728[sip]   P-RTP-Stat: PS=77, OS=12608, PR=66, OR=9762, PL=0, JI=2
09:22:30.728[sip]   
09:22:30.728[sip]   ------------------------------------------------------------------------
09:22:30.728[sip]nta: sent BYE (165355) to */192.168.0.101:5060
09:22:30.738[app:dbg]Delete all RX-TX medias from SLIC 12
09:22:30.768[sip]recv 276 bytes from udp/[192.168.0.101]:5060 at 19:51:53.770000:
09:22:30.768[sip]   ------------------------------------------------------------------------
09:22:30.768[sip]   SIP/2.0 200 OK
09:22:30.768[sip]   Via: SIP/2.0/UDP 192.168.0.217;branch=z9hG4bKHZmvv1j29H30e;rport=5060
09:22:30.768[sip]   To: sip:304@192.168.0.101;tag=32223
09:22:30.768[sip]   From: sip:218@192.168.0.101;tag=v7D82K4a9FHap
09:22:30.768[sip]   Call-ID: 000031f0-35218c5e434310009d120080f0a4b6a0@192.168.0.101
09:22:30.768[sip]   CSeq: 165353 BYE
09:22:30.768[sip]   Content-Length: 0
09:22:30.768[sip]   
09:22:30.768[sip]   ------------------------------------------------------------------------
09:22:30.768[sip]nta: received 200 OK for BYE (165353)
09:22:30.768[sip]nta: 200 OK is going to a transaction
09:22:30.768[sip]nua(0x36df00): event r_bye 200 OK
09:22:30.768[app:dbg]got nua_r_bye : 200(OK)
09:22:30.768[app:dbg]sip: call 0204000d: BYE/INFO: 200 OK
09:22:30.768[sip]nua(0x36df00): call state changed: terminating -> terminated
09:22:30.768[sip]nua(0x36df00): event i_state 200 to BYE
09:22:30.768[app:dbg]got nua_i_state : 200(to BYE)
09:22:30.768[app:dbg]NO SIP IN nua_i_state == 200 : to BYE
09:22:30.768[app:dbg]self_i_state(): call state 10: : : sdp_init have_oc
09:22:30.768[app:dbg]sip: call 0204000d: terminated
09:22:30.768[app:dbg]self_callstate_terminated: call id = 0204000D need_exchange_at_answer = 0
09:22:30.768[sip]nua(0x36df00): event i_terminated 200 to BYE
09:22:30.768[sip]nua(0x36df00): removing session usage
09:22:30.768[sip]nua: terminated session 0x36df00
09:22:30.768[sip]nua(0x36df00): recv signal r_destroy
09:22:30.768[sip]recv 265 bytes from udp/[192.168.0.101]:5060 at 19:51:53.770000:
09:22:30.768[sip]   ------------------------------------------------------------------------
09:22:30.768[sip]   SIP/2.0 200 OK
09:22:30.768[sip]   Via: SIP/2.0/UDP 192.168.0.217;branch=z9hG4bKj8DNyv356tSKa;rport=5060
09:22:30.768[sip]   To: sip:219@192.168.0.101;tag=28587
09:22:30.768[sip]   From: "218" <sip:218@192.168.0.101>;tag=Xg704eNe6r7vH
09:22:30.768[sip]   Call-ID: de25ec9b-e2c2-1234-17ba-a8f94b0e6be9
09:22:30.768[sip]   CSeq: 165355 BYE
09:22:30.768[sip]   Content-Length: 0
09:22:30.768[sip]   
09:22:30.768[sip]   ------------------------------------------------------------------------
09:22:30.768[sip]nta: received 200 OK for BYE (165355)
09:22:30.768[sip]nta: 200 OK is going to a transaction
09:22:30.768[sip]nua(0x395500): event r_bye 200 OK
09:22:30.768[app:dbg]got nua_r_bye : 200(OK)
09:22:30.778[sip]nua(0x395500): call state changed: terminating -> terminated
09:22:30.778[sip]nua(0x395500): event i_state 200 to BYE
09:22:30.778[sip]nua(0x395500): event i_terminated 200 to BYE
09:22:30.778[sip]nua(0x395500): removing session usage
09:22:30.778[sip]nua: terminated session 0x395500
09:22:30.778[sip]recv 352 bytes from udp/[192.168.0.101]:5060 at 19:51:53.780000:
09:22:30.778[sip]   ------------------------------------------------------------------------
09:22:30.778[sip]   BYE sip:219@192.168.0.217:5060 SIP/2.0
09:22:30.778[sip]   Via: SIP/2.0/UDP 192.168.0.101:5060;branch=z9hG4bK00004512
09:22:30.778[sip]   Max-Forwards: 70
09:22:30.778[sip]   To: sip:219@192.168.0.101;tag=Z2Sj84pN0am2r
09:22:30.778[sip]   From: "Potapova" <sip:218@192.168.0.101>;tag=670
09:22:30.778[sip]   Call-ID: 00007ca2-35218c5e4b4410009d130080f0a4b6a0@192.168.0.101
09:22:30.778[sip]   CSeq: 3 BYE
09:22:30.778[sip]   Allow: INVITE,ACK,CANCEL,BYE,REGISTER
09:22:30.778[sip]   Content-Length: 0
09:22:30.778[sip]   
09:22:30.778[sip]   ------------------------------------------------------------------------
09:22:30.778[sip]nta: received BYE sip:219@192.168.0.217:5060 SIP/2.0 (CSeq 3)
09:22:30.778[sip]nta: BYE (3) going to existing leg
09:22:30.778[sip]nua(0x390a00): event i_bye 100 Trying
09:22:30.768[app:dbg]sip: call 0004000a: BYE/INFO: 200 OK
09:22:30.778[app:dbg]got nua_i_state : 200(to BYE)
09:22:30.778[app:dbg]NO SIP IN nua_i_state == 200 : to BYE
09:22:30.778[app:dbg]self_i_state(): call state 10: : : sdp_init have_oc
09:22:30.778[app:dbg]sip: call 0004000a: terminated
09:22:30.778[app:dbg]self_callstate_terminated: call id = 0004000A need_exchange_at_answer = 0
09:22:30.778[sip]nua(0x395500): recv signal r_destroy
09:22:30.778[app:dbg]got nua_i_bye : 100(Trying)
09:22:30.778[sip]nua(0x390a00): recv signal r_respond 200 OK
09:22:30.778[sip]send 523 bytes to udp/[192.168.0.101]:5060 at 19:51:53.780000:
09:22:30.778[sip]   ------------------------------------------------------------------------
09:22:30.788[sip]   SIP/2.0 200 OK
09:22:30.788[sip]   Via: SIP/2.0/UDP 192.168.0.101:5060;branch=z9hG4bK00004512
09:22:30.788[sip]   From: "Potapova" <sip:218@192.168.0.101>;tag=670
09:22:30.788[sip]   To: sip:219@192.168.0.101;tag=Z2Sj84pN0am2r
09:22:30.788[sip]   Call-ID: 00007ca2-35218c5e4b4410009d130080f0a4b6a0@192.168.0.101
09:22:30.788[sip]   CSeq: 3 BYE
09:22:30.788[sip]   User-Agent: TAU-8.IP/2.1.0 SN/VI33023837 sofia-sip/1.12.10
09:22:30.788[sip]   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, INFO
09:22:30.788[sip]   Supported: timer, 100rel, replaces
09:22:30.788[sip]   Content-Length: 0
09:22:30.788[sip]   P-RTP-Stat: PS=71, OS=10622, PR=80, OR=13124, PL=0, JI=0
09:22:30.788[sip]   
09:22:30.788[sip]   ------------------------------------------------------------------------
09:22:30.788[sip]nta: sent 200 OK for BYE (3)
09:22:30.788[sip]nua(0x390a00): removing session usage
09:22:30.788[sip]nua(0x390a00): call state changed: ready -> terminated
09:22:30.788[sip]nua(0x390a00): event i_state 200 Session Terminated
09:22:30.788[app:dbg]got nua_i_state : 200(Session Terminated)
09:22:30.788[app:dbg]NO SIP IN nua_i_state == 200 : Session Terminated
09:22:30.788[app:dbg]self_i_state(): call state 10: : : sdp_init have_oc
09:22:30.788[app:dbg]sip: call 02050005: terminated
09:22:30.788[app:dbg]7336: endpoint 5 set to busy
09:22:30.788[app:dbg]sip -[msg_clear]-> pbx
09:22:30.788[app:dbg]ITC: [msg_clear] -> pbx
09:22:30.788[app:dbg]dump_port_calls() SLIC 5:
09:22:30.788[app:dbg]Q:(0x363000,0x02050005,(nil))
09:22:30.788[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
09:22:30.788[app:dbg]SLIC 5: peer cleared(02050005)
09:22:30.788[app:dbg]SLIC 5: current call cleared
09:22:30.788[app:dbg]SLIC 5: -> busy - no hold call, no wait call
09:22:30.788[app:info]SLIC 5: from state 'talking' to state 'busy'
09:22:30.788[app:dbg]port_start_tone(5 22 0 0)
09:22:30.788[app:dbg]CMD_START_TONE: port = 5
09:22:30.788[app:dbg]Port 5: check vapi queue ('free') at vapi_start_tone_chan:1412
09:22:30.788[app:dbg]Chan 5: current state is CREATED
09:22:30.788[app:dbg]Port 5: set vapi queue MSP to 'busy' with 'start_tone' at vapi_start_tone_chan:1449
09:22:30.788[app:dbg]VQ Conn 5 = MSP :    'start_tone' =
09:22:30.788[app:dbg]Conn 5, tone config: tone_high: 425Hz, tone_low: 0Hz, tone_t_on1: 330ms, tone_t_off1: 330ms, tone_t_on2: 0ms, tone_t_off2: 0ms
09:22:30.788[app:dbg]chan 5 start tone, id=22, direction=TDM
09:22:30.788[app:dbg]Port 5: user port 3, old state busy, new state 
09:22:30.788[app:dbg]Set port 5 led to state 'LED_ON'
09:22:30.788[app:dbg]pbx -[msg_fxs_state]-> group
09:22:30.788[app:dbg]vapi: chan 5: connection STATISTIC
09:22:30.788[app:dbg]vapi: chan 5: Rx_pack = 105
09:22:30.788[app:dbg]vapi: chan 5: Rx_oct  = 16470
09:22:30.788[app:dbg]vapi: chan 5: Lost_pack  = 0
09:22:30.788[app:dbg]vapi: chan 5: Tx_pack = 125
09:22:30.788[app:dbg]vapi: chan 5: Tx_oct  = 19910
09:22:30.788[app:dbg]vapi: chan 5: peak_jiter = 0
09:22:30.788[app:dbg]SLIC 5: Common port statistic
09:22:30.788[app:dbg]SLIC 5: Rx_pack = 13024
09:22:30.788[app:dbg]SLIC 5: Rx_oct  = 2224864
09:22:30.788[app:dbg]SLIC 5: Lost_pack  = 0
09:22:30.788[app:dbg]SLIC 5: Tx_pack = 15180
09:22:30.788[app:dbg]SLIC 5: Tx_oct  = 2383188
09:22:30.788[app:dbg]SLIC 5: peak_jiter = 0
09:22:30.788[app:dbg]SLIC 5: reset call 0x02050005 (active)
09:22:30.788[app:dbg]CMD_SET_VOICE: port = 5
09:22:30.788[app:dbg]Port 5: check vapi queue ('busy''start_tone') at vapi_start_stop_chan:1652
09:22:30.788[app:dbg]Port 5 put cmd 'set voice',cur 'start_tone' to queue at (vapi_start_stop_chan:1659)
09:22:30.788[app:dbg]VQ Conn 5 = MSP :    'start_tone' =
09:22:30.788[app:dbg]VQ Conn 5 + 01  :     'set voice'  + <-get_ptr 
09:22:30.798[app:dbg]vapi_cb_req: 5 0 result 0x00000000 requid 0x00000922
09:22:30.798[app:dbg]ITC: [msg_fxs_state] -> group
09:22:30.798[app:dbg]-----[GM] self_fxs_state()
09:22:30.798[app:dbg]Port 5: new state is busy
09:22:30.798[app:dbg]self_callstate_terminated: call id = 02050005 need_exchange_at_answer = 0
09:22:30.798[sip]nua(0x390a00): event i_terminated 200 Session Terminated
09:22:30.798[sip]nua(0x390a00): recv signal r_destroy
09:22:30.788[app:dbg]incom_calls_set_media_started() call 0x02050005, group -1, task <sip> media stopped
09:22:30.798[app:dbg]incom_calls_rem() rem call 0x02050005, group -1, task <sip> from list
09:22:30.798[app:dbg]Delete all RX-TX medias from SLIC 5
09:22:30.798[app:dbg]dump_port_calls() SLIC 5:
09:22:30.798[app:dbg]Q:NONE
09:22:30.798[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
09:22:30.798[app:dbg]vapi_proc_event: VAPI_CB
09:22:30.798[app:dbg]vapi_cb_chan: chan 5 reqest_id 0x00000922 result 0x00000000
09:22:30.798[app:dbg]Conn 5: Start tone - Successfull
09:22:30.798[app:dbg]Port 5: check vapi queue ('busy''start_tone') at vapi_next_ops:2599
09:22:30.798[app:dbg]Port 5 get cmd 'set voice' from queue at (vapi_next_ops:2618)
09:22:30.798[app:dbg]Port 5: check vapi queue ('free') at vapi_start_stop_chan:1652
09:22:30.798[app:dbg]Chan 5: current state is CREATED
09:22:30.798[app:dbg]vapi: Conn 5. start_stop voice chan, TX stop, RX stop
09:22:30.798[app:dbg]Port 5: set vapi queue MSP to 'busy' with 'set voice' at vapi_start_stop_chan:1695
09:22:30.798[app:dbg]VQ Conn 5 = MSP :     'set voice' =
09:22:30.798[app:dbg]vapi_cb_req: 5 0 result 0x00000000 requid 0x00000401
09:22:30.798[app:dbg]vapi_proc_event: VAPI_CB
09:22:30.798[app:dbg]vapi_cb_chan: chan 5 reqest_id 0x00000401 result 0x00000000
09:22:30.798[app:dbg]vapi: conn 5. RTCP disabled
09:22:30.798[app:dbg]vapi_cb_req: 5 0 result 0x00000000 requid 0x000004ff
09:22:30.798[app:dbg]vapi_proc_event: VAPI_CB
09:22:30.798[app:dbg]vapi_cb_chan: chan 5 reqest_id 0x000004ff result 0x00000000
09:22:30.798[app:dbg]Conn 5: Set voice mode successeful
09:22:30.798[app:dbg]Stop all medias on chan 5
09:22:30.798[app:dbg]Port 5: check vapi queue ('busy''set voice') at vapi_next_ops:2599
09:22:30.808[app:dbg]Mute all RX-TX medias on SLIC 5
09:22:31.868[sip]nta: timer I fired, terminate 200 response
09:22:31.868[sip]nta_incoming_timer: 0/0 resent, 0/0 tout, 1/2 term, 1/2 free
09:22:33.658[sip]nta: timer K fired, terminate REGISTER (149637)
09:22:33.658[sip]nta_outgoing_timer: 0/0 resent, 0/2 tout, 1/9 term, 1/11 free
09:22:33.678[sip]nta: timer K fired, terminate OPTIONS (20340)
09:22:33.678[sip]nta_outgoing_timer: 0/0 resent, 0/2 tout, 1/8 term, 1/10 free
09:22:33.828[app:dbg]slic5. Event 8.
09:22:33.828[app:dbg]slic 5. Pre-On-hook event
09:22:33.828[app:dbg]HIO: preonhook TDM port '5', port enabled 1
09:22:33.828[app:dbg]CMD_STOP_TONE: port = 5
09:22:33.828[app:dbg]Port 5: check vapi queue ('free') at vapi_stop_tone_chan:1503
09:22:33.828[app:dbg]Chan 5: current state is CREATED
09:22:33.828[app:dbg]Port 5: set vapi queue MSP to 'busy' with 'stop_tone' at vapi_stop_tone_chan:1549
09:22:33.828[app:dbg]VQ Conn 5 = MSP :     'stop_tone' =
09:22:33.828[app:dbg]chan 5 stop tone
09:22:33.838[app:dbg]vapi_cb_req: 5 0 result 0x00000000 requid 0x00000923
09:22:33.838[app:dbg]vapi_proc_event: VAPI_CB
09:22:33.838[app:dbg]vapi_cb_chan: chan 5 reqest_id 0x00000923 result 0x00000000
09:22:33.838[app:dbg]Conn 5: Stop tone - Successfull
09:22:33.838[app:dbg]Port 5: check vapi queue ('busy''stop_tone') at vapi_next_ops:2599
09:22:33.838[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, conn 5
09:22:34.448[sip]nta: timer K fired, terminate OPTIONS (20337)
09:22:34.448[sip]nta_outgoing_timer: 0/0 resent, 0/2 tout, 1/7 term, 1/9 free
09:22:34.738[app:dbg]slic5. Event 1.
09:22:34.738[app:dbg]slic 5. On-hook event
09:22:34.738[app:dbg]Set port 5 led to state 'LED_OFF'
09:22:34.738[app:dbg]HIO: onhook TDM port '5', port enabled 1
09:22:34.738[app:dbg]SLIC 5 (219): onhook state: busy
09:22:34.738[app:dbg]regex ID 5: dial reset
09:22:34.738[app:info]SLIC 5: from state 'busy' to state 'hangup'
09:22:34.738[app:dbg]CMD_STOP_TONE: port = 5
09:22:34.738[app:dbg]Port 5: check vapi queue ('free') at vapi_stop_tone_chan:1503
09:22:34.738[app:dbg]Chan 5: current state is CREATED
09:22:34.738[app:ERR]chan 5: no generated tones!
09:22:34.738[app:dbg]vapi_chan.c:1539: conn 5 peek cmd 'no event' from queue
09:22:34.738[app:dbg]Port 5: check vapi queue ('free') at __cmd_engine:321
09:22:34.738[app:dbg]Port 5: check vapi queue ('free') at vapi_next_ops:2599
09:22:34.738[app:dbg]SLIC 5: reset
09:22:34.738[app:dbg]dump_port_calls() SLIC 5:
09:22:34.738[app:dbg]Q:NONE
09:22:34.738[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
09:22:34.738[app:dbg]Delete all RX-TX medias from SLIC 5
09:22:34.738[app:dbg]free_final_mx: final_mx was NULL for SLIC 5
09:22:34.738[app:dbg]CMD_DESTROY_CONN: port = 5
09:22:34.738[app:dbg]Port 5: check vapi queue ('free') at vapi_destroy_chan:895
09:22:34.738[app:dbg]Destroying connection 5...
09:22:34.738[app:dbg]Chan 5: current state is CREATED
09:22:34.738[app:dbg]Port 5: set vapi queue MSP to 'busy' with 'destroy' at vapi_destroy_chan:921
09:22:34.738[app:dbg]VQ Conn 5 = MSP :       'destroy' =
09:22:34.738[app:dbg]Chan 5: CREATED -> DESTROYING
09:22:34.738[app:dbg]vapi_cb_req: 5 0 result 0x00000000 requid 0x0000014b
09:22:34.738[app:dbg]CMD_DESTROY_IPONLY_CONN: port = 5
09:22:34.738[app:dbg]Port 5: check vapi queue ('busy''destroy') at vapi_destroy_chan:895
09:22:34.738[app:dbg]Clear vapi queue of Port 5/chan 13
09:22:34.738[app:dbg]Port 5 put cmd 'destroy',cur 'destroy' to queue at (vapi_destroy_chan:902)
09:22:34.738[app:dbg]VQ Conn 13 = MSP :       'destroy' =
09:22:34.738[app:dbg]VQ Conn 13 + 00  :       'destroy' (hold) + <-get_ptr 
09:22:34.738[app:dbg]Port 5: user port 3, old state hangup, new state 
09:22:34.738[app:dbg]Set port 5 led to state 'LED_OFF'
09:22:34.738[app:dbg]pbx -[msg_fxs_state]-> group
09:22:34.738[app:dbg]ITC: [msg_fxs_state] -> group
09:22:34.738[app:dbg]-----[GM] self_fxs_state()
09:22:34.738[app:dbg]Port 5: new state is hangup
09:22:34.738[app:dbg]dump_port_calls() SLIC 5:
09:22:34.738[app:dbg]Q:NONE
09:22:34.738[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
09:22:34.738[app:dbg]Set port 5 led to state 'LED_OFF'
09:22:34.738[app:dbg]vapi_proc_event: VAPI_CB
09:22:34.738[app:dbg]vapi_cb_chan: chan 5 reqest_id 0x0000014b result 0x00000000
09:22:34.738[app:dbg]vapi_cb_req: 5 0 result 0x00000000 requid 0x00000103
09:22:34.738[app:dbg]vapi_proc_event: VAPI_CB
09:22:34.738[app:dbg]vapi_cb_chan: chan 5 reqest_id 0x00000103 result 0x00000000
09:22:34.738[app:dbg]Conn 5 destroyed
09:22:34.738[app:dbg]Chan 5: DESTROYING -> INITIAL
09:22:34.738[app:dbg]Port 5: check vapi queue ('busy''destroy') at vapi_next_ops:2599
09:22:34.748[app:dbg]Port 5 get cmd 'destroy' from queue at (vapi_next_ops:2618)
09:22:34.748[app:dbg]Port 5: check vapi queue ('free') at vapi_destroy_chan:895
09:22:34.748[app:dbg]Destroying connection 13...
09:22:34.748[app:dbg]Chan 13: current state is INITIAL
09:22:34.748[app:ERR]vapi_destroy_chan() chan 13: current state initial: duplicate destroying connection!
09:22:34.748[app:dbg]Port 5: check vapi queue ('free') at vapi_next_ops:2761
09:22:34.748[app:dbg]Port 5: check vapi queue ('free') at vapi_next_ops:2599
09:22:34.748[app:dbg]Delete all RX-TX medias from SLIC 13
09:22:34.768[app:dbg]Delete all RX-TX medias from SLIC 5
09:22:35.468[sip]send 382 bytes to udp/[192.168.0.101]:5060 at 19:51:58.470000:
09:22:35.468[sip]   ------------------------------------------------------------------------
09:22:35.468[sip]   OPTIONS sip:217@192.168.0.101 SIP/2.0
09:22:35.468[sip]   Via: SIP/2.0/UDP 192.168.0.217;rport;branch=z9hG4bKKH7D0Qm933F6N
09:22:35.468[sip]   Max-Forwards: 70
09:22:35.468[sip]   From: "217" <sip:217@192.168.0.101>;tag=mZ31mUXe08ymS
09:22:35.468[sip]   To: "217" <sip:217@192.168.0.101>
09:22:35.468[sip]   Call-ID: 8b4927db-e2c2-1234-17ba-a8f94b0e6be9
09:22:35.468[sip]   CSeq: 20331 OPTIONS
09:22:35.468[sip]   Subject: KEEPALIVE
09:22:35.468[sip]   User-Agent: TAU-8.IP/2.1.0 SN/VI33023837 sofia-sip/1.12.10
09:22:35.468[sip]   Content-Length: 0
09:22:35.468[sip]   
09:22:35.468[sip]   ------------------------------------------------------------------------
09:22:35.468[sip]nta: sent OPTIONS (20331) to */192.168.0.101:5060
09:22:35.488[sip]recv 289 bytes from udp/[192.168.0.101]:5060 at 19:51:58.490000:
09:22:35.488[sip]   ------------------------------------------------------------------------
09:22:35.488[sip]   SIP/2.0 501 Not Implemented
09:22:35.488[sip]   Via: SIP/2.0/UDP 192.168.0.217;branch=z9hG4bKKH7D0Qm933F6N;rport=5060
09:22:35.488[sip]   To: "217" <sip:217@192.168.0.101>;tag=11769
09:22:35.488[sip]   From: "217" <sip:217@192.168.0.101>;tag=mZ31mUXe08ymS
09:22:35.488[sip]   Call-ID: 8b4927db-e2c2-1234-17ba-a8f94b0e6be9
09:22:35.488[sip]   CSeq: 20331 OPTIONS
09:22:35.488[sip]   Content-Length: 0
09:22:35.488[sip]   
09:22:35.488[sip]   ------------------------------------------------------------------------
09:22:35.488[sip]nta: received 501 Not Implemented for OPTIONS (20331)
09:22:35.488[sip]nta: 501 Not Implemented is going to a transaction
09:22:35.708[sip]nta: timer K fired, terminate REFER (165352)
09:22:35.708[sip]nta_outgoing_timer: 0/0 resent, 0/2 tout, 1/7 term, 1/9 free
09:22:35.778[sip]nta: timer K fired, terminate BYE (165353)
09:22:35.778[sip]nta: timer K fired, terminate BYE (165355)
09:22:35.778[sip]nta_outgoing_timer: 0/0 resent, 0/2 tout, 2/6 term, 2/8 free
09:22:40.498[sip]nta: timer K fired, terminate OPTIONS (20331)
09:22:40.498[sip]nta_outgoing_timer: 0/0 resent, 0/2 tout, 1/4 term, 1/6 free
09:22:41.398[app:dbg]app: REINIT
09:22:41.398[app:ERR]pbx: select Interrupted system call

