Jan  1 01:11:02 tau24 syslog.info syslogd started: BusyBox v1.15.3
Dec 31 22:11:03 tau24 user.notice tau24: 2.13.1.2|(03.105)[sip]nta: timer B fired, timeout INVITE (315)
Dec 31 22:11:03 tau24 user.notice tau24: 2.13.1.2|(03.108)[sip]nua(0x676d00): call state changed: calling -> terminated
Dec 31 22:11:03 tau24 user.notice tau24: 2.13.1.2|(03.110)[sip]nua(0x676d00): removing session usage
Dec 31 22:11:03 tau24 user.notice tau24: 2.13.1.2|(03.112)[sip]nta_outgoing_timer: 0/1 resent, 1/1 tout, 0/2 term, 0/3 free
Dec 31 22:11:03 tau24 user.debug tau24: 2.13.1.2|(03.114)[app:dbg]SIP: got nua_r_invite : 408(Request Timeout)
Dec 31 22:11:03 tau24 user.debug tau24: 2.13.1.2|(03.116)[app:dbg]sip: call 00020004: INVITE: 408 Request Timeout
Dec 31 22:11:03 tau24 user.debug tau24: 2.13.1.2|(03.118)[app:dbg]sip: call 00020004: destroying proposed SDP session
Dec 31 22:11:03 tau24 user.debug tau24: 2.13.1.2|(03.119)[app:dbg]sip: call 00020004: destroying proposed channel of media stream 0
Dec 31 22:11:03 tau24 user.warn tau24: 2.13.1.2|(03.121)[app:WARN]paris_num 2 , it was proxy call 1
Dec 31 22:11:03 tau24 user.debug tau24: 2.13.1.2|(03.122)[app:dbg]SIP: got nua_i_state : 408(Request Timeout)
Dec 31 22:11:03 tau24 user.warn tau24: 2.13.1.2|(03.124)[app:WARN]NO SIP IN nua_i_state == 408 : Request Timeout
Dec 31 22:11:03 tau24 user.debug tau24: 2.13.1.2|(03.126)[app:dbg]self_i_state(): call state 10: : : sdp_init have_oc
Dec 31 22:11:03 tau24 user.debug tau24: 2.13.1.2|(03.127)[app:dbg]sip: call 00020004: terminated flag 0x1
Dec 31 22:11:03 tau24 user.debug tau24: 2.13.1.2|(03.129)[app:dbg]sip -[msg_remote_busy]-> pbx
Dec 31 22:11:03 tau24 user.debug tau24: 2.13.1.2|(03.130)[app:dbg]ITC: [msg_remote_busy] -> pbx
Dec 31 22:11:03 tau24 user.debug tau24: 2.13.1.2|(03.132)[app:dbg]port 2: peer is busy
Dec 31 22:11:03 tau24 user.debug tau24: 2.13.1.2|(03.133)[app:dbg]port 2: -> busy
Dec 31 22:11:03 tau24 user.debug tau24: 2.13.1.2|(03.136)[app:dbg]Port: 2: Chan 2: current state is CREATED
Dec 31 22:11:03 tau24 user.debug tau24: 2.13.1.2|(03.137)[app:dbg]Port 2: chan: 2 check vapi queue ('free') at vapi_start_tone_chan:1833
Dec 31 22:11:03 tau24 user.debug tau24: 2.13.1.2|(03.139)[app:dbg]Port 2: chan: 2: set vapi queue MSP to 'busy' with 'start_tone' at vapi_start_tone_chan:1854
Dec 31 22:11:03 tau24 user.debug tau24: 2.13.1.2|(03.140)[app:dbg]VQ Port 2 = MSP :    'start_tone' =
Dec 31 22:11:03 tau24 user.debug tau24: 2.13.1.2|(03.143)[app:dbg]chan 2 start tone, id=22, direction=TDM
Dec 31 22:11:03 tau24 user.debug tau24: 2.13.1.2|(03.144)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''start_tone') at __cmd_engine:414
Dec 31 22:11:03 tau24 user.debug tau24: 2.13.1.2|(03.146)[app:dbg]voip_lock: set voip lock
Dec 31 22:11:03 tau24 user.debug tau24: 2.13.1.2|(03.148)[app:dbg]pbx -[msg_fxs_state]-> group
Dec 31 22:11:03 tau24 user.debug tau24: 2.13.1.2|(03.149)[app:dbg]self_callstate_terminated: call id = 00020004 need_exchange_at_answer = 0
Dec 31 22:11:03 tau24 user.debug tau24: 2.13.1.2|(03.151)[app:dbg]sip: call 00020004: destroy
Dec 31 22:11:03 tau24 user.debug tau24: 2.13.1.2|(03.156)[app:dbg]ITC: [msg_fxs_state] -> group
Dec 31 22:11:03 tau24 user.debug tau24: 2.13.1.2|(03.157)[app:dbg][SG] Port 2: new state is busy
Dec 31 22:11:03 tau24 user.debug tau24: 2.13.1.2|(03.160)[app:dbg]vapi_cb_req(): Conn 2 CALLBACK msg (level = 0x0; result = 0x0; req_id = 0x E20; len = 12)
Dec 31 22:11:03 tau24 user.debug tau24: 2.13.1.2|(03.161)[app:dbg]vapi: chan: 2 Callback request = 0x E20
Dec 31 22:11:03 tau24 user.debug tau24: 2.13.1.2|(03.163)[app:dbg]Conn 2: Start tone - Successfull
Dec 31 22:11:03 tau24 user.debug tau24: 2.13.1.2|(03.164)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''start_tone') at vapi_cb_chan:4384
Dec 31 22:11:03 tau24 user.debug tau24: 2.13.1.2|(03.166)[app:dbg]Port 2: chan: 2: set vapi queue MSP to 'free' with  at vapi_cb_chan:4385
Dec 31 22:11:03 tau24 user.debug tau24: 2.13.1.2|(03.167)[app:dbg]Port 2: chan: 2 check vapi queue ('free') at vapi_next_ops:3738
Dec 31 22:11:03 tau24 user.notice tau24: 2.13.1.2|(03.696)[sip]nta: timer D fired, terminate INVITE (300)
Dec 31 22:11:03 tau24 user.notice tau24: 2.13.1.2|(03.699)[sip]nta_outgoing_timer: 0/0 resent, 0/0 tout, 1/3 term, 1/3 free
Dec 31 22:11:05 tau24 user.debug tau24: 2.13.1.2|(05.725)[app:dbg]HIO: port 2 <Talk/busy> msg <Pre Onhook><2>
Dec 31 22:11:05 tau24 user.debug tau24: 2.13.1.2|(05.727)[app:dbg]HIO: preonhook TDM port '2', port enabled 1
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.324)[app:dbg]HIO: port 2 <Talk/busy> msg <Onhook><1>
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.325)[app:dbg]HIO: onhook TDM port '2', port enabled 1
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.327)[app:dbg]port 2: onhook state: busy
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.328)[app:dbg]regex ID 2: dial reset
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.330)[app:dbg]pbx -[msg_clear]-> sip
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.331)[app:dbg]Port: 2: Chan 2: current state is CREATED
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.333)[app:dbg]Port 2: chan: 2 check vapi queue ('free') at vapi_stop_tone_chan:1967
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.334)[app:dbg]Port 2: chan: 2: set vapi queue MSP to 'busy' with 'stop_tone' at vapi_stop_tone_chan:1988
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.336)[app:dbg]VQ Port 2 = MSP :     'stop_tone' =
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.338)[app:dbg]chan 2 stop tone
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.339)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''stop_tone') at __cmd_engine:414
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.341)[app:dbg]port 2: reset
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.342)[app:dbg]dump_port_calls() port 2:
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.343)[app:dbg]Q:(0x666000,0x00020004,(nil))
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.345)[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) C:((nil),0x00000000,(nil))
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.346)[app:dbg]port 2: reset call 0x00020004 (active)
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.348)[app:dbg]Port 2: vpl are:
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.349)[app:dbg]<state>: cur/next: 0x689000/(nil)
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.351)[app:dbg]port_state_voice() can`t find pair media
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.352)[app:dbg]Port: 2: Chan 2: current state is CREATED
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.354)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''stop_tone') at vapi_state_chan:2791
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.355)[app:dbg]Port 2 chan 2 put cmd 'set state',cur 'stop_tone' to queue at (vapi_state_chan:2796)
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.357)[app:dbg]VQ Port 2 = MSP :     'stop_tone' =
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.358)[app:dbg]VQ Port 2 + 02  :     'set state'/tx<stop>,rx<stop>,drop + <-get_ptr 
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.359)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''stop_tone') at __cmd_engine:414
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.361)[app:dbg]remove_call_from_global:324 - enter
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.362)[app:dbg]Port: 2: Chan 2: current state is CREATED
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.364)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''stop_tone') at vapi_destroy_chan:1482
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.365)[app:dbg]Clear vapi queue of Port 2
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.367)[app:dbg]Port 2: clear VPL
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.368)[app:dbg]Port 2: vpl are:
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.369)[app:dbg]<state>: cur/next: 0x689000/(nil)
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.371)[app:dbg]Port 2: vpl is empty
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.372)[app:dbg]Port 2 chan 2 put cmd 'destroy',cur 'stop_tone' to queue at (vapi_destroy_chan:1490)
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.374)[app:dbg]VQ Port 2 = MSP :     'stop_tone' =
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.375)[app:dbg]VQ Port 2 + 00  :       'destroy'/         <none> + <-get_ptr 
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.377)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''stop_tone') at __cmd_engine:414
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.378)[app:dbg]voip_lock: remove voip lock
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.380)[app:dbg]pbx -[msg_fxs_state]-> group
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.381)[app:dbg]dump_port_calls() port 2:
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.383)[app:dbg]Q:NONE
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.384)[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) C:((nil),0x00000000,(nil))
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.386)[app:dbg]HIO: port 2 <Talk/hangup> msg <State><16>
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.387)[app:dbg]Port: 2:  Talk -> ReadyAfterInit (No errors)
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.389)[app:dbg]ITC: [msg_clear] -> sip
Dec 31 22:11:06 tau24 user.err tau24: 2.13.1.2|(06.391)[app:ERR]sip: call 00020004 not found
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.393)[app:dbg]ITC: [msg_fxs_state] -> group
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.394)[app:dbg][SG] Port 2: new state is hangup
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.401)[app:dbg]vapi_cb_req(): Conn 2 CALLBACK msg (level = 0x0; result = 0x0; req_id = 0x E21; len = 0)
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.410)[app:dbg]vapi: chan: 2 Callback request = 0x E21
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.412)[app:dbg]Conn 2: Stop tone - Successfull
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.413)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''stop_tone') at vapi_cb_chan:4384
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.415)[app:dbg]Port 2: chan: 2: set vapi queue MSP to 'free' with  at vapi_cb_chan:4385
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.416)[app:dbg]VQ Port 2 + 00  :       'destroy'/         <none> + <-get_ptr 
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.417)[app:dbg]Port 2: chan: 2 check vapi queue ('free') at vapi_next_ops:3738
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.419)[app:dbg]Port 2 get cmd 'destroy' from queue at (vapi_next_ops:3755)
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.420)[app:dbg]Port: 2: Chan 2: current state is CREATED
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.422)[app:dbg]Port 2: chan: 2 check vapi queue ('free') at vapi_destroy_chan:1482
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.423)[app:dbg]Port 2: chan: 2: set vapi queue MSP to 'busy' with 'destroy' at vapi_destroy_chan:1505
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.424)[app:dbg]VQ Port 2 = MSP :       'destroy' =
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.426)[app:dbg]Chan 2: CREATED -> DESTROYING
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.427)[app:dbg]vapi: destroy: Destroy mediaforks on TDM 2
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.429)[app:dbg]vapi: destroy: TDM 2 get statistic
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.431)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''destroy') at vapi_next_ops:3883
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.434)[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, conn 2
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.436)[app:dbg]vapi_cb_req(): Conn 2 CALLBACK msg (level = 0x0; result = 0x0; req_id = 0x 15E; len = 208)
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.438)[app:dbg]vapi: chan: 2 Callback request = 0x 15E
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.440)[app:dbg]port 2: (chan 2) get port STATISTIC
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.441)[app:dbg]port 2: Rx_pack = 200
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.442)[app:dbg]port 2: Rx_oct  = 32000
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.444)[app:dbg]port 2: Lost_pack  = 0
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.445)[app:dbg]port 2: Tx_pack = 210
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.447)[app:dbg]port 2: Tx_oct  = 33600
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.448)[app:dbg]port 2: peak_jiter = 0
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.450)[app:dbg]vapi: destroy: TDM 2 Destroy
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.452)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''destroy') at vapi_cb_chan:4378
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.459)[app:dbg]vapi_cb_req(): Conn 2 CALLBACK msg (level = 0x0; result = 0x0; req_id = 0x 103; len = 0)
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.461)[app:dbg]vapi: chan: 2 Callback request = 0x 103
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.462)[app:dbg]vapi: destroy: reset and turn off RTCP timers
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.464)[app:dbg]Chan 2: DESTROYING -> INITIAL
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.465)[app:dbg]vapi: destroy: Done (port 2) - TDM-just actions
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.467)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''destroy') at vapi_cb_chan:4384
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.468)[app:dbg]Port 2: chan: 2: set vapi queue MSP to 'free' with  at vapi_cb_chan:4385
Dec 31 22:11:06 tau24 user.debug tau24: 2.13.1.2|(06.470)[app:dbg]Port 2: chan: 2 check vapi queue ('free') at vapi_next_ops:3738
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.398)[app:dbg]HIO: port 2 <ReadyAfterInit/hangup> msg <Offhook><0>
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.400)[app:dbg]Port: 2:  ReadyAfterInit -> Release (No errors)
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.401)[app:dbg]HIO: offhook TDM port '2' port enabled 1
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.403)[app:dbg]HIO: offhook TDM port '2' direction unknown -> outgoing
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.404)[app:dbg]port 2: offhook state: hangup
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.406)[app:dbg]regex ID 2: dial reset
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.407)[app:dbg]Port: 2: Chan 2: current state is INITIAL
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.408)[app:dbg]Port 2: chan: 2 check vapi queue ('free') at vapi_create_chan:1329
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.410)[app:dbg]Port 2: chan: 2: set vapi queue MSP to 'busy' with 'create' at vapi_create_chan:1350
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.411)[app:dbg]VQ Port 2 = MSP :        'create' =
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.413)[app:dbg]vapi: create: Create TDM 2
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.414)[app:dbg]Chan 2: INITIAL -> CREATING
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.416)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''create') at __cmd_engine:414
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.418)[app:dbg]Port: 2: Chan 2: current state is CREATING
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.420)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''create') at vapi_start_tone_chan:1833
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.421)[app:dbg]Port 2 chan 2 put cmd 'start_tone',cur 'create' to queue at (vapi_start_tone_chan:1838)
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.422)[app:dbg]VQ Port 2 = MSP :        'create' =
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.424)[app:dbg]VQ Port 2 + 01  :    'start_tone'/   tone<21>,Tdm + <-get_ptr 
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.425)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''create') at __cmd_engine:414
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.427)[app:dbg]voip_lock: set voip lock
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.429)[app:dbg]pbx -[msg_fxs_state]-> group
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.430)[app:dbg]dump_port_calls() port 2:
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.432)[app:dbg]Q:NONE
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.433)[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) C:((nil),0x00000000,(nil))
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.435)[app:dbg]HIO: port 2 <Release/hangdown> msg <State><16>
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.436)[app:dbg]Port: 2:  Release -> Talk (No errors)
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.441)[app:dbg]ITC: [msg_fxs_state] -> group
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.443)[app:dbg][SG] Port 2: new state is hangdown
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.451)[app:dbg]vapi_cb_req(): Conn 2 CALLBACK msg (level = 0x0; result = 0x0; req_id = 0x   0; len = 0)
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.454)[app:dbg]vapi: chan: 2 Callback request = 0x   0
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.455)[app:dbg]vapi: chan 2: voip DTMF SET
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.459)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''create') at vapi_cb_chan:4378
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.461)[app:dbg]vapi_cb_req(): Conn 2 CALLBACK msg (level = 0x0; result = 0x0; req_id = 0x  61; len = 12)
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.463)[app:dbg]vapi: chan: 2 Callback request = 0x  61
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.465)[app:dbg]vapi: create: Set TDM 2 SSRC to 0x7fea6b43
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.466)[app:dbg]Chan 2: CREATING -> CREATED
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.468)[app:dbg]vapi: create: TDM 2 Done
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.469)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''create') at vapi_cb_chan:4384
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.471)[app:dbg]Port 2: chan: 2: set vapi queue MSP to 'free' with  at vapi_cb_chan:4385
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.472)[app:dbg]VQ Port 2 + 01  :    'start_tone'/   tone<21>,Tdm + <-get_ptr 
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.473)[app:dbg]Port 2: chan: 2 check vapi queue ('free') at vapi_next_ops:3738
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.475)[app:dbg]Port 2 get cmd 'start_tone' from queue at (vapi_next_ops:3755)
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.476)[app:dbg]Port: 2: Chan 2: current state is CREATED
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.478)[app:dbg]Port 2: chan: 2 check vapi queue ('free') at vapi_start_tone_chan:1833
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.479)[app:dbg]Port 2: chan: 2: set vapi queue MSP to 'busy' with 'start_tone' at vapi_start_tone_chan:1854
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.481)[app:dbg]VQ Port 2 = MSP :    'start_tone' =
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.485)[app:dbg]chan 2 start tone, id=21, direction=TDM
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.487)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''start_tone') at vapi_next_ops:3883
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.490)[app:dbg]vapi_cb_req(): Conn 2 CALLBACK msg (level = 0x0; result = 0x0; req_id = 0x E20; len = 12)
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.491)[app:dbg]vapi: chan: 2 Callback request = 0x E20
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.493)[app:dbg]Conn 2: Start tone - Successfull
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.494)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''start_tone') at vapi_cb_chan:4384
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.496)[app:dbg]Port 2: chan: 2: set vapi queue MSP to 'free' with  at vapi_cb_chan:4385
Dec 31 22:11:08 tau24 user.debug tau24: 2.13.1.2|(08.497)[app:dbg]Port 2: chan: 2 check vapi queue ('free') at vapi_next_ops:3738
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.408)[app:dbg]vapi: tone detect: Conn 2. Detect signal <DTMF digit 1> (level 8 dBov)
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.470)[app:dbg]HIO: port 2 <Talk/hangdown> msg <Digit><3>
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.472)[app:dbg]Port 2: Start dial duration timer (300)
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.473)[app:dbg]Port: 2: Chan 2: current state is CREATED
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.475)[app:dbg]Port 2: chan: 2 check vapi queue ('free') at vapi_stop_tone_chan:1967
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.476)[app:dbg]Port 2: chan: 2: set vapi queue MSP to 'busy' with 'stop_tone' at vapi_stop_tone_chan:1988
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.478)[app:dbg]VQ Port 2 = MSP :     'stop_tone' =
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.480)[app:dbg]chan 2 stop tone
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.481)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''stop_tone') at __cmd_engine:414
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.483)[app:dbg]voip_lock: set voip lock
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.485)[app:dbg]pbx -[msg_fxs_state]-> group
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.486)[app:dbg]NO DVO ENABLED
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.488)[app:dbg]check item 0: 0x0002/00000000,0 : <1>
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.490)[app:dbg]regex_match_item: check route 0x68bc00 repeat off rf 0, rt 0, crt 0, digit '1' mask 0x02
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.491)[app:dbg]<cur match>: dial <1>r 0, dt 0, sub 0 {0,0}
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.492)[app:dbg]check item 1: 0x0001/00000000,0 : <F>
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.494)[app:dbg]check 'cant dial more' within cycle: item 0, crt 0, {0,0}
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.495)[app:dbg]MATCH: fulldialed 0, can`t dial more 0, dialtone 0
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.497)[app:dbg]02: [0,]
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.498)[app:dbg]port_process_digit() regex route 0x68bc00, final 0, dt 0
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.500)[app:dbg]port 2: dial candidates
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.501)[app:dbg]regex ID 2, route 0: L 15 en, S 5 dis
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.506)[app:dbg]ITC: [msg_fxs_state] -> group
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.507)[app:dbg][SG] Port 2: new state is dial
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.509)[app:dbg]vapi_cb_req(): Conn 2 CALLBACK msg (level = 0x0; result = 0x0; req_id = 0x E21; len = 0)
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.511)[app:dbg]vapi: chan: 2 Callback request = 0x E21
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.512)[app:dbg]Conn 2: Stop tone - Successfull
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.514)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''stop_tone') at vapi_cb_chan:4384
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.515)[app:dbg]Port 2: chan: 2: set vapi queue MSP to 'free' with  at vapi_cb_chan:4385
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.517)[app:dbg]Port 2: chan: 2 check vapi queue ('free') at vapi_next_ops:3738
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.519)[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, conn 2
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.522)[app:dbg]vapi: tone detect: Conn 2. End of signal <DTMF digit 1>, duration 85 ms
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.568)[app:dbg]vapi: tone detect: Conn 2. Detect signal <DTMF digit 0> (level 10 dBov)
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.632)[app:dbg]HIO: port 2 <Talk/dial> msg <Digit><3>
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.634)[app:dbg]check item 0: 0x0002/00000000,0 : <1>
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.635)[app:dbg]regex_match_item: check route 0x68bc00 repeat off rf 0, rt 0, crt 0, digit '1' mask 0x02
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.637)[app:dbg]<cur match>: dial <1>r 0, dt 0, sub 0 {0,0}
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.638)[app:dbg]check item 1: 0x0001/00000000,0 : <0>
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.640)[app:dbg]regex_match_item: check route 0x68bc00 repeat off rf 0, rt 0, crt 0, digit '0' mask 0x01
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.641)[app:dbg]<cur match>: dial <0>r 0, dt 0, sub 0 {0,0}
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.643)[app:dbg]check item 2: 0x0001/00000000,0 : <F>
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.644)[app:dbg]check 'cant dial more' within cycle: item 1, crt 0, {0,0}
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.645)[app:dbg]MATCH: fulldialed 0, can`t dial more 0, dialtone 0
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.647)[app:dbg]02: [0,]
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.648)[app:dbg]port_process_digit() regex route 0x68bc00, final 0, dt 0
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.650)[app:dbg]port 2: dial candidates
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.651)[app:dbg]regex ID 2, route 0: L 15 en, S 5 dis
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.657)[app:dbg]vapi: tone detect: Conn 2. End of signal <DTMF digit 0>, duration 85 ms
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.727)[app:dbg]vapi: tone detect: Conn 2. Detect signal <DTMF digit 0> (level 8 dBov)
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.804)[app:dbg]HIO: port 2 <Talk/dial> msg <Digit><3>
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.806)[app:dbg]check item 0: 0x0002/00000000,0 : <1>
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.808)[app:dbg]regex_match_item: check route 0x68bc00 repeat off rf 0, rt 0, crt 0, digit '1' mask 0x02
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.809)[app:dbg]<cur match>: dial <1>r 0, dt 0, sub 0 {0,0}
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.811)[app:dbg]check item 1: 0x0001/00000000,0 : <0>
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.812)[app:dbg]regex_match_item: check route 0x68bc00 repeat off rf 0, rt 0, crt 0, digit '0' mask 0x01
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.813)[app:dbg]<cur match>: dial <0>r 0, dt 0, sub 0 {0,0}
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.815)[app:dbg]check item 2: 0x0001/00000000,0 : <0>
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.816)[app:dbg]regex_match_item: check route 0x68bc00 repeat off rf 0, rt 0, crt 0, digit '0' mask 0x01
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.818)[app:dbg]<cur match>: dial <0>r 0, dt 0, sub 0 {0,0}
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.819)[app:dbg]end of items - test dial ended
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.821)[app:dbg]check 'cant dial more' out of the cycle: item 2, crt 0, {0,0}
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.822)[app:dbg]MATCH: fulldialed 1, can`t dial more 1, dialtone 0
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.823)[app:dbg]02: [0,]
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.825)[app:dbg]port_process_digit() regex route 0x68bc00, final 1, dt 0
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.826)[app:dbg]port 2: final action
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.828)[app:dbg]port 2: dial <100>
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.829)[app:dbg]pbx: allocating memory for new call
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.831)[app:dbg]pbx: created new outgoing call for port 2
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.832)[app:dbg]port 2: PHONE_FROM = (1003)
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.834)[app:dbg]port 2: NAME_FROM  = ()
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.835)[app:dbg]port 2: -> calling to sip//100
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.836)[app:dbg]limiter_is_proxy_host:367> host not set - return 'it is proxy'
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.838)[app:dbg]check_call_limits: host - [proxy], pr_id 0
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.839)[app:dbg]All limits:
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.841)[app:dbg]get_calls_count_by_host:354 - for '[proxy]' we have 0 calls
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.842)[app:dbg]Call accepted
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.844)[app:dbg]add_call_to_global:285 - enter
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.846)[app:dbg]Origin remote host: 
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.847)[app:dbg]Actual remote host: [proxy]
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.848)[app:dbg]ext: 0
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.850)[app:dbg]__itc_call_to_port_eng() USER: 100; PHONE: 1003; NAME: ; R_USER: ;
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.851)[app:dbg]pbx -[msg_call]-> sip
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.853)[app:dbg]Port: 2: Chan 2: current state is CREATED
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.854)[app:dbg]Port 2: chan: 2 check vapi queue ('free') at vapi_stop_tone_chan:1967
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.856)[app:dbg]Port 2: chan: 2: set vapi queue MSP to 'busy' with 'stop_tone' at vapi_stop_tone_chan:1988
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.857)[app:dbg]VQ Port 2 = MSP :     'stop_tone' =
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.859)[app:dbg]chan 2 stop tone
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.861)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''stop_tone') at __cmd_engine:414
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.862)[app:dbg]voip_lock: set voip lock
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.864)[app:dbg]pbx -[msg_fxs_state]-> group
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.866)[app:dbg]regex ID 2: dial reset
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.868)[app:dbg]ITC: [msg_call] -> sip
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.869)[app:dbg]sip: outgoing call 00020005 from endpoint 2
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.871)[app:dbg]Available RTP ports: 35002...40000
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.872)[app:dbg]Selected port for current call: 35022
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.874)[app:dbg]sip_paramss_create() normal - using cur proxy [192.168.0.152] if proxy call
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.876)[app:dbg]ITC: [msg_fxs_state] -> group
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.884)[app:dbg]vapi: tone detect: Conn 2. End of signal <DTMF digit 0>, duration 85 ms
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.887)[app:dbg]vapi_cb_req(): Conn 2 CALLBACK msg (level = 0x0; result = 0x0; req_id = 0x E21; len = 0)
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.889)[app:dbg]sip_paramss_create() to host is <(null)>- should not have port, to user is <100> use proxy 1
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.894)[app:dbg][SG] Port 2: new state is calling
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.898)[app:dbg]vapi: chan: 2 Callback request = 0x E21
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.900)[app:dbg]stun_get_public_ip(port = 5060)
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.905)[app:dbg]Conn 2: Stop tone - Successfull
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.907)[app:dbg]stun_get_public_ip: Always using local IP
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.910)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''stop_tone') at vapi_cb_chan:4384
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.912)[app:dbg]sip_paramss_create() send to is <sip:100@192.168.0.152>, <not outbound>
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.915)[app:dbg]Port 2: chan: 2: set vapi queue MSP to 'free' with  at vapi_cb_chan:4385
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.917)[app:dbg]sip_paramss_create() target,request url is <sip:100@192.168.0.152>
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.920)[app:dbg]Port 2: chan: 2 check vapi queue ('free') at vapi_next_ops:3738
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.921)[app:dbg]sip: call 00020005: sip  INVITE from sip:1003@192.168.0.152 to sip:100@192.168.0.152
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.926)[app:dbg]sip: call 00020005: targeturl is <sip:100@192.168.0.152>
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.928)[app:dbg]Build contact field with To-Host '192.168.0.152'
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.929)[app:dbg]stun_get_public_ip(port = 35022)
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.931)[app:dbg]stun_get_public_ip: Always using local IP
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.933)[app:dbg]sdp_codecs_init() init call sdp (offer)
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.935)[app:dbg]sdp_codecs_dump() ssup present off, ecan absent on, rfc present 96, nse absent 0, ptime absent 0
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.942)[app:dbg]sdp_codecs_dump() G723: none
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.946)[app:dbg]sdp_codecs_dump() G711A:
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.948)[app:dbg]sdp_codecs_dump() PT 8, vbd absent off
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.949)[app:dbg]sdp_codecs_dump() G711U:
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.950)[app:dbg]sdp_codecs_dump() PT 0, vbd absent off
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.952)[app:dbg]sdp_codecs_dump() G726-32: none
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.953)[app:dbg]sdp_codecs_g711a_add_to_media_attrs() g711a: have one at last
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.955)[app:dbg]sdp_codecs_g711u_add_to_media_attrs() g711u: have one at last
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.958)[app:dbg]sdp_codecs_rfc2833_add_to_media_attrs() present, pt 96
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.960)[app:dbg]sdp_codecs_nse_add_to_media_attrs() absent, pt 0
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.962)[app:dbg]sdp_codecs_ptime_add_to_attrs() ptime absent 0
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.964)[app:dbg]sdp_codecs_ecan_add_to_attrs() ecan absent on
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.966)[app:dbg]sdp_codecs_ssup_add_to_attrs() ssup present off
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.968)[app:dbg]sdp_tail:  8 0 96 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:96 telephone-event/8000 a=fmtp:96 16 a=silenceSupp:off - - - -
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.970)[app:dbg]make_sdp: SDP: s=Session SDP m=audio 35022 RTP/AVP 8 0 96 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:96 telephone-event/8000 a=fmtp:96 16 a=silenceSupp:off - - - -
Dec 31 22:11:09 tau24 user.debug tau24: 2.13.1.2|(09.972)[app:dbg]sip: get_support_params: profile 0 supported: 'timer, 100rel, replaces'
Dec 31 22:11:09 tau24 user.notice tau24: 2.13.1.2|(09.978)[sip]nua(0x677700): adding session usage
Dec 31 22:11:09 tau24 user.notice tau24: 2.13.1.2|(09.984)[sip]send 856 bytes to udp/[192.168.0.152]:5060 at 00:10:42.618307:
Dec 31 22:11:09 tau24 user.notice tau24: 2.13.1.2|(09.986)[sip]   ------------------------------------------------------------------------
Dec 31 22:11:09 tau24 user.notice tau24: 2.13.1.2|(09.988)[sip]   INVITE sip:100@192.168.0.152 SIP/2.0
Dec 31 22:11:09 tau24 user.notice tau24: 2.13.1.2|(09.989)[sip]   Via: SIP/2.0/UDP 192.168.0.186;rport;branch=z9hG4bKU5ypvrNt637Dp
Dec 31 22:11:09 tau24 user.notice tau24: 2.13.1.2|(09.991)[sip]   Max-Forwards: 70
Dec 31 22:11:09 tau24 user.notice tau24: 2.13.1.2|(09.992)[sip]   From: <sip:1003@192.168.0.152>;tag=XHaZapjBgprgD
Dec 31 22:11:09 tau24 user.notice tau24: 2.13.1.2|(09.994)[sip]   To: <sip:100@192.168.0.152>
Dec 31 22:11:09 tau24 user.notice tau24: 2.13.1.2|(09.997)[sip]   Call-ID: 3ddcaf6b-70fc-122d-bb9f-a8f94b265d12
Dec 31 22:11:09 tau24 user.notice tau24: 2.13.1.2|(09.998)[sip]   CSeq: 321 INVITE
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.000)[sip]   Contact: <sip:1003@192.168.0.186:5060>
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.001)[sip]   User-Agent: TAU-72 build 2.13.1.2 sofia-sip/1.12.10
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.003)[sip]   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, INFO
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.004)[sip]   Supported: timer, 100rel, replaces
Dec 31 22:11:10 tau24 user.debug tau24: 2.13.1.2|(10.008)[app:dbg]SIP: got nua_r_set_params : 200(OK)
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.074)[sip]   Min-SE: 120
Dec 31 22:11:10 tau24 user.warn tau24: 2.13.1.2|(10.078)[app:WARN]NO SIP IN nua_r_set_params == 200 : OK
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.079)[sip]   Content-Type: application/sdp
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.083)[sip]   Content-Disposition: session
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.085)[sip]   Content-Length: 266
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.087)[sip]   
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.089)[sip]   v=0
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.090)[sip]   o=- 2264488505173328569 9075254609413588441 IN IP4 192.168.0.186
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.092)[sip]   s=Session SDP
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.093)[sip]   c=IN IP4 192.168.0.186
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.094)[sip]   t=0 0
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.098)[sip]   m=audio 35022 RTP/AVP 8 0 96
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.099)[sip]   a=rtpmap:8 PCMA/8000
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.101)[sip]   a=rtpmap:0 PCMU/8000
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.102)[sip]   a=rtpmap:96 telephone-event/8000
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.104)[sip]   a=fmtp:96 16
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.106)[sip]   a=silenceSupp:off - - - -
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.108)[sip]   ------------------------------------------------------------------------
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.109)[sip]nta: sent INVITE (321) to */192.168.0.152:5060
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.111)[sip]nua(0x677700): call state changed: init -> calling, sent offer
Dec 31 22:11:10 tau24 user.debug tau24: 2.13.1.2|(10.116)[app:dbg]SIP: got nua_i_state : 0(INVITE sent)
Dec 31 22:11:10 tau24 user.warn tau24: 2.13.1.2|(10.117)[app:WARN]NO SIP IN nua_i_state == 0 : INVITE sent
Dec 31 22:11:10 tau24 user.debug tau24: 2.13.1.2|(10.119)[app:dbg]self_i_state(): call state 2: os : local sdp : sdp_init no_oc
Dec 31 22:11:10 tau24 user.debug tau24: 2.13.1.2|(10.120)[app:dbg]sip: call 00020005: SDP offer sent
Dec 31 22:11:10 tau24 user.debug tau24: 2.13.1.2|(10.122)[app:dbg]self_create_local_media() 0: add rtpmap 8
Dec 31 22:11:10 tau24 user.debug tau24: 2.13.1.2|(10.123)[app:dbg]self_create_local_media() 1: add rtpmap 0
Dec 31 22:11:10 tau24 user.debug tau24: 2.13.1.2|(10.125)[app:dbg]self_create_local_media() 2: add rtpmap 96
Dec 31 22:11:10 tau24 user.debug tau24: 2.13.1.2|(10.128)[app:dbg]sip: call 00020005: media stream 0, creating proposed audio channel, local RTP 192.168.0.186:35022, rtpmaps cnt: 3
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.615)[sip]nta: timer A fired, retransmit INVITE (321)
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.618)[sip]send 856 bytes to udp/[192.168.0.152]:5060 at 00:10:43.252325:
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.619)[sip]   ------------------------------------------------------------------------
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.621)[sip]   INVITE sip:100@192.168.0.152 SIP/2.0
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.622)[sip]   Via: SIP/2.0/UDP 192.168.0.186;rport;branch=z9hG4bKU5ypvrNt637Dp
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.624)[sip]   Max-Forwards: 70
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.626)[sip]   From: <sip:1003@192.168.0.152>;tag=XHaZapjBgprgD
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.628)[sip]   To: <sip:100@192.168.0.152>
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.630)[sip]   Call-ID: 3ddcaf6b-70fc-122d-bb9f-a8f94b265d12
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.631)[sip]   CSeq: 321 INVITE
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.632)[sip]   Contact: <sip:1003@192.168.0.186:5060>
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.634)[sip]   User-Agent: TAU-72 build 2.13.1.2 sofia-sip/1.12.10
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.637)[sip]   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, INFO
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.639)[sip]   Supported: timer, 100rel, replaces
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.641)[sip]   Min-SE: 120
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.643)[sip]   Content-Type: application/sdp
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.644)[sip]   Content-Disposition: session
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.647)[sip]   Content-Length: 266
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.649)[sip]   
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.650)[sip]   v=0
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.652)[sip]   o=- 2264488505173328569 9075254609413588441 IN IP4 192.168.0.186
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.654)[sip]   s=Session SDP
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.657)[sip]   c=IN IP4 192.168.0.186
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.658)[sip]   t=0 0
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.660)[sip]   m=audio 35022 RTP/AVP 8 0 96
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.662)[sip]   a=rtpmap:8 PCMA/8000
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.664)[sip]   a=rtpmap:0 PCMU/8000
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.666)[sip]   a=rtpmap:96 telephone-event/8000
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.668)[sip]   a=fmtp:96 16
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.670)[sip]   a=silenceSupp:off - - - -
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.672)[sip]   ------------------------------------------------------------------------
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.673)[sip]nta: resent INVITE (321) to */192.168.0.152:5060
Dec 31 22:11:10 tau24 user.notice tau24: 2.13.1.2|(10.676)[sip]nta_outgoing_timer: 1/1 resent, 0/1 tout, 0/2 term, 0/3 free
Dec 31 22:11:11 tau24 user.notice tau24: 2.13.1.2|(11.625)[sip]nta: timer A fired, retransmit INVITE (321)
Dec 31 22:11:11 tau24 user.notice tau24: 2.13.1.2|(11.628)[sip]send 856 bytes to udp/[192.168.0.152]:5060 at 00:10:44.262241:
Dec 31 22:11:11 tau24 user.notice tau24: 2.13.1.2|(11.629)[sip]   ------------------------------------------------------------------------
Dec 31 22:11:11 tau24 user.notice tau24: 2.13.1.2|(11.631)[sip]   INVITE sip:100@192.168.0.152 SIP/2.0
Dec 31 22:11:11 tau24 user.notice tau24: 2.13.1.2|(11.632)[sip]   Via: SIP/2.0/UDP 192.168.0.186;rport;branch=z9hG4bKU5ypvrNt637Dp
Dec 31 22:11:11 tau24 user.notice tau24: 2.13.1.2|(11.634)[sip]   Max-Forwards: 70
Dec 31 22:11:11 tau24 user.notice tau24: 2.13.1.2|(11.635)[sip]   From: <sip:1003@192.168.0.152>;tag=XHaZapjBgprgD
Dec 31 22:11:11 tau24 user.notice tau24: 2.13.1.2|(11.638)[sip]   To: <sip:100@192.168.0.152>
Dec 31 22:11:11 tau24 user.notice tau24: 2.13.1.2|(11.640)[sip]   Call-ID: 3ddcaf6b-70fc-122d-bb9f-a8f94b265d12
Dec 31 22:11:11 tau24 user.notice tau24: 2.13.1.2|(11.641)[sip]   CSeq: 321 INVITE
Dec 31 22:11:11 tau24 user.notice tau24: 2.13.1.2|(11.643)[sip]   Contact: <sip:1003@192.168.0.186:5060>
Dec 31 22:11:11 tau24 user.notice tau24: 2.13.1.2|(11.644)[sip]   User-Agent: TAU-72 build 2.13.1.2 sofia-sip/1.12.10
Dec 31 22:11:11 tau24 user.notice tau24: 2.13.1.2|(11.647)[sip]   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, INFO
Dec 31 22:11:11 tau24 user.notice tau24: 2.13.1.2|(11.648)[sip]   Supported: timer, 100rel, replaces
Dec 31 22:11:11 tau24 user.notice tau24: 2.13.1.2|(11.650)[sip]   Min-SE: 120
Dec 31 22:11:11 tau24 user.notice tau24: 2.13.1.2|(11.651)[sip]   Content-Type: application/sdp
Dec 31 22:11:11 tau24 user.notice tau24: 2.13.1.2|(11.653)[sip]   Content-Disposition: session
Dec 31 22:11:11 tau24 user.notice tau24: 2.13.1.2|(11.654)[sip]   Content-Length: 266
Dec 31 22:11:11 tau24 user.notice tau24: 2.13.1.2|(11.657)[sip]   
Dec 31 22:11:11 tau24 user.notice tau24: 2.13.1.2|(11.659)[sip]   v=0
Dec 31 22:11:11 tau24 user.notice tau24: 2.13.1.2|(11.660)[sip]   o=- 2264488505173328569 9075254609413588441 IN IP4 192.168.0.186
Dec 31 22:11:11 tau24 user.notice tau24: 2.13.1.2|(11.661)[sip]   s=Session SDP
Dec 31 22:11:11 tau24 user.notice tau24: 2.13.1.2|(11.663)[sip]   c=IN IP4 192.168.0.186
Dec 31 22:11:11 tau24 user.notice tau24: 2.13.1.2|(11.664)[sip]   t=0 0
Dec 31 22:11:11 tau24 user.notice tau24: 2.13.1.2|(11.667)[sip]   m=audio 35022 RTP/AVP 8 0 96
Dec 31 22:11:11 tau24 user.notice tau24: 2.13.1.2|(11.669)[sip]   a=rtpmap:8 PCMA/8000
Dec 31 22:11:11 tau24 user.notice tau24: 2.13.1.2|(11.670)[sip]   a=rtpmap:0 PCMU/8000
Dec 31 22:11:11 tau24 user.notice tau24: 2.13.1.2|(11.672)[sip]   a=rtpmap:96 telephone-event/8000
Dec 31 22:11:11 tau24 user.notice tau24: 2.13.1.2|(11.673)[sip]   a=fmtp:96 16
Dec 31 22:11:11 tau24 user.notice tau24: 2.13.1.2|(11.674)[sip]   a=silenceSupp:off - - - -
Dec 31 22:11:11 tau24 user.notice tau24: 2.13.1.2|(11.678)[sip]   ------------------------------------------------------------------------
Dec 31 22:11:11 tau24 user.notice tau24: 2.13.1.2|(11.679)[sip]nta: resent INVITE (321) to */192.168.0.152:5060
Dec 31 22:11:11 tau24 user.notice tau24: 2.13.1.2|(11.680)[sip]nta_outgoing_timer: 1/1 resent, 0/1 tout, 0/2 term, 0/3 free
Dec 31 22:11:12 tau24 user.notice tau24: 2.13.1.2|(12.986)[sip]tport_udp_error: No route to host (113) [icmp type=3 code=1]
Dec 31 22:11:12 tau24 user.notice tau24: 2.13.1.2|(12.988)[sip]	reported by [192.168.0.186]:0
Dec 31 22:11:12 tau24 user.notice tau24: 2.13.1.2|(12.990)[sip]nta: INVITE (321): No route to host (113) with udp/[192.168.0.152]:5060
Dec 31 22:11:12 tau24 user.notice tau24: 2.13.1.2|(12.992)[sip]nua(0x677700): call state changed: calling -> init
Dec 31 22:11:12 tau24 user.notice tau24: 2.13.1.2|(12.994)[sip]nua(0x677700): removing session usage
Dec 31 22:11:12 tau24 user.debug tau24: 2.13.1.2|(12.997)[app:dbg]SIP: got nua_r_invite : 503(Service Unavailable)
Dec 31 22:11:12 tau24 user.notice tau24: 2.13.1.2|(12.998)[sip]tport_udp_error: No route to host (113) [icmp type=3 code=1]
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.002)[app:dbg]sip: call 00020005: INVITE: 503 Service Unavailable
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.004)[sip]	reported by [192.168.0.186]:0
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.010)[app:dbg]sip: call 00020005: destroying proposed SDP session
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.012)[sip]nta_agent: tport: 192.168.0.152: No route to host
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.017)[app:dbg]sip: call 00020005: destroying proposed channel of media stream 0
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.018)[sip]tport_udp_error: No route to host (113) [icmp type=3 code=1]
Dec 31 22:11:13 tau24 user.warn tau24: 2.13.1.2|(13.023)[app:WARN]paris_num 2 , it was proxy call 1
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.024)[sip]	reported by [192.168.0.186]:0
Dec 31 22:11:13 tau24 user.warn tau24: 2.13.1.2|(13.029)[app:WARN]server 192.168.0.152 unreachable
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.030)[sip]nta_agent: tport: 192.168.0.152: No route to host
Dec 31 22:11:13 tau24 user.warn tau24: 2.13.1.2|(13.034)[app:WARN]Unreachable is current - should reregister all to the next
Dec 31 22:11:13 tau24 user.warn tau24: 2.13.1.2|(13.038)[app:WARN]	>Switch next (1 of 1)
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.041)[app:dbg]================ switch_server ===================
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.044)[app:dbg]switch to servers pair 1 for profile 0
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.048)[app:dbg]sip -[msg_reg_sip_proxy_state]-> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.051)[app:dbg]sip -[msg_reg_sip_proxy_state]-> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.057)[app:dbg]sip -[msg_reg_sip_proxy_state]-> pbx
Dec 31 22:11:13 tau24 user.warn tau24: 2.13.1.2|(13.062)[app:WARN]prepare registration for ep 2, cfg: 1003 4321
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.068)[app:dbg]sip -[msg_reg_sip_proxy_state]-> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.073)[app:dbg]sip -[msg_reg_sip_proxy_state]-> pbx
Dec 31 22:11:13 tau24 user.warn tau24: 2.13.1.2|(13.079)[app:WARN]prepare registration for ep 4, cfg: 1005 4321
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.083)[app:dbg]sip -[msg_reg_sip_proxy_state]-> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.088)[app:dbg]sip -[msg_reg_sip_proxy_state]-> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.094)[app:dbg]sip -[msg_reg_sip_proxy_state]-> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.100)[app:dbg]sip -[msg_reg_sip_proxy_state]-> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.106)[app:dbg]sip -[msg_reg_sip_proxy_state]-> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.111)[app:dbg]sip -[msg_reg_sip_proxy_state]-> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.117)[app:dbg]sip -[msg_reg_sip_proxy_state]-> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.122)[app:dbg]sip -[msg_reg_sip_proxy_state]-> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.129)[app:dbg]sip -[msg_reg_sip_proxy_state]-> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.134)[app:dbg]sip -[msg_reg_sip_proxy_state]-> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.140)[app:dbg]sip -[msg_reg_sip_proxy_state]-> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.146)[app:dbg]sip -[msg_reg_sip_proxy_state]-> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.151)[app:dbg]sip -[msg_reg_sip_proxy_state]-> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.157)[app:dbg]sip -[msg_reg_sip_proxy_state]-> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.162)[app:dbg]sip -[msg_reg_sip_proxy_state]-> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.169)[app:dbg]sip -[msg_reg_sip_proxy_state]-> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.174)[app:dbg]sip -[msg_reg_sip_proxy_state]-> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.180)[app:dbg]sip -[msg_reg_sip_proxy_state]-> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.186)[app:dbg]sip -[msg_reg_sip_proxy_state]-> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.192)[app:dbg]sip -[msg_reg_sip_proxy_state]-> pbx
Dec 31 22:11:13 tau24 user.warn tau24: 2.13.1.2|(13.198)[app:WARN]prepare registration for ep 24, cfg:  
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.201)[app:dbg]sip -[msg_reg_sip_proxy_state]-> pbx
Dec 31 22:11:13 tau24 user.warn tau24: 2.13.1.2|(13.204)[app:WARN]prepare registration for ep 25, cfg:  
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.209)[app:dbg]sip -[msg_reg_sip_proxy_state]-> pbx
Dec 31 22:11:13 tau24 user.warn tau24: 2.13.1.2|(13.213)[app:WARN]prepare registration for ep 26, cfg:  
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.218)[app:dbg]sip -[msg_reg_sip_proxy_state]-> pbx
Dec 31 22:11:13 tau24 user.warn tau24: 2.13.1.2|(13.222)[app:WARN]prepare registration for ep 27, cfg:  
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.227)[app:dbg]sip -[msg_reg_sip_proxy_state]-> pbx
Dec 31 22:11:13 tau24 user.warn tau24: 2.13.1.2|(13.230)[app:WARN]prepare registration for ep 28, cfg:  
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.235)[app:dbg]sip -[msg_reg_sip_proxy_state]-> pbx
Dec 31 22:11:13 tau24 user.warn tau24: 2.13.1.2|(13.241)[app:WARN]prepare registration for ep 29, cfg:  
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.245)[app:dbg]sip -[msg_reg_sip_proxy_state]-> pbx
Dec 31 22:11:13 tau24 user.warn tau24: 2.13.1.2|(13.252)[app:WARN]prepare registration for ep 30, cfg:  
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.255)[app:dbg]sip -[msg_reg_sip_proxy_state]-> pbx
Dec 31 22:11:13 tau24 user.warn tau24: 2.13.1.2|(13.261)[app:WARN]prepare registration for ep 31, cfg:  
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.324)[app:dbg]ITC: [msg_reg_sip_proxy_state] -> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.325)[app:dbg]ITC: [msg_reg_sip_proxy_state] -> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.327)[app:dbg]ITC: [msg_reg_sip_proxy_state] -> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.329)[app:dbg]ITC: [msg_reg_sip_proxy_state] -> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.331)[app:dbg]ITC: [msg_reg_sip_proxy_state] -> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.332)[app:dbg]ITC: [msg_reg_sip_proxy_state] -> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.334)[app:dbg]ITC: [msg_reg_sip_proxy_state] -> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.336)[app:dbg]ITC: [msg_reg_sip_proxy_state] -> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.338)[app:dbg]ITC: [msg_reg_sip_proxy_state] -> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.339)[app:dbg]ITC: [msg_reg_sip_proxy_state] -> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.341)[app:dbg]ITC: [msg_reg_sip_proxy_state] -> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.343)[app:dbg]ITC: [msg_reg_sip_proxy_state] -> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.345)[app:dbg]ITC: [msg_reg_sip_proxy_state] -> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.347)[app:dbg]ITC: [msg_reg_sip_proxy_state] -> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.348)[app:dbg]ITC: [msg_reg_sip_proxy_state] -> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.350)[app:dbg]ITC: [msg_reg_sip_proxy_state] -> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.352)[app:dbg]ITC: [msg_reg_sip_proxy_state] -> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.353)[app:dbg]ITC: [msg_reg_sip_proxy_state] -> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.355)[app:dbg]ITC: [msg_reg_sip_proxy_state] -> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.357)[app:dbg]ITC: [msg_reg_sip_proxy_state] -> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.359)[app:dbg]ITC: [msg_reg_sip_proxy_state] -> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.360)[app:dbg]ITC: [msg_reg_sip_proxy_state] -> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.362)[app:dbg]ITC: [msg_reg_sip_proxy_state] -> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.364)[app:dbg]ITC: [msg_reg_sip_proxy_state] -> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.366)[app:dbg]ITC: [msg_reg_sip_proxy_state] -> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.368)[app:dbg]ITC: [msg_reg_sip_proxy_state] -> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.369)[app:dbg]ITC: [msg_reg_sip_proxy_state] -> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.371)[app:dbg]ITC: [msg_reg_sip_proxy_state] -> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.373)[app:dbg]ITC: [msg_reg_sip_proxy_state] -> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.375)[app:dbg]ITC: [msg_reg_sip_proxy_state] -> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.377)[app:dbg]ITC: [msg_reg_sip_proxy_state] -> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.378)[app:dbg]ITC: [msg_reg_sip_proxy_state] -> pbx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.473)[app:dbg]Duplicate invite to [192.168.0.153]
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.477)[app:dbg]sip_paramss_create() normal - using cur proxy [192.168.0.153] if proxy call
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.478)[app:dbg]sip_paramss_create() to host is <(null)>- should not have port, to user is <100> use proxy 1
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.480)[app:dbg]stun_get_public_ip(port = 5060)
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.481)[app:dbg]stun_get_public_ip: Always using local IP
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.483)[app:dbg]sip_paramss_create() send to is <sip:100@192.168.0.153>, <not outbound>
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.484)[app:dbg]sip_paramss_create() target,request url is <sip:100@192.168.0.153>
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.491)[app:dbg]sip: get_support_params: profile 0 supported: 'timer, 100rel, replaces'
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.497)[sip]nua(0x677700): adding session usage
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.503)[sip]send 856 bytes to udp/[192.168.0.153]:5060 at 00:10:46.137762:
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.505)[sip]   ------------------------------------------------------------------------
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.508)[sip]   INVITE sip:100@192.168.0.153 SIP/2.0
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.509)[sip]   Via: SIP/2.0/UDP 192.168.0.186;rport;branch=z9hG4bKverFyK6X3cy0H
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.511)[sip]   Max-Forwards: 70
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.512)[sip]   From: <sip:1003@192.168.0.152>;tag=Z3vgecmja84Nm
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.514)[sip]   To: <sip:100@192.168.0.152>
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.515)[sip]   Call-ID: 3ff5b668-70fc-122d-bb9f-a8f94b265d12
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.518)[sip]   CSeq: 323 INVITE
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.519)[sip]   Contact: <sip:1003@192.168.0.186:5060>
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.521)[sip]   User-Agent: TAU-72 build 2.13.1.2 sofia-sip/1.12.10
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.522)[sip]   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, INFO
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.524)[sip]   Supported: timer, 100rel, replaces
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.526)[sip]   Min-SE: 120
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.528)[sip]   Content-Type: application/sdp
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.530)[sip]   Content-Disposition: session
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.531)[sip]   Content-Length: 266
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.532)[sip]   
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.534)[sip]   v=0
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.536)[sip]   o=- 6771640052087120481 3614900920081067566 IN IP4 192.168.0.186
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.538)[sip]   s=Session SDP
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.539)[sip]   c=IN IP4 192.168.0.186
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.541)[sip]   t=0 0
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.542)[sip]   m=audio 35022 RTP/AVP 8 0 96
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.544)[sip]   a=rtpmap:8 PCMA/8000
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.545)[sip]   a=rtpmap:0 PCMU/8000
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.548)[sip]   a=rtpmap:96 telephone-event/8000
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.549)[sip]   a=fmtp:96 16
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.551)[sip]   a=silenceSupp:off - - - -
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.552)[sip]   ------------------------------------------------------------------------
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.554)[sip]nta: sent INVITE (323) to */192.168.0.153:5060
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.556)[sip]nua(0x677700): call state changed: init -> calling, sent offer
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.560)[sip]recv 368 bytes from udp/[192.168.0.153]:5060 at 00:10:46.193449:
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.561)[sip]   ------------------------------------------------------------------------
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.563)[sip]   SIP/2.0 100 Trying
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.564)[sip]   Via: SIP/2.0/UDP 192.168.0.186;branch=z9hG4bKverFyK6X3cy0H;received=192.168.0.186;rport=5060
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.567)[sip]   From: <sip:1003@192.168.0.152>;tag=Z3vgecmja84Nm
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.568)[sip]   To: <sip:100@192.168.0.152>
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.570)[sip]   Call-ID: 3ff5b668-70fc-122d-bb9f-a8f94b265d12
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.572)[sip]   CSeq: 323 INVITE
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.573)[sip]   Contact: <sip:100@192.168.0.153:5060>
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.574)[sip]   User-Agent: Eltex smg_pa_sip smg_pa_sip-3.6.0.21
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.577)[sip]   Content-Length: 0
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.579)[sip]   
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.580)[sip]   ------------------------------------------------------------------------
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.582)[sip]nta: received 100 Trying for INVITE (323)
Dec 31 22:11:13 tau24 user.notice tau24: 2.13.1.2|(13.583)[sip]nta: 100 Trying is going to a transaction
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.586)[app:dbg]SIP: got nua_i_state : 503(Service Unavailable)
Dec 31 22:11:13 tau24 user.warn tau24: 2.13.1.2|(13.588)[app:WARN]NO SIP IN nua_i_state == 503 : Service Unavailable
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.590)[app:dbg]self_i_state(): call state 10: : : sdp_init have_oc
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.592)[app:dbg]sip: call 00020005: should not be terminated
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.594)[app:dbg]SIP: got nua_i_terminated : 503(Service Unavailable)
Dec 31 22:11:13 tau24 user.warn tau24: 2.13.1.2|(13.596)[app:WARN]NO SIP IN nua_i_terminated == 503 : Service Unavailable
Dec 31 22:11:13 tau24 user.warn tau24: 2.13.1.2|(13.598)[app:WARN]sip: event nua_i_terminated (6) not handled: 503 Service Unavailable
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.600)[app:dbg]SIP: got nua_r_set_params : 200(OK)
Dec 31 22:11:13 tau24 user.warn tau24: 2.13.1.2|(13.602)[app:WARN]NO SIP IN nua_r_set_params == 200 : OK
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.603)[app:dbg]SIP: got nua_i_state : 0(INVITE sent)
Dec 31 22:11:13 tau24 user.warn tau24: 2.13.1.2|(13.606)[app:WARN]NO SIP IN nua_i_state == 0 : INVITE sent
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.607)[app:dbg]self_i_state(): call state 2: os : local sdp : sdp_init have_oc
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.609)[app:dbg]sip: call 00020005: SDP offer sent
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.610)[app:dbg]self_create_local_media() 0: add rtpmap 8
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.612)[app:dbg]self_create_local_media() 1: add rtpmap 0
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.613)[app:dbg]self_create_local_media() 2: add rtpmap 96
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.615)[app:dbg]sip: call 00020005: media stream 0, creating proposed audio channel, local RTP 192.168.0.186:35022, rtpmaps cnt: 3
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.618)[app:dbg]SIP: got nua_r_invite : 100(Trying)
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.620)[app:dbg]sip: call 00020005: INVITE: 100 Trying
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.622)[app:dbg]Contact on answer to INVITE: sip:100@192.168.0.153:5060
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.624)[app:dbg]Setup new proxy addr for call; sip:100@192.168.0.153:5060
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.627)[app:dbg]call 00131077 got 100/Trying - set received_1xx
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.629)[app:dbg]call 0x00020005 remember remote sip contact <sip:100@192.168.0.153:5060>
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.632)[app:dbg]SIP: got nua_r_set_params : 200(OK)
Dec 31 22:11:13 tau24 user.warn tau24: 2.13.1.2|(13.633)[app:WARN]NO SIP IN nua_r_set_params == 200 : OK
Dec 31 22:11:13 tau24 user.debug tau24: 2.13.1.2|(13.635)[app:dbg]SIP: got nua_r_set_params : 200(OK)
Dec 31 22:11:13 tau24 user.warn tau24: 2.13.1.2|(13.638)[app:WARN]NO SIP IN nua_r_set_params == 200 : OK
Dec 31 22:11:14 tau24 user.notice tau24: 2.13.1.2|(14.221)[sip]recv 505 bytes from udp/[192.168.0.153]:5060 at 00:10:46.853929:
Dec 31 22:11:14 tau24 user.notice tau24: 2.13.1.2|(14.222)[sip]   ------------------------------------------------------------------------
Dec 31 22:11:14 tau24 user.notice tau24: 2.13.1.2|(14.224)[sip]   SIP/2.0 180 Ringing
Dec 31 22:11:14 tau24 user.notice tau24: 2.13.1.2|(14.226)[sip]   Via: SIP/2.0/UDP 192.168.0.186;branch=z9hG4bKverFyK6X3cy0H;received=192.168.0.186;rport=5060
Dec 31 22:11:14 tau24 user.notice tau24: 2.13.1.2|(14.228)[sip]   From: <sip:1003@192.168.0.152>;tag=Z3vgecmja84Nm
Dec 31 22:11:14 tau24 user.notice tau24: 2.13.1.2|(14.229)[sip]   To: <sip:100@192.168.0.152>;tag=375857dIr801p0D598D0t1
Dec 31 22:11:14 tau24 user.notice tau24: 2.13.1.2|(14.231)[sip]   Call-ID: 3ff5b668-70fc-122d-bb9f-a8f94b265d12
Dec 31 22:11:14 tau24 user.notice tau24: 2.13.1.2|(14.232)[sip]   CSeq: 323 INVITE
Dec 31 22:11:14 tau24 user.notice tau24: 2.13.1.2|(14.234)[sip]   Contact: <sip:100@192.168.0.153:5060>
Dec 31 22:11:14 tau24 user.notice tau24: 2.13.1.2|(14.237)[sip]   Supported: replaces
Dec 31 22:11:14 tau24 user.notice tau24: 2.13.1.2|(14.238)[sip]   Allow: INVITE, ACK, BYE, CANCEL, PRACK, REGISTER, INFO, REFER, NOTIFY, OPTIONS, UPDATE
Dec 31 22:11:14 tau24 user.notice tau24: 2.13.1.2|(14.240)[sip]   User-Agent: Eltex smg_pa_sip smg_pa_sip-3.6.0.21
Dec 31 22:11:14 tau24 user.notice tau24: 2.13.1.2|(14.241)[sip]   Content-Length: 0
Dec 31 22:11:14 tau24 user.notice tau24: 2.13.1.2|(14.243)[sip]   
Dec 31 22:11:14 tau24 user.notice tau24: 2.13.1.2|(14.244)[sip]   ------------------------------------------------------------------------
Dec 31 22:11:14 tau24 user.notice tau24: 2.13.1.2|(14.248)[sip]nta: received 180 Ringing for INVITE (323)
Dec 31 22:11:14 tau24 user.notice tau24: 2.13.1.2|(14.249)[sip]nta: 180 Ringing is going to a transaction
Dec 31 22:11:14 tau24 user.notice tau24: 2.13.1.2|(14.251)[sip]nua(0x677700): call state changed: calling -> proceeding
Dec 31 22:11:14 tau24 user.debug tau24: 2.13.1.2|(14.255)[app:dbg]SIP: got nua_r_invite : 180(Ringing)
Dec 31 22:11:14 tau24 user.debug tau24: 2.13.1.2|(14.257)[app:dbg]sip: call 00020005: INVITE: 180 Ringing
Dec 31 22:11:14 tau24 user.debug tau24: 2.13.1.2|(14.258)[app:dbg]Contact on answer to INVITE: sip:100@192.168.0.153:5060
Dec 31 22:11:14 tau24 user.debug tau24: 2.13.1.2|(14.260)[app:dbg]Setup new proxy addr for call; sip:100@192.168.0.153:5060
Dec 31 22:11:14 tau24 user.debug tau24: 2.13.1.2|(14.262)[app:dbg]call 00131077 got 180/Ringing - set received_1xx
Dec 31 22:11:14 tau24 user.debug tau24: 2.13.1.2|(14.263)[app:dbg]call 0x00020005 remember remote sip contact <sip:100@192.168.0.153:5060>
Dec 31 22:11:14 tau24 user.debug tau24: 2.13.1.2|(14.268)[app:dbg]sip: call 00020005: ringing back
Dec 31 22:11:14 tau24 user.debug tau24: 2.13.1.2|(14.270)[app:dbg]No SDP description!!!
Dec 31 22:11:14 tau24 user.debug tau24: 2.13.1.2|(14.271)[app:dbg]sip: call 00020005: 180 ringing without SDP descr
Dec 31 22:11:14 tau24 user.debug tau24: 2.13.1.2|(14.273)[app:dbg]sip -[msg_free]-> pbx
Dec 31 22:11:14 tau24 user.debug tau24: 2.13.1.2|(14.274)[app:dbg]ITC: [msg_free] -> pbx
Dec 31 22:11:14 tau24 user.debug tau24: 2.13.1.2|(14.276)[app:dbg]port 2: peer free
Dec 31 22:11:14 tau24 user.debug tau24: 2.13.1.2|(14.277)[app:dbg]Port: 2: Chan 2: current state is CREATED
Dec 31 22:11:14 tau24 user.debug tau24: 2.13.1.2|(14.279)[app:dbg]Port 2: chan: 2 check vapi queue ('free') at vapi_start_tone_chan:1833
Dec 31 22:11:14 tau24 user.debug tau24: 2.13.1.2|(14.280)[app:dbg]Port 2: chan: 2: set vapi queue MSP to 'busy' with 'start_tone' at vapi_start_tone_chan:1854
Dec 31 22:11:14 tau24 user.debug tau24: 2.13.1.2|(14.282)[app:dbg]VQ Port 2 = MSP :    'start_tone' =
Dec 31 22:11:14 tau24 user.debug tau24: 2.13.1.2|(14.284)[app:dbg]chan 2 start tone, id=23, direction=TDM
Dec 31 22:11:14 tau24 user.debug tau24: 2.13.1.2|(14.286)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''start_tone') at __cmd_engine:414
Dec 31 22:11:14 tau24 user.debug tau24: 2.13.1.2|(14.288)[app:dbg]voip_lock: set voip lock
Dec 31 22:11:14 tau24 user.debug tau24: 2.13.1.2|(14.289)[app:dbg]pbx -[msg_fxs_state]-> group
Dec 31 22:11:14 tau24 user.debug tau24: 2.13.1.2|(14.291)[app:dbg]SIP: got nua_i_state : 180(Ringing)
Dec 31 22:11:14 tau24 user.warn tau24: 2.13.1.2|(14.293)[app:WARN]NO SIP IN nua_i_state == 180 : Ringing
Dec 31 22:11:14 tau24 user.debug tau24: 2.13.1.2|(14.294)[app:dbg]self_i_state(): call state 3: : : sdp_sent have_oc
Dec 31 22:11:14 tau24 user.debug tau24: 2.13.1.2|(14.298)[app:dbg]ITC: [msg_fxs_state] -> group
Dec 31 22:11:14 tau24 user.debug tau24: 2.13.1.2|(14.299)[app:dbg]vapi_cb_req(): Conn 2 CALLBACK msg (level = 0x0; result = 0x0; req_id = 0x E20; len = 12)
Dec 31 22:11:14 tau24 user.debug tau24: 2.13.1.2|(14.304)[app:dbg]SIP: got nua_r_set_params : 200(OK)
Dec 31 22:11:14 tau24 user.debug tau24: 2.13.1.2|(14.309)[app:dbg][SG] Port 2: new state is ringback
Dec 31 22:11:14 tau24 user.debug tau24: 2.13.1.2|(14.310)[app:dbg]vapi: chan: 2 Callback request = 0x E20
Dec 31 22:11:14 tau24 user.warn tau24: 2.13.1.2|(14.312)[app:WARN]NO SIP IN nua_r_set_params == 200 : OK
Dec 31 22:11:14 tau24 user.debug tau24: 2.13.1.2|(14.317)[app:dbg]Conn 2: Start tone - Successfull
Dec 31 22:11:14 tau24 user.debug tau24: 2.13.1.2|(14.319)[app:dbg]SIP: got nua_r_set_params : 200(OK)
Dec 31 22:11:14 tau24 user.debug tau24: 2.13.1.2|(14.322)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''start_tone') at vapi_cb_chan:4384
Dec 31 22:11:14 tau24 user.warn tau24: 2.13.1.2|(14.324)[app:WARN]NO SIP IN nua_r_set_params == 200 : OK
Dec 31 22:11:14 tau24 user.debug tau24: 2.13.1.2|(14.327)[app:dbg]Port 2: chan: 2: set vapi queue MSP to 'free' with  at vapi_cb_chan:4385
Dec 31 22:11:14 tau24 user.debug tau24: 2.13.1.2|(14.329)[app:dbg]SIP: got nua_r_set_params : 200(OK)
Dec 31 22:11:14 tau24 user.debug tau24: 2.13.1.2|(14.332)[app:dbg]Port 2: chan: 2 check vapi queue ('free') at vapi_next_ops:3738
Dec 31 22:11:14 tau24 user.warn tau24: 2.13.1.2|(14.334)[app:WARN]NO SIP IN nua_r_set_params == 200 : OK
Dec 31 22:11:15 tau24 user.debug tau24: 2.13.1.2|(15.008)[app:dbg]# ROUTE: eth0. dest: 192.168.0.0, gw: 0.0.0.0, mask: 255.255.255.0
Dec 31 22:11:15 tau24 user.debug tau24: 2.13.1.2|(15.010)[app:dbg]# ROUTE: eth0. dest: 0.0.0.0, gw: 192.168.0.200, mask: 0.0.0.0
Dec 31 22:11:16 tau24 user.notice tau24: 2.13.1.2|(16.931)[sip]recv 753 bytes from udp/[192.168.0.153]:5060 at 00:10:49.563793:
Dec 31 22:11:16 tau24 user.notice tau24: 2.13.1.2|(16.932)[sip]   ------------------------------------------------------------------------
Dec 31 22:11:16 tau24 user.notice tau24: 2.13.1.2|(16.934)[sip]   SIP/2.0 200 OK
Dec 31 22:11:16 tau24 user.notice tau24: 2.13.1.2|(16.936)[sip]   Via: SIP/2.0/UDP 192.168.0.186;branch=z9hG4bKverFyK6X3cy0H;received=192.168.0.186;rport=5060
Dec 31 22:11:16 tau24 user.notice tau24: 2.13.1.2|(16.938)[sip]   From: <sip:1003@192.168.0.152>;tag=Z3vgecmja84Nm
Dec 31 22:11:16 tau24 user.notice tau24: 2.13.1.2|(16.939)[sip]   To: <sip:100@192.168.0.152>;tag=375857dIr801p0D598D0t1
Dec 31 22:11:16 tau24 user.notice tau24: 2.13.1.2|(16.941)[sip]   Call-ID: 3ff5b668-70fc-122d-bb9f-a8f94b265d12
Dec 31 22:11:16 tau24 user.notice tau24: 2.13.1.2|(16.942)[sip]   CSeq: 323 INVITE
Dec 31 22:11:16 tau24 user.notice tau24: 2.13.1.2|(16.944)[sip]   Contact: <sip:100@192.168.0.153:5060>
Dec 31 22:11:16 tau24 user.notice tau24: 2.13.1.2|(16.945)[sip]   Accept: multipart/mixed, application/sdp
Dec 31 22:11:16 tau24 user.notice tau24: 2.13.1.2|(16.948)[sip]   Supported: replaces
Dec 31 22:11:16 tau24 user.notice tau24: 2.13.1.2|(16.950)[sip]   Allow: INVITE, ACK, BYE, CANCEL, PRACK, REGISTER, INFO, REFER, NOTIFY, OPTIONS, UPDATE
Dec 31 22:11:16 tau24 user.notice tau24: 2.13.1.2|(16.951)[sip]   Content-Type: application/sdp
Dec 31 22:11:16 tau24 user.notice tau24: 2.13.1.2|(16.953)[sip]   User-Agent: Eltex smg_pa_sip smg_pa_sip-3.6.0.21
Dec 31 22:11:16 tau24 user.notice tau24: 2.13.1.2|(16.954)[sip]   Content-Length: 178
Dec 31 22:11:16 tau24 user.notice tau24: 2.13.1.2|(16.957)[sip]   
Dec 31 22:11:16 tau24 user.notice tau24: 2.13.1.2|(16.958)[sip]   v=0
Dec 31 22:11:16 tau24 user.notice tau24: 2.13.1.2|(16.960)[sip]   o=- 801 786039 IN IP4 192.168.0.153
Dec 31 22:11:16 tau24 user.notice tau24: 2.13.1.2|(16.962)[sip]   s=SMG SIP session
Dec 31 22:11:16 tau24 user.notice tau24: 2.13.1.2|(16.963)[sip]   c=IN IP4 192.168.0.153
Dec 31 22:11:16 tau24 user.notice tau24: 2.13.1.2|(16.965)[sip]   t=0 0
Dec 31 22:11:16 tau24 user.notice tau24: 2.13.1.2|(16.968)[sip]   m=audio 20000 RTP/AVP 8
Dec 31 22:11:16 tau24 user.notice tau24: 2.13.1.2|(16.969)[sip]   a=rtpmap:8 PCMA/8000
Dec 31 22:11:16 tau24 user.notice tau24: 2.13.1.2|(16.971)[sip]   a=silenceSupp:off - - - -
Dec 31 22:11:16 tau24 user.notice tau24: 2.13.1.2|(16.972)[sip]   a=sendrecv
Dec 31 22:11:16 tau24 user.notice tau24: 2.13.1.2|(16.974)[sip]   ------------------------------------------------------------------------
Dec 31 22:11:16 tau24 user.notice tau24: 2.13.1.2|(16.976)[sip]nta: received 200 OK for INVITE (323)
Dec 31 22:11:16 tau24 user.notice tau24: 2.13.1.2|(16.978)[sip]nta: 200 OK is going to a transaction
Dec 31 22:11:16 tau24 user.notice tau24: 2.13.1.2|(16.983)[sip]nua(0x677700): INVITE: processed SDP answer in 200 OK
Dec 31 22:11:16 tau24 user.debug tau24: 2.13.1.2|(16.987)[app:dbg]SIP: got nua_r_invite : 200(OK)
Dec 31 22:11:16 tau24 user.debug tau24: 2.13.1.2|(16.988)[app:dbg]sip: call 00020005: INVITE: 200 OK
Dec 31 22:11:16 tau24 user.debug tau24: 2.13.1.2|(16.990)[app:dbg]call 0x00020005 remember remote sip contact <sip:100@192.168.0.153:5060>
Dec 31 22:11:16 tau24 user.debug tau24: 2.13.1.2|(16.993)[app:dbg]attr: name: silenceSupp value: off - - - -
Dec 31 22:11:16 tau24 user.debug tau24: 2.13.1.2|(16.994)[app:dbg]sdp_codecs_set_nse() nse absent pt 0
Dec 31 22:11:16 tau24 user.notice tau24: 2.13.1.2|(16.985)[sip]nua(0x677700): call state changed: proceeding -> completing, received answer
Dec 31 22:11:16 tau24 user.debug tau24: 2.13.1.2|(16.998)[app:dbg]sip: call 00020005: current status (200)
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.004)[app:dbg]SIP: got nua_i_state : 200(OK)
Dec 31 22:11:17 tau24 user.warn tau24: 2.13.1.2|(17.074)[app:WARN]NO SIP IN nua_i_state == 200 : OK
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.077)[app:dbg]self_i_state(): call state 4: ar : remote sdp : sdp_sent have_oc
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.078)[app:dbg]sip: call 00020005: calltype 1, mode_codec 0, codec 0
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.080)[app:dbg]sip: call 00020005: SDP answer received
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.082)[app:dbg]self_destroy_current_media() nothing to destroy
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.084)[app:dbg]No telephone-event in remote sdp - switch off in local
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.087)[app:dbg]fmtp_parse() fmtp (nil), mask 0x69f240
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.089)[app:dbg]sdp_codecs_set_rfc2833() have only flash rfc2833 events
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.090)[app:dbg]sdp_codecs_set_rfc2833() absent pt 0 remote fmtp , local fmtp 16 profile 0
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.092)[app:dbg]sip: set options: call 00020005: media stream 0: 192.168.0.186:35022 -> 192.168.0.153:20000: MFPT 0 <drop>
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.094)[app:dbg]sip_set_rxtx_opts(): check rtpm <PCMA>:8
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.096)[app:dbg]sip_set_rxtx_opts(): check offered 0: 8
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.098)[app:dbg]self_itc_codec(): payload 8
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.100)[app:dbg]Supported codec[0]: <G.711A>:8, vbd off, vad off, ecan on
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.102)[app:dbg]self_start_media() 0: add rtpmap 8
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.104)[app:dbg]self_start_media(): call 0x00020005 (ep 2): (nil), 0x4dab80
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.106)[app:dbg]call 0x00020005 (ep 2): remote 0, mode sendrecv :: TX start, RX start, cnt 1 (self_start_media)
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.108)[app:dbg]sip -[msg_set_media]-> pbx
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.110)[app:dbg]ITC: [msg_set_media] -> pbx
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.112)[app:dbg]Port 2: set media TX start / RX start, call 0x00020005
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.113)[app:dbg]192.168.0.186:35022->192.168.0.153:20000, <G.711A:8>
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.114)[app:dbg]vad 0 g723_hr 1 vbd 0, ecan 1 rfc2833 pt -1, NSE pt 0, MFPT 0, <drop>
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.116)[app:dbg]dump_port_calls() port 2:
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.117)[app:dbg]Q:(0x689000,0x00020005,(nil))
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.119)[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) C:((nil),0x00000000,(nil))
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.120)[app:dbg]Calltype: active, modem 0, fax 0
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.122)[app:dbg]a8:f9:4b:26:5d:12,(BA00A8C0):0-00:00:00:00:00:00,(0):0
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.123)[app:dbg]DTMF 0(pt 0), rfc2833 pt (96/cur 0) nse pt 0 MFPT 0
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.125)[app:dbg]Port 2: <start> media
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.126)[app:dbg]port 2: starting media (G.711A) 192.168.0.186:35022 -> 192.168.0.153:20000
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.128)[app:dbg]validate_ptime() codec G.711A, ptime 0
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.129)[app:dbg]validate_ptime() using config 20
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.130)[app:dbg]self_on_set_media(): set ptime to 20
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.132)[app:dbg]Calltype: active, modem 0, fax 0
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.133)[app:dbg]a8:f9:4b:26:5d:12,192.168.0.186(BA00A8C0):35022-00:00:00:00:00:00,192.168.0.153(0):20000
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.135)[app:dbg]DTMF 0(pt 0), rfc2833 pt (96/cur -1) nse pt 0 MFPT 0
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.136)[app:dbg]AUD[0]: codec G.711A (pt 8,pte 20), VBD 0/dnlp 0/ddc 0, VAD 0, CNG 0, ECAN 1
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.138)[app:dbg]Port 2: vpl are:
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.139)[app:dbg]<state>: cur/next: 0x666000/(nil)
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.141)[app:dbg]port_state_voice() can`t find pair media
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.142)[app:dbg]port 2: start voice (TX start / RX start) - first time (drop mode)
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.143)[app:dbg]resolve_ip() chan 02: remote IP <192.168.0.153> (arp query 0 times)
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.145)[app:dbg]arp: mac lookup for ip 192.168.0.153, iface: eth0
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.147)[app:dbg]# ROUTE: eth0. dest: 192.168.0.0, gw: 0.0.0.0, mask: 255.255.255.0
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.149)[app:dbg]# ROUTE: eth0. dest: 0.0.0.0, gw: 192.168.0.200, mask: 0.0.0.0
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.150)[app:dbg]arp: <192.168.0.153> is local network
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.152)[app:dbg]arp: eth0: arp request 192.168.0.153 - mac a8:f9:4b:8a:63:5f
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.154)[app:dbg]chan 2: get mac succesfull, repeat 0 times
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.155)[app:dbg]Port: 2: Chan 2: current state is CREATED
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.157)[app:dbg]Port 2: chan: 2 check vapi queue ('free') at vapi_state_chan:2791
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.158)[app:dbg]Port 2: chan: 2: set vapi queue MSP to 'busy' with 'set state' at vapi_state_chan:2831
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.160)[app:dbg]VQ Port 2 = MSP :     'set state' =
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.161)[app:dbg]vapi_state_chan() can`t find pair media
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.163)[app:dbg]Port 2: vpl are:
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.164)[app:dbg]<state>: cur/next: 0x666000/(nil)
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.166)[app:dbg]Port 2: vpl is empty
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.167)[app:dbg]vapi: set voice: TDM 2, TX start, RX start, drop mode 
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.168)[app:dbg]vapi: Conn 2. Configure and start voice (drop RTCP)
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.170)[app:dbg]vapi: Conn 2, Set PTE=30 (temporary before set codec)
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.171)[app:dbg]vapi: Conn 2. Set VAD mode to 0
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.173)[app:dbg]Conn 2 Eth src=a8:f9:4b:26:5d:12, dst=a8:f9:4b:8a:63:5f
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.174)[app:dbg]Conn 2 IP src=192.168.0.186:35022, dst=192.168.0.153:20000
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.176)[app:dbg]vapi: Conn 2. to TmdActive - Ok
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.178)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''set state') at __cmd_engine:414
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.179)[app:dbg]show_dump():
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.181)[app:dbg]queue_size():
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.183)[app:dbg]sorm_process(): queue is empty
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.186)[app:dbg]vapi_cb_req(): Conn 2 CALLBACK msg (level = 0x0; result = 0x0; req_id = 0x A02; len = 0)
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.188)[app:dbg]vapi: chan: 2 Callback request = 0x A02
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.190)[app:dbg]vapi: Conn 2. VAPI_SetPayloadType_Buf TX pt to 8
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.191)[app:dbg]vapi: Conn 2. VAPI_SetPayloadType_Buf RX pt to 8
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.193)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''set state') at vapi_cb_chan:4378
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.202)[app:dbg]vapi_cb_req(): Conn 2 CALLBACK msg (level = 0x0; result = 0x0; req_id = 0x A62; len = 24)
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.204)[app:dbg]vapi: chan: 2 Callback request = 0x A62
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.206)[app:dbg]vapi: Conn 2. Prof 0. Set silence detector
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.208)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''set state') at vapi_cb_chan:4378
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.210)[app:dbg]vapi_cb_req(): Conn 2 CALLBACK msg (level = 0x0; result = 0x0; req_id = 0x A0E; len = 12)
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.212)[app:dbg]vapi: chan: 2 Callback request = 0x A0E
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.214)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''set state') at vapi_cb_chan:4378
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.218)[app:dbg]sip: call 00020005: call answered
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.220)[app:dbg]sip -[msg_answer]-> pbx
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.222)[app:dbg]ITC: [msg_answer] -> pbx
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.223)[app:dbg]port 2: peer answered
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.225)[app:dbg]Port: 2: Chan 2: current state is CREATED
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.226)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''set state') at vapi_stop_tone_chan:1967
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.228)[app:dbg]Port 2 chan 2 put cmd 'stop_tone',cur 'set state' to queue at (vapi_stop_tone_chan:1972)
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.229)[app:dbg]VQ Port 2 = MSP :     'set state' =
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.231)[app:dbg]VQ Port 2 + 02  :     'stop_tone'/         <none> + <-get_ptr 
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.232)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''set state') at __cmd_engine:414
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.234)[app:dbg]voip_lock: set voip lock
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.236)[app:dbg]pbx -[msg_fxs_state]-> group
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.238)[app:dbg]ITC: [msg_fxs_state] -> group
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.239)[app:dbg][SG] Port 2: new state is talking
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.243)[app:dbg]sip: call 00020005: ACK to sip:100@192.168.0.152
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.251)[app:dbg]SIP: got nua_r_set_params : 200(OK)
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.251)[app:dbg]vapi_cb_req(): Conn 2 CALLBACK msg (level = 0x0; result = 0x0; req_id = 0x A33; len = 0)
Dec 31 22:11:17 tau24 user.notice tau24: 2.13.1.2|(17.257)[sip]send 353 bytes to udp/[192.168.0.153]:5060 at 00:10:49.891743:
Dec 31 22:11:17 tau24 user.warn tau24: 2.13.1.2|(17.259)[app:WARN]NO SIP IN nua_r_set_params == 200 : OK
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.263)[app:dbg]vapi: chan: 2 Callback request = 0x A33
Dec 31 22:11:17 tau24 user.notice tau24: 2.13.1.2|(17.265)[sip]   ------------------------------------------------------------------------
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.268)[app:dbg]SIP: got nua_r_set_params : 200(OK)
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.271)[app:dbg]Conn 2 Eth src=a8:f9:4b:26:5d:12, dst=a8:f9:4b:8a:63:5f
Dec 31 22:11:17 tau24 user.notice tau24: 2.13.1.2|(17.273)[sip]   ACK sip:100@192.168.0.153:5060 SIP/2.0
Dec 31 22:11:17 tau24 user.warn tau24: 2.13.1.2|(17.275)[app:WARN]NO SIP IN nua_r_set_params == 200 : OK
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.278)[app:dbg]Conn 2 IP src=192.168.0.186:35022, dst=192.168.0.153:20000
Dec 31 22:11:17 tau24 user.notice tau24: 2.13.1.2|(17.281)[sip]   Via: SIP/2.0/UDP 192.168.0.186;rport;branch=z9hG4bKXQH8ZeQ10NmKD
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.285)[app:dbg]vapi: Conn 2. RTP through base iface
Dec 31 22:11:17 tau24 user.notice tau24: 2.13.1.2|(17.287)[sip]   Max-Forwards: 70
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.290)[app:dbg]vapi: Conn 2. Set no-VLAN connection
Dec 31 22:11:17 tau24 user.notice tau24: 2.13.1.2|(17.292)[sip]   From: <sip:1003@192.168.0.152>;tag=Z3vgecmja84Nm
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.296)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''set state') at vapi_cb_chan:4378
Dec 31 22:11:17 tau24 user.notice tau24: 2.13.1.2|(17.297)[sip]   To: <sip:100@192.168.0.152>;tag=375857dIr801p0D598D0t1
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.299)[app:dbg]vapi_cb_req(): Conn 2 CALLBACK msg (level = 0x0; result = 0x0; req_id = 0x A08; len = 12)
Dec 31 22:11:17 tau24 user.notice tau24: 2.13.1.2|(17.304)[sip]   Call-ID: 3ff5b668-70fc-122d-bb9f-a8f94b265d12
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.306)[app:dbg]vapi: chan: 2 Callback request = 0x A08
Dec 31 22:11:17 tau24 user.notice tau24: 2.13.1.2|(17.311)[sip]   CSeq: 323 ACK
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.311)[app:dbg]vapi: Conn 2. Set RTP IP params
Dec 31 22:11:17 tau24 user.notice tau24: 2.13.1.2|(17.316)[sip]   Contact: <sip:1003@192.168.0.186:5060>
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.316)[app:dbg]SRC address: 192.168.0.186:35022
Dec 31 22:11:17 tau24 user.notice tau24: 2.13.1.2|(17.321)[sip]   Content-Length: 0
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.321)[app:dbg]DST address: 192.168.0.153:20000
Dec 31 22:11:17 tau24 user.notice tau24: 2.13.1.2|(17.326)[sip]   
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.327)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''set state') at vapi_cb_chan:4378
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.328)[app:dbg]vapi_cb_req(): Conn 2 CALLBACK msg (level = 0x0; result = 0x0; req_id = 0x A09; len = 0)
Dec 31 22:11:17 tau24 user.notice tau24: 2.13.1.2|(17.333)[sip]   ------------------------------------------------------------------------
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.335)[app:dbg]vapi: chan: 2 Callback request = 0x A09
Dec 31 22:11:17 tau24 user.notice tau24: 2.13.1.2|(17.339)[sip]nta: sent ACK (323) to */192.168.0.153:5060
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.340)[app:dbg]Set TELEPHONE EVENT PT=-1, RFC=96
Dec 31 22:11:17 tau24 user.notice tau24: 2.13.1.2|(17.344)[sip]nua(0x677700): call state changed: completing -> ready
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.345)[app:dbg]vapi: Conn 2. Set DTMF PT as RFC: m_PT = 96
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.350)[app:dbg]SIP: got nua_i_state : 200(ACK sent)
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.351)[app:dbg]vapi: Conn 2. Set DTMF mode (0)
Dec 31 22:11:17 tau24 user.warn tau24: 2.13.1.2|(17.354)[app:WARN]NO SIP IN nua_i_state == 200 : ACK sent
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.355)[app:dbg]vapi: Conn 2. Set DTMF: arg1 0x 125 pt 0x60FF
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.360)[app:dbg]self_i_state(): call state 8: : : sdp_init have_oc
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.360)[app:dbg]vapi: Conn 2. VAPI_SetPayloadType_Buf DTMF TX pt to 96
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.364)[app:dbg]sip: call 00020005: ACK from sip:1003@192.168.0.152
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.365)[app:dbg]vapi: Conn 2. Set DTMF override (1)
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.369)[app:dbg]SIP: got nua_i_active : 200(Call active)
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.370)[app:dbg]vapi: Conn 2. VAPI_SetPayloadType_Buf RX pt to 96
Dec 31 22:11:17 tau24 user.warn tau24: 2.13.1.2|(17.374)[app:WARN]NO SIP IN nua_i_active == 200 : Call active
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.376)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''set state') at vapi_cb_chan:4378
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.379)[app:dbg]vapi_cb_req(): Conn 2 CALLBACK msg (level = 0x0; result = 0x0; req_id = 0x A12; len = 36)
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.386)[app:dbg]vapi: chan: 2 Callback request = 0x A12
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.388)[app:dbg]vapi: Conn 2. Set tone params
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.390)[app:dbg]vapi: Conn 2, Set PTE=20
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.392)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''set state') at vapi_cb_chan:4378
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.394)[app:dbg]vapi_cb_req(): Conn 2 CALLBACK msg (level = 0x0; result = 0x0; req_id = 0x A18; len = 48)
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.398)[app:dbg]vapi: chan: 2 Callback request = 0x A18
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.400)[app:dbg]Conn 2. Switch to Voice: Disable verify src udp
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.402)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''set state') at vapi_cb_chan:4378
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.404)[app:dbg]vapi_cb_req(): Conn 2 CALLBACK msg (level = 0x0; result = 0x0; req_id = 0x A0A; len = 12)
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.407)[app:dbg]vapi: chan: 2 Callback request = 0x A0A
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.408)[app:dbg]chan 2: set jitter buffer options, MFPT 0x00
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.410)[app:dbg]Conn 2: Prof 0: JB Set mftp: codec PT, vbd VO || MFPT(p) VO
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.411)[app:dbg]Conn 2, JB it not MFPT, set delay to [0;200]ms, mode soft th 500
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.412)[app:dbg]Conn 2, JB COMMAND: 0014 0200 8090 0000 0000 00C8 0000 2710 0008 01F4
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.415)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''set state') at vapi_cb_chan:4378
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.417)[app:dbg]vapi_cb_req(): Conn 2 CALLBACK msg (level = 0x0; result = 0x0; req_id = 0x A15; len = 12)
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.419)[app:dbg]vapi: chan: 2 Callback request = 0x A15
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.420)[app:dbg]vapi_passthru_echocan_cb() NLP enabled, DC enabled, session 0, on 1, value 0x800F
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.422)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''set state') at vapi_cb_chan:4378
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.425)[app:dbg]vapi_cb_req(): Conn 2 CALLBACK msg (level = 0x0; result = 0x0; req_id = 0x A16; len = 12)
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.429)[app:dbg]vapi: chan: 2 Callback request = 0x A16
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.430)[app:dbg]vapi_cb_setchan:3371> 0 0 0
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.432)[app:dbg]Conn 2: Start voice
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.433)[app:dbg]Conn 2: voice TX start, RX start
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.435)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''set state') at vapi_cb_chan:4378
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.438)[app:dbg]vapi_cb_req(): Conn 2 CALLBACK msg (level = 0x0; result = 0x0; req_id = 0x A17; len = 0)
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.439)[app:dbg]vapi: chan: 2 Callback request = 0x A17
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.441)[app:dbg]vapi_cb_setchan() Conn 2: Configure (drop RTCP mode) + start voice done
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.443)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''set state') at vapi_cb_chan:4384
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.444)[app:dbg]Port 2: chan: 2: set vapi queue MSP to 'free' with  at vapi_cb_chan:4385
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.446)[app:dbg]VQ Port 2 + 02  :     'stop_tone'/         <none> + <-get_ptr 
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.447)[app:dbg]Port 2: chan: 2 check vapi queue ('free') at vapi_next_ops:3738
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.449)[app:dbg]Port 2 get cmd 'stop_tone' from queue at (vapi_next_ops:3755)
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.450)[app:dbg]Port: 2: Chan 2: current state is CREATED
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.451)[app:dbg]Port 2: chan: 2 check vapi queue ('free') at vapi_stop_tone_chan:1967
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.453)[app:dbg]Port 2: chan: 2: set vapi queue MSP to 'busy' with 'stop_tone' at vapi_stop_tone_chan:1988
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.454)[app:dbg]VQ Port 2 = MSP :     'stop_tone' =
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.456)[app:dbg]chan 2 stop tone
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.458)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''stop_tone') at vapi_next_ops:3883
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.459)[app:dbg]Chan 02: voice configured/+started processing
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.462)[app:dbg]vapi: Conn 2. event 'RTP Monitor Ind': Start RTP stream , PT 0x0008 'PCM-A', silence 0
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.464)[app:dbg]Conn 2. Event 'SSRC Change': 0x7bc8504c
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.467)[app:dbg]vapi_cb_req(): Conn 2 CALLBACK msg (level = 0x0; result = 0x0; req_id = 0x E21; len = 0)
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.468)[app:dbg]vapi: chan: 2 Callback request = 0x E21
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.470)[app:dbg]Conn 2: Stop tone - Successfull
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.471)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''stop_tone') at vapi_cb_chan:4384
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.473)[app:dbg]Port 2: chan: 2: set vapi queue MSP to 'free' with  at vapi_cb_chan:4385
Dec 31 22:11:17 tau24 user.debug tau24: 2.13.1.2|(17.474)[app:dbg]Port 2: chan: 2 check vapi queue ('free') at vapi_next_ops:3738
Dec 31 22:11:20 tau24 user.notice tau24: 2.13.1.2|(20.945)[sip]nta: timer D fired, terminate INVITE (308)
Dec 31 22:11:20 tau24 user.notice tau24: 2.13.1.2|(20.948)[sip]nta_outgoing_timer: 0/0 resent, 0/1 tout, 1/4 term, 1/5 free
Dec 31 22:11:21 tau24 user.notice tau24: 2.13.1.2|(21.515)[sip]recv 571 bytes from udp/[192.168.0.153]:5060 at 00:10:54.147844:
Dec 31 22:11:21 tau24 user.notice tau24: 2.13.1.2|(21.517)[sip]   ------------------------------------------------------------------------
Dec 31 22:11:21 tau24 user.notice tau24: 2.13.1.2|(21.518)[sip]   BYE sip:1003@192.168.0.186:5060 SIP/2.0
Dec 31 22:11:21 tau24 user.notice tau24: 2.13.1.2|(21.520)[sip]   Via: SIP/2.0/UDP 192.168.0.153:5060;rport;branch=z9hG4bK-oS1c-370700-801
Dec 31 22:11:21 tau24 user.notice tau24: 2.13.1.2|(21.521)[sip]   From: <sip:100@192.168.0.152>;tag=375857dIr801p0D598D0t1
Dec 31 22:11:21 tau24 user.notice tau24: 2.13.1.2|(21.523)[sip]   To: <sip:1003@192.168.0.152>;tag=Z3vgecmja84Nm
Dec 31 22:11:21 tau24 user.notice tau24: 2.13.1.2|(21.524)[sip]   Call-ID: 3ff5b668-70fc-122d-bb9f-a8f94b265d12
Dec 31 22:11:21 tau24 user.notice tau24: 2.13.1.2|(21.526)[sip]   CSeq: 3 BYE
Dec 31 22:11:21 tau24 user.notice tau24: 2.13.1.2|(21.528)[sip]   User-Agent: Eltex smg_pa_sip smg_pa_sip-3.6.0.21
Dec 31 22:11:21 tau24 user.notice tau24: 2.13.1.2|(21.530)[sip]   Max-Forwards: 70
Dec 31 22:11:21 tau24 user.notice tau24: 2.13.1.2|(21.531)[sip]   Contact: <sip:100@192.168.0.153:5060>
Dec 31 22:11:21 tau24 user.notice tau24: 2.13.1.2|(21.533)[sip]   Allow: INVITE, ACK, BYE, CANCEL, PRACK, REGISTER, INFO, REFER, NOTIFY, OPTIONS, UPDATE
Dec 31 22:11:21 tau24 user.notice tau24: 2.13.1.2|(21.534)[sip]   Supported: replaces
Dec 31 22:11:21 tau24 user.notice tau24: 2.13.1.2|(21.536)[sip]   Reason: Q.850;cause=16;text="Normal call clearing" 
Dec 31 22:11:21 tau24 user.notice tau24: 2.13.1.2|(21.538)[sip]   Content-Length: 0
Dec 31 22:11:21 tau24 user.notice tau24: 2.13.1.2|(21.539)[sip]   
Dec 31 22:11:21 tau24 user.notice tau24: 2.13.1.2|(21.541)[sip]   ------------------------------------------------------------------------
Dec 31 22:11:21 tau24 user.notice tau24: 2.13.1.2|(21.542)[sip]nta: received BYE sip:1003@192.168.0.186:5060 SIP/2.0 (CSeq 3)
Dec 31 22:11:21 tau24 user.notice tau24: 2.13.1.2|(21.544)[sip]nta: BYE (3) going to existing leg
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.548)[app:dbg]SIP: got nua_i_bye : 100(Trying)
Dec 31 22:11:21 tau24 user.notice tau24: 2.13.1.2|(21.552)[sip]send 469 bytes to udp/[192.168.0.153]:5060 at 00:10:54.187007:
Dec 31 22:11:21 tau24 user.notice tau24: 2.13.1.2|(21.554)[sip]   ------------------------------------------------------------------------
Dec 31 22:11:21 tau24 user.notice tau24: 2.13.1.2|(21.556)[sip]   SIP/2.0 200 OK
Dec 31 22:11:21 tau24 user.notice tau24: 2.13.1.2|(21.558)[sip]   Via: SIP/2.0/UDP 192.168.0.153:5060;rport=5060;branch=z9hG4bK-oS1c-370700-801
Dec 31 22:11:21 tau24 user.notice tau24: 2.13.1.2|(21.559)[sip]   From: <sip:100@192.168.0.152>;tag=375857dIr801p0D598D0t1
Dec 31 22:11:21 tau24 user.notice tau24: 2.13.1.2|(21.561)[sip]   To: <sip:1003@192.168.0.152>;tag=Z3vgecmja84Nm
Dec 31 22:11:21 tau24 user.notice tau24: 2.13.1.2|(21.562)[sip]   Call-ID: 3ff5b668-70fc-122d-bb9f-a8f94b265d12
Dec 31 22:11:21 tau24 user.notice tau24: 2.13.1.2|(21.564)[sip]   CSeq: 3 BYE
Dec 31 22:11:21 tau24 user.notice tau24: 2.13.1.2|(21.565)[sip]   User-Agent: TAU-72 build 2.13.1.2 sofia-sip/1.12.10
Dec 31 22:11:21 tau24 user.notice tau24: 2.13.1.2|(21.568)[sip]   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, INFO
Dec 31 22:11:21 tau24 user.notice tau24: 2.13.1.2|(21.569)[sip]   Supported: timer, 100rel, replaces
Dec 31 22:11:21 tau24 user.notice tau24: 2.13.1.2|(21.571)[sip]   Content-Length: 0
Dec 31 22:11:21 tau24 user.notice tau24: 2.13.1.2|(21.572)[sip]   
Dec 31 22:11:21 tau24 user.notice tau24: 2.13.1.2|(21.574)[sip]   ------------------------------------------------------------------------
Dec 31 22:11:21 tau24 user.notice tau24: 2.13.1.2|(21.575)[sip]nta: sent 200 OK for BYE (3)
Dec 31 22:11:21 tau24 user.notice tau24: 2.13.1.2|(21.577)[sip]nua(0x677700): removing session usage
Dec 31 22:11:21 tau24 user.notice tau24: 2.13.1.2|(21.579)[sip]nua(0x677700): call state changed: ready -> terminated
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.581)[app:dbg]SIP: got nua_i_state : 200(Session Terminated)
Dec 31 22:11:21 tau24 user.warn tau24: 2.13.1.2|(21.582)[app:WARN]NO SIP IN nua_i_state == 200 : Session Terminated
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.584)[app:dbg]self_i_state(): call state 10: : : sdp_init have_oc
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.586)[app:dbg]sip: call 00020005: terminated flag 0x49
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.587)[app:dbg]7586: endpoint 2 set to busy
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.589)[app:dbg]sip -[msg_clear]-> pbx
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.590)[app:dbg]ITC: [msg_clear] -> pbx
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.592)[app:dbg]dump_port_calls() port 2:
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.593)[app:dbg]Q:(0x689000,0x00020005,(nil))
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.595)[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) C:((nil),0x00000000,(nil))
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.596)[app:dbg]port 2: peer cleared(00020005)
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.598)[app:dbg]port 2: current call cleared
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.599)[app:dbg]port 2: -> busy - no hold call, no wait call
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.601)[app:dbg]Port: 2: Chan 2: current state is CREATED
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.602)[app:dbg]Port 2: chan: 2 check vapi queue ('free') at vapi_stop_fax:3200
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.603)[app:dbg]vapi_stop_fax() port 2: no fax started - nothing to do there - exiting
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.605)[app:dbg]Port 2: chan: 2 check vapi queue ('free') at __cmd_engine:396
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.607)[app:dbg]Port 2: chan: 2 check vapi queue ('free') at vapi_next_ops:3738
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.608)[app:dbg]Port: 2: Chan 2: current state is CREATED
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.610)[app:dbg]Port 2: chan: 2 check vapi queue ('free') at vapi_start_tone_chan:1833
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.611)[app:dbg]Port 2: chan: 2: set vapi queue MSP to 'busy' with 'start_tone' at vapi_start_tone_chan:1854
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.613)[app:dbg]VQ Port 2 = MSP :    'start_tone' =
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.615)[app:dbg]chan 2 start tone, id=22, direction=TDM
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.617)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''start_tone') at __cmd_engine:414
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.618)[app:dbg]voip_lock: set voip lock
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.620)[app:dbg]pbx -[msg_fxs_state]-> group
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.622)[app:dbg]port 2: reset call 0x00020005 (active)
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.623)[app:dbg]Port 2: vpl are:
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.625)[app:dbg]<state>: cur/next: 0x666000/(nil)
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.627)[app:dbg]port_state_voice() can`t find pair media
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.628)[app:dbg]Port: 2: Chan 2: current state is CREATED
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.630)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''start_tone') at vapi_state_chan:2791
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.631)[app:dbg]Port 2 chan 2 put cmd 'set state',cur 'start_tone' to queue at (vapi_state_chan:2796)
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.633)[app:dbg]VQ Port 2 = MSP :    'start_tone' =
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.634)[app:dbg]VQ Port 2 + 03  :     'set state'/tx<stop>,rx<stop>,drop + <-get_ptr 
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.636)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''start_tone') at __cmd_engine:414
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.637)[app:dbg]remove_call_from_global:324 - enter
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.639)[app:dbg]dump_port_calls() port 2:
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.640)[app:dbg]Q:NONE
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.642)[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) C:((nil),0x00000000,(nil))
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.643)[app:dbg]HIO: port 2 <Talk/busy> msg <State><16>
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.645)[app:dbg]self_callstate_terminated: call id = 00020005 need_exchange_at_answer = 0
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.646)[app:dbg]ITC: [msg_fxs_state] -> group
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.660)[app:dbg]vapi_cb_req(): Conn 2 CALLBACK msg (level = 0x0; result = 0x0; req_id = 0x E20; len = 12)
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.665)[app:dbg]sip: call 00020005: destroy
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.668)[app:dbg][SG] Port 2: new state is busy
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.671)[app:dbg]vapi: chan: 2 Callback request = 0x E20
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.680)[app:dbg]Conn 2: Start tone - Successfull
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.681)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''start_tone') at vapi_cb_chan:4384
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.682)[app:dbg]Port 2: chan: 2: set vapi queue MSP to 'free' with  at vapi_cb_chan:4385
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.684)[app:dbg]VQ Port 2 + 03  :     'set state'/tx<stop>,rx<stop>,drop + <-get_ptr 
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.685)[app:dbg]Port 2: chan: 2 check vapi queue ('free') at vapi_next_ops:3738
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.687)[app:dbg]Port 2 get cmd 'set state' from queue at (vapi_next_ops:3755)
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.688)[app:dbg]Port: 2: Chan 2: current state is CREATED
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.690)[app:dbg]Port 2: chan: 2 check vapi queue ('free') at vapi_state_chan:2791
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.691)[app:dbg]Port 2: chan: 2: set vapi queue MSP to 'busy' with 'set state' at vapi_state_chan:2831
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.693)[app:dbg]VQ Port 2 = MSP :     'set state' =
Dec 31 22:11:21 tau24 user.warn tau24: 2.13.1.2|(21.694)[app:WARN]vapi_state_chan() can`t find operating media!
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.695)[app:dbg]vapi_state_chan() can`t find pair media
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.697)[app:dbg]Port 2: vpl are:
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.698)[app:dbg]<state>: cur/next: 0x666000/(nil)
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.700)[app:dbg]Port 2: vpl is empty
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.701)[app:dbg]vapi: set voice: TDM 2, TX stop, RX stop, drop mode 
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.703)[app:dbg]vapi: state chan: get TDM 2 IP/UDP header
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.705)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''set state') at vapi_next_ops:3883
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.708)[app:dbg]vapi_cb_req(): Conn 2 CALLBACK msg (level = 0x0; result = 0x0; req_id = 0x 257; len = 40)
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.709)[app:dbg]vapi: chan: 2 Callback request = 0x 257
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.711)[app:dbg]Media: 192.168.0.186:35022 -> 192.168.0.153:20000
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.712)[app:dbg]buff : 192.168.0.186:35022 -> 192.168.0.153:20000
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.714)[app:dbg]Media: 192.168.0.186:35022 -> 192.168.0.153:20000
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.715)[app:dbg]IPo1 : 0.0.0.0:0 -> 0.0.0.0:0
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.717)[app:dbg]Media: 192.168.0.186:35022 -> 192.168.0.153:20000
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.718)[app:dbg]IPo2 : 0.0.0.0:0 -> 0.0.0.0:0
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.719)[app:dbg]vapi: state chan: TDM 2 reset and turn off RTCP timer
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.721)[app:dbg]vapi: state chan: TDM 2 Disable RTCP
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.722)[app:dbg]chan 2. RTCP disabled(0000)
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.724)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''set state') at vapi_cb_chan:4378
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.727)[app:dbg]vapi_cb_req(): Conn 2 CALLBACK msg (level = 0x0; result = 0x0; req_id = 0x 22B; len = 12)
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.729)[app:dbg]vapi: chan: 2 Callback request = 0x 22B
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.730)[app:dbg]vapi: state chan: TDM 2 set RX
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.732)[app:dbg]vapi: state chan: TDM 2 set TX
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.734)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''set state') at vapi_cb_chan:4378
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.737)[app:dbg]vapi_cb_req(): Conn 2 CALLBACK msg (level = 0x0; result = 0x0; req_id = 0x 256; len = 0)
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.738)[app:dbg]vapi: chan: 2 Callback request = 0x 256
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.740)[app:dbg]vapi: state chan: Done
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.741)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''set state') at vapi_cb_chan:4384
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.743)[app:dbg]Port 2: chan: 2: set vapi queue MSP to 'free' with  at vapi_cb_chan:4385
Dec 31 22:11:21 tau24 user.debug tau24: 2.13.1.2|(21.744)[app:dbg]Port 2: chan: 2 check vapi queue ('free') at vapi_next_ops:3738
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.228)[app:dbg]HIO: port 2 <Talk/busy> msg <Pre Onhook><2>
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.229)[app:dbg]HIO: preonhook TDM port '2', port enabled 1
Dec 31 22:11:22 tau24 user.notice tau24: 2.13.1.2|(22.345)[sip]nta: timer F fired, terminating ACK (323)
Dec 31 22:11:22 tau24 user.notice tau24: 2.13.1.2|(22.347)[sip]nta_outgoing_timer: 0/0 resent, 1/1 tout, 0/3 term, 1/4 free
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.507)[app:dbg]vapi: Conn 2. event 'RTP Monitor Ind': Stop RTP stream , PT 0x0008 'PCM-A', silence 0
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.826)[app:dbg]HIO: port 2 <Talk/busy> msg <Onhook><1>
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.828)[app:dbg]HIO: onhook TDM port '2', port enabled 1
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.829)[app:dbg]port 2: onhook state: busy
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.830)[app:dbg]regex ID 2: dial reset
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.832)[app:dbg]Port: 2: Chan 2: current state is CREATED
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.834)[app:dbg]Port 2: chan: 2 check vapi queue ('free') at vapi_stop_tone_chan:1967
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.835)[app:dbg]Port 2: chan: 2: set vapi queue MSP to 'busy' with 'stop_tone' at vapi_stop_tone_chan:1988
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.837)[app:dbg]VQ Port 2 = MSP :     'stop_tone' =
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.839)[app:dbg]chan 2 stop tone
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.840)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''stop_tone') at __cmd_engine:414
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.842)[app:dbg]port 2: reset
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.843)[app:dbg]dump_port_calls() port 2:
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.844)[app:dbg]Q:NONE
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.846)[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) C:((nil),0x00000000,(nil))
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.848)[app:dbg]Port: 2: Chan 2: current state is CREATED
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.849)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''stop_tone') at vapi_destroy_chan:1482
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.850)[app:dbg]Clear vapi queue of Port 2
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.852)[app:dbg]Port 2: clear VPL
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.853)[app:dbg]Port 2: vpl is empty
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.855)[app:dbg]Port 2: vpl is empty
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.857)[app:dbg]Port 2 chan 2 put cmd 'destroy',cur 'stop_tone' to queue at (vapi_destroy_chan:1490)
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.858)[app:dbg]VQ Port 2 = MSP :     'stop_tone' =
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.859)[app:dbg]VQ Port 2 + 00  :       'destroy'/         <none> + <-get_ptr 
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.861)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''stop_tone') at __cmd_engine:414
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.863)[app:dbg]voip_lock: remove voip lock
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.864)[app:dbg]pbx -[msg_fxs_state]-> group
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.866)[app:dbg]dump_port_calls() port 2:
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.867)[app:dbg]Q:NONE
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.869)[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) C:((nil),0x00000000,(nil))
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.870)[app:dbg]HIO: port 2 <Talk/hangup> msg <State><16>
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.872)[app:dbg]Port: 2:  Talk -> ReadyAfterInit (No errors)
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.876)[app:dbg]ITC: [msg_fxs_state] -> group
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.878)[app:dbg][SG] Port 2: new state is hangup
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.880)[app:dbg]vapi_cb_req(): Conn 2 CALLBACK msg (level = 0x0; result = 0x0; req_id = 0x E21; len = 0)
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.881)[app:dbg]vapi: chan: 2 Callback request = 0x E21
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.883)[app:dbg]Conn 2: Stop tone - Successfull
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.884)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''stop_tone') at vapi_cb_chan:4384
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.886)[app:dbg]Port 2: chan: 2: set vapi queue MSP to 'free' with  at vapi_cb_chan:4385
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.887)[app:dbg]VQ Port 2 + 00  :       'destroy'/         <none> + <-get_ptr 
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.889)[app:dbg]Port 2: chan: 2 check vapi queue ('free') at vapi_next_ops:3738
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.890)[app:dbg]Port 2 get cmd 'destroy' from queue at (vapi_next_ops:3755)
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.892)[app:dbg]Port: 2: Chan 2: current state is CREATED
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.893)[app:dbg]Port 2: chan: 2 check vapi queue ('free') at vapi_destroy_chan:1482
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.894)[app:dbg]Port 2: chan: 2: set vapi queue MSP to 'busy' with 'destroy' at vapi_destroy_chan:1505
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.896)[app:dbg]VQ Port 2 = MSP :       'destroy' =
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.898)[app:dbg]Chan 2: CREATED -> DESTROYING
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.899)[app:dbg]vapi: destroy: Destroy mediaforks on TDM 2
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.900)[app:dbg]vapi: destroy: TDM 2 get statistic
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.903)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''destroy') at vapi_next_ops:3883
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.905)[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, conn 2
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.908)[app:dbg]vapi_cb_req(): Conn 2 CALLBACK msg (level = 0x0; result = 0x0; req_id = 0x 15E; len = 208)
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.910)[app:dbg]vapi: chan: 2 Callback request = 0x 15E
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.911)[app:dbg]port 2: (chan 2) get port STATISTIC
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.913)[app:dbg]port 2: Rx_pack = 404
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.914)[app:dbg]port 2: Rx_oct  = 64640
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.916)[app:dbg]port 2: Lost_pack  = 0
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.917)[app:dbg]port 2: Tx_pack = 424
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.918)[app:dbg]port 2: Tx_oct  = 67840
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.920)[app:dbg]port 2: peak_jiter = 1
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.921)[app:dbg]vapi: destroy: TDM 2 Destroy
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.923)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''destroy') at vapi_cb_chan:4378
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.934)[app:dbg]vapi_cb_req(): Conn 2 CALLBACK msg (level = 0x0; result = 0x0; req_id = 0x 103; len = 0)
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.939)[app:dbg]vapi: chan: 2 Callback request = 0x 103
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.940)[app:dbg]vapi: destroy: reset and turn off RTCP timers
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.942)[app:dbg]Chan 2: DESTROYING -> INITIAL
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.943)[app:dbg]vapi: destroy: Done (port 2) - TDM-just actions
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.945)[app:dbg]Port 2: chan: 2 check vapi queue ('busy''destroy') at vapi_cb_chan:4384
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.946)[app:dbg]Port 2: chan: 2: set vapi queue MSP to 'free' with  at vapi_cb_chan:4385
Dec 31 22:11:22 tau24 user.debug tau24: 2.13.1.2|(22.948)[app:dbg]Port 2: chan: 2 check vapi queue ('free') at vapi_next_ops:3738
Jan  1 01:11:25 tau24 syslog.info syslogd exiting