root@TAU-8:~# 07:46:59.360[sip]recv 1029 bytes from udp/[10.10.2.2]:5060 at 14:15:15.360000:
   ------------------------------------------------------------------------
07:46:59.360[sip]   INVITE sip:3477951@10.0.5.14:5060 SIP/2.0
07:46:59.360[sip]   Via: SIP/2.0/UDP 10.10.2.2:5060;branch=z9hG4bKl9sbs5009gqg2js2o691.1
07:46:59.360[sip]   Accept: application/sdp
07:46:59.360[sip]   Allow: INVITE,ACK,CANCEL,BYE,INFO,PRACK,UPDATE,OPTIONS,REGISTER,REFER,SUBSCRIBE,MESSAGE,PUBLISH
07:46:59.360[sip]   Call-ID: SD5ntsd01-75b99711bd59a17946a8fe9c2172726d-cl5k9s0
07:46:59.360[sip]   Contact: <sip:10.10.2.2:5060;transport=udp>
07:46:59.360[sip]   CSeq: 498 INVITE
07:46:59.360[sip]   Expires: 3600
07:46:59.360[sip]   From: "anonymous" <sip:anonymous@anonymous.invalid:5060>;tag=SD5ntsd01-nfvnryso45
07:46:59.360[sip]   To: "3477951" <sip:3477951@10.10.2.2:5060;user=phone>
07:46:59.360[sip]   Organization: Iskratel
07:46:59.360[sip]   User-Agent: SI3000
07:46:59.360[sip]   Max-Forwards: 69
07:46:59.360[sip]   Subject: Call from SI3000
07:46:59.360[sip]   Content-Length: 326
07:46:59.360[sip]   Content-Type: application/sdp
07:46:59.360[sip]   Content-Disposition: session;handling=required
07:46:59.360[sip]
07:46:59.360[sip]   v=0
07:46:59.360[sip]   o=- 1812302 6455706 IN IP4 10.10.2.2
07:46:59.360[sip]   s=-
07:46:59.360[sip]   c=IN IP4 10.10.2.2
07:46:59.360[sip]   b=AS:64
07:46:59.360[sip]   t=0 0
07:46:59.360[sip]   m=audio 17632 RTP/AVP 8 0 18 4 101
07:46:59.360[sip]   a=rtpmap:8 PCMA/8000
07:46:59.360[sip]   a=rtpmap:0 PCMU/8000
07:46:59.360[sip]   a=rtpmap:18 G729/8000
07:46:59.360[sip]   a=fmtp:18 annexb=no
07:46:59.360[sip]   a=rtpmap:4 G723/8000
07:46:59.360[sip]   a=fmtp:4 annexa=no
07:46:59.360[sip]   a=rtpmap:101 telephone-event/8000
07:46:59.360[sip]   a=fmtp:101 0-15
07:46:59.360[sip]   a=ptime:20
07:46:59.360[sip]   a=sendrecv
07:46:59.360[sip]   ------------------------------------------------------------------------
07:46:59.370[app:dbg]self_pre_invite_param() entering
07:46:59.370[app:dbg]stun_get_public_ip(port = 8000)
07:46:59.370[app:dbg]stun_get_public_ip: Always using local IP
07:46:59.370[app:dbg]sip: group call (0) profile(0)
07:46:59.370[app:dbg]sip: get_support_params: profile 0 supported: 'timer, 100rel, replaces'
07:46:59.370[sip]send 388 bytes to udp/[10.10.2.2]:5060 at 14:15:15.370000:
   ------------------------------------------------------------------------
07:46:59.370[sip]   SIP/2.0 100 Trying
07:46:59.370[sip]   Via: SIP/2.0/UDP 10.10.2.2:5060;branch=z9hG4bKl9sbs5009gqg2js2o691.1
07:46:59.370[sip]   From: "anonymous" <sip:anonymous@anonymous.invalid:5060>;tag=SD5ntsd01-nfvnryso45
07:46:59.370[sip]   To: "3477951" <sip:3477951@10.10.2.2:5060;user=phone>
07:46:59.370[sip]   Call-ID: SD5ntsd01-75b99711bd59a17946a8fe9c2172726d-cl5k9s0
07:46:59.370[sip]   CSeq: 498 INVITE
07:46:59.370[sip]   User-Agent: TAU-8.IP/2.3.0 SN/VI33020063 sofia-sip/1.12.10
07:46:59.370[sip]   Content-Length: 0
07:46:59.370[sip]
07:46:59.370[sip]   ------------------------------------------------------------------------
07:46:59.370[app:dbg]got nua_i_invite : 100(Trying)
07:46:59.370[app:dbg]NO CALL IN nua_i_invite == 100 : Trying
07:46:59.370[app:dbg]stun_get_public_ip(port = 8000)
07:46:59.370[app:dbg]stun_get_public_ip: Always using local IP
07:46:59.370[app:dbg]sip: get_support_params: profile 0 supported: 'timer, 100rel, replaces'
07:46:59.370[app:dbg]sip: INVITE from sip:anonymous@anonymous.invalid:5060
07:46:59.370[app:dbg]stun_get_public_ip(port = 8000)
07:46:59.370[app:dbg]stun_get_public_ip: Always using local IP
07:46:59.370[app:dbg]sip: group call (0)
07:46:59.370[app:dbg]replaces 1, have accepted 0, ep 0x1c0b54, state 1
07:46:59.370[app:dbg]available RTP ports: 23000...26000
07:46:59.370[app:dbg]selected port for current call: 23028
07:46:59.370[app:dbg]self_i_invite (9422): no alert_info received
07:46:59.370[app:dbg]sdp_codecs_init() init call sdp (empty)
07:46:59.370[app:dbg]sdp_codecs_set_ssup() ssup present 0 ssup yes
07:46:59.370[app:dbg]G711A: PT 8
07:46:59.370[app:dbg]sdp_codecs_add_g711a_item() pt 8
07:46:59.370[app:dbg]G711U: PT 0
07:46:59.370[app:dbg]sdp_codecs_add_g711u_item() pt 0
07:46:59.370[app:dbg]G723: PT 4, bitrate default, annexa no
07:46:59.370[app:dbg]sdp_codecs_add_g723_item() pt 4, rate absent 6.3 ssup present off
07:46:59.370[app:dbg]sdp_codecs_set_rfc2833() present pt 101 remote fmtp 0-15, local fmtp 0-15
07:46:59.380[app:dbg]attr: name: ptime value: 20
07:46:59.380[app:dbg]sdp_codecs_set_ptime() ptime present : 20
07:46:59.380[app:dbg]sdp_codecs_dump() ssup absent on, ecan absent on, rfc present 101, nse absent 0, ptime present 20
07:46:59.380[app:dbg]sdp_codecs_dump() G723:
07:46:59.380[app:dbg]sdp_codecs_dump() PT 4, rate absent 6.3, ssup present off
07:46:59.380[app:dbg]sdp_codecs_dump() G711A:
07:46:59.380[app:dbg]sdp_codecs_dump() PT 8, vbd absent off
07:46:59.380[app:dbg]sdp_codecs_dump() G711U:
07:46:59.380[app:dbg]sdp_codecs_dump() PT 0, vbd absent off
07:46:59.380[app:dbg]sdp_codecs_dump() G726-24: none
07:46:59.380[app:dbg]sdp_codecs_dump() G726-32: none
07:46:59.380[app:dbg]sdp_codecs_dump() G722: none
07:46:59.380[app:dbg]stun_get_public_ip(port = 23028)
07:46:59.380[app:dbg]stun_get_public_ip: Always using local IP
07:46:59.380[app:dbg]self_i_invite: handle call id 0x02060006, call id 0x02060006
07:46:59.380[app:dbg]got nua_i_state : 100(Trying)
07:46:59.380[app:dbg]NO SIP IN nua_i_state == 100 : Trying
07:46:59.380[app:dbg]self_i_state(): call state 5: or : remote sdp : sdp_init no_oc
07:46:59.380[app:dbg]sip: call 02060006: SDP offer received
07:46:59.380[app:dbg]sdp_codecs_set_ssup() ssup present 0 ssup yes
07:46:59.380[app:dbg]sdp_codecs_set_rfc2833() present pt 101 remote fmtp 0-15, local fmtp 0-15
07:46:59.380[app:dbg]attr: name: ptime value: 20
07:46:59.380[app:dbg]sdp_codecs_set_ptime() ptime present : 20
07:46:59.380[app:dbg]sip: call 02060006: media stream 0, creating proposed audio channel, remote RTP 10.10.2.2:17632
07:46:59.380[app:dbg]sip: call 02060006: select audio media
07:46:59.380[app:dbg]G711A: PT 8
07:46:59.380[app:dbg]G711U: PT 0
07:46:59.380[app:dbg]G723: PT 4
07:46:59.380[app:dbg]sip: call 02060006: remote SDP offer copy
07:46:59.380[app:dbg]sip: call 02060006: called from sip:anonymous@anonymous.invalid:5060 to sip:3477951@10.10.2.2:5060;user=phone
07:46:59.380[app:dbg]stun_get_public_ip(port = 8000)
07:46:59.380[app:dbg]stun_get_public_ip: Always using local IP
07:46:59.380[app:dbg]ITC_CALL to group 0
07:46:59.380[app:dbg]sdp_codecs_get_rfc2833: present=1 pt=101
07:46:59.380[app:dbg]sip -[msg_call]-> group
07:46:59.380[app:dbg]ITC: [msg_call] -> group
07:46:59.380[app:dbg] [SG] self_on_call()
07:46:59.380[app:dbg][SG] Incoming group call from anonymous.invalid:5060/anonymous("anonymous") payload 101 call ID: 02060006 group: 0 ep_src: 6
07:46:59.380[app:dbg] [GM] load_in_handle():
07:46:59.380[app:dbg][SG] addCall()
07:46:59.380[app:dbg]group -[msg_free]-> sip
07:46:59.380[app:dbg] [GM] load_in_handle():
07:46:59.380[app:dbg]group -[msg_call]-> pbx
07:46:59.380[app:dbg]ITC: [msg_call] -> pbx
07:46:59.380[app:dbg]SLIC 6: incoming call from anonymous.invalid:5060/anonymous("anonymous") payload 101 call ID: 02060006 group: 0
07:46:59.380[app:dbg]pbx: allocating memory for new call
07:46:59.380[app:dbg]pbx: created new incoming call for SLIC 6
07:46:59.380[app:dbg]self_call_create (4694): created
07:46:59.380[app:dbg]SLIC 6: -> ringing
07:46:59.380[app:info]SLIC 6: from state 'hangup' to state 'ringing'
07:46:59.380[app:dbg]CMD_CREATE_CONN: port = 6
07:46:59.380[app:dbg]Port 6: check vapi queue ('free') at vapi_create_chan:710
07:46:59.380[app:dbg]Chan 6: current state is INITIAL
07:46:59.380[app:dbg]Port 6: set vapi queue MSP to 'busy' with 'create' at vapi_create_chan:736
07:46:59.380[app:dbg]VQ Conn 6 = MSP :        'create' =
07:46:59.380[app:dbg]Creating connection 6....
07:46:59.380[app:dbg]Chan 6: INITIAL -> CREATING
07:46:59.390[app:dbg]Created succefuly 6....
07:46:59.390[app:info]SLIC 6: has incoming call from anonymous
07:46:59.390[app:dbg]port 6: port_seize
07:46:59.390[app:dbg]port 6: seize
07:46:59.390[app:dbg]port 6: seize has cadence pulse = 0, pause = 0
07:46:59.390[app:dbg]Set port 6 led to state 'LED_RINGING'
07:46:59.390[app:dbg]Port 6: user port 0, old state ringing, new state
07:46:59.390[app:dbg]Set port 6 led to state 'LED_OFF'
07:46:59.390[app:dbg]pbx -[msg_fxs_state]-> group
07:46:59.390[app:dbg]ITC: [msg_fxs_state] -> group
07:46:59.390[app:dbg]-----[GM] self_fxs_state()
07:46:59.390[app:dbg]Port 6: new state is ringing
07:46:59.390[app:dbg]self_callstate_received (7492): complete
07:46:59.390[app:dbg]got nua_r_set_params : 200(OK)
07:46:59.390[app:dbg]NO SIP IN nua_r_set_params == 200 : OK
07:46:59.390[app:dbg]pbx -[msg_free]-> group
07:46:59.390[app:dbg]ITC: [msg_free] -> group
07:46:59.390[app:dbg][SG] self_on_free()
07:46:59.390[app:dbg]SLIC 6: list of all calls:
07:46:59.390[app:dbg]   call ID: 02060006
07:46:59.390[app:dbg]incom_calls_add() add call 0x02060006, group 0, task <group> to list
07:46:59.390[app:dbg]slic6. Event 6.
07:46:59.390[app:dbg]slic 6. Ring on event
07:46:59.390[app:dbg]Set port 6 led to state 'LED_RINGING'
07:46:59.400[app:dbg]ITC: [msg_free] -> sip
07:46:59.400[app:dbg]sip: call 02060006: endpoint 6 ringing
07:46:59.400[app:dbg]sip: call 02060006,sip: INVITE: 180 Ringing
07:46:59.400[app:dbg]send_18x() call 0x02060006, hdr <none>, sip, rel mode/cfg off/supp/req, inv w/ sdp, to group
07:46:59.400[app:dbg]send_18x(): respond w/o sdp 0, sdp 0
07:46:59.400[app:dbg]sdp_codecs_get_rfc2833: present=1 pt=101
07:46:59.400[app:dbg]Sending 180 Ringing without SDP
07:46:59.390[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x00000050
07:46:59.400[sip]send 580 bytes to udp/[10.10.2.2]:5060 at 14:15:15.400000:
   ------------------------------------------------------------------------
07:46:59.400[sip]   SIP/2.0 180 Ringing
07:46:59.400[sip]   Via: SIP/2.0/UDP 10.10.2.2:5060;branch=z9hG4bKl9sbs5009gqg2js2o691.1
07:46:59.400[sip]   From: "anonymous" <sip:anonymous@anonymous.invalid:5060>;tag=SD5ntsd01-nfvnryso45
07:46:59.400[sip]   To: "3477951" <sip:3477951@10.10.2.2:5060;user=phone>;tag=2XU7tyej1XQaS
07:46:59.400[sip]   Call-ID: SD5ntsd01-75b99711bd59a17946a8fe9c2172726d-cl5k9s0
07:46:59.400[sip]   CSeq: 498 INVITE
07:46:59.400[sip]   Contact: <sip:3477951@10.0.5.14:5060>
07:46:59.400[sip]   User-Agent: TAU-8.IP/2.3.0 SN/VI33020063 sofia-sip/1.12.10
07:46:59.400[sip]   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, INFO
07:46:59.400[sip]   Supported: timer, 100rel, replaces
07:46:59.400[sip]   Content-Length: 0
07:46:59.400[sip]
07:46:59.400[sip]   ------------------------------------------------------------------------
07:46:59.400[app:dbg]vapi_proc_event: VAPI_CB
07:46:59.400[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x00000050 result 0x00000000
07:46:59.400[app:dbg]got nua_i_state : 180(Ringing)
07:46:59.400[app:dbg]NO SIP IN nua_i_state == 180 : Ringing
07:46:59.400[app:dbg]self_i_state(): call state 6: : : sdp_recv no_oc
07:46:59.400[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x00000007
07:46:59.400[app:dbg]vapi_proc_event: VAPI_CB
07:46:59.400[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x00000007 result 0x00000000
07:46:59.400[app:dbg]vapi: Conn 6. Set In-Activ state
07:46:59.400[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x00000051
07:46:59.400[app:dbg]vapi_proc_event: VAPI_CB
07:46:59.400[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x00000051 result 0x00000000
07:46:59.400[app:dbg]vapi: Conn 6 - SET AGC
07:46:59.410[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x00000000
07:46:59.410[app:dbg]vapi_proc_event: VAPI_CB
07:46:59.410[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x00000000 result 0x00000000
07:46:59.410[app:dbg]vapi: Conn 6 - << CREATED >>
07:46:59.410[app:dbg]vapi: Conn 6 - fix DTMF detector
07:46:59.410[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x0000004a
07:46:59.410[app:dbg]vapi_proc_event: VAPI_CB
07:46:59.410[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x0000004a result 0x00000000
07:46:59.410[app:dbg]vapi: Conn 6 - fix CNG generator
07:46:59.420[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x0000004d
07:46:59.420[app:dbg]vapi_proc_event: VAPI_CB
07:46:59.420[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x0000004d result 0x00000000
07:46:59.420[app:dbg]vapi: Conn 6 - caller id Set param
07:46:59.420[app:dbg]vapi: chan '6' set param Caller ID
07:46:59.430[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x0000000c
07:46:59.430[app:dbg]vapi_proc_event: VAPI_CB
07:46:59.430[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x0000000c result 0x00000000
07:46:59.430[app:dbg]vapi: Conn 6 - enable ind ptime and pt
07:46:59.430[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x00000052
07:46:59.430[app:dbg]vapi_proc_event: VAPI_CB
07:46:59.430[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x00000052 result 0x00000000
07:46:59.430[app:dbg]vapi: Conn 6. Set Active state
07:46:59.440[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x0000004b
07:46:59.440[app:dbg]vapi_proc_event: VAPI_CB
07:46:59.440[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x0000004b result 0x00000000
07:46:59.440[app:dbg]Chan 6: CREATING -> CREATED
07:46:59.440[app:dbg]Port 6: check vapi queue ('busy''create') at vapi_next_ops:2614
07:47:00.400[app:dbg]slic6. Event 7.
07:47:00.400[app:dbg]slic 6. Ring off event
07:47:00.400[app:dbg]Set port 6 led to state 'LED_OFF'
07:47:00.400[app:dbg]Set port 6 led to state 'LED_OFF'
07:47:00.610[app:info]SLIC 6: DTMF caller-id generated
07:47:00.610[app:dbg]CMD_START_CID_DTMF: port = 6
07:47:00.610[app:dbg]Port 6: check vapi queue ('free') at vapi_cid_dtmf_chan:3103
07:47:00.610[app:dbg]Chan 6: current state is CREATED
07:47:00.610[app:dbg]Port 6: set vapi queue MSP to 'busy' with 'cid_dtmf_event' at vapi_cid_dtmf_chan:3132
07:47:00.610[app:dbg]VQ Conn 6 = MSP : 'cid_dtmf_event' =
07:47:00.610[app:info]Generating Caller-ID DTMF tone 'A'
07:47:00.610[app:dbg]chan 6 start tone, id=9, direction=TDM
07:47:00.610[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x00000949
07:47:00.610[app:dbg]vapi_proc_event: VAPI_CB
07:47:00.610[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x00000949 result 0x00000000
07:47:00.610[app:dbg]Conn 6: Caller Id DTMF tone - Successfull
07:47:00.610[app:dbg]Port 6: check vapi queue ('busy''cid_dtmf_event') at vapi_next_ops:2614
07:47:00.760[app:dbg]Port 6: check vapi queue ('free') at vapi_cid_dtmf_chan:3103
07:47:00.760[app:dbg]Chan 6: current state is CREATED
07:47:00.760[app:dbg]Port 6: set vapi queue MSP to 'busy' with 'cid_dtmf_event' at vapi_cid_dtmf_chan:3132
07:47:00.760[app:dbg]VQ Conn 6 = MSP : 'cid_dtmf_event' =
07:47:00.760[app:info]Generating Caller-ID DTMF tone '1'
07:47:00.760[app:dbg]chan 6 start tone, id=0, direction=TDM
07:47:00.760[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, conn 6
07:47:00.760[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x00000949
07:47:00.760[app:dbg]vapi_proc_event: VAPI_CB
07:47:00.760[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x00000949 result 0x00000000
07:47:00.760[app:dbg]Conn 6: Caller Id DTMF tone - Successfull
07:47:00.760[app:dbg]Port 6: check vapi queue ('busy''cid_dtmf_event') at vapi_next_ops:2614
07:47:00.920[app:dbg]Port 6: check vapi queue ('free') at vapi_cid_dtmf_chan:3103
07:47:00.920[app:dbg]Chan 6: current state is CREATED
07:47:00.920[app:dbg]Port 6: set vapi queue MSP to 'busy' with 'cid_dtmf_event' at vapi_cid_dtmf_chan:3132
07:47:00.920[app:dbg]VQ Conn 6 = MSP : 'cid_dtmf_event' =
07:47:00.920[app:info]Generating Caller-ID DTMF tone '1'
07:47:00.920[app:dbg]chan 6 start tone, id=0, direction=TDM
07:47:00.920[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, conn 6
07:47:00.920[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x00000949
07:47:00.920[app:dbg]vapi_proc_event: VAPI_CB
07:47:00.920[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x00000949 result 0x00000000
07:47:00.920[app:dbg]Conn 6: Caller Id DTMF tone - Successfull
07:47:00.920[app:dbg]Port 6: check vapi queue ('busy''cid_dtmf_event') at vapi_next_ops:2614
07:47:01.080[app:dbg]Port 6: check vapi queue ('free') at vapi_cid_dtmf_chan:3103
07:47:01.080[app:dbg]Chan 6: current state is CREATED
07:47:01.080[app:dbg]Port 6: set vapi queue MSP to 'busy' with 'cid_dtmf_event' at vapi_cid_dtmf_chan:3132
07:47:01.080[app:dbg]VQ Conn 6 = MSP : 'cid_dtmf_event' =
07:47:01.080[app:info]Generating Caller-ID DTMF tone '1'
07:47:01.080[app:dbg]chan 6 start tone, id=0, direction=TDM
07:47:01.080[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, conn 6
07:47:01.080[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x00000949
07:47:01.080[app:dbg]vapi_proc_event: VAPI_CB
07:47:01.080[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x00000949 result 0x00000000
07:47:01.080[app:dbg]Conn 6: Caller Id DTMF tone - Successfull
07:47:01.080[app:dbg]Port 6: check vapi queue ('busy''cid_dtmf_event') at vapi_next_ops:2614
07:47:01.250[app:dbg]Port 6: check vapi queue ('free') at vapi_cid_dtmf_chan:3103
07:47:01.250[app:dbg]Chan 6: current state is CREATED
07:47:01.250[app:dbg]Port 6: set vapi queue MSP to 'busy' with 'cid_dtmf_event' at vapi_cid_dtmf_chan:3132
07:47:01.250[app:dbg]VQ Conn 6 = MSP : 'cid_dtmf_event' =
07:47:01.250[app:info]Generating Caller-ID DTMF tone '1'
07:47:01.250[app:dbg]chan 6 start tone, id=0, direction=TDM
07:47:01.250[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, conn 6
07:47:01.250[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x00000949
07:47:01.250[app:dbg]vapi_proc_event: VAPI_CB
07:47:01.250[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x00000949 result 0x00000000
07:47:01.250[app:dbg]Conn 6: Caller Id DTMF tone - Successfull
07:47:01.250[app:dbg]Port 6: check vapi queue ('busy''cid_dtmf_event') at vapi_next_ops:2614
07:47:01.400[app:dbg]Port 6: check vapi queue ('free') at vapi_cid_dtmf_chan:3103
07:47:01.400[app:dbg]Chan 6: current state is CREATED
07:47:01.400[app:dbg]Port 6: set vapi queue MSP to 'busy' with 'cid_dtmf_event' at vapi_cid_dtmf_chan:3132
07:47:01.400[app:dbg]VQ Conn 6 = MSP : 'cid_dtmf_event' =
07:47:01.400[app:info]Generating Caller-ID DTMF tone '1'
07:47:01.400[app:dbg]chan 6 start tone, id=0, direction=TDM
07:47:01.400[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, conn 6
07:47:01.400[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x00000949
07:47:01.400[app:dbg]vapi_proc_event: VAPI_CB
07:47:01.400[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x00000949 result 0x00000000
07:47:01.400[app:dbg]Conn 6: Caller Id DTMF tone - Successfull
07:47:01.400[app:dbg]Port 6: check vapi queue ('busy''cid_dtmf_event') at vapi_next_ops:2614
07:47:01.560[app:dbg]Port 6: check vapi queue ('free') at vapi_cid_dtmf_chan:3103
07:47:01.560[app:dbg]Chan 6: current state is CREATED
07:47:01.560[app:dbg]Port 6: set vapi queue MSP to 'busy' with 'cid_dtmf_event' at vapi_cid_dtmf_chan:3132
07:47:01.560[app:dbg]VQ Conn 6 = MSP : 'cid_dtmf_event' =
07:47:01.560[app:info]Generating Caller-ID DTMF tone '1'
07:47:01.560[app:dbg]chan 6 start tone, id=0, direction=TDM
07:47:01.560[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, conn 6
07:47:01.560[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x00000949
07:47:01.560[app:dbg]vapi_proc_event: VAPI_CB
07:47:01.560[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x00000949 result 0x00000000
07:47:01.560[app:dbg]Conn 6: Caller Id DTMF tone - Successfull
07:47:01.560[app:dbg]Port 6: check vapi queue ('busy''cid_dtmf_event') at vapi_next_ops:2614
07:47:01.720[app:dbg]Port 6: check vapi queue ('free') at vapi_cid_dtmf_chan:3103
07:47:01.720[app:dbg]Chan 6: current state is CREATED
07:47:01.720[app:dbg]Port 6: set vapi queue MSP to 'busy' with 'cid_dtmf_event' at vapi_cid_dtmf_chan:3132
07:47:01.720[app:dbg]VQ Conn 6 = MSP : 'cid_dtmf_event' =
07:47:01.720[app:info]Generating Caller-ID DTMF tone '1'
07:47:01.720[app:dbg]chan 6 start tone, id=0, direction=TDM
07:47:01.720[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, conn 6
07:47:01.720[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x00000949
07:47:01.720[app:dbg]vapi_proc_event: VAPI_CB
07:47:01.720[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x00000949 result 0x00000000
07:47:01.720[app:dbg]Conn 6: Caller Id DTMF tone - Successfull
07:47:01.720[app:dbg]Port 6: check vapi queue ('busy''cid_dtmf_event') at vapi_next_ops:2614
07:47:01.880[app:dbg]Port 6: check vapi queue ('free') at vapi_cid_dtmf_chan:3103
07:47:01.880[app:dbg]Chan 6: current state is CREATED
07:47:01.880[app:dbg]Port 6: set vapi queue MSP to 'busy' with 'cid_dtmf_event' at vapi_cid_dtmf_chan:3132
07:47:01.880[app:dbg]VQ Conn 6 = MSP : 'cid_dtmf_event' =
07:47:01.880[app:info]Generating Caller-ID DTMF tone '1'
07:47:01.880[app:dbg]chan 6 start tone, id=0, direction=TDM
07:47:01.880[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, conn 6
07:47:01.880[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x00000949
07:47:01.880[app:dbg]vapi_proc_event: VAPI_CB
07:47:01.880[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x00000949 result 0x00000000
07:47:01.880[app:dbg]Conn 6: Caller Id DTMF tone - Successfull
07:47:01.880[app:dbg]Port 6: check vapi queue ('busy''cid_dtmf_event') at vapi_next_ops:2614
07:47:02.040[app:dbg]Port 6: check vapi queue ('free') at vapi_cid_dtmf_chan:3103
07:47:02.040[app:dbg]Chan 6: current state is CREATED
07:47:02.040[app:dbg]Port 6: set vapi queue MSP to 'busy' with 'cid_dtmf_event' at vapi_cid_dtmf_chan:3132
07:47:02.040[app:dbg]VQ Conn 6 = MSP : 'cid_dtmf_event' =
07:47:02.040[app:info]Generating Caller-ID DTMF tone '1'
07:47:02.040[app:dbg]chan 6 start tone, id=0, direction=TDM
07:47:02.040[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, conn 6
07:47:02.040[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x00000949
07:47:02.040[app:dbg]vapi_proc_event: VAPI_CB
07:47:02.040[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x00000949 result 0x00000000
07:47:02.040[app:dbg]Conn 6: Caller Id DTMF tone - Successfull
07:47:02.040[app:dbg]Port 6: check vapi queue ('busy''cid_dtmf_event') at vapi_next_ops:2614
07:47:02.200[app:dbg]Port 6: check vapi queue ('free') at vapi_cid_dtmf_chan:3103
07:47:02.200[app:dbg]Chan 6: current state is CREATED
07:47:02.200[app:dbg]Port 6: set vapi queue MSP to 'busy' with 'cid_dtmf_event' at vapi_cid_dtmf_chan:3132
07:47:02.200[app:dbg]VQ Conn 6 = MSP : 'cid_dtmf_event' =
07:47:02.200[app:info]Generating Caller-ID DTMF tone 'C'
07:47:02.200[app:dbg]chan 6 start tone, id=11, direction=TDM
07:47:02.200[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, conn 6
07:47:02.200[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x00000949
07:47:02.200[app:dbg]vapi_proc_event: VAPI_CB
07:47:02.200[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x00000949 result 0x00000000
07:47:02.200[app:dbg]Conn 6: Caller Id DTMF tone - Successfull
07:47:02.200[app:dbg]Port 6: check vapi queue ('busy''cid_dtmf_event') at vapi_next_ops:2614
07:47:02.360[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, conn 6
07:47:04.370[app:dbg]port_process (11409): seize next tone
07:47:04.370[app:dbg]port 6: clear
07:47:04.370[app:dbg]Set port 6 led to state 'LED_OFF'
07:47:04.370[app:dbg]port 6: port_seize
07:47:04.370[app:dbg]port 6: seize
07:47:04.370[app:dbg]port 6: seize has cadence pulse = 1000, pause = 4000
07:47:04.370[app:dbg]Set port 6 led to state 'LED_RINGING'
07:47:04.400[app:dbg]slic6. Event 6.
07:47:04.400[app:dbg]slic 6. Ring on event
07:47:04.400[app:dbg]Set port 6 led to state 'LED_RINGING'
root@TAU-8:~# 07:47:05.390[app:dbg]slic6. Event 7.
07:47:05.390[app:dbg]slic 6. Ring off event
07:47:05.390[app:dbg]Set port 6 led to state 'LED_OFF'
07:47:05.390[app:dbg]Set port 6 led to state 'LED_OFF'
07:47:09.020[app:dbg] [GM] load_in_handle():
07:47:09.020[app:dbg]group -[msg_clear]-> pbx
07:47:09.020[app:dbg] [GM] load_in_handle():
07:47:09.020[app:dbg]group -[msg_call]-> pbx
07:47:09.020[app:dbg]ITC: [msg_clear] -> pbx
07:47:09.020[app:dbg]dump_port_calls() SLIC 6:
07:47:09.020[app:dbg]Q:(0x335c00,0x02060006,(nil))
07:47:09.020[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((                                                                                       nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
07:47:09.020[app:dbg]SLIC 6: peer cleared(02060006)
07:47:09.020[app:dbg]SLIC 6: current call cleared
07:47:09.020[app:dbg]SLIC 6: -> hangup
07:47:09.020[app:info]SLIC 6: from state 'ringing' to state 'hangup'
07:47:09.020[app:dbg]port 6: clear
07:47:09.020[app:dbg]Set port 6 led to state 'LED_OFF'
07:47:09.020[app:dbg]CMD_STOP_TONE: port = 6
07:47:09.020[app:dbg]Port 6: check vapi queue ('free') at vapi_stop_tone_chan:151                                                                                       8
07:47:09.020[app:dbg]Chan 6: current state is CREATED
07:47:09.020[app:ERR]chan 6: no generated tones!
07:47:09.020[app:dbg]vapi_chan.c:1554: conn 6 peek cmd 'no event' from queue
07:47:09.020[app:dbg]Port 6: check vapi queue ('free') at __cmd_engine:342
07:47:09.020[app:dbg]Port 6: check vapi queue ('free') at vapi_next_ops:2614
07:47:09.020[app:dbg]SLIC 6: reset
07:47:09.020[app:dbg]dump_port_calls() SLIC 6:
07:47:09.020[app:dbg]Q:(0x335c00,0x02060006,(nil))
07:47:09.020[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((                                                                                       nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
07:47:09.020[app:dbg]vapi: chan 6: connection STATISTIC
07:47:09.020[app:dbg]vapi: chan 6: Rx_pack = 0
07:47:09.020[app:dbg]vapi: chan 6: Rx_oct  = 0
07:47:09.020[app:dbg]vapi: chan 6: Lost_pack  = 0
07:47:09.020[app:dbg]vapi: chan 6: Tx_pack = 0
07:47:09.020[app:dbg]vapi: chan 6: Tx_oct  = 0
07:47:09.020[app:dbg]vapi: chan 6: peak_jiter = 0
07:47:09.020[app:dbg]SLIC 6: Common port statistic
07:47:09.020[app:dbg]SLIC 6: Rx_pack = 0
07:47:09.020[app:dbg]SLIC 6: Rx_oct  = 0
07:47:09.020[app:dbg]SLIC 6: Lost_pack  = 0
07:47:09.020[app:dbg]SLIC 6: Tx_pack = 0
07:47:09.020[app:dbg]SLIC 6: Tx_oct  = 0
07:47:09.020[app:dbg]SLIC 6: peak_jiter = 0
07:47:09.020[app:dbg]SLIC 6: reset call 0x02060006 (active)
07:47:09.020[app:dbg]CMD_SET_VOICE: port = 6
07:47:09.020[app:dbg]Port 6: check vapi queue ('free') at vapi_start_stop_chan:16                                                                                       67
07:47:09.020[app:dbg]Chan 6: current state is CREATED
07:47:09.020[app:dbg]vapi: Conn 6. start_stop voice chan, TX stop, RX stop
07:47:09.020[app:dbg]Port 6: set vapi queue MSP to 'busy' with 'set voice' at vap                                                                                       i_start_stop_chan:1710
07:47:09.020[app:dbg]VQ Conn 6 = MSP :     'set voice' =
07:47:09.020[app:ERR]Conn 6. error: -68022 (VAPI_ERR_IP_HDR_NOT_SET)
07:47:09.020[app:dbg]Port 6: check vapi queue ('free') at __cmd_engine:350
07:47:09.020[app:dbg]Port 6: check vapi queue ('free') at vapi_next_ops:2614
07:47:09.020[app:dbg]incom_calls_set_media_started() call 0x02060006, group 0, ta                                                                                       sk <group> media stopped
07:47:09.020[app:dbg]incom_calls_rem() rem call 0x02060006, group 0, task <group>                                                                                        from list
07:47:09.020[app:dbg]free_final_mx: final_mx was NULL for SLIC 6
07:47:09.020[app:dbg]CMD_DESTROY_CONN: port = 6
07:47:09.020[app:dbg]Port 6: check vapi queue ('free') at vapi_destroy_chan:906
07:47:09.020[app:dbg]Destroying connection 6...
07:47:09.020[app:dbg]Chan 6: current state is CREATED
07:47:09.020[app:dbg]Port 6: set vapi queue MSP to 'busy' with 'destroy' at vapi_                                                                                       destroy_chan:932
07:47:09.020[app:dbg]VQ Conn 6 = MSP :       'destroy' =
07:47:09.020[app:dbg]Chan 6: CREATED -> DESTROYING
07:47:09.020[app:dbg]CMD_DESTROY_IPONLY_CONN: port = 6
07:47:09.020[app:dbg]Port 6: check vapi queue ('busy''destroy') at vapi_destroy_c                                                                                       han:906
07:47:09.020[app:dbg]Clear vapi queue of Port 6/chan 14
07:47:09.020[app:dbg]Port 6 put cmd 'destroy',cur 'destroy' to queue at (vapi_des                                                                                       troy_chan:913)
07:47:09.020[app:dbg]VQ Conn 14 = MSP :       'destroy' =
07:47:09.020[app:dbg]VQ Conn 14 + 00  :       'destroy' (hold) + <-get_ptr
07:47:09.020[app:dbg]Port 6: user port 0, old state hangup, new state
07:47:09.020[app:dbg]Set port 6 led to state 'LED_OFF'
07:47:09.020[app:dbg]pbx -[msg_fxs_state]-> group
07:47:09.020[app:dbg]dump_port_calls() SLIC 6:
07:47:09.020[app:dbg]Q:NONE
07:47:09.020[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((                                                                                       nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
07:47:09.030[app:dbg]ITC: [msg_fxs_state] -> group
07:47:09.030[app:dbg]-----[GM] self_fxs_state()
07:47:09.030[app:dbg]Port 6: new state is hangup
07:47:09.030[app:dbg]Delete all RX-TX medias from SLIC 6
07:47:09.030[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x0000014c
07:47:09.030[app:dbg]ITC: [msg_call] -> pbx
07:47:09.030[app:dbg]SLIC 4: incoming call from anonymous.invalid:5060/anonymous(                                                                                       "anonymous") payload 101 call ID: 02060006 group: 0
07:47:09.030[app:dbg]pbx: allocating memory for new call
07:47:09.030[app:dbg]pbx: created new incoming call for SLIC 4
07:47:09.030[app:dbg]self_call_create (4694): created
07:47:09.030[app:dbg]SLIC 4: -> ringing
07:47:09.030[app:info]SLIC 4: from state 'hangup' to state 'ringing'
07:47:09.030[app:dbg]CMD_CREATE_CONN: port = 4
07:47:09.030[app:dbg]Port 4: check vapi queue ('free') at vapi_create_chan:710
07:47:09.030[app:dbg]Chan 4: current state is INITIAL
07:47:09.030[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'create' at vapi_c                                                                                       reate_chan:736
07:47:09.030[app:dbg]VQ Conn 4 = MSP :        'create' =
07:47:09.030[app:dbg]Creating connection 4....
07:47:09.030[app:dbg]Chan 4: INITIAL -> CREATING
07:47:09.030[app:dbg]Created succefuly 4....
07:47:09.030[app:info]SLIC 4: has incoming call from anonymous
07:47:09.030[app:dbg]port 4: port_seize
07:47:09.030[app:dbg]port 4: seize
07:47:09.030[app:dbg]port 4: seize has cadence pulse = 0, pause = 0
07:47:09.030[app:dbg]Set port 4 led to state 'LED_RINGING'
07:47:09.030[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000050
07:47:09.030[app:dbg]Port 4: user port 2, old state ringing, new state
07:47:09.030[app:dbg]Set port 4 led to state 'LED_OFF'
07:47:09.030[app:dbg]pbx -[msg_fxs_state]-> group
07:47:09.030[app:dbg]ITC: [msg_fxs_state] -> group
07:47:09.030[app:dbg]-----[GM] self_fxs_state()
07:47:09.030[app:dbg]Port 4: new state is ringing
07:47:09.040[app:dbg]Delete all RX-TX medias from SLIC 14
07:47:09.040[app:dbg]pbx -[msg_free]-> group
07:47:09.040[app:dbg]ITC: [msg_free] -> group
07:47:09.040[app:dbg][SG] self_on_free()
07:47:09.040[app:dbg]SLIC 4: list of all calls:
07:47:09.040[app:dbg]   call ID: 02060006
07:47:09.040[app:dbg]incom_calls_add() add call 0x02060006, group 0, task <group>                                                                                        to list
07:47:09.040[app:dbg]vapi_proc_event: VAPI_CB
07:47:09.040[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x0000014c result 0x00000000
07:47:09.040[app:dbg]slic4. Event 6.
07:47:09.040[app:dbg]slic 4. Ring on event
07:47:09.040[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x00000103
07:47:09.040[app:dbg]Set port 4 led to state 'LED_RINGING'
07:47:09.040[app:dbg]vapi_proc_event: VAPI_CB
07:47:09.040[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000050 result 0x00000000
07:47:09.040[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000007
07:47:09.040[app:dbg]vapi_proc_event: VAPI_CB
07:47:09.040[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x00000103 result 0x00000000
07:47:09.040[app:dbg]Conn 6 destroyed
07:47:09.040[app:dbg]Chan 6: DESTROYING -> INITIAL
07:47:09.040[app:dbg]Port 6: check vapi queue ('busy''destroy') at vapi_next_ops:                                                                                       2614
07:47:09.040[app:dbg]Port 6 get cmd 'destroy' from queue at (vapi_next_ops:2633)
07:47:09.040[app:dbg]Port 6: check vapi queue ('free') at vapi_destroy_chan:906
07:47:09.040[app:dbg]Destroying connection 14...
07:47:09.040[app:dbg]Chan 14: current state is INITIAL
07:47:09.040[app:ERR]vapi_destroy_chan() chan 14: current state initial: duplicat                                                                                       e destroying connection!
07:47:09.040[app:dbg]Port 6: check vapi queue ('free') at vapi_next_ops:2776
07:47:09.040[app:dbg]Port 6: check vapi queue ('free') at vapi_next_ops:2614
07:47:09.040[app:dbg]vapi_proc_event: VAPI_CB
07:47:09.040[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000007 result 0x00000000
07:47:09.040[app:dbg]vapi: Conn 4. Set In-Activ state
07:47:09.040[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000051
07:47:09.040[app:dbg]vapi_proc_event: VAPI_CB
07:47:09.040[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000051 result 0x00000000
07:47:09.040[app:dbg]vapi: Conn 4 - SET AGC
07:47:09.050[app:dbg]Delete all RX-TX medias from SLIC 6
07:47:09.050[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000000
07:47:09.050[app:dbg]vapi_proc_event: VAPI_CB
07:47:09.050[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000000 result 0x00000000
07:47:09.050[app:dbg]vapi: Conn 4 - << CREATED >>
07:47:09.050[app:dbg]vapi: Conn 4 - fix DTMF detector
07:47:09.050[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x0000004a
07:47:09.050[app:dbg]vapi_proc_event: VAPI_CB
07:47:09.050[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x0000004a result 0x00000000
07:47:09.050[app:dbg]vapi: Conn 4 - fix CNG generator
07:47:09.050[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x0000004d
07:47:09.050[app:dbg]vapi_proc_event: VAPI_CB
07:47:09.050[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x0000004d result 0x00000000
07:47:09.050[app:dbg]vapi: Conn 4 - caller id Set param
07:47:09.050[app:dbg]vapi: chan '4' set param Caller ID
07:47:09.060[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x0000000c
07:47:09.060[app:dbg]vapi_proc_event: VAPI_CB
07:47:09.060[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x0000000c result 0x00000000
07:47:09.060[app:dbg]vapi: Conn 4 - enable ind ptime and pt
07:47:09.060[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000052
07:47:09.060[app:dbg]vapi_proc_event: VAPI_CB
07:47:09.060[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000052 result 0x00000000
07:47:09.060[app:dbg]vapi: Conn 4. Set Active state
07:47:09.070[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x0000004b
07:47:09.070[app:dbg]vapi_proc_event: VAPI_CB
07:47:09.070[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x0000004b result 0x00000000
07:47:09.070[app:dbg]Chan 4: CREATING -> CREATED
07:47:09.070[app:dbg]Port 4: check vapi queue ('busy''create') at vapi_next_ops:2                                                                                       614
07:47:10.060[app:dbg]slic4. Event 7.
07:47:10.060[app:dbg]slic 4. Ring off event
07:47:10.060[app:dbg]Set port 4 led to state 'LED_OFF'
07:47:10.060[app:dbg]Set port 4 led to state 'LED_OFF'
07:47:10.270[app:info]SLIC 4: DTMF caller-id generated
07:47:10.270[app:dbg]CMD_START_CID_DTMF: port = 4
07:47:10.270[app:dbg]Port 4: check vapi queue ('free') at vapi_cid_dtmf_chan:3103
07:47:10.270[app:dbg]Chan 4: current state is CREATED
07:47:10.270[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'cid_dtmf_event' a                                                                                       t vapi_cid_dtmf_chan:3132
07:47:10.270[app:dbg]VQ Conn 4 = MSP : 'cid_dtmf_event' =
07:47:10.270[app:info]Generating Caller-ID DTMF tone 'A'
07:47:10.270[app:dbg]chan 4 start tone, id=9, direction=TDM
07:47:10.270[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000949
07:47:10.270[app:dbg]vapi_proc_event: VAPI_CB
07:47:10.270[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000949 result 0x00000000
07:47:10.270[app:dbg]Conn 4: Caller Id DTMF tone - Successfull
07:47:10.270[app:dbg]Port 4: check vapi queue ('busy''cid_dtmf_event') at vapi_ne                                                                                       xt_ops:2614
07:47:10.420[app:dbg]Port 4: check vapi queue ('free') at vapi_cid_dtmf_chan:3103
07:47:10.420[app:dbg]Chan 4: current state is CREATED
07:47:10.420[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'cid_dtmf_event' a                                                                                       t vapi_cid_dtmf_chan:3132
07:47:10.420[app:dbg]VQ Conn 4 = MSP : 'cid_dtmf_event' =
07:47:10.420[app:info]Generating Caller-ID DTMF tone '1'
07:47:10.420[app:dbg]chan 4 start tone, id=0, direction=TDM
07:47:10.420[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, con                                                                                       n 4
07:47:10.420[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000949
07:47:10.420[app:dbg]vapi_proc_event: VAPI_CB
07:47:10.420[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000949 result 0x00000000
07:47:10.420[app:dbg]Conn 4: Caller Id DTMF tone - Successfull
07:47:10.420[app:dbg]Port 4: check vapi queue ('busy''cid_dtmf_event') at vapi_ne                                                                                       xt_ops:2614
07:47:10.580[app:dbg]Port 4: check vapi queue ('free') at vapi_cid_dtmf_chan:3103
07:47:10.580[app:dbg]Chan 4: current state is CREATED
07:47:10.580[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'cid_dtmf_event' a                                                                                       t vapi_cid_dtmf_chan:3132
07:47:10.580[app:dbg]VQ Conn 4 = MSP : 'cid_dtmf_event' =
07:47:10.580[app:info]Generating Caller-ID DTMF tone '1'
07:47:10.580[app:dbg]chan 4 start tone, id=0, direction=TDM
07:47:10.580[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, con                                                                                       n 4
07:47:10.580[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000949
07:47:10.580[app:dbg]vapi_proc_event: VAPI_CB
07:47:10.580[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000949 result 0x00000000
07:47:10.580[app:dbg]Conn 4: Caller Id DTMF tone - Successfull
07:47:10.580[app:dbg]Port 4: check vapi queue ('busy''cid_dtmf_event') at vapi_ne                                                                                       xt_ops:2614
07:47:10.740[app:dbg]Port 4: check vapi queue ('free') at vapi_cid_dtmf_chan:3103
07:47:10.740[app:dbg]Chan 4: current state is CREATED
07:47:10.740[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'cid_dtmf_event' a                                                                                       t vapi_cid_dtmf_chan:3132
07:47:10.740[app:dbg]VQ Conn 4 = MSP : 'cid_dtmf_event' =
07:47:10.740[app:info]Generating Caller-ID DTMF tone '1'
07:47:10.740[app:dbg]chan 4 start tone, id=0, direction=TDM
07:47:10.740[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, con                                                                                       n 4
07:47:10.740[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000949
07:47:10.740[app:dbg]vapi_proc_event: VAPI_CB
07:47:10.740[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000949 result 0x00000000
07:47:10.740[app:dbg]Conn 4: Caller Id DTMF tone - Successfull
07:47:10.740[app:dbg]Port 4: check vapi queue ('busy''cid_dtmf_event') at vapi_ne                                                                                       xt_ops:2614
07:47:10.900[app:dbg]Port 4: check vapi queue ('free') at vapi_cid_dtmf_chan:3103
07:47:10.900[app:dbg]Chan 4: current state is CREATED
07:47:10.900[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'cid_dtmf_event' a                                                                                       t vapi_cid_dtmf_chan:3132
07:47:10.900[app:dbg]VQ Conn 4 = MSP : 'cid_dtmf_event' =
07:47:10.900[app:info]Generating Caller-ID DTMF tone '1'
07:47:10.900[app:dbg]chan 4 start tone, id=0, direction=TDM
07:47:10.900[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, con                                                                                       n 4
07:47:10.900[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000949
07:47:10.900[app:dbg]vapi_proc_event: VAPI_CB
07:47:10.900[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000949 result 0x00000000
07:47:10.900[app:dbg]Conn 4: Caller Id DTMF tone - Successfull
07:47:10.900[app:dbg]Port 4: check vapi queue ('busy''cid_dtmf_event') at vapi_ne                                                                                       xt_ops:2614
07:47:11.060[app:dbg]Port 4: check vapi queue ('free') at vapi_cid_dtmf_chan:3103
07:47:11.060[app:dbg]Chan 4: current state is CREATED
07:47:11.060[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'cid_dtmf_event' a                                                                                       t vapi_cid_dtmf_chan:3132
07:47:11.060[app:dbg]VQ Conn 4 = MSP : 'cid_dtmf_event' =
07:47:11.060[app:info]Generating Caller-ID DTMF tone '1'
07:47:11.060[app:dbg]chan 4 start tone, id=0, direction=TDM
07:47:11.060[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, con                                                                                       n 4
07:47:11.060[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000949
07:47:11.060[app:dbg]vapi_proc_event: VAPI_CB
07:47:11.060[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000949 result 0x00000000
07:47:11.060[app:dbg]Conn 4: Caller Id DTMF tone - Successfull
07:47:11.060[app:dbg]Port 4: check vapi queue ('busy''cid_dtmf_event') at vapi_ne                                                                                       xt_ops:2614
07:47:11.220[app:dbg]Port 4: check vapi queue ('free') at vapi_cid_dtmf_chan:3103
07:47:11.220[app:dbg]Chan 4: current state is CREATED
07:47:11.220[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'cid_dtmf_event' a                                                                                       t vapi_cid_dtmf_chan:3132
07:47:11.220[app:dbg]VQ Conn 4 = MSP : 'cid_dtmf_event' =
07:47:11.220[app:info]Generating Caller-ID DTMF tone '1'
07:47:11.220[app:dbg]chan 4 start tone, id=0, direction=TDM
07:47:11.220[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, con                                                                                       n 4
07:47:11.220[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000949
07:47:11.220[app:dbg]vapi_proc_event: VAPI_CB
07:47:11.220[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000949 result 0x00000000
07:47:11.220[app:dbg]Conn 4: Caller Id DTMF tone - Successfull
07:47:11.220[app:dbg]Port 4: check vapi queue ('busy''cid_dtmf_event') at vapi_ne                                                                                       xt_ops:2614
07:47:11.380[app:dbg]Port 4: check vapi queue ('free') at vapi_cid_dtmf_chan:3103
07:47:11.380[app:dbg]Chan 4: current state is CREATED
07:47:11.380[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'cid_dtmf_event' a                                                                                       t vapi_cid_dtmf_chan:3132
07:47:11.380[app:dbg]VQ Conn 4 = MSP : 'cid_dtmf_event' =
07:47:11.380[app:info]Generating Caller-ID DTMF tone '1'
07:47:11.380[app:dbg]chan 4 start tone, id=0, direction=TDM
07:47:11.380[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, con                                                                                       n 4
07:47:11.380[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000949
07:47:11.380[app:dbg]vapi_proc_event: VAPI_CB
07:47:11.380[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000949 result 0x00000000
07:47:11.380[app:dbg]Conn 4: Caller Id DTMF tone - Successfull
07:47:11.380[app:dbg]Port 4: check vapi queue ('busy''cid_dtmf_event') at vapi_ne                                                                                       xt_ops:2614
07:47:11.540[app:dbg]Port 4: check vapi queue ('free') at vapi_cid_dtmf_chan:3103
07:47:11.540[app:dbg]Chan 4: current state is CREATED
07:47:11.540[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'cid_dtmf_event' a                                                                                       t vapi_cid_dtmf_chan:3132
07:47:11.540[app:dbg]VQ Conn 4 = MSP : 'cid_dtmf_event' =
07:47:11.540[app:info]Generating Caller-ID DTMF tone '1'
07:47:11.540[app:dbg]chan 4 start tone, id=0, direction=TDM
07:47:11.540[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, con                                                                                       n 4
07:47:11.540[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000949
07:47:11.540[app:dbg]vapi_proc_event: VAPI_CB
07:47:11.540[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000949 result 0x00000000
07:47:11.540[app:dbg]Conn 4: Caller Id DTMF tone - Successfull
07:47:11.540[app:dbg]Port 4: check vapi queue ('busy''cid_dtmf_event') at vapi_ne                                                                                       xt_ops:2614
07:47:11.570[app:dbg]slic4. Event 2.
07:47:11.570[app:dbg]slic 4. Off-hook event
07:47:11.570[app:dbg]Set port 4 led to state 'LED_ON'
07:47:11.570[app:dbg]HIO: offhook TDM port '4' port enabled 1
07:47:11.570[app:dbg]SLIC 4 (103): offhook state: ringing
07:47:11.570[app:dbg]regex ID 4: dial reset
07:47:11.570[app:dbg]SLIC 4: -> talking(call id: 02060006)
07:47:11.570[app:dbg]pbx -[msg_answer]-> group
07:47:11.570[app:info]SLIC 4: from state 'ringing' to state 'talking'
07:47:11.570[app:dbg]CMD_STOP_TONE: port = 4
07:47:11.570[app:dbg]Port 4: check vapi queue ('free') at vapi_stop_tone_chan:151                                                                                       8
07:47:11.570[app:dbg]Chan 4: current state is CREATED
07:47:11.570[app:ERR]chan 4: no generated tones!
07:47:11.570[app:dbg]vapi_chan.c:1554: conn 4 peek cmd 'no event' from queue
07:47:11.570[app:dbg]Port 4: check vapi queue ('free') at __cmd_engine:342
07:47:11.570[app:dbg]Port 4: check vapi queue ('free') at vapi_next_ops:2614
07:47:11.570[app:dbg]Port 4: user port 2, old state talking, new state
07:47:11.570[app:dbg]Set port 4 led to state 'LED_ON'
07:47:11.570[app:dbg]pbx -[msg_fxs_state]-> group
07:47:11.570[app:dbg]dump_port_calls() SLIC 4:
07:47:11.570[app:dbg]Q:(0x335c00,0x02060006,(nil))
07:47:11.570[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((                                                                                       nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
07:47:11.570[app:dbg]ITC: [msg_answer] -> group
07:47:11.570[app:dbg][SG] self_on_answer()
07:47:11.570[app:dbg][SG] setStateCall()
07:47:11.570[app:dbg][SG] self_on_answer(): removed from queue call(group 0) with                                                                                        call_id: 0x02060006
07:47:11.570[app:dbg][GM] findCall()
07:47:11.570[app:dbg] [GM] load_in_handle():
07:47:11.570[app:dbg]group -[msg_answer]-> sip
07:47:11.570[app:dbg]ITC: [msg_fxs_state] -> group
07:47:11.570[app:dbg]-----[GM] self_fxs_state()
07:47:11.570[app:dbg]Port 4: new state is talking
07:47:11.570[app:dbg]ITC: [msg_answer] -> sip
07:47:11.570[app:dbg]sip: call 02060006: endpoint 4 answered
07:47:11.570[app:dbg]sip: call 02060006: INVITE: 200 OK SIP_T NO
07:47:11.570[app:dbg]sip: call 02060006: set endpoint 4 to state 'gs_answer'
07:47:11.570[app:dbg]self_on_answer() sdp state <receive> - create answer sdp
07:47:11.570[app:dbg]sdp_codecs_set_ptime() ptime present : 20
07:47:11.570[app:dbg]sdp_codecs_dump() ssup absent on, ecan absent on, rfc presen                                                                                       t 101, nse absent 0, ptime present 20
07:47:11.570[app:dbg]sdp_codecs_dump() G723:
07:47:11.570[app:dbg]sdp_codecs_dump() PT 4, rate absent 6.3, ssup present off
07:47:11.570[app:dbg]sdp_codecs_dump() G711A:
07:47:11.570[app:dbg]sdp_codecs_dump() PT 8, vbd absent off
07:47:11.570[app:dbg]sdp_codecs_dump() G711U:
07:47:11.570[app:dbg]sdp_codecs_dump() PT 0, vbd absent off
07:47:11.570[app:dbg]sdp_codecs_dump() G726-24: none
07:47:11.570[app:dbg]sdp_codecs_dump() G726-32: none
07:47:11.570[app:dbg]sdp_codecs_dump() G722: none
07:47:11.570[app:dbg]sdp_codecs_g711a_add_to_media_attrs() g711a: have one at las                                                                                       t
07:47:11.570[app:dbg]sdp_codecs_g711u_add_to_media_attrs() g711u: have one at las                                                                                       t
07:47:11.570[app:dbg]sdp_codecs_rfc2833_add_to_media_attrs() present, pt 101
07:47:11.570[app:dbg]sdp_codecs_nse_add_to_media_attrs() absent, pt 0
07:47:11.570[app:dbg]sdp_codecs_ptime_add_to_attrs() ptime present 20
07:47:11.570[app:dbg]sdp_codecs_ecan_add_to_attrs() ecan absent on
07:47:11.570[app:dbg]sdp_codecs_ssup_add_to_attrs() ssup absent on
07:47:11.570[app:dbg]sdp_tail:  8 0 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
07:47:11.570[app:dbg]make_sdp: SDP: s=Session SDP
m=audio 23028 RTP/AVP 8 0 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
07:47:11.570[app:dbg]sdp_codecs_set_ptime() ptime present : 20
07:47:11.570[app:dbg]sdp_codecs_get_rfc2833: present=1 pt=101
07:47:11.570[app:dbg]self_on_answer: call_id = 02060006 need_exchange_at_answer =                                                                                        0
07:47:11.580[sip]send 889 bytes to udp/[10.10.2.2]:5060 at 14:15:27.580000:
   ------------------------------------------------------------------------
07:47:11.580[sip]   SIP/2.0 200 OK
07:47:11.580[sip]   Via: SIP/2.0/UDP 10.10.2.2:5060;branch=z9hG4bKl9sbs5009gqg2js                                                                                       2o691.1
07:47:11.580[sip]   From: "anonymous" <sip:anonymous@anonymous.invalid:5060>;tag=                                                                                       SD5ntsd01-nfvnryso45
07:47:11.580[sip]   To: "3477951" <sip:3477951@10.10.2.2:5060;user=phone>;tag=2XU                                                                                       7tyej1XQaS
07:47:11.580[sip]   Call-ID: SD5ntsd01-75b99711bd59a17946a8fe9c2172726d-cl5k9s0
07:47:11.580[sip]   CSeq: 498 INVITE
07:47:11.580[sip]   Contact: <sip:3477951@10.0.5.14:5060>
07:47:11.580[sip]   User-Agent: TAU-8.IP/2.3.0 SN/VI33020063 sofia-sip/1.12.10
07:47:11.580[sip]   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUB                                                                                       SCRIBE, NOTIFY, REFER, UPDATE, INFO
07:47:11.580[sip]   Supported: timer, 100rel, replaces
07:47:11.580[sip]   Session-Expires: 1800;refresher=uas
07:47:11.580[sip]   Min-SE: 120
07:47:11.580[sip]   Content-Type: application/sdp
07:47:11.580[sip]   Content-Disposition: session
07:47:11.580[sip]   Content-Length: 201
07:47:11.580[sip]
07:47:11.580[sip]   v=0
07:47:11.580[sip]   o=- 2614377005215393572 968427467053647067 IN IP4 10.0.5.14
07:47:11.580[sip]   s=Session SDP
07:47:11.580[sip]   c=IN IP4 10.0.5.14
07:47:11.580[sip]   t=0 0
07:47:11.580[sip]   m=audio 23028 RTP/AVP 8 101
07:47:11.580[sip]   a=rtpmap:101 telephone-event/8000
07:47:11.580[sip]   a=fmtp:101 0-15
07:47:11.580[sip]   a=ptime:20
07:47:11.580[sip]   -------------------------------------------------------------                                                                                       -----------
07:47:11.580[app:dbg]got nua_i_state : 200(OK)
07:47:11.580[app:dbg]NO SIP IN nua_i_state == 200 : OK
07:47:11.580[app:dbg]self_i_state(): call state 7: as : local sdp : sdp_recv no_o                                                                                       c
07:47:11.580[app:dbg]sip: call 02060006: SDP answer sent for the first invite
07:47:11.580[app:dbg]self_destroy_current_media() nothing to destroy
07:47:11.580[app:dbg]self_start_media: 1. handle call id 0x02060006, call id 0x02                                                                                       060006
07:47:11.580[app:dbg]sip: set options: call 02060006: media stream 0: 10.0.5.14:2                                                                                       3028 -> 10.10.2.2:17632: MFPT 0 <drop>
07:47:11.580[app:dbg]self_itc_codec(): payload 8
07:47:11.580[app:dbg]self_itc_codec(): payload 8
07:47:11.580[app:dbg]Supported codec[0]: <G.711A>:8, vbd off, vad on, ecan on
07:47:11.580[app:dbg]sdp_codecs_get_rfc2833: present=1 pt=101
07:47:11.580[app:dbg]validate_ptime() codec G.711A, ptime 20, check_bigger 1, pre                                                                                       sent 1
07:47:11.580[app:dbg]validate_ptime() using 20
07:47:11.580[app:dbg]sdp_codecs_set_ptime() ptime present : 20
07:47:11.580[app:dbg]self_start_media: 2. handle call id 0x02060006, call id 0x02                                                                                       060006
07:47:11.580[app:dbg]sip -[msg_set_media]-> pbx
07:47:11.580[app:dbg]sip: call 02060006: local SDP offer copy
07:47:11.580[app:dbg]ITC: [msg_set_media] -> pbx
07:47:11.580[app:dbg]self_on_set_media: call id 0x02060006 tx/rx 1/1
07:47:11.580[app:dbg]dump_port_calls() SLIC 4:
07:47:11.580[app:dbg]Q:(0x335c00,0x02060006,(nil))
07:47:11.580[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((                                                                                       nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
07:47:11.580[app:dbg]SLIC 4: TX start / RX start: 10.0.5.14:23028->10.10.2.2:1763                                                                                       2, <G.711A:8>
07:47:11.580[app:dbg]SLIC 4: send only 0 vad 1 g723_hr 1 vbd 0, ecan 1 rfc2833 pt                                                                                        101, NSE pt 0, MFPT 0
07:47:11.580[app:dbg]incom_calls_set_media_started() call 0x02060006, group 0, ta                                                                                       sk <group> media started
07:47:11.580[app:dbg]self_set_media_start(): set ptime to 20
07:47:11.580[app:dbg]port_set_ip_param
07:47:11.580[app:dbg]set media param for '4', 10.0.5.14:23028, mode=local, random                                                                                        97
07:47:11.580[app:dbg]port_set_ip_param
07:47:11.580[app:dbg]set media param for '4', 10.10.2.2:17632, mode=remote, rando                                                                                       m 97
07:47:11.580[app:dbg]CMD_CREATE_CONN: port = 4
07:47:11.580[app:dbg]Port 4: check vapi queue ('free') at vapi_create_chan:710
07:47:11.580[app:dbg]Chan 4: current state is CREATED
07:47:11.580[app:dbg]chan 4: no need to create - already exists
07:47:11.580[app:dbg]Port 4: check vapi queue ('free') at __cmd_engine:342
07:47:11.590[app:dbg]Port 4: check vapi queue ('free') at vapi_next_ops:2614
07:47:11.590[app:dbg]SLIC 4: starting media (G.711A) 10.0.5.14:23028 -> 10.10.2.2                                                                                       :17632
07:47:11.590[app:dbg]port 4: start voice - first time
07:47:11.590[app:dbg]port_start_voice() chan 04: remote IP <10.10.2.2> (arp query                                                                                        0 times)
07:47:11.590[app:dbg]chan 4: get mac succesfull, repeat 0 times
07:47:11.590[app:dbg]CMD_START_VOICE: port = 4
07:47:11.590[app:dbg]vapi_set_chan_param: chan=4 hold=0 deactivate=0
07:47:11.590[app:dbg]Port 4: check vapi queue ('free') at vapi_set_chan_param:218                                                                                       9
07:47:11.590[app:dbg]Chan 4: current state is CREATED
07:47:11.590[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'start voice' at v                                                                                       api_set_chan_param:2213
07:47:11.590[app:dbg]VQ Conn 4 = MSP :   'start voice' =
07:47:11.590[app:dbg]Conn 4 Eth src=a8:f9:4b:09:c6:f5, dst=00:00:00:00:00:00
07:47:11.590[app:dbg]Conn 4 IP src=10.0.5.14:23028, dst=10.10.2.2:17632
07:47:11.590[app:dbg]CHECK REQID: 0x00000502(Conn 4)
07:47:11.590[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000502
07:47:11.590[app:dbg]vapi: Conn 4. Disable - Ok
07:47:11.590[app:dbg]vapi_proc_event: VAPI_CB
07:47:11.590[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000502 result 0x00000000
07:47:11.590[app:dbg]VOIP_DISABLE: chan = 4
07:47:11.590[app:dbg]vapi_cb_setchan: chan 4 deactivate 0
07:47:11.590[app:dbg]vapi: create: TDM channel 4 Set SSRC to 4BA7BC80
07:47:11.590[app:dbg]vapi: Conn 4. Set src/dst eth mac - Ok
07:47:11.590[app:dbg]Reserved IP: 192.168.253.1
07:47:11.590[app:dbg]vapi_cb_setchan: ch4. msp_ip = 192.168.253.2
07:47:11.590[app:dbg]IP PARAMS: 1FDA8C0 30028 2FDA8C0 30028
07:47:11.590[app:dbg]Create RX-TX media for SLIC 4(sendonly: 0, rtcp: 0)
07:47:11.590[app:dbg]FORCE_BIND; bind msp_sock
07:47:11.590[app:dbg]bind net_sock addr = 192.168.253.1 port = 19573
07:47:11.590[app:dbg]FORCE_BIND; bind net_sock
07:47:11.590[app:dbg]bind net_sock addr = 10.0.5.14 port = 62553
07:47:11.590[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000508
07:47:11.590[app:dbg]vapi: Conn 4. Set src/dst ip addr - ok
07:47:11.590[app:dbg]vapi_proc_event: VAPI_CB
07:47:11.590[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000508 result 0x00000000
07:47:11.590[app:dbg]VOIP_SET_IP: chan = 4
07:47:11.590[app:dbg]vapi_cb_setchan: chan 4 deactivate 0
07:47:11.590[app:dbg]chan 4. vapi_cb_setchan: configure ecan on
07:47:11.590[app:dbg]vapi_passthru_echocan_cb() NLP, DCRF enabled, session 0, on                                                                                        1, tail 32ms, value 0x8003
07:47:11.590[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000548
07:47:11.590[app:dbg]vapi_proc_event: VAPI_CB
07:47:11.590[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000548 result 0x00000000
07:47:11.590[app:dbg]VOIP_DTMF_CID_START: chan = 4
07:47:11.590[app:dbg]vapi_cb_setchan: chan 4 deactivate 0
07:47:11.590[app:dbg]chan 4. vapi_cb_setchan: VOIP_SSRC_FILT
07:47:11.590[app:dbg]vapi_cb_setchan: ch4. msp_ip = 192.168.253.2
07:47:11.590[app:dbg]RTCP IP PARAMS: 1FDA8C0 30029 2FDA8C0 30029
07:47:11.600[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000511
07:47:11.600[app:dbg]vapi_proc_event: VAPI_CB
07:47:11.600[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000511 result 0x00000000
07:47:11.600[app:dbg]VOIP_SET_JBOPT: chan = 4
07:47:11.600[app:dbg]vapi_cb_setchan: chan 4 deactivate 0
07:47:11.600[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_PT
07:47:11.600[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_PT
07:47:11.600[app:dbg]for chan <4> set codec type = 5 'G711A'
07:47:11.610[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x0000054f
07:47:11.610[app:dbg]vapi_proc_event: VAPI_CB
07:47:11.610[sip]recv 381 bytes from udp/[10.10.2.2]:5060 at 14:15:27.610000:
   ------------------------------------------------------------------------
07:47:11.610[sip]   ACK sip:3477951@10.0.5.14:5060 SIP/2.0
07:47:11.610[sip]   Via: SIP/2.0/UDP 10.10.2.2:5060;branch=z9hG4bK717hm000dgf0qmc                                                                                       nd4q1.1
07:47:11.610[sip]   Call-ID: SD5ntsd01-75b99711bd59a17946a8fe9c2172726d-cl5k9s0
07:47:11.610[sip]   CSeq: 498 ACK
07:47:11.610[sip]   From: "anonymous" <sip:anonymous@anonymous.invalid:5060>;tag=                                                                                       SD5ntsd01-nfvnryso45
07:47:11.610[sip]   To: "3477951" <sip:3477951@10.10.2.2:5060;user=phone>;tag=2XU                                                                                       7tyej1XQaS
07:47:11.610[sip]   Max-Forwards: 69
07:47:11.610[sip]   Content-Length: 0
07:47:11.610[sip]
07:47:11.610[sip]   -------------------------------------------------------------                                                                                       -----------
07:47:11.610[app:dbg]got nua_i_ack : 200(OK)
07:47:11.610[app:dbg]got nua_i_state : 200(OK)
07:47:11.610[app:dbg]NO SIP IN nua_i_state == 200 : OK
07:47:11.610[app:dbg]self_i_state(): call state 8: : : sdp_init have_oc
07:47:11.610[app:dbg]sip: call 02060006: ACK from sip:anonymous@anonymous.invalid                                                                                       :5060
07:47:11.610[app:dbg]sip: call 02060006: ACK from sip:anonymous@anonymous.invalid                                                                                       :5060
07:47:11.610[app:dbg]got nua_i_active : 200(Call active)
07:47:11.610[app:dbg]NO SIP IN nua_i_active == 200 : Call active
07:47:11.610[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x0000054f result 0x00000000
07:47:11.610[app:dbg]VOIP_SET_TIMESTAMP: chan = 4
07:47:11.610[app:dbg]vapi_cb_setchan: chan 4 deactivate 0
07:47:11.610[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_CODEC
07:47:11.610[app:dbg]set_packet_interval = 20
07:47:11.610[app:dbg]vapi: Conn 4. Set 'Packet interval' 20
07:47:11.610[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_PACKET
07:47:11.610[app:dbg]SET TX DTMF PT: 101
07:47:11.610[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000510
07:47:11.610[app:dbg]vapi_proc_event: VAPI_CB
07:47:11.610[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000510 result 0x00000000
07:47:11.610[app:dbg]VOIP_SET_PACKET2: chan = 4
07:47:11.610[app:dbg]vapi_cb_setchan: chan 4 deactivate 0
07:47:11.610[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_PACKET2
07:47:11.610[app:dbg]SET RX DTMF PT: 101
07:47:11.620[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000514
07:47:11.620[app:dbg]vapi_proc_event: VAPI_CB
07:47:11.620[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000514 result 0x00000000
07:47:11.620[app:dbg]VOIP_SET_DTMFOPT2: chan = 4
07:47:11.620[app:dbg]vapi_cb_setchan: chan 4 deactivate 0
07:47:11.620[app:dbg]vapi: Chan 4 set chach (packet mode)
07:47:11.620[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_DTMFOPT dtmf 1, pt 101
07:47:11.620[app:dbg]Enable RFC2833 events
07:47:11.620[app:dbg]Set RFC2833 PT: 101(01A6, 65FF)
07:47:11.620[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_DTMFOPT2
07:47:11.620[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_PT2
07:47:11.620[app:dbg]vapi: Conn 4. Enable RTP indication
07:47:11.620[app:dbg]chan 4. vapi_cb_setchan: VOIP_ENABLE_RTP_IND
07:47:11.620[app:dbg]chan 4: set jitter buffer options
07:47:11.620[app:dbg]Conn 4, JB it not MFPT, set delay to [0;200]ms, mode soft th                                                                                        500
07:47:11.620[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_INDCTL
07:47:11.620[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_JBOPT
07:47:11.620[app:dbg]vapi: Conn 4. Set tone ctl options
07:47:11.620[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_VLAN
07:47:11.620[app:dbg]VAD: 1 CNG: 0 PTE: 20
07:47:11.620[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000517
07:47:11.620[app:dbg]vapi_proc_event: VAPI_CB
07:47:11.620[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000517 result 0x00000000
07:47:11.620[app:dbg]VOIP_SET_ECHOCAN: chan = 4
07:47:11.620[app:dbg]vapi_cb_setchan: chan 4 deactivate 0
07:47:11.620[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_VCEOPT
07:47:11.620[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000519
07:47:11.620[app:dbg]vapi_proc_event: VAPI_CB
07:47:11.620[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000519 result 0x00000000
07:47:11.620[app:dbg]VOIP_SET_DONE: chan = 4
07:47:11.620[app:dbg]vapi_cb_setchan: chan 4 deactivate 0
07:47:11.620[app:dbg]vapi_cb_setchan() Conn 4: set eActive state ok
07:47:11.620[app:dbg]Port 4: check vapi queue ('busy''start voice') at vapi_next_                                                                                       ops:2614
07:47:11.640[app:dbg]vapi: Conn 4. event 'RTP Monitor Ind': Start RTP stream , PT                                                                                        0x0008 'PCM-A', silence 0
07:47:11.640[app:dbg]vapi: generic event, code 5 <SSRC change>, conn 0
07:47:14.050[sip]send 375 bytes to udp/[10.10.2.2]:5060 at 14:15:30.050000:
   ------------------------------------------------------------------------
07:47:14.050[sip]   OPTIONS sip:3477951@voip.sinor.ru SIP/2.0
07:47:14.050[sip]   Via: SIP/2.0/UDP 10.0.5.14;rport;branch=z9hG4bK321pQNZSe2K8Q
07:47:14.050[sip]   Max-Forwards: 70
07:47:14.050[sip]   From: <sip:3477951@voip.sinor.ru>;tag=tNH1c67Nrp5mc
07:47:14.050[sip]   To: <sip:3477951@voip.sinor.ru>
07:47:14.050[sip]   Call-ID: de920740-987a-1200-8fa4-a8f94b09c6f5
07:47:14.050[sip]   CSeq: 24 OPTIONS
07:47:14.050[sip]   Subject: KEEPALIVE
07:47:14.050[sip]   User-Agent: TAU-8.IP/2.3.0 SN/VI33020063 sofia-sip/1.12.10
07:47:14.050[sip]   Content-Length: 0
07:47:14.050[sip]
07:47:14.050[sip]   -------------------------------------------------------------                                                                                       -----------
07:47:14.060[sip]recv 296 bytes from udp/[10.10.2.2]:5060 at 14:15:30.060000:
   ------------------------------------------------------------------------
07:47:14.060[sip]   SIP/2.0 482 Loop Detected
07:47:14.060[sip]   Via: SIP/2.0/UDP 10.0.5.14;branch=z9hG4bK321pQNZSe2K8Q;rport=                                                                                       5060
07:47:14.060[sip]   From: <sip:3477951@voip.sinor.ru>;tag=tNH1c67Nrp5mc
07:47:14.060[sip]   To: <sip:3477951@voip.sinor.ru>;tag=SDa1l9299-ouhb-pfa3g6o3s1
07:47:14.060[sip]   Call-ID: de920740-987a-1200-8fa4-a8f94b09c6f5
07:47:14.060[sip]   CSeq: 24 OPTIONS
07:47:14.060[sip]   Content-Length: 0
07:47:14.060[sip]
07:47:14.060[sip]   -------------------------------------------------------------                                                                                       -----------
07:47:18.870[app:dbg]slic4. Event 8.
07:47:18.870[app:dbg]slic 4. Pre-On-hook event
07:47:18.870[app:dbg]HIO: preonhook TDM port '4', port enabled 1
07:47:18.870[app:dbg]CMD_STOP_TONE: port = 4
07:47:18.870[app:dbg]Port 4: check vapi queue ('free') at vapi_stop_tone_chan:151                                                                                       8
07:47:18.870[app:dbg]Chan 4: current state is CREATED
07:47:18.870[app:ERR]chan 4: no generated tones!
07:47:18.870[app:dbg]vapi_chan.c:1554: conn 4 peek cmd 'no event' from queue
07:47:18.870[app:dbg]Port 4: check vapi queue ('free') at __cmd_engine:342
07:47:18.870[app:dbg]Port 4: check vapi queue ('free') at vapi_next_ops:2614
07:47:19.770[app:dbg]slic4. Event 1.
07:47:19.770[app:dbg]slic 4. On-hook event
07:47:19.770[app:dbg]Set port 4 led to state 'LED_OFF'
07:47:19.770[app:dbg]HIO: onhook TDM port '4', port enabled 1
07:47:19.770[app:dbg]SLIC 4 (103): onhook state: talking
07:47:19.770[app:dbg]regex ID 4: dial reset
07:47:19.770[app:dbg]pbx -[msg_clear]-> sip
07:47:19.770[app:info]SLIC 4: from state 'talking' to state 'hangup'
07:47:19.770[app:dbg]CMD_STOP_TONE: port = 4
07:47:19.770[app:dbg]Port 4: check vapi queue ('free') at vapi_stop_tone_chan:151                                                                                       8
07:47:19.770[app:dbg]Chan 4: current state is CREATED
07:47:19.770[app:ERR]chan 4: no generated tones!
07:47:19.770[app:dbg]vapi_chan.c:1554: conn 4 peek cmd 'no event' from queue
07:47:19.770[app:dbg]Port 4: check vapi queue ('free') at __cmd_engine:342
07:47:19.770[app:dbg]Port 4: check vapi queue ('free') at vapi_next_ops:2614
07:47:19.770[app:dbg]SLIC 4: reset
07:47:19.770[app:dbg]dump_port_calls() SLIC 4:
07:47:19.770[app:dbg]Q:(0x335c00,0x02060006,(nil))
07:47:19.770[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((                                                                                       nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
07:47:19.770[app:dbg]vapi: chan 4: connection STATISTIC
07:47:19.770[app:dbg]vapi: chan 4: Rx_pack = 0
07:47:19.770[app:dbg]vapi: chan 4: Rx_oct  = 0
07:47:19.770[app:dbg]vapi: chan 4: Lost_pack  = 0
07:47:19.770[app:dbg]vapi: chan 4: Tx_pack = 0
07:47:19.770[app:dbg]vapi: chan 4: Tx_oct  = 0
07:47:19.770[app:dbg]vapi: chan 4: peak_jiter = 0
07:47:19.770[app:dbg]SLIC 4: Common port statistic
07:47:19.770[app:dbg]SLIC 4: Rx_pack = 0
07:47:19.770[app:dbg]SLIC 4: Rx_oct  = 0
07:47:19.770[app:dbg]SLIC 4: Lost_pack  = 0
07:47:19.770[app:dbg]SLIC 4: Tx_pack = 0
07:47:19.770[app:dbg]SLIC 4: Tx_oct  = 0
07:47:19.770[app:dbg]SLIC 4: peak_jiter = 0
07:47:19.770[app:dbg]SLIC 4: reset call 0x02060006 (active)
07:47:19.770[app:dbg]CMD_SET_VOICE: port = 4
07:47:19.770[app:dbg]Port 4: check vapi queue ('free') at vapi_start_stop_chan:16                                                                                       67
07:47:19.770[app:dbg]Chan 4: current state is CREATED
07:47:19.770[app:dbg]vapi: Conn 4. start_stop voice chan, TX stop, RX stop
07:47:19.770[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'set voice' at vap                                                                                       i_start_stop_chan:1710
07:47:19.770[app:dbg]VQ Conn 4 = MSP :     'set voice' =
07:47:19.770[app:dbg]incom_calls_set_media_started() call 0x02060006, group 0, ta                                                                                       sk <group> media stopped
07:47:19.770[app:dbg]incom_calls_rem() rem call 0x02060006, group 0, task <group>                                                                                        from list
07:47:19.770[app:dbg]free_final_mx: final_mx was NULL for SLIC 4
07:47:19.770[app:dbg]CMD_DESTROY_CONN: port = 4
07:47:19.770[app:dbg]Port 4: check vapi queue ('busy''set voice') at vapi_destroy                                                                                       _chan:906
07:47:19.770[app:dbg]Clear vapi queue of Port 4/chan 4
07:47:19.770[app:dbg]Port 4 put cmd 'destroy',cur 'set voice' to queue at (vapi_d                                                                                       estroy_chan:913)
07:47:19.770[app:dbg]VQ Conn 4 = MSP :     'set voice' =
07:47:19.770[app:dbg]VQ Conn 4 + 00  :       'destroy'  + <-get_ptr
07:47:19.770[app:dbg]CMD_DESTROY_IPONLY_CONN: port = 4
07:47:19.770[app:dbg]Port 4: check vapi queue ('busy''set voice') at vapi_destroy                                                                                       _chan:906
07:47:19.770[app:dbg]Clear vapi queue of Port 4/chan 12
07:47:19.770[app:dbg]Port 4 put cmd 'destroy',cur 'set voice' to queue at (vapi_d                                                                                       estroy_chan:913)
07:47:19.770[app:dbg]VQ Conn 12 = MSP :     'set voice' =
07:47:19.770[app:dbg]VQ Conn 12 + 00  :       'destroy'  + <-get_ptr
07:47:19.770[app:dbg]VQ Conn 12 + 01  :       'destroy' (hold) +
07:47:19.770[app:dbg]Port 4: user port 2, old state hangup, new state
07:47:19.770[app:dbg]Set port 4 led to state 'LED_OFF'
07:47:19.770[app:dbg]pbx -[msg_fxs_state]-> group
07:47:19.770[app:dbg]dump_port_calls() SLIC 4:
07:47:19.770[app:dbg]Q:NONE
07:47:19.770[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((                                                                                       nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
07:47:19.770[app:dbg]Set port 4 led to state 'LED_OFF'
07:47:19.770[app:dbg]Delete all RX-TX medias from SLIC 4
07:47:19.770[app:dbg]ITC: [msg_clear] -> sip
07:47:19.770[app:dbg]call 02060006,flags(00000048): endpoint 4 cleared
07:47:19.770[app:dbg]sip: call 02060006: BYE to sip:3477951@10.10.2.2:5060;user=p                                                                                       hone
07:47:19.770[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000401
07:47:19.780[app:dbg]vapi_proc_event: VAPI_CB
07:47:19.780[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000401 result 0x00000000
07:47:19.780[app:dbg]vapi: conn 4. RTCP disabled
07:47:19.780[sip]send 713 bytes to udp/[10.10.2.2]:5060 at 14:15:35.780000:
   ------------------------------------------------------------------------
07:47:19.780[sip]   BYE sip:10.10.2.2:5060;transport=udp SIP/2.0
07:47:19.780[sip]   Via: SIP/2.0/UDP 10.0.5.14;rport;branch=z9hG4bK4BUFSggXBBaUK
07:47:19.780[sip]   Max-Forwards: 70
07:47:19.780[sip]   From: "3477951" <sip:3477951@10.10.2.2:5060;user=phone>;tag=2                                                                                       XU7tyej1XQaS
07:47:19.780[sip]   To: "anonymous" <sip:anonymous@anonymous.invalid:5060>;tag=SD                                                                                       5ntsd01-nfvnryso45
07:47:19.780[sip]   Call-ID: SD5ntsd01-75b99711bd59a17946a8fe9c2172726d-cl5k9s0
07:47:19.780[sip]   CSeq: 1419 BYE
07:47:19.780[sip]   Contact: <sip:3477951@10.0.5.14:5060>
07:47:19.780[sip]   User-Agent: TAU-8.IP/2.3.0 SN/VI33020063 sofia-sip/1.12.10
07:47:19.780[sip]   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUB                                                                                       SCRIBE, NOTIFY, REFER, UPDATE, INFO
07:47:19.780[sip]   Supported: timer, 100rel, replaces
07:47:19.780[sip]   Reason: Q.850;cause=16;text="Normal call clearing"
07:47:19.780[sip]   Content-Length: 0
07:47:19.780[sip]   P-RTP-Stat: PS=0, OS=0, PR=0, OR=0, PL=0, JI=0
07:47:19.780[sip]
07:47:19.780[sip]   -------------------------------------------------------------                                                                                       -----------
07:47:19.780[app:dbg]Delete all RX-TX medias from SLIC 12
07:47:19.780[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x000004ff
07:47:19.780[app:dbg]vapi_proc_event: VAPI_CB
07:47:19.780[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x000004ff result 0x00000000
07:47:19.780[app:dbg]Conn 4: Set voice mode successeful
07:47:19.780[app:dbg]Stop all medias on chan 4
07:47:19.780[app:dbg]Port 4: check vapi queue ('busy''set voice') at vapi_next_op                                                                                       s:2614
07:47:19.780[app:dbg]Port 4 get cmd 'destroy' from queue at (vapi_next_ops:2633)
07:47:19.780[app:dbg]VQ Conn 4 + 01  :       'destroy' (hold) + <-get_ptr
07:47:19.780[app:dbg]Port 4: check vapi queue ('free') at vapi_destroy_chan:906
07:47:19.780[app:dbg]Destroying connection 4...
07:47:19.780[app:dbg]Chan 4: current state is CREATED
07:47:19.780[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'destroy' at vapi_                                                                                       destroy_chan:932
07:47:19.780[app:dbg]VQ Conn 4 = MSP :       'destroy' =
07:47:19.780[app:dbg]VQ Conn 4 + 01  :       'destroy' (hold) + <-get_ptr
07:47:19.780[app:dbg]Chan 4: CREATED -> DESTROYING
07:47:19.790[app:dbg]Mute all RX-TX medias on SLIC 4
07:47:19.790[app:dbg]ITC: [msg_fxs_state] -> group
07:47:19.790[app:dbg]-----[GM] self_fxs_state()
07:47:19.790[app:dbg]Port 4: new state is hangup
07:47:19.780[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x0000014c
07:47:19.790[app:dbg]vapi_proc_event: VAPI_CB
07:47:19.790[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x0000014c result 0x00000000
07:47:19.800[app:dbg]Delete all RX-TX medias from SLIC 4
07:47:19.800[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000103
07:47:19.800[app:dbg]vapi_proc_event: VAPI_CB
07:47:19.800[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000103 result 0x00000000
07:47:19.800[app:dbg]Conn 4 destroyed
07:47:19.800[app:dbg]Chan 4: DESTROYING -> INITIAL
07:47:19.800[app:dbg]Port 4: check vapi queue ('busy''destroy') at vapi_next_ops:                                                                                       2614
07:47:19.800[app:dbg]Port 4 get cmd 'destroy' from queue at (vapi_next_ops:2633)
07:47:19.800[app:dbg]Port 4: check vapi queue ('free') at vapi_destroy_chan:906
07:47:19.800[app:dbg]Destroying connection 12...
07:47:19.800[app:dbg]Chan 12: current state is INITIAL
07:47:19.800[app:ERR]vapi_destroy_chan() chan 12: current state initial: duplicat                                                                                       e destroying connection!
07:47:19.800[app:dbg]Port 4: check vapi queue ('free') at vapi_next_ops:2776
07:47:19.800[app:dbg]Port 4: check vapi queue ('free') at vapi_next_ops:2614
07:47:19.820[sip]recv 337 bytes from udp/[10.10.2.2]:5060 at 14:15:35.820000:
   ------------------------------------------------------------------------
07:47:19.820[sip]   SIP/2.0 200 OK
07:47:19.820[sip]   Via: SIP/2.0/UDP 10.0.5.14;branch=z9hG4bK4BUFSggXBBaUK;rport=                                                                                       5060
07:47:19.820[sip]   From: "3477951" <sip:3477951@10.10.2.2:5060;user=phone>;tag=2                                                                                       XU7tyej1XQaS
07:47:19.820[sip]   To: "anonymous" <sip:anonymous@anonymous.invalid:5060>;tag=SD                                                                                       5ntsd01-nfvnryso45
07:47:19.820[sip]   Call-ID: SD5ntsd01-75b99711bd59a17946a8fe9c2172726d-cl5k9s0
07:47:19.820[sip]   CSeq: 1419 BYE
07:47:19.820[sip]   Content-Length: 0
07:47:19.820[sip]
07:47:19.820[sip]   -------------------------------------------------------------                                                                                       -----------
07:47:19.820[app:dbg]got nua_r_bye : 200(OK)
07:47:19.820[app:dbg]sip: call 02060006: BYE/INFO: 200 OK
07:47:19.820[app:dbg]got nua_i_state : 200(to BYE)
07:47:19.820[app:dbg]NO SIP IN nua_i_state == 200 : to BYE
07:47:19.820[app:dbg]self_i_state(): call state 10: : : sdp_init have_oc
07:47:19.820[app:dbg]sip: call 02060006: terminated
07:47:19.820[app:dbg]self_callstate_terminated: call id = 02060006 need_exchange_                                                                                       at_answer = 0
07:47:28.650[sip]recv 1029 bytes from udp/[10.10.2.2]:5060 at 14:15:44.650000:
   ------------------------------------------------------------------------
07:47:28.650[sip]   INVITE sip:3477951@10.0.5.14:5060 SIP/2.0
07:47:28.650[sip]   Via: SIP/2.0/UDP 10.10.2.2:5060;branch=z9hG4bKhevl9q10dgphphc                                                                                       na0p1.1
07:47:28.650[sip]   Accept: application/sdp
07:47:28.650[sip]   Allow: INVITE,ACK,CANCEL,BYE,INFO,PRACK,UPDATE,OPTIONS,REGIST                                                                                       ER,REFER,SUBSCRIBE,MESSAGE,PUBLISH
07:47:28.650[sip]   Call-ID: SDbnd6b01-df0948dd00f678cfed57742b79d7c956-cl5k9s0
07:47:28.650[sip]   Contact: <sip:10.10.2.2:5060;transport=udp>
07:47:28.650[sip]   CSeq: 458 INVITE
07:47:28.650[sip]   Expires: 3600
07:47:28.650[sip]   From: "anonymous" <sip:anonymous@anonymous.invalid:5060>;tag=                                                                                       SDbnd6b01-y3lf4kkrbq
07:47:28.650[sip]   To: "3477951" <sip:3477951@10.10.2.2:5060;user=phone>
07:47:28.650[sip]   Organization: Iskratel
07:47:28.650[sip]   User-Agent: SI3000
07:47:28.650[sip]   Max-Forwards: 69
07:47:28.650[sip]   Subject: Call from SI3000
07:47:28.650[sip]   Content-Length: 326
07:47:28.650[sip]   Content-Type: application/sdp
07:47:28.650[sip]   Content-Disposition: session;handling=required
07:47:28.650[sip]
07:47:28.650[sip]   v=0
07:47:28.650[sip]   o=- 1561386 4841142 IN IP4 10.10.2.2
07:47:28.650[sip]   s=-
07:47:28.650[sip]   c=IN IP4 10.10.2.2
07:47:28.650[sip]   b=AS:64
07:47:28.650[sip]   t=0 0
07:47:28.650[sip]   m=audio 17824 RTP/AVP 8 0 18 4 101
07:47:28.660[sip]   a=rtpmap:8 PCMA/8000
07:47:28.660[sip]   a=rtpmap:0 PCMU/8000
07:47:28.660[sip]   a=rtpmap:18 G729/8000
07:47:28.660[sip]   a=fmtp:18 annexb=no
07:47:28.660[sip]   a=rtpmap:4 G723/8000
07:47:28.660[sip]   a=fmtp:4 annexa=no
07:47:28.660[sip]   a=rtpmap:101 telephone-event/8000
07:47:28.660[sip]   a=fmtp:101 0-15
07:47:28.660[sip]   a=ptime:20
07:47:28.660[sip]   a=sendrecv
07:47:28.660[sip]   -------------------------------------------------------------                                                                                       -----------
07:47:28.660[app:dbg]self_pre_invite_param() entering
07:47:28.660[app:dbg]stun_get_public_ip(port = 8000)
07:47:28.660[app:dbg]stun_get_public_ip: Always using local IP
07:47:28.660[app:dbg]sip: group call (0) profile(0)
07:47:28.660[app:dbg]sip: get_support_params: profile 0 supported: 'timer, 100rel                                                                                       , replaces'
07:47:28.660[sip]send 388 bytes to udp/[10.10.2.2]:5060 at 14:15:44.660000:
   ------------------------------------------------------------------------
07:47:28.660[sip]   SIP/2.0 100 Trying
07:47:28.660[sip]   Via: SIP/2.0/UDP 10.10.2.2:5060;branch=z9hG4bKhevl9q10dgphphc                                                                                       na0p1.1
07:47:28.660[sip]   From: "anonymous" <sip:anonymous@anonymous.invalid:5060>;tag=                                                                                       SDbnd6b01-y3lf4kkrbq
07:47:28.660[sip]   To: "3477951" <sip:3477951@10.10.2.2:5060;user=phone>
07:47:28.660[sip]   Call-ID: SDbnd6b01-df0948dd00f678cfed57742b79d7c956-cl5k9s0
07:47:28.660[sip]   CSeq: 458 INVITE
07:47:28.660[sip]   User-Agent: TAU-8.IP/2.3.0 SN/VI33020063 sofia-sip/1.12.10
07:47:28.660[sip]   Content-Length: 0
07:47:28.660[sip]
07:47:28.660[sip]   -------------------------------------------------------------                                                                                       -----------
07:47:28.660[app:dbg]got nua_i_invite : 100(Trying)
07:47:28.660[app:dbg]NO CALL IN nua_i_invite == 100 : Trying
07:47:28.660[app:dbg]stun_get_public_ip(port = 8000)
07:47:28.660[app:dbg]stun_get_public_ip: Always using local IP
07:47:28.660[app:dbg]sip: get_support_params: profile 0 supported: 'timer, 100rel                                                                                       , replaces'
07:47:28.660[app:dbg]sip: INVITE from sip:anonymous@anonymous.invalid:5060
07:47:28.660[app:dbg]stun_get_public_ip(port = 8000)
07:47:28.660[app:dbg]stun_get_public_ip: Always using local IP
07:47:28.660[app:dbg]sip: group call (0)
07:47:28.660[app:dbg]replaces 1, have accepted 0, ep 0x1c0b54, state 1
07:47:28.660[app:dbg]available RTP ports: 23000...26000
07:47:28.660[app:dbg]selected port for current call: 23032
07:47:28.670[app:dbg]self_i_invite (9422): no alert_info received
07:47:28.670[app:dbg]sdp_codecs_init() init call sdp (empty)
07:47:28.670[app:dbg]sdp_codecs_set_ssup() ssup present 0 ssup yes
07:47:28.670[app:dbg]G711A: PT 8
07:47:28.670[app:dbg]sdp_codecs_add_g711a_item() pt 8
07:47:28.670[app:dbg]G711U: PT 0
07:47:28.670[app:dbg]sdp_codecs_add_g711u_item() pt 0
07:47:28.670[app:dbg]G723: PT 4, bitrate default, annexa no
07:47:28.670[app:dbg]sdp_codecs_add_g723_item() pt 4, rate absent 6.3 ssup presen                                                                                       t off
07:47:28.670[app:dbg]sdp_codecs_set_rfc2833() present pt 101 remote fmtp 0-15, lo                                                                                       cal fmtp 0-15
07:47:28.670[app:dbg]attr: name: ptime value: 20
07:47:28.670[app:dbg]sdp_codecs_set_ptime() ptime present : 20
07:47:28.670[app:dbg]sdp_codecs_dump() ssup absent on, ecan absent on, rfc presen                                                                                       t 101, nse absent 0, ptime present 20
07:47:28.670[app:dbg]sdp_codecs_dump() G723:
07:47:28.670[app:dbg]sdp_codecs_dump() PT 4, rate absent 6.3, ssup present off
07:47:28.670[app:dbg]sdp_codecs_dump() G711A:
07:47:28.670[app:dbg]sdp_codecs_dump() PT 8, vbd absent off
07:47:28.670[app:dbg]sdp_codecs_dump() G711U:
07:47:28.670[app:dbg]sdp_codecs_dump() PT 0, vbd absent off
07:47:28.670[app:dbg]sdp_codecs_dump() G726-24: none
07:47:28.670[app:dbg]sdp_codecs_dump() G726-32: none
07:47:28.670[app:dbg]sdp_codecs_dump() G722: none
07:47:28.670[app:dbg]stun_get_public_ip(port = 23032)
07:47:28.670[app:dbg]stun_get_public_ip: Always using local IP
07:47:28.670[app:dbg]self_i_invite: handle call id 0x02060007, call id 0x02060007
07:47:28.670[app:dbg]got nua_i_state : 100(Trying)
07:47:28.670[app:dbg]NO SIP IN nua_i_state == 100 : Trying
07:47:28.670[app:dbg]self_i_state(): call state 5: or : remote sdp : sdp_init no_                                                                                       oc
07:47:28.670[app:dbg]sip: call 02060007: SDP offer received
07:47:28.670[app:dbg]sdp_codecs_set_ssup() ssup present 0 ssup yes
07:47:28.670[app:dbg]sdp_codecs_set_rfc2833() present pt 101 remote fmtp 0-15, lo                                                                                       cal fmtp 0-15
07:47:28.670[app:dbg]attr: name: ptime value: 20
07:47:28.670[app:dbg]sdp_codecs_set_ptime() ptime present : 20
07:47:28.670[app:dbg]sip: call 02060007: media stream 0, creating proposed audio                                                                                        channel, remote RTP 10.10.2.2:17824
07:47:28.670[app:dbg]sip: call 02060007: select audio media
07:47:28.670[app:dbg]G711A: PT 8
07:47:28.670[app:dbg]G711U: PT 0
07:47:28.670[app:dbg]G723: PT 4
07:47:28.670[app:dbg]sip: call 02060007: remote SDP offer copy
07:47:28.670[app:dbg]sip: call 02060007: called from sip:anonymous@anonymous.inva                                                                                       lid:5060 to sip:3477951@10.10.2.2:5060;user=phone
07:47:28.670[app:dbg]stun_get_public_ip(port = 8000)
07:47:28.670[app:dbg]stun_get_public_ip: Always using local IP
07:47:28.670[app:dbg]ITC_CALL to group 0
07:47:28.670[app:dbg]sdp_codecs_get_rfc2833: present=1 pt=101
07:47:28.670[app:dbg]sip -[msg_call]-> group
07:47:28.670[app:dbg]ITC: [msg_call] -> group
07:47:28.670[app:dbg] [SG] self_on_call()
07:47:28.670[app:dbg][SG] Incoming group call from anonymous.invalid:5060/anonymo                                                                                       us("anonymous") payload 101 call ID: 02060007 group: 0 ep_src: 6
07:47:28.670[app:dbg] [GM] load_in_handle():
07:47:28.670[app:dbg][SG] addCall()
07:47:28.670[app:dbg]group -[msg_free]-> sip
07:47:28.670[app:dbg] [GM] load_in_handle():
07:47:28.670[app:dbg]group -[msg_call]-> pbx
07:47:28.670[app:dbg]ITC: [msg_call] -> pbx
07:47:28.670[app:dbg]SLIC 6: incoming call from anonymous.invalid:5060/anonymous(                                                                                       "anonymous") payload 101 call ID: 02060007 group: 0
07:47:28.670[app:dbg]pbx: allocating memory for new call
07:47:28.670[app:dbg]pbx: created new incoming call for SLIC 6
07:47:28.670[app:dbg]self_call_create (4694): created
07:47:28.680[app:dbg]self_callstate_received (7492): complete
07:47:28.680[app:dbg]got nua_r_set_params : 200(OK)
07:47:28.680[app:dbg]NO SIP IN nua_r_set_params == 200 : OK
07:47:28.670[app:dbg]SLIC 6: -> ringing
07:47:28.680[app:info]SLIC 6: from state 'hangup' to state 'ringing'
07:47:28.680[app:dbg]CMD_CREATE_CONN: port = 6
07:47:28.680[app:dbg]Port 6: check vapi queue ('free') at vapi_create_chan:710
07:47:28.680[app:dbg]Chan 6: current state is INITIAL
07:47:28.680[app:dbg]Port 6: set vapi queue MSP to 'busy' with 'create' at vapi_c                                                                                       reate_chan:736
07:47:28.680[app:dbg]VQ Conn 6 = MSP :        'create' =
07:47:28.680[app:dbg]Creating connection 6....
07:47:28.680[app:dbg]Chan 6: INITIAL -> CREATING
07:47:28.680[app:dbg]Created succefuly 6....
07:47:28.680[app:info]SLIC 6: has incoming call from anonymous
07:47:28.680[app:dbg]port 6: port_seize
07:47:28.680[app:dbg]port 6: seize
07:47:28.680[app:dbg]port 6: seize has cadence pulse = 0, pause = 0
07:47:28.680[app:dbg]Set port 6 led to state 'LED_RINGING'
07:47:28.680[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x00000050
07:47:28.680[app:dbg]Port 6: user port 0, old state ringing, new state
07:47:28.680[app:dbg]Set port 6 led to state 'LED_OFF'
07:47:28.680[app:dbg]pbx -[msg_fxs_state]-> group
07:47:28.680[app:dbg]ITC: [msg_fxs_state] -> group
07:47:28.680[app:dbg]-----[GM] self_fxs_state()
07:47:28.680[app:dbg]Port 6: new state is ringing
07:47:28.680[app:dbg]pbx -[msg_free]-> group
07:47:28.680[app:dbg]ITC: [msg_free] -> group
07:47:28.680[app:dbg][SG] self_on_free()
07:47:28.680[app:dbg]SLIC 6: list of all calls:
07:47:28.680[app:dbg]   call ID: 02060007
07:47:28.680[app:dbg]incom_calls_add() add call 0x02060007, group 0, task <group>                                                                                        to list
07:47:28.680[app:dbg]vapi_proc_event: VAPI_CB
07:47:28.680[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x00000050 result 0x00000000
07:47:28.680[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x00000007
07:47:28.680[app:dbg]slic6. Event 6.
07:47:28.680[app:dbg]slic 6. Ring on event
07:47:28.680[app:dbg]Set port 6 led to state 'LED_RINGING'
07:47:28.680[app:dbg]vapi_proc_event: VAPI_CB
07:47:28.680[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x00000007 result 0x00000000
07:47:28.690[app:dbg]ITC: [msg_free] -> sip
07:47:28.690[app:dbg]sip: call 02060007: endpoint 6 ringing
07:47:28.690[app:dbg]sip: call 02060007,sip: INVITE: 180 Ringing
07:47:28.690[app:dbg]send_18x() call 0x02060007, hdr <none>, sip, rel mode/cfg of                                                                                       f/supp/req, inv w/ sdp, to group
07:47:28.690[app:dbg]send_18x(): respond w/o sdp 0, sdp 0
07:47:28.690[app:dbg]sdp_codecs_get_rfc2833: present=1 pt=101
07:47:28.690[app:dbg]Sending 180 Ringing without SDP
07:47:28.690[sip]send 580 bytes to udp/[10.10.2.2]:5060 at 14:15:44.690000:
   ------------------------------------------------------------------------
07:47:28.690[sip]   SIP/2.0 180 Ringing
07:47:28.690[sip]   Via: SIP/2.0/UDP 10.10.2.2:5060;branch=z9hG4bKhevl9q10dgphphc                                                                                       na0p1.1
07:47:28.690[sip]   From: "anonymous" <sip:anonymous@anonymous.invalid:5060>;tag=                                                                                       SDbnd6b01-y3lf4kkrbq
07:47:28.690[sip]   To: "3477951" <sip:3477951@10.10.2.2:5060;user=phone>;tag=36m                                                                                       0vSZNy6DXm
07:47:28.690[sip]   Call-ID: SDbnd6b01-df0948dd00f678cfed57742b79d7c956-cl5k9s0
07:47:28.690[sip]   CSeq: 458 INVITE
07:47:28.690[sip]   Contact: <sip:3477951@10.0.5.14:5060>
07:47:28.690[sip]   User-Agent: TAU-8.IP/2.3.0 SN/VI33020063 sofia-sip/1.12.10
07:47:28.690[sip]   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUB                                                                                       SCRIBE, NOTIFY, REFER, UPDATE, INFO
07:47:28.690[sip]   Supported: timer, 100rel, replaces
07:47:28.690[sip]   Content-Length: 0
07:47:28.690[sip]
07:47:28.690[sip]   -------------------------------------------------------------                                                                                       -----------
07:47:28.690[app:dbg]got nua_i_state : 180(Ringing)
07:47:28.690[app:dbg]NO SIP IN nua_i_state == 180 : Ringing
07:47:28.690[app:dbg]self_i_state(): call state 6: : : sdp_recv no_oc
07:47:28.680[app:dbg]vapi: Conn 6. Set In-Activ state
07:47:28.690[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x00000051
07:47:28.690[app:dbg]vapi_proc_event: VAPI_CB
07:47:28.690[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x00000051 result 0x00000000
07:47:28.690[app:dbg]vapi: Conn 6 - SET AGC
07:47:28.700[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x00000000
07:47:28.700[app:dbg]vapi_proc_event: VAPI_CB
07:47:28.700[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x00000000 result 0x00000000
07:47:28.700[app:dbg]vapi: Conn 6 - << CREATED >>
07:47:28.700[app:dbg]vapi: Conn 6 - fix DTMF detector
07:47:28.700[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x0000004a
07:47:28.700[app:dbg]vapi_proc_event: VAPI_CB
07:47:28.700[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x0000004a result 0x00000000
07:47:28.700[app:dbg]vapi: Conn 6 - fix CNG generator
07:47:28.710[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x0000004d
07:47:28.710[app:dbg]vapi_proc_event: VAPI_CB
07:47:28.710[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x0000004d result 0x00000000
07:47:28.710[app:dbg]vapi: Conn 6 - caller id Set param
07:47:28.710[app:dbg]vapi: chan '6' set param Caller ID
07:47:28.720[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x0000000c
07:47:28.720[app:dbg]vapi_proc_event: VAPI_CB
07:47:28.720[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x0000000c result 0x00000000
07:47:28.720[app:dbg]vapi: Conn 6 - enable ind ptime and pt
07:47:28.730[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x00000052
07:47:28.730[app:dbg]vapi_proc_event: VAPI_CB
07:47:28.730[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x00000052 result 0x00000000
07:47:28.730[app:dbg]vapi: Conn 6. Set Active state
07:47:28.740[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x0000004b
07:47:28.740[app:dbg]vapi_proc_event: VAPI_CB
07:47:28.740[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x0000004b result 0x00000000
07:47:28.740[app:dbg]Chan 6: CREATING -> CREATED
07:47:28.740[app:dbg]Port 6: check vapi queue ('busy''create') at vapi_next_ops:2                                                                                       614
07:47:29.700[app:dbg]slic6. Event 7.
07:47:29.700[app:dbg]slic 6. Ring off event
07:47:29.700[app:dbg]Set port 6 led to state 'LED_OFF'
07:47:29.700[app:dbg]Set port 6 led to state 'LED_OFF'
07:47:29.910[app:info]SLIC 6: DTMF caller-id generated
07:47:29.910[app:dbg]CMD_START_CID_DTMF: port = 6
07:47:29.910[app:dbg]Port 6: check vapi queue ('free') at vapi_cid_dtmf_chan:3103
07:47:29.910[app:dbg]Chan 6: current state is CREATED
07:47:29.910[app:dbg]Port 6: set vapi queue MSP to 'busy' with 'cid_dtmf_event' a                                                                                       t vapi_cid_dtmf_chan:3132
07:47:29.910[app:dbg]VQ Conn 6 = MSP : 'cid_dtmf_event' =
07:47:29.910[app:info]Generating Caller-ID DTMF tone 'A'
07:47:29.910[app:dbg]chan 6 start tone, id=9, direction=TDM
07:47:29.910[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x00000949
07:47:29.910[app:dbg]vapi_proc_event: VAPI_CB
07:47:29.910[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x00000949 result 0x00000000
07:47:29.910[app:dbg]Conn 6: Caller Id DTMF tone - Successfull
07:47:29.910[app:dbg]Port 6: check vapi queue ('busy''cid_dtmf_event') at vapi_ne                                                                                       xt_ops:2614
07:47:30.060[app:dbg]Port 6: check vapi queue ('free') at vapi_cid_dtmf_chan:3103
07:47:30.060[app:dbg]Chan 6: current state is CREATED
07:47:30.060[app:dbg]Port 6: set vapi queue MSP to 'busy' with 'cid_dtmf_event' a                                                                                       t vapi_cid_dtmf_chan:3132
07:47:30.060[app:dbg]VQ Conn 6 = MSP : 'cid_dtmf_event' =
07:47:30.060[app:info]Generating Caller-ID DTMF tone '1'
07:47:30.060[app:dbg]chan 6 start tone, id=0, direction=TDM
07:47:30.060[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, con                                                                                       n 6
07:47:30.060[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x00000949
07:47:30.060[app:dbg]vapi_proc_event: VAPI_CB
07:47:30.060[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x00000949 result 0x00000000
07:47:30.060[app:dbg]Conn 6: Caller Id DTMF tone - Successfull
07:47:30.060[app:dbg]Port 6: check vapi queue ('busy''cid_dtmf_event') at vapi_ne                                                                                       xt_ops:2614
07:47:30.220[app:dbg]Port 6: check vapi queue ('free') at vapi_cid_dtmf_chan:3103
07:47:30.220[app:dbg]Chan 6: current state is CREATED
07:47:30.220[app:dbg]Port 6: set vapi queue MSP to 'busy' with 'cid_dtmf_event' a                                                                                       t vapi_cid_dtmf_chan:3132
07:47:30.220[app:dbg]VQ Conn 6 = MSP : 'cid_dtmf_event' =
07:47:30.220[app:info]Generating Caller-ID DTMF tone '1'
07:47:30.220[app:dbg]chan 6 start tone, id=0, direction=TDM
07:47:30.220[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, con                                                                                       n 6
07:47:30.220[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x00000949
07:47:30.220[app:dbg]vapi_proc_event: VAPI_CB
07:47:30.220[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x00000949 result 0x00000000
07:47:30.220[app:dbg]Conn 6: Caller Id DTMF tone - Successfull
07:47:30.220[app:dbg]Port 6: check vapi queue ('busy''cid_dtmf_event') at vapi_ne                                                                                       xt_ops:2614
07:47:30.390[app:dbg]Port 6: check vapi queue ('free') at vapi_cid_dtmf_chan:3103
07:47:30.390[app:dbg]Chan 6: current state is CREATED
07:47:30.390[app:dbg]Port 6: set vapi queue MSP to 'busy' with 'cid_dtmf_event' a                                                                                       t vapi_cid_dtmf_chan:3132
07:47:30.390[app:dbg]VQ Conn 6 = MSP : 'cid_dtmf_event' =
07:47:30.390[app:info]Generating Caller-ID DTMF tone '1'
07:47:30.390[app:dbg]chan 6 start tone, id=0, direction=TDM
07:47:30.390[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, con                                                                                       n 6
07:47:30.390[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x00000949
07:47:30.390[app:dbg]vapi_proc_event: VAPI_CB
07:47:30.390[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x00000949 result 0x00000000
07:47:30.390[app:dbg]Conn 6: Caller Id DTMF tone - Successfull
07:47:30.390[app:dbg]Port 6: check vapi queue ('busy''cid_dtmf_event') at vapi_ne                                                                                       xt_ops:2614
07:47:30.540[app:dbg]Port 6: check vapi queue ('free') at vapi_cid_dtmf_chan:3103
07:47:30.540[app:dbg]Chan 6: current state is CREATED
07:47:30.540[app:dbg]Port 6: set vapi queue MSP to 'busy' with 'cid_dtmf_event' a                                                                                       t vapi_cid_dtmf_chan:3132
07:47:30.540[app:dbg]VQ Conn 6 = MSP : 'cid_dtmf_event' =
07:47:30.540[app:info]Generating Caller-ID DTMF tone '1'
07:47:30.540[app:dbg]chan 6 start tone, id=0, direction=TDM
07:47:30.540[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, con                                                                                       n 6
07:47:30.540[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x00000949
07:47:30.540[app:dbg]vapi_proc_event: VAPI_CB
07:47:30.540[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x00000949 result 0x00000000
07:47:30.540[app:dbg]Conn 6: Caller Id DTMF tone - Successfull
07:47:30.540[app:dbg]Port 6: check vapi queue ('busy''cid_dtmf_event') at vapi_ne                                                                                       xt_ops:2614
07:47:30.700[app:dbg]Port 6: check vapi queue ('free') at vapi_cid_dtmf_chan:3103
07:47:30.700[app:dbg]Chan 6: current state is CREATED
07:47:30.700[app:dbg]Port 6: set vapi queue MSP to 'busy' with 'cid_dtmf_event' a                                                                                       t vapi_cid_dtmf_chan:3132
07:47:30.700[app:dbg]VQ Conn 6 = MSP : 'cid_dtmf_event' =
07:47:30.700[app:info]Generating Caller-ID DTMF tone '1'
07:47:30.700[app:dbg]chan 6 start tone, id=0, direction=TDM
07:47:30.700[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, con                                                                                       n 6
07:47:30.700[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x00000949
07:47:30.700[app:dbg]vapi_proc_event: VAPI_CB
07:47:30.700[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x00000949 result 0x00000000
07:47:30.700[app:dbg]Conn 6: Caller Id DTMF tone - Successfull
07:47:30.700[app:dbg]Port 6: check vapi queue ('busy''cid_dtmf_event') at vapi_ne                                                                                       xt_ops:2614
07:47:30.860[app:dbg]Port 6: check vapi queue ('free') at vapi_cid_dtmf_chan:3103
07:47:30.860[app:dbg]Chan 6: current state is CREATED
07:47:30.860[app:dbg]Port 6: set vapi queue MSP to 'busy' with 'cid_dtmf_event' a                                                                                       t vapi_cid_dtmf_chan:3132
07:47:30.860[app:dbg]VQ Conn 6 = MSP : 'cid_dtmf_event' =
07:47:30.860[app:info]Generating Caller-ID DTMF tone '1'
07:47:30.860[app:dbg]chan 6 start tone, id=0, direction=TDM
07:47:30.860[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, con                                                                                       n 6
07:47:30.860[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x00000949
07:47:30.860[app:dbg]vapi_proc_event: VAPI_CB
07:47:30.860[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x00000949 result 0x00000000
07:47:30.860[app:dbg]Conn 6: Caller Id DTMF tone - Successfull
07:47:30.860[app:dbg]Port 6: check vapi queue ('busy''cid_dtmf_event') at vapi_ne                                                                                       xt_ops:2614
07:47:31.020[app:dbg]Port 6: check vapi queue ('free') at vapi_cid_dtmf_chan:3103
07:47:31.020[app:dbg]Chan 6: current state is CREATED
07:47:31.020[app:dbg]Port 6: set vapi queue MSP to 'busy' with 'cid_dtmf_event' a                                                                                       t vapi_cid_dtmf_chan:3132
07:47:31.020[app:dbg]VQ Conn 6 = MSP : 'cid_dtmf_event' =
07:47:31.020[app:info]Generating Caller-ID DTMF tone '1'
07:47:31.020[app:dbg]chan 6 start tone, id=0, direction=TDM
07:47:31.020[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, con                                                                                       n 6
07:47:31.020[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x00000949
07:47:31.020[app:dbg]vapi_proc_event: VAPI_CB
07:47:31.020[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x00000949 result 0x00000000
07:47:31.020[app:dbg]Conn 6: Caller Id DTMF tone - Successfull
07:47:31.020[app:dbg]Port 6: check vapi queue ('busy''cid_dtmf_event') at vapi_ne                                                                                       xt_ops:2614
07:47:31.180[app:dbg]Port 6: check vapi queue ('free') at vapi_cid_dtmf_chan:3103
07:47:31.180[app:dbg]Chan 6: current state is CREATED
07:47:31.180[app:dbg]Port 6: set vapi queue MSP to 'busy' with 'cid_dtmf_event' a                                                                                       t vapi_cid_dtmf_chan:3132
07:47:31.180[app:dbg]VQ Conn 6 = MSP : 'cid_dtmf_event' =
07:47:31.180[app:info]Generating Caller-ID DTMF tone '1'
07:47:31.180[app:dbg]chan 6 start tone, id=0, direction=TDM
07:47:31.180[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, con                                                                                       n 6
07:47:31.180[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x00000949
07:47:31.180[app:dbg]vapi_proc_event: VAPI_CB
07:47:31.180[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x00000949 result 0x00000000
07:47:31.180[app:dbg]Conn 6: Caller Id DTMF tone - Successfull
07:47:31.180[app:dbg]Port 6: check vapi queue ('busy''cid_dtmf_event') at vapi_ne                                                                                       xt_ops:2614
07:47:31.350[app:dbg]Port 6: check vapi queue ('free') at vapi_cid_dtmf_chan:3103
07:47:31.350[app:dbg]Chan 6: current state is CREATED
07:47:31.350[app:dbg]Port 6: set vapi queue MSP to 'busy' with 'cid_dtmf_event' a                                                                                       t vapi_cid_dtmf_chan:3132
07:47:31.350[app:dbg]VQ Conn 6 = MSP : 'cid_dtmf_event' =
07:47:31.350[app:info]Generating Caller-ID DTMF tone '1'
07:47:31.350[app:dbg]chan 6 start tone, id=0, direction=TDM
07:47:31.350[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, con                                                                                       n 6
07:47:31.350[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x00000949
07:47:31.350[app:dbg]vapi_proc_event: VAPI_CB
07:47:31.350[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x00000949 result 0x00000000
07:47:31.350[app:dbg]Conn 6: Caller Id DTMF tone - Successfull
07:47:31.350[app:dbg]Port 6: check vapi queue ('busy''cid_dtmf_event') at vapi_ne                                                                                       xt_ops:2614
07:47:31.500[app:dbg]Port 6: check vapi queue ('free') at vapi_cid_dtmf_chan:3103
07:47:31.500[app:dbg]Chan 6: current state is CREATED
07:47:31.500[app:dbg]Port 6: set vapi queue MSP to 'busy' with 'cid_dtmf_event' a                                                                                       t vapi_cid_dtmf_chan:3132
07:47:31.500[app:dbg]VQ Conn 6 = MSP : 'cid_dtmf_event' =
07:47:31.500[app:info]Generating Caller-ID DTMF tone 'C'
07:47:31.500[app:dbg]chan 6 start tone, id=11, direction=TDM
07:47:31.500[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, con                                                                                       n 6
07:47:31.500[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x00000949
07:47:31.500[app:dbg]vapi_proc_event: VAPI_CB
07:47:31.500[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x00000949 result 0x00000000
07:47:31.500[app:dbg]Conn 6: Caller Id DTMF tone - Successfull
07:47:31.500[app:dbg]Port 6: check vapi queue ('busy''cid_dtmf_event') at vapi_ne                                                                                       xt_ops:2614
07:47:31.660[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, con                                                                                       n 6
07:47:33.640[app:dbg]port_process (11409): seize next tone
07:47:33.640[app:dbg]port 6: clear
07:47:33.640[app:dbg]Set port 6 led to state 'LED_OFF'
07:47:33.640[app:dbg]port 6: port_seize
07:47:33.640[app:dbg]port 6: seize
07:47:33.640[app:dbg]port 6: seize has cadence pulse = 1000, pause = 4000
07:47:33.640[app:dbg]Set port 6 led to state 'LED_RINGING'
07:47:33.670[app:dbg]slic6. Event 6.
07:47:33.670[app:dbg]slic 6. Ring on event
07:47:33.670[app:dbg]Set port 6 led to state 'LED_RINGING'
07:47:34.660[app:dbg]slic6. Event 7.
07:47:34.660[app:dbg]slic 6. Ring off event
07:47:34.660[app:dbg]Set port 6 led to state 'LED_OFF'
07:47:34.660[app:dbg]Set port 6 led to state 'LED_OFF'
07:47:38.010[app:dbg] [GM] load_in_handle():
07:47:38.010[app:dbg]group -[msg_clear]-> pbx
07:47:38.010[app:dbg] [GM] load_in_handle():
07:47:38.010[app:dbg]group -[msg_call]-> pbx
07:47:38.010[app:dbg]ITC: [msg_clear] -> pbx
07:47:38.010[app:dbg]dump_port_calls() SLIC 6:
07:47:38.010[app:dbg]Q:(0x336400,0x02060007,(nil))
07:47:38.010[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((                                                                                       nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
07:47:38.010[app:dbg]SLIC 6: peer cleared(02060007)
07:47:38.010[app:dbg]SLIC 6: current call cleared
07:47:38.010[app:dbg]SLIC 6: -> hangup
07:47:38.010[app:info]SLIC 6: from state 'ringing' to state 'hangup'
07:47:38.010[app:dbg]port 6: clear
07:47:38.010[app:dbg]Set port 6 led to state 'LED_OFF'
07:47:38.010[app:dbg]CMD_STOP_TONE: port = 6
07:47:38.010[app:dbg]Port 6: check vapi queue ('free') at vapi_stop_tone_chan:151                                                                                       8
07:47:38.010[app:dbg]Chan 6: current state is CREATED
07:47:38.010[app:ERR]chan 6: no generated tones!
07:47:38.010[app:dbg]vapi_chan.c:1554: conn 6 peek cmd 'no event' from queue
07:47:38.010[app:dbg]Port 6: check vapi queue ('free') at __cmd_engine:342
07:47:38.010[app:dbg]Port 6: check vapi queue ('free') at vapi_next_ops:2614
07:47:38.010[app:dbg]SLIC 6: reset
07:47:38.010[app:dbg]dump_port_calls() SLIC 6:
07:47:38.010[app:dbg]Q:(0x336400,0x02060007,(nil))
07:47:38.010[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((                                                                                       nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
07:47:38.010[app:dbg]vapi: chan 6: connection STATISTIC
07:47:38.010[app:dbg]vapi: chan 6: Rx_pack = 0
07:47:38.010[app:dbg]vapi: chan 6: Rx_oct  = 0
07:47:38.010[app:dbg]vapi: chan 6: Lost_pack  = 0
07:47:38.010[app:dbg]vapi: chan 6: Tx_pack = 0
07:47:38.010[app:dbg]vapi: chan 6: Tx_oct  = 0
07:47:38.010[app:dbg]vapi: chan 6: peak_jiter = 0
07:47:38.010[app:dbg]SLIC 6: Common port statistic
07:47:38.010[app:dbg]SLIC 6: Rx_pack = 0
07:47:38.010[app:dbg]SLIC 6: Rx_oct  = 0
07:47:38.010[app:dbg]SLIC 6: Lost_pack  = 0
07:47:38.010[app:dbg]SLIC 6: Tx_pack = 0
07:47:38.010[app:dbg]SLIC 6: Tx_oct  = 0
07:47:38.010[app:dbg]SLIC 6: peak_jiter = 0
07:47:38.010[app:dbg]SLIC 6: reset call 0x02060007 (active)
07:47:38.010[app:dbg]CMD_SET_VOICE: port = 6
07:47:38.010[app:dbg]Port 6: check vapi queue ('free') at vapi_start_stop_chan:16                                                                                       67
07:47:38.010[app:dbg]Chan 6: current state is CREATED
07:47:38.010[app:dbg]vapi: Conn 6. start_stop voice chan, TX stop, RX stop
07:47:38.010[app:dbg]Port 6: set vapi queue MSP to 'busy' with 'set voice' at vap                                                                                       i_start_stop_chan:1710
07:47:38.010[app:dbg]VQ Conn 6 = MSP :     'set voice' =
07:47:38.010[app:ERR]Conn 6. error: -68022 (VAPI_ERR_IP_HDR_NOT_SET)
07:47:38.010[app:dbg]Port 6: check vapi queue ('free') at __cmd_engine:350
07:47:38.010[app:dbg]Port 6: check vapi queue ('free') at vapi_next_ops:2614
07:47:38.010[app:dbg]incom_calls_set_media_started() call 0x02060007, group 0, ta                                                                                       sk <group> media stopped
07:47:38.010[app:dbg]incom_calls_rem() rem call 0x02060007, group 0, task <group>                                                                                        from list
07:47:38.010[app:dbg]free_final_mx: final_mx was NULL for SLIC 6
07:47:38.010[app:dbg]CMD_DESTROY_CONN: port = 6
07:47:38.010[app:dbg]Port 6: check vapi queue ('free') at vapi_destroy_chan:906
07:47:38.010[app:dbg]Destroying connection 6...
07:47:38.010[app:dbg]Chan 6: current state is CREATED
07:47:38.010[app:dbg]Port 6: set vapi queue MSP to 'busy' with 'destroy' at vapi_                                                                                       destroy_chan:932
07:47:38.010[app:dbg]VQ Conn 6 = MSP :       'destroy' =
07:47:38.010[app:dbg]Chan 6: CREATED -> DESTROYING
07:47:38.010[app:dbg]CMD_DESTROY_IPONLY_CONN: port = 6
07:47:38.010[app:dbg]Port 6: check vapi queue ('busy''destroy') at vapi_destroy_c                                                                                       han:906
07:47:38.010[app:dbg]Clear vapi queue of Port 6/chan 14
07:47:38.010[app:dbg]Port 6 put cmd 'destroy',cur 'destroy' to queue at (vapi_des                                                                                       troy_chan:913)
07:47:38.010[app:dbg]VQ Conn 14 = MSP :       'destroy' =
07:47:38.010[app:dbg]VQ Conn 14 + 00  :       'destroy' (hold) + <-get_ptr
07:47:38.010[app:dbg]Port 6: user port 0, old state hangup, new state
07:47:38.010[app:dbg]Set port 6 led to state 'LED_OFF'
07:47:38.010[app:dbg]pbx -[msg_fxs_state]-> group
07:47:38.010[app:dbg]dump_port_calls() SLIC 6:
07:47:38.010[app:dbg]Q:NONE
07:47:38.010[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((                                                                                       nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
07:47:38.020[app:dbg]ITC: [msg_fxs_state] -> group
07:47:38.020[app:dbg]-----[GM] self_fxs_state()
07:47:38.020[app:dbg]Port 6: new state is hangup
07:47:38.020[app:dbg]Delete all RX-TX medias from SLIC 6
07:47:38.020[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x0000014c
07:47:38.020[app:dbg]ITC: [msg_call] -> pbx
07:47:38.020[app:dbg]SLIC 4: incoming call from anonymous.invalid:5060/anonymous(                                                                                       "anonymous") payload 101 call ID: 02060007 group: 0
07:47:38.020[app:dbg]pbx: allocating memory for new call
07:47:38.020[app:dbg]pbx: created new incoming call for SLIC 4
07:47:38.020[app:dbg]self_call_create (4694): created
07:47:38.020[app:dbg]SLIC 4: -> ringing
07:47:38.020[app:info]SLIC 4: from state 'hangup' to state 'ringing'
07:47:38.020[app:dbg]CMD_CREATE_CONN: port = 4
07:47:38.020[app:dbg]Port 4: check vapi queue ('free') at vapi_create_chan:710
07:47:38.020[app:dbg]Chan 4: current state is INITIAL
07:47:38.020[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'create' at vapi_c                                                                                       reate_chan:736
07:47:38.020[app:dbg]VQ Conn 4 = MSP :        'create' =
07:47:38.020[app:dbg]Creating connection 4....
07:47:38.020[app:dbg]Chan 4: INITIAL -> CREATING
07:47:38.020[app:dbg]Created succefuly 4....
07:47:38.020[app:info]SLIC 4: has incoming call from anonymous
07:47:38.020[app:dbg]port 4: port_seize
07:47:38.020[app:dbg]port 4: seize
07:47:38.020[app:dbg]port 4: seize has cadence pulse = 0, pause = 0
07:47:38.020[app:dbg]Set port 4 led to state 'LED_RINGING'
07:47:38.020[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000050
07:47:38.020[app:dbg]Port 4: user port 2, old state ringing, new state
07:47:38.020[app:dbg]Set port 4 led to state 'LED_OFF'
07:47:38.020[app:dbg]pbx -[msg_fxs_state]-> group
07:47:38.030[app:dbg]Delete all RX-TX medias from SLIC 14
07:47:38.030[app:dbg]pbx -[msg_free]-> group
07:47:38.030[app:dbg]SLIC 4: list of all calls:
07:47:38.030[app:dbg]   call ID: 02060007
07:47:38.030[app:dbg]incom_calls_add() add call 0x02060007, group 0, task <group>                                                                                        to list
07:47:38.030[app:dbg]vapi_proc_event: VAPI_CB
07:47:38.030[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x0000014c result 0x00000000
07:47:38.020[app:dbg]ITC: [msg_fxs_state] -> group
07:47:38.030[app:dbg]-----[GM] self_fxs_state()
07:47:38.030[app:dbg]Port 4: new state is ringing
07:47:38.030[app:dbg]ITC: [msg_free] -> group
07:47:38.030[app:dbg][SG] self_on_free()
07:47:38.030[app:dbg]slic4. Event 6.
07:47:38.030[app:dbg]slic 4. Ring on event
07:47:38.030[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x00000103
07:47:38.030[app:dbg]Set port 4 led to state 'LED_RINGING'
07:47:38.030[app:dbg]vapi_proc_event: VAPI_CB
07:47:38.030[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000050 result 0x00000000
07:47:38.030[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000007
07:47:38.030[app:dbg]vapi_proc_event: VAPI_CB
07:47:38.030[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x00000103 result 0x00000000
07:47:38.030[app:dbg]Conn 6 destroyed
07:47:38.030[app:dbg]Chan 6: DESTROYING -> INITIAL
07:47:38.030[app:dbg]Port 6: check vapi queue ('busy''destroy') at vapi_next_ops:                                                                                       2614
07:47:38.030[app:dbg]Port 6 get cmd 'destroy' from queue at (vapi_next_ops:2633)
07:47:38.030[app:dbg]Port 6: check vapi queue ('free') at vapi_destroy_chan:906
07:47:38.030[app:dbg]Destroying connection 14...
07:47:38.030[app:dbg]Chan 14: current state is INITIAL
07:47:38.030[app:ERR]vapi_destroy_chan() chan 14: current state initial: duplicat                                                                                       e destroying connection!
07:47:38.030[app:dbg]Port 6: check vapi queue ('free') at vapi_next_ops:2776
07:47:38.030[app:dbg]Port 6: check vapi queue ('free') at vapi_next_ops:2614
07:47:38.030[app:dbg]vapi_proc_event: VAPI_CB
07:47:38.030[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000007 result 0x00000000
07:47:38.030[app:dbg]vapi: Conn 4. Set In-Activ state
07:47:38.030[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000051
07:47:38.030[app:dbg]vapi_proc_event: VAPI_CB
07:47:38.030[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000051 result 0x00000000
07:47:38.030[app:dbg]vapi: Conn 4 - SET AGC
07:47:38.040[app:dbg]Delete all RX-TX medias from SLIC 6
07:47:38.040[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000000
07:47:38.040[app:dbg]vapi_proc_event: VAPI_CB
07:47:38.040[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000000 result 0x00000000
07:47:38.040[app:dbg]vapi: Conn 4 - << CREATED >>
07:47:38.040[app:dbg]vapi: Conn 4 - fix DTMF detector
07:47:38.050[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x0000004a
07:47:38.050[app:dbg]vapi_proc_event: VAPI_CB
07:47:38.050[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x0000004a result 0x00000000
07:47:38.050[app:dbg]vapi: Conn 4 - fix CNG generator
07:47:38.050[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x0000004d
07:47:38.050[app:dbg]vapi_proc_event: VAPI_CB
07:47:38.050[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x0000004d result 0x00000000
07:47:38.050[app:dbg]vapi: Conn 4 - caller id Set param
07:47:38.050[app:dbg]vapi: chan '4' set param Caller ID
07:47:38.060[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x0000000c
07:47:38.060[app:dbg]vapi_proc_event: VAPI_CB
07:47:38.060[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x0000000c result 0x00000000
07:47:38.060[app:dbg]vapi: Conn 4 - enable ind ptime and pt
07:47:38.060[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000052
07:47:38.060[app:dbg]vapi_proc_event: VAPI_CB
07:47:38.060[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000052 result 0x00000000
07:47:38.060[app:dbg]vapi: Conn 4. Set Active state
07:47:38.070[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x0000004b
07:47:38.070[app:dbg]vapi_proc_event: VAPI_CB
07:47:38.070[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x0000004b result 0x00000000
07:47:38.070[app:dbg]Chan 4: CREATING -> CREATED
07:47:38.070[app:dbg]Port 4: check vapi queue ('busy''create') at vapi_next_ops:2                                                                                       614
07:47:39.060[app:dbg]slic4. Event 7.
07:47:39.060[app:dbg]slic 4. Ring off event
07:47:39.060[app:dbg]Set port 4 led to state 'LED_OFF'
07:47:39.060[app:dbg]Set port 4 led to state 'LED_OFF'
07:47:39.270[app:info]SLIC 4: DTMF caller-id generated
07:47:39.270[app:dbg]CMD_START_CID_DTMF: port = 4
07:47:39.270[app:dbg]Port 4: check vapi queue ('free') at vapi_cid_dtmf_chan:3103
07:47:39.270[app:dbg]Chan 4: current state is CREATED
07:47:39.270[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'cid_dtmf_event' a                                                                                       t vapi_cid_dtmf_chan:3132
07:47:39.270[app:dbg]VQ Conn 4 = MSP : 'cid_dtmf_event' =
07:47:39.270[app:info]Generating Caller-ID DTMF tone '1'
07:47:39.270[app:dbg]chan 4 start tone, id=0, direction=TDM
07:47:39.270[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000949
07:47:39.270[app:dbg]vapi_proc_event: VAPI_CB
07:47:39.270[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000949 result 0x00000000
07:47:39.270[app:dbg]Conn 4: Caller Id DTMF tone - Successfull
07:47:39.270[app:dbg]Port 4: check vapi queue ('busy''cid_dtmf_event') at vapi_ne                                                                                       xt_ops:2614
07:47:39.420[app:dbg]Port 4: check vapi queue ('free') at vapi_cid_dtmf_chan:3103
07:47:39.420[app:dbg]Chan 4: current state is CREATED
07:47:39.420[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'cid_dtmf_event' a                                                                                       t vapi_cid_dtmf_chan:3132
07:47:39.420[app:dbg]VQ Conn 4 = MSP : 'cid_dtmf_event' =
07:47:39.420[app:info]Generating Caller-ID DTMF tone '1'
07:47:39.420[app:dbg]chan 4 start tone, id=0, direction=TDM
07:47:39.420[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, con                                                                                       n 4
07:47:39.420[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000949
07:47:39.420[app:dbg]vapi_proc_event: VAPI_CB
07:47:39.420[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000949 result 0x00000000
07:47:39.420[app:dbg]Conn 4: Caller Id DTMF tone - Successfull
07:47:39.420[app:dbg]Port 4: check vapi queue ('busy''cid_dtmf_event') at vapi_ne                                                                                       xt_ops:2614
07:47:39.580[app:dbg]Port 4: check vapi queue ('free') at vapi_cid_dtmf_chan:3103
07:47:39.580[app:dbg]Chan 4: current state is CREATED
07:47:39.580[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'cid_dtmf_event' a                                                                                       t vapi_cid_dtmf_chan:3132
07:47:39.580[app:dbg]VQ Conn 4 = MSP : 'cid_dtmf_event' =
07:47:39.580[app:info]Generating Caller-ID DTMF tone '1'
07:47:39.580[app:dbg]chan 4 start tone, id=0, direction=TDM
07:47:39.580[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, con                                                                                       n 4
07:47:39.580[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000949
07:47:39.580[app:dbg]vapi_proc_event: VAPI_CB
07:47:39.580[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000949 result 0x00000000
07:47:39.580[app:dbg]Conn 4: Caller Id DTMF tone - Successfull
07:47:39.580[app:dbg]Port 4: check vapi queue ('busy''cid_dtmf_event') at vapi_ne                                                                                       xt_ops:2614
07:47:39.740[app:dbg]Port 4: check vapi queue ('free') at vapi_cid_dtmf_chan:3103
07:47:39.740[app:dbg]Chan 4: current state is CREATED
07:47:39.740[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'cid_dtmf_event' a                                                                                       t vapi_cid_dtmf_chan:3132
07:47:39.740[app:dbg]VQ Conn 4 = MSP : 'cid_dtmf_event' =
07:47:39.740[app:info]Generating Caller-ID DTMF tone '1'
07:47:39.740[app:dbg]chan 4 start tone, id=0, direction=TDM
07:47:39.740[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, con                                                                                       n 4
07:47:39.740[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000949
07:47:39.740[app:dbg]vapi_proc_event: VAPI_CB
07:47:39.740[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000949 result 0x00000000
07:47:39.740[app:dbg]Conn 4: Caller Id DTMF tone - Successfull
07:47:39.740[app:dbg]Port 4: check vapi queue ('busy''cid_dtmf_event') at vapi_ne                                                                                       xt_ops:2614
07:47:39.900[app:dbg]Port 4: check vapi queue ('free') at vapi_cid_dtmf_chan:3103
07:47:39.900[app:dbg]Chan 4: current state is CREATED
07:47:39.900[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'cid_dtmf_event' a                                                                                       t vapi_cid_dtmf_chan:3132
07:47:39.900[app:dbg]VQ Conn 4 = MSP : 'cid_dtmf_event' =
07:47:39.900[app:info]Generating Caller-ID DTMF tone '1'
07:47:39.900[app:dbg]chan 4 start tone, id=0, direction=TDM
07:47:39.900[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, con                                                                                       n 4
07:47:39.900[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000949
07:47:39.900[app:dbg]vapi_proc_event: VAPI_CB
07:47:39.900[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000949 result 0x00000000
07:47:39.900[app:dbg]Conn 4: Caller Id DTMF tone - Successfull
07:47:39.900[app:dbg]Port 4: check vapi queue ('busy''cid_dtmf_event') at vapi_ne                                                                                       xt_ops:2614
07:47:40.060[app:dbg]Port 4: check vapi queue ('free') at vapi_cid_dtmf_chan:3103
07:47:40.060[app:dbg]Chan 4: current state is CREATED
07:47:40.060[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'cid_dtmf_event' a                                                                                       t vapi_cid_dtmf_chan:3132
07:47:40.060[app:dbg]VQ Conn 4 = MSP : 'cid_dtmf_event' =
07:47:40.060[app:info]Generating Caller-ID DTMF tone '1'
07:47:40.060[app:dbg]chan 4 start tone, id=0, direction=TDM
07:47:40.060[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, con                                                                                       n 4
07:47:40.060[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000949
07:47:40.060[app:dbg]vapi_proc_event: VAPI_CB
07:47:40.060[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000949 result 0x00000000
07:47:40.060[app:dbg]Conn 4: Caller Id DTMF tone - Successfull
07:47:40.060[app:dbg]Port 4: check vapi queue ('busy''cid_dtmf_event') at vapi_ne                                                                                       xt_ops:2614
07:47:40.220[app:dbg]Port 4: check vapi queue ('free') at vapi_cid_dtmf_chan:3103
07:47:40.220[app:dbg]Chan 4: current state is CREATED
07:47:40.220[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'cid_dtmf_event' a                                                                                       t vapi_cid_dtmf_chan:3132
07:47:40.220[app:dbg]VQ Conn 4 = MSP : 'cid_dtmf_event' =
07:47:40.220[app:info]Generating Caller-ID DTMF tone '1'
07:47:40.220[app:dbg]chan 4 start tone, id=0, direction=TDM
07:47:40.220[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, con                                                                                       n 4
07:47:40.220[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000949
07:47:40.220[app:dbg]vapi_proc_event: VAPI_CB
07:47:40.220[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000949 result 0x00000000
07:47:40.220[app:dbg]Conn 4: Caller Id DTMF tone - Successfull
07:47:40.220[app:dbg]Port 4: check vapi queue ('busy''cid_dtmf_event') at vapi_ne                                                                                       xt_ops:2614
07:47:40.380[app:dbg]Port 4: check vapi queue ('free') at vapi_cid_dtmf_chan:3103
07:47:40.380[app:dbg]Chan 4: current state is CREATED
07:47:40.380[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'cid_dtmf_event' a                                                                                       t vapi_cid_dtmf_chan:3132
07:47:40.380[app:dbg]VQ Conn 4 = MSP : 'cid_dtmf_event' =
07:47:40.380[app:info]Generating Caller-ID DTMF tone '1'
07:47:40.380[app:dbg]chan 4 start tone, id=0, direction=TDM
07:47:40.380[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, con                                                                                       n 4
07:47:40.380[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000949
07:47:40.380[app:dbg]vapi_proc_event: VAPI_CB
07:47:40.380[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000949 result 0x00000000
07:47:40.380[app:dbg]Conn 4: Caller Id DTMF tone - Successfull
07:47:40.380[app:dbg]Port 4: check vapi queue ('busy''cid_dtmf_event') at vapi_ne                                                                                       xt_ops:2614
07:47:40.540[app:dbg]Port 4: check vapi queue ('free') at vapi_cid_dtmf_chan:3103
07:47:40.540[app:dbg]Chan 4: current state is CREATED
07:47:40.540[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'cid_dtmf_event' a                                                                                       t vapi_cid_dtmf_chan:3132
07:47:40.540[app:dbg]VQ Conn 4 = MSP : 'cid_dtmf_event' =
07:47:40.540[app:info]Generating Caller-ID DTMF tone '1'
07:47:40.540[app:dbg]chan 4 start tone, id=0, direction=TDM
07:47:40.540[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, con                                                                                       n 4
07:47:40.540[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000949
07:47:40.540[app:dbg]vapi_proc_event: VAPI_CB
07:47:40.540[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000949 result 0x00000000
07:47:40.540[app:dbg]Conn 4: Caller Id DTMF tone - Successfull
07:47:40.540[app:dbg]Port 4: check vapi queue ('busy''cid_dtmf_event') at vapi_ne                                                                                       xt_ops:2614
07:47:40.700[app:dbg]Port 4: check vapi queue ('free') at vapi_cid_dtmf_chan:3103
07:47:40.700[app:dbg]Chan 4: current state is CREATED
07:47:40.700[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'cid_dtmf_event' a                                                                                       t vapi_cid_dtmf_chan:3132
07:47:40.700[app:dbg]VQ Conn 4 = MSP : 'cid_dtmf_event' =
07:47:40.700[app:info]Generating Caller-ID DTMF tone 'C'
07:47:40.700[app:dbg]chan 4 start tone, id=11, direction=TDM
07:47:40.700[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, con                                                                                       n 4
07:47:40.700[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000949
07:47:40.700[app:dbg]vapi_proc_event: VAPI_CB
07:47:40.700[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000949 result 0x00000000
07:47:40.700[app:dbg]Conn 4: Caller Id DTMF tone - Successfull
07:47:40.700[app:dbg]Port 4: check vapi queue ('busy''cid_dtmf_event') at vapi_ne                                                                                       xt_ops:2614
07:47:40.860[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, con                                                                                       n 4
07:47:42.990[app:dbg]port_process (11409): seize next tone
07:47:42.990[app:dbg]port 4: clear
07:47:42.990[app:dbg]Set port 4 led to state 'LED_OFF'
07:47:42.990[app:dbg]port 4: port_seize
07:47:42.990[app:dbg]port 4: seize
07:47:42.990[app:dbg]port 4: seize has cadence pulse = 1000, pause = 4000
07:47:42.990[app:dbg]Set port 4 led to state 'LED_RINGING'
07:47:43.020[app:dbg]slic4. Event 6.
07:47:43.020[app:dbg]slic 4. Ring on event
07:47:43.020[app:dbg]Set port 4 led to state 'LED_RINGING'
07:47:44.000[app:dbg] [GM] load_in_handle():
07:47:44.000[app:dbg]group -[msg_clear]-> pbx
07:47:44.000[app:dbg] [GM] load_in_handle():
07:47:44.000[app:dbg]group -[msg_busy]-> sip
07:47:44.000[app:dbg]ITC: [msg_clear] -> pbx
07:47:44.000[app:dbg]dump_port_calls() SLIC 4:
07:47:44.000[app:dbg]Q:(0x336400,0x02060007,(nil))
07:47:44.000[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((                                                                                       nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
07:47:44.000[app:dbg]SLIC 4: peer cleared(02060007)
07:47:44.000[app:dbg]SLIC 4: current call cleared
07:47:44.000[app:dbg]SLIC 4: -> hangup
07:47:44.000[app:info]SLIC 4: from state 'ringing' to state 'hangup'
07:47:44.000[app:dbg]port 4: clear
07:47:44.000[app:dbg]Set port 4 led to state 'LED_OFF'
07:47:44.000[app:dbg]CMD_STOP_TONE: port = 4
07:47:44.000[app:dbg]Port 4: check vapi queue ('free') at vapi_stop_tone_chan:151                                                                                       8
07:47:44.000[app:dbg]Chan 4: current state is CREATED
07:47:44.000[app:ERR]chan 4: no generated tones!
07:47:44.000[app:dbg]vapi_chan.c:1554: conn 4 peek cmd 'no event' from queue
07:47:44.000[app:dbg]Port 4: check vapi queue ('free') at __cmd_engine:342
07:47:44.000[app:dbg]Port 4: check vapi queue ('free') at vapi_next_ops:2614
07:47:44.000[app:dbg]SLIC 4: reset
07:47:44.000[app:dbg]dump_port_calls() SLIC 4:
07:47:44.000[app:dbg]Q:(0x336400,0x02060007,(nil))
07:47:44.000[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((                                                                                       nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
07:47:44.000[app:dbg]vapi: chan 4: connection STATISTIC
07:47:44.000[app:dbg]vapi: chan 4: Rx_pack = 0
07:47:44.000[app:dbg]vapi: chan 4: Rx_oct  = 0
07:47:44.000[app:dbg]vapi: chan 4: Lost_pack  = 0
07:47:44.000[app:dbg]vapi: chan 4: Tx_pack = 0
07:47:44.000[app:dbg]vapi: chan 4: Tx_oct  = 0
07:47:44.000[app:dbg]vapi: chan 4: peak_jiter = 0
07:47:44.000[app:dbg]SLIC 4: Common port statistic
07:47:44.000[app:dbg]SLIC 4: Rx_pack = 0
07:47:44.000[app:dbg]SLIC 4: Rx_oct  = 0
07:47:44.000[app:dbg]SLIC 4: Lost_pack  = 0
07:47:44.000[app:dbg]SLIC 4: Tx_pack = 0
07:47:44.000[app:dbg]SLIC 4: Tx_oct  = 0
07:47:44.000[app:dbg]SLIC 4: peak_jiter = 0
07:47:44.000[app:dbg]SLIC 4: reset call 0x02060007 (active)
07:47:44.000[app:dbg]CMD_SET_VOICE: port = 4
07:47:44.000[app:dbg]Port 4: check vapi queue ('free') at vapi_start_stop_chan:16                                                                                       67
07:47:44.000[app:dbg]Chan 4: current state is CREATED
07:47:44.000[app:dbg]vapi: Conn 4. start_stop voice chan, TX stop, RX stop
07:47:44.000[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'set voice' at vap                                                                                       i_start_stop_chan:1710
07:47:44.000[app:dbg]VQ Conn 4 = MSP :     'set voice' =
07:47:44.000[app:ERR]Conn 4. error: -68022 (VAPI_ERR_IP_HDR_NOT_SET)
07:47:44.000[app:dbg]Port 4: check vapi queue ('free') at __cmd_engine:350
07:47:44.000[app:dbg]Port 4: check vapi queue ('free') at vapi_next_ops:2614
07:47:44.000[app:dbg]incom_calls_set_media_started() call 0x02060007, group 0, ta                                                                                       sk <group> media stopped
07:47:44.000[app:dbg]incom_calls_rem() rem call 0x02060007, group 0, task <group>                                                                                        from list
07:47:44.000[app:dbg]free_final_mx: final_mx was NULL for SLIC 4
07:47:44.000[app:dbg]CMD_DESTROY_CONN: port = 4
07:47:44.000[app:dbg]Port 4: check vapi queue ('free') at vapi_destroy_chan:906
07:47:44.000[app:dbg]Destroying connection 4...
07:47:44.000[app:dbg]Chan 4: current state is CREATED
07:47:44.000[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'destroy' at vapi_                                                                                       destroy_chan:932
07:47:44.000[app:dbg]VQ Conn 4 = MSP :       'destroy' =
07:47:44.000[app:dbg]Chan 4: CREATED -> DESTROYING
07:47:44.000[app:dbg]CMD_DESTROY_IPONLY_CONN: port = 4
07:47:44.000[app:dbg]Port 4: check vapi queue ('busy''destroy') at vapi_destroy_c                                                                                       han:906
07:47:44.000[app:dbg]Clear vapi queue of Port 4/chan 12
07:47:44.000[app:dbg]Port 4 put cmd 'destroy',cur 'destroy' to queue at (vapi_des                                                                                       troy_chan:913)
07:47:44.000[app:dbg]VQ Conn 12 = MSP :       'destroy' =
07:47:44.000[app:dbg]VQ Conn 12 + 00  :       'destroy' (hold) + <-get_ptr
07:47:44.000[app:dbg]Port 4: user port 2, old state hangup, new state
07:47:44.000[app:dbg]Set port 4 led to state 'LED_OFF'
07:47:44.000[app:dbg]pbx -[msg_fxs_state]-> group
07:47:44.000[app:dbg]dump_port_calls() SLIC 4:
07:47:44.000[app:dbg]Q:NONE
07:47:44.000[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((                                                                                       nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
07:47:44.000[app:dbg]slic4. Event 7.
07:47:44.000[app:dbg]slic 4. Ring off event
07:47:44.000[app:dbg]Set port 4 led to state 'LED_OFF'
07:47:44.000[app:dbg]Set port 4 led to state 'LED_OFF'
07:47:44.010[app:dbg]ITC: [msg_busy] -> sip
07:47:44.010[app:dbg]self_on_busy, code: 1
07:47:44.010[app:dbg]sip: call 02060007: endpoint 0 is busy
07:47:44.010[app:dbg]sip: BUSY call SIPT 0
07:47:44.010[app:dbg]sip: call 02060007: BYE to sip:3477951@10.10.2.2:5060;user=p                                                                                       hone
07:47:44.010[app:dbg]ITC: [msg_fxs_state] -> group
07:47:44.010[app:dbg]-----[GM] self_fxs_state()
07:47:44.010[app:dbg]Port 4: new state is hangup
07:47:44.010[app:dbg]Delete all RX-TX medias from SLIC 4
07:47:44.010[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x0000014c
07:47:44.010[sip]send 543 bytes to udp/[10.10.2.2]:5060 at 14:16:00.010000:
   ------------------------------------------------------------------------
07:47:44.010[sip]   SIP/2.0 486 Busy Here
07:47:44.010[sip]   Via: SIP/2.0/UDP 10.10.2.2:5060;branch=z9hG4bKhevl9q10dgphphc                                                                                       na0p1.1
07:47:44.010[sip]   From: "anonymous" <sip:anonymous@anonymous.invalid:5060>;tag=                                                                                       SDbnd6b01-y3lf4kkrbq
07:47:44.010[sip]   To: "3477951" <sip:3477951@10.10.2.2:5060;user=phone>;tag=36m                                                                                       0vSZNy6DXm
07:47:44.010[sip]   Call-ID: SDbnd6b01-df0948dd00f678cfed57742b79d7c956-cl5k9s0
07:47:44.010[sip]   CSeq: 458 INVITE
07:47:44.010[sip]   User-Agent: TAU-8.IP/2.3.0 SN/VI33020063 sofia-sip/1.12.10
07:47:44.010[sip]   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUB                                                                                       SCRIBE, NOTIFY, REFER, UPDATE, INFO
07:47:44.010[sip]   Supported: timer, 100rel, replaces
07:47:44.010[sip]   Content-Length: 0
07:47:44.010[sip]
07:47:44.010[sip]   -------------------------------------------------------------                                                                                       -----------
07:47:44.010[app:dbg]got nua_i_state : 486(Busy Here)
07:47:44.010[app:dbg]NO SIP IN nua_i_state == 486 : Busy Here
07:47:44.010[app:dbg]self_i_state(): call state 10: : : sdp_recv no_oc
07:47:44.010[app:dbg]sip: call 02060007: terminated
07:47:44.010[app:dbg]self_callstate_terminated: call id = 02060007 need_exchange_                                                                                       at_answer = 0
07:47:44.020[app:dbg]Delete all RX-TX medias from SLIC 12
07:47:44.020[app:dbg]vapi_proc_event: VAPI_CB
07:47:44.020[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x0000014c result 0x00000000
07:47:44.020[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000103
07:47:44.020[app:dbg]vapi_proc_event: VAPI_CB
07:47:44.020[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000103 result 0x00000000
07:47:44.020[app:dbg]Conn 4 destroyed
07:47:44.020[app:dbg]Chan 4: DESTROYING -> INITIAL
07:47:44.020[app:dbg]Port 4: check vapi queue ('busy''destroy') at vapi_next_ops:                                                                                       2614
07:47:44.020[app:dbg]Port 4 get cmd 'destroy' from queue at (vapi_next_ops:2633)
07:47:44.020[app:dbg]Port 4: check vapi queue ('free') at vapi_destroy_chan:906
07:47:44.020[app:dbg]Destroying connection 12...
07:47:44.020[app:dbg]Chan 12: current state is INITIAL
07:47:44.020[app:ERR]vapi_destroy_chan() chan 12: current state initial: duplicat                                                                                       e destroying connection!
07:47:44.020[app:dbg]Port 4: check vapi queue ('free') at vapi_next_ops:2776
07:47:44.020[app:dbg]Port 4: check vapi queue ('free') at vapi_next_ops:2614
07:47:44.020[sip]recv 381 bytes from udp/[10.10.2.2]:5060 at 14:16:00.020000:
   ------------------------------------------------------------------------
07:47:44.020[sip]   ACK sip:3477951@10.0.5.14:5060 SIP/2.0
07:47:44.020[sip]   Via: SIP/2.0/UDP 10.10.2.2:5060;branch=z9hG4bKhevl9q10dgphphc                                                                                       na0p1.1
07:47:44.020[sip]   CSeq: 458 ACK
07:47:44.020[sip]   Call-ID: SDbnd6b01-df0948dd00f678cfed57742b79d7c956-cl5k9s0
07:47:44.020[sip]   From: "anonymous" <sip:anonymous@anonymous.invalid:5060>;tag=                                                                                       SDbnd6b01-y3lf4kkrbq
07:47:44.020[sip]   To: "3477951" <sip:3477951@10.10.2.2:5060;user=phone>;tag=36m                                                                                       0vSZNy6DXm
07:47:44.020[sip]   Max-Forwards: 69
07:47:44.020[sip]   Content-Length: 0
07:47:44.020[sip]
07:47:44.020[sip]   -------------------------------------------------------------                                                                                       -----------
07:47:44.030[app:dbg]Delete all RX-TX medias from SLIC 4
07:47:44.070[sip]send 375 bytes to udp/[10.10.2.2]:5060 at 14:16:00.070000:
   ------------------------------------------------------------------------
07:47:44.070[sip]   OPTIONS sip:3477951@voip.sinor.ru SIP/2.0
07:47:44.070[sip]   Via: SIP/2.0/UDP 10.0.5.14;rport;branch=z9hG4bK5mm8tB108K0DF
07:47:44.070[sip]   Max-Forwards: 70
07:47:44.070[sip]   From: <sip:3477951@voip.sinor.ru>;tag=tNH1c67Nrp5mc
07:47:44.070[sip]   To: <sip:3477951@voip.sinor.ru>
07:47:44.070[sip]   Call-ID: de920740-987a-1200-8fa4-a8f94b09c6f5
07:47:44.070[sip]   CSeq: 24 OPTIONS
07:47:44.070[sip]   Subject: KEEPALIVE
07:47:44.070[sip]   User-Agent: TAU-8.IP/2.3.0 SN/VI33020063 sofia-sip/1.12.10
07:47:44.070[sip]   Content-Length: 0
07:47:44.070[sip]
07:47:44.070[sip]   -------------------------------------------------------------                                                                                       -----------
07:47:44.070[sip]recv 296 bytes from udp/[10.10.2.2]:5060 at 14:16:00.070000:
   ------------------------------------------------------------------------
07:47:44.070[sip]   SIP/2.0 482 Loop Detected
07:47:44.070[sip]   Via: SIP/2.0/UDP 10.0.5.14;branch=z9hG4bK5mm8tB108K0DF;rport=                                                                                       5060
07:47:44.070[sip]   From: <sip:3477951@voip.sinor.ru>;tag=tNH1c67Nrp5mc
07:47:44.070[sip]   To: <sip:3477951@voip.sinor.ru>;tag=SDa1l9299-ouhb-pfa3g6o3s1
07:47:44.070[sip]   Call-ID: de920740-987a-1200-8fa4-a8f94b09c6f5
07:47:44.070[sip]   CSeq: 24 OPTIONS
07:47:44.070[sip]   Content-Length: 0
07:47:44.070[sip]
07:47:44.070[sip]   -------------------------------------------------------------                                                                                       -----------

root@TAU-8:~# 07:48:14.080[sip]send 375 bytes to udp/[10.10.2.2]:5060 at 14:16:30                                                                                       .080000:
   ------------------------------------------------------------------------
07:48:14.080[sip]   OPTIONS sip:3477951@voip.sinor.ru SIP/2.0
07:48:14.080[sip]   Via: SIP/2.0/UDP 10.0.5.14;rport;branch=z9hG4bK6XD1v6H45vp0a
07:48:14.080[sip]   Max-Forwards: 70
07:48:14.080[sip]   From: <sip:3477951@voip.sinor.ru>;tag=tNH1c67Nrp5mc
07:48:14.080[sip]   To: <sip:3477951@voip.sinor.ru>
07:48:14.080[sip]   Call-ID: de920740-987a-1200-8fa4-a8f94b09c6f5
07:48:14.080[sip]   CSeq: 24 OPTIONS
07:48:14.080[sip]   Subject: KEEPALIVE
07:48:14.080[sip]   User-Agent: TAU-8.IP/2.3.0 SN/VI33020063 sofia-sip/1.12.10
07:48:14.080[sip]   Content-Length: 0
07:48:14.080[sip]
07:48:14.080[sip]   -------------------------------------------------------------                                                                                       -----------
07:48:14.090[sip]recv 296 bytes from udp/[10.10.2.2]:5060 at 14:16:30.090000:
   ------------------------------------------------------------------------
07:48:14.090[sip]   SIP/2.0 482 Loop Detected
07:48:14.090[sip]   Via: SIP/2.0/UDP 10.0.5.14;branch=z9hG4bK6XD1v6H45vp0a;rport=                                                                                       5060
07:48:14.090[sip]   From: <sip:3477951@voip.sinor.ru>;tag=tNH1c67Nrp5mc
07:48:14.090[sip]   To: <sip:3477951@voip.sinor.ru>;tag=SDa1l9299-ouhb-pfa3g6o3s1
07:48:14.090[sip]   Call-ID: de920740-987a-1200-8fa4-a8f94b09c6f5
07:48:14.090[sip]   CSeq: 24 OPTIONS
07:48:14.090[sip]   Content-Length: 0
07:48:14.090[sip]
07:48:14.090[sip]   -------------------------------------------------------------                                                                                       -----------
07:48:44.100[sip]send 375 bytes to udp/[10.10.2.2]:5060 at 14:17:00.100000:
   ------------------------------------------------------------------------
07:48:44.100[sip]   OPTIONS sip:3477951@voip.sinor.ru SIP/2.0
07:48:44.100[sip]   Via: SIP/2.0/UDP 10.0.5.14;rport;branch=z9hG4bK766Sy12725cKp
07:48:44.100[sip]   Max-Forwards: 70
07:48:44.100[sip]   From: <sip:3477951@voip.sinor.ru>;tag=tNH1c67Nrp5mc
07:48:44.100[sip]   To: <sip:3477951@voip.sinor.ru>
07:48:44.100[sip]   Call-ID: de920740-987a-1200-8fa4-a8f94b09c6f5
07:48:44.100[sip]   CSeq: 24 OPTIONS
07:48:44.100[sip]   Subject: KEEPALIVE
07:48:44.100[sip]   User-Agent: TAU-8.IP/2.3.0 SN/VI33020063 sofia-sip/1.12.10
07:48:44.100[sip]   Content-Length: 0
07:48:44.100[sip]
07:48:44.100[sip]   -------------------------------------------------------------                                                                                       -----------
07:48:44.110[sip]recv 296 bytes from udp/[10.10.2.2]:5060 at 14:17:00.110000:
   ------------------------------------------------------------------------
07:48:44.110[sip]   SIP/2.0 482 Loop Detected
07:48:44.110[sip]   Via: SIP/2.0/UDP 10.0.5.14;branch=z9hG4bK766Sy12725cKp;rport=                                                                                       5060
07:48:44.110[sip]   From: <sip:3477951@voip.sinor.ru>;tag=tNH1c67Nrp5mc
07:48:44.110[sip]   To: <sip:3477951@voip.sinor.ru>;tag=SDa1l9299-ouhb-pfa3g6o3s1
07:48:44.110[sip]   Call-ID: de920740-987a-1200-8fa4-a8f94b09c6f5
07:48:44.110[sip]   CSeq: 24 OPTIONS
07:48:44.110[sip]   Content-Length: 0
07:48:44.110[sip]
07:48:44.110[sip]   -------------------------------------------------------------                                                                                       -----------
root@TAU-8:~# 07:49:14.120[sip]send 375 bytes to udp/[10.10.2.2]:5060 at 14:17:30.120000:
   ------------------------------------------------------------------------
07:49:14.120[sip]   OPTIONS sip:3477951@voip.sinor.ru SIP/2.0
07:49:14.120[sip]   Via: SIP/2.0/UDP 10.0.5.14;rport;branch=z9hG4bK8F0j0vKB0e35H
07:49:14.120[sip]   Max-Forwards: 70
07:49:14.120[sip]   From: <sip:3477951@voip.sinor.ru>;tag=tNH1c67Nrp5mc
07:49:14.120[sip]   To: <sip:3477951@voip.sinor.ru>
07:49:14.120[sip]   Call-ID: de920740-987a-1200-8fa4-a8f94b09c6f5
07:49:14.120[sip]   CSeq: 24 OPTIONS
07:49:14.120[sip]   Subject: KEEPALIVE
07:49:14.120[sip]   User-Agent: TAU-8.IP/2.3.0 SN/VI33020063 sofia-sip/1.12.10
07:49:14.120[sip]   Content-Length: 0
07:49:14.120[sip]
07:49:14.120[sip]   ------------------------------------------------------------------------
