Версия ПО: #2.6.7-b7-ru
Где копать?
Код: Выделить всё
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]slic5. Event 2.
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]slic 5. Off-hook event
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]Set port 5 led to state 'LED_ON'
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]HIO: offhook TDM port '5' port enabled 1
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]SLIC 5 (phone150): offhook state: ringing
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]regex ID 5: dial reset
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]SLIC 5: -> talking(call id: 02050000)
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]pbx -[msg_answer]-> sip
Sep 2 16:34:37 TAU-8 user.info syslog: 16:34:37.536[app:info]SLIC 5: from state 'ringing' to state 'talking'
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]CMD_STOP_TONE: port = 5
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]Port 5: check vapi queue ('free') at [vapi_chan.c:1516, function vapi_stop_tone_chan()]
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]Chan 5: current state is CREATED
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]Port 5: set vapi queue MSP to 'busy' with 'stop_tone' at [vapi_chan.c:1562, function vapi_stop_tone_chan()]
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]VQ Conn 5 = MSP : 'stop_tone' =
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]chan 5 stop tone
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]Port 5: user port 3, old state talking, new state
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]pbx -[msg_fxs_state]-> group
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]dump_port_calls() SLIC 5:
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]Q:(0x33ec00,0x02050000,(nil))
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]... preparing to read from pipe
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]Unmute all RX-TX medias on SLIC 5
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]ITC: [msg_answer] -> sip
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]sip: call 02050000: endpoint 5 answered
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]sip: call 02050000: INVITE: 200 OK SIP_T NO
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]sip: call 02050000: set endpoint 5
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]self_on_answer() sdp state <receive> - create answer sdp
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]sdp_codecs_set_ptime() ptime present : 20
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]sdp_codecs_dump() ssup absent on, ecan absent on, rfc present 101, nse absent 0, ptime present 20
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]sdp_codecs_dump() G723: none
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]sdp_codecs_dump() G711A:
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]sdp_codecs_dump() PT 8, vbd absent off
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]sdp_codecs_dump() G711U:
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]sdp_codecs_dump() PT 0, vbd absent off
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]sdp_codecs_dump() G726-24: none
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]sdp_codecs_dump() G726-32: none
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]sdp_codecs_dump() G722:
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]sdp_codecs_dump() PT 9
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]sdp_codecs_g711a_add_to_media_attrs() g711a: have one at last
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]sdp_codecs_g711u_add_to_media_attrs() g711u: have one at last
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]sdp_codecs_rfc2833_add_to_media_attrs() present, pt 101
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]sdp_codecs_nse_add_to_media_attrs() absent, pt 0
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]sdp_codecs_ptime_add_to_attrs() ptime present 20
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]sdp_codecs_ecan_add_to_attrs() ecan absent on
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]sdp_codecs_ssup_add_to_attrs() ssup absent on
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]sdp_tail: 8 0 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]make_sdp: SDP: s=Session SDP m=audio 12004 RTP/AVP 8 0 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]sdp_codecs_set_ptime() ptime present : 20
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.536[app:dbg]sdp_codecs_get_rfc2833: present=1 pt=101
Sep 2 16:34:37 TAU-8 user.warn syslog: 16:34:37.536[app:WARN][get_group_profile_id]-1 is not group index!!!!
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.546[app:dbg]vapi_cb_req: 5 0 result 0x00000000 requid 0x00000924
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.546[app:dbg]ITC: [msg_fxs_state] -> group
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.546[app:dbg]-----[GM] self_fxs_state()
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.546[app:dbg]Port 5: new state is talking
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.546[app:dbg]vapi_proc_event: VAPI_CB
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.546[app:dbg]vapi_cb_chan: chan 5 reqest_id 0x00000924 result 0x00000000
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.546[app:dbg]Conn 5: Stop tone - Successfull
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.546[app:dbg]Port 5: check vapi queue ('busy''stop_tone') at [vapi_chan.c:2612, function vapi_next_ops()]
Sep 2 16:34:37 TAU-8 user.debug syslog: 16:34:37.546[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, conn 5
Sep 2 16:34:37 TAU-8 user.notice syslog: 16:34:37.586[sip]send 1138 bytes to tcp/[95.213.198.99]:5060 at 09:41:46.880000: ------------------------------------------------------------------------
Sep 2 16:34:37 TAU-8 user.notice syslog: 16:34:37.586[sip] SIP/2.0 200 OK
Sep 2 16:34:37 TAU-8 user.notice syslog: 16:34:37.586[sip] Via: SIP/2.0/TCP 95.213.198.99:5060;rport=5060;branch=z9hG4bKPj9f0985c76251bcafc5f5e57f11bac479;alias
Sep 2 16:34:37 TAU-8 user.notice syslog: 16:34:37.586[sip] v: SIP/2.0/TCP 185.164.149.20:44009;rport=44009;received=185.164.149.20;branch=z9hG4bKPjc1D-Ou4T7pfaAgclXLAjKMQIaxFjUndK;alias
Sep 2 16:34:37 TAU-8 user.notice syslog: 16:34:37.586[sip] Record-Route: <sip:95.213.198.99:5060;transport=TCP;lr>
Sep 2 16:34:37 TAU-8 user.notice syslog: 16:34:37.586[sip] f: <sip:79818915737@ip.b24-9983-1528359928.bitrixphone.com>;tag=VVVVV185.164.149.20_5090_1ad68efe740ec4fd80ba0c2d46c3f86c
Sep 2 16:34:37 TAU-8 user.notice syslog: 16:34:37.586[sip] To: <sip:phone150@ip.b24-9983-1528359928.bitrixphone.com>;tag=evS8yZ6DS4QHN
Sep 2 16:34:37 TAU-8 user.notice syslog: 16:34:37.586[sip] i: 1dc54YnUPB33m0BVtv6A8aATi0UR-0P0
Sep 2 16:34:37 TAU-8 user.notice syslog: 16:34:37.586[sip] CSeq: 1559 INVITE
Sep 2 16:34:37 TAU-8 user.notice syslog: 16:34:37.586[sip] Contact: <sip:phone150@192.168.5.227:5060>
Sep 2 16:34:37 TAU-8 user.notice syslog: 16:34:37.586[sip] User-Agent: TAU-8.IP/2.6.7 SN/VI33028492 sofia-sip/1.9
Sep 2 16:34:45 TAU-8 user.notice syslog: 16:34:45.126[sip] Supported: timer, 100rel, replaces
Sep 2 16:34:45 TAU-8 user.notice syslog: 16:34:45.126[sip] Session-Expires: 1800;refresher=uas
Sep 2 16:34:45 TAU-8 user.notice syslog: 16:34:45.126[sip] Min-SE: 120
Sep 2 16:34:45 TAU-8 user.notice syslog: 16:34:45.126[sip] Content-Type: application/sdp
Sep 2 16:34:45 TAU-8 user.notice syslog: 16:34:45.126[sip] Content-Disposition: session
Sep 2 16:34:45 TAU-8 user.notice syslog: 16:34:45.126[sip] Content-Length: 210
Sep 2 16:34:45 TAU-8 user.notice syslog: 16:34:45.126[sip]
Sep 2 16:34:45 TAU-8 user.notice syslog: 16:34:45.126[sip] v=0
Sep 2 16:34:45 TAU-8 user.notice syslog: 16:34:45.126[sip] o=- 6718197144190623291 2316302827016473515 IN IP4 192.168.5.227
Sep 2 16:34:45 TAU-8 user.notice syslog: 16:34:45.126[sip] s=Session SDP
Sep 2 16:34:45 TAU-8 user.notice syslog: 16:34:45.126[sip] c=IN IP4 192.168.5.227
Sep 2 16:34:45 TAU-8 user.notice syslog: 16:34:45.126[sip] t=0 0
Sep 2 16:34:45 TAU-8 user.notice syslog: 16:34:45.126[sip] m=audio 12004 RTP/AVP 8 101
Sep 2 16:34:45 TAU-8 user.notice syslog: 16:34:45.126[sip] a=rtpmap:101 telephone-event/8000
Sep 2 16:34:45 TAU-8 user.notice syslog: 16:34:45.126[sip] a=fmtp:101 0-15
Sep 2 16:34:45 TAU-8 user.notice syslog: 16:34:45.126[sip] a=ptime:20
Sep 2 16:34:45 TAU-8 user.notice syslog: 16:34:45.126[sip] ------------------------------------------------------------------------
Sep 2 16:34:45 TAU-8 user.debug syslog: 16:34:45.436[app:dbg]... preparing to read from pipe
Sep 2 16:34:45 TAU-8 user.warn syslog: 16:34:45.436[app:WARN]__REPEAT
Sep 2 16:34:46 TAU-8 user.debug syslog: 16:34:46.516[app:dbg]... preparing to read from pipe
Sep 2 16:34:46 TAU-8 user.warn syslog: 16:34:46.516[app:WARN]__REPEAT
Sep 2 16:34:47 TAU-8 user.debug syslog: 16:34:47.596[app:dbg]... preparing to read from pipe
Sep 2 16:34:47 TAU-8 user.warn syslog: 16:34:47.596[app:WARN]__REPEAT
Sep 2 16:34:48 TAU-8 user.debug syslog: 16:34:48.676[app:dbg]... preparing to read from pipe
Sep 2 16:34:48 TAU-8 user.warn syslog: 16:34:48.676[app:WARN]__REPEAT
Sep 2 16:34:49 TAU-8 user.notice syslog: 16:34:49.136[sip]send 1138 bytes to tcp/[95.213.198.99]:5060 at 09:41:58.430000: ------------------------------------------------------------------------
Sep 2 16:34:53 TAU-8 user.notice syslog: 16:34:53.146[sip] Supported: timer, 100rel, replaces
Sep 2 16:34:53 TAU-8 user.notice syslog: 16:34:53.146[sip] Session-Expires: 1800;refresher=uas
Sep 2 16:34:53 TAU-8 user.notice syslog: 16:34:53.146[sip] Min-SE: 120
Sep 2 16:34:53 TAU-8 user.notice syslog: 16:34:53.146[sip] Content-Type: application/sdp
Sep 2 16:34:53 TAU-8 user.notice syslog: 16:34:53.146[sip] Content-Disposition: session
Sep 2 16:34:53 TAU-8 user.notice syslog: 16:34:53.146[sip] Content-Length: 210
Sep 2 16:34:53 TAU-8 user.notice syslog: 16:34:53.146[sip]
Sep 2 16:34:53 TAU-8 user.notice syslog: 16:34:53.146[sip] v=0
Sep 2 16:34:53 TAU-8 user.notice syslog: 16:34:53.146[sip] o=- 6718197144190623291 2316302827016473515 IN IP4 192.168.5.227
Sep 2 16:34:53 TAU-8 user.notice syslog: 16:34:53.146[sip] s=Session SDP
Sep 2 16:34:53 TAU-8 user.notice syslog: 16:34:53.146[sip] c=IN IP4 192.168.5.227
Sep 2 16:34:53 TAU-8 user.notice syslog: 16:34:53.146[sip] t=0 0
Sep 2 16:34:53 TAU-8 user.notice syslog: 16:34:53.146[sip] m=audio 12004 RTP/AVP 8 101
Sep 2 16:34:53 TAU-8 user.notice syslog: 16:34:53.146[sip] a=rtpmap:101 telephone-event/8000
Sep 2 16:34:53 TAU-8 user.notice syslog: 16:34:53.146[sip] a=fmtp:101 0-15
Sep 2 16:34:53 TAU-8 user.notice syslog: 16:34:53.146[sip] a=ptime:20
Sep 2 16:34:53 TAU-8 user.notice syslog: 16:34:53.146[sip] ------------------------------------------------------------------------
Sep 2 16:34:54 TAU-8 user.debug syslog: 16:34:54.076[app:dbg]... preparing to read from pipe
Sep 2 16:34:54 TAU-8 user.warn syslog: 16:34:54.076[app:WARN]__REPEAT
Sep 2 16:34:55 TAU-8 user.debug syslog: 16:34:55.156[app:dbg]... preparing to read from pipe
Sep 2 16:34:55 TAU-8 user.warn syslog: 16:34:55.156[app:WARN]__REPEAT
Sep 2 16:34:56 TAU-8 user.debug syslog: 16:34:56.236[app:dbg]... preparing to read from pipe
Sep 2 16:34:56 TAU-8 user.warn syslog: 16:34:56.236[app:WARN]__REPEAT
Sep 2 16:34:56 TAU-8 user.notice syslog: 16:34:56.906[sip]send 855 bytes to tcp/[95.213.198.99]:5060 at 09:42:06.200000: ------------------------------------------------------------------------
Sep 2 16:34:56 TAU-8 user.notice syslog: 16:34:56.906[sip] Supported: timer, 100rel, replaces, path
Sep 2 16:34:56 TAU-8 user.notice syslog: 16:34:56.906[sip] Proxy-Authorization: Digest username="phone150", realm="voximplant.com", nonce="5aeece906add8f89", opaque="3a2f23083c083e0e", algorithm=MD5, uri="sip:
Sep 2 16:34:56 TAU-8 user.notice syslog: 16:34:56.906[sip] ip.b24-9983-1528359928.bitrixphone.com", response="7ce9fd14d2bfa42e7fa2920280929564"
Sep 2 16:34:56 TAU-8 user.notice syslog: 16:34:56.906[sip] Content-Length: 0
Sep 2 16:34:56 TAU-8 user.notice syslog: 16:34:56.906[sip]
Sep 2 16:34:56 TAU-8 user.notice syslog: 16:34:56.906[sip] ------------------------------------------------------------------------
Sep 2 16:34:57 TAU-8 user.notice syslog: 16:34:57.156[sip]send 1138 bytes to tcp/[95.213.198.99]:5060 at 09:42:06.450000: ---------------------------
Sep 2 16:34:57 TAU-8 user.notice syslog: 16:34:57.156[sip] Supported: timer, 100rel, replaces
Sep 2 16:34:57 TAU-8 user.notice syslog: 16:34:57.156[sip] Session-Expires: 1800;refresher=uas
Sep 2 16:34:57 TAU-8 user.notice syslog: 16:34:57.156[sip] Min-SE: 120
Sep 2 16:34:57 TAU-8 user.notice syslog: 16:34:57.156[sip] Content-Type: application/sdp
Sep 2 16:34:57 TAU-8 user.notice syslog: 16:34:57.156[sip] Content-Disposition: session
Sep 2 16:34:57 TAU-8 user.notice syslog: 16:34:57.156[sip] Content-Length: 210
Sep 2 16:34:57 TAU-8 user.notice syslog: 16:34:57.156[sip]
Sep 2 16:34:57 TAU-8 user.notice syslog: 16:34:57.156[sip] v=0
Sep 2 16:34:57 TAU-8 user.notice syslog: 16:34:57.156[sip] o=- 6718197144190623291 2316302827016473515 IN IP4 192.168.5.227
Sep 2 16:34:57 TAU-8 user.notice syslog: 16:34:57.156[sip] s=Session SDP
Sep 2 16:34:57 TAU-8 user.notice syslog: 16:34:57.156[sip] c=IN IP4 192.168.5.227
Sep 2 16:34:57 TAU-8 user.notice syslog: 16:34:57.156[sip] t=0 0
Sep 2 16:34:57 TAU-8 user.notice syslog: 16:34:57.156[sip] m=audio 12004 RTP/AVP 8 101
Sep 2 16:34:57 TAU-8 user.notice syslog: 16:34:57.156[sip] a=rtpmap:101 telephone-event/8000
Sep 2 16:34:57 TAU-8 user.notice syslog: 16:34:57.156[sip] a=fmtp:101 0-15
Sep 2 16:34:57 TAU-8 user.notice syslog: 16:34:57.156[sip] a=ptime:20
Sep 2 16:34:57 TAU-8 user.notice syslog: 16:34:57.156[sip] ------------------------------------------------------------------------
Sep 2 16:34:57 TAU-8 user.notice syslog: 16:34:57.266[sip]recv 398 bytes from tcp/[95.213.198.99]:5060 at 09:42:06.560000: ------------------------------------------------------------------------
Sep 2 16:34:57 TAU-8 user.notice syslog: 16:34:57.266[sip] SIP/2.0 200 OK
Sep 2 16:34:57 TAU-8 user.notice syslog: 16:34:57.266[sip] v: SIP/2.0/TCP 192.168.5.227;rport=50825;received=95.161.222.61;branch=z9hG4bK5rSQpBUaFc3gp
Sep 2 16:34:57 TAU-8 user.notice syslog: 16:34:57.266[sip] i: 106400dd-a565-123b-ddb9-a8f94b15f392
Sep 2 16:34:57 TAU-8 user.notice syslog: 16:34:57.266[sip] f: <sip:phone150@ip.b24-9983-1528359928.bitrixphone.com>;tag=41vgDHyapBSpH
Sep 2 16:34:57 TAU-8 user.notice syslog: 16:34:57.266[sip] t: <sip:phone150@ip.b24-9983-1528359928.bitrixphone.com>;tag=z9hG4bK5rSQpBUaFc3gp
Sep 2 16:34:57 TAU-8 user.notice syslog: 16:34:57.266[sip] CSeq: 36 REGISTER
Sep 2 16:34:57 TAU-8 user.notice syslog: 16:34:57.266[sip] m: <sip:phone150@10.25.158.2:5060>;expires=130
Sep 2 16:34:57 TAU-8 user.notice syslog: 16:34:57.266[sip] Expires: 130
Sep 2 16:34:57 TAU-8 user.notice syslog: 16:34:57.266[sip] l: 0
Sep 2 16:34:57 TAU-8 user.notice syslog: 16:34:57.266[sip]
Sep 2 16:34:57 TAU-8 user.notice syslog: 16:34:57.266[sip] ------------------------------------------------------------------------
Sep 2 16:34:57 TAU-8 user.debug syslog: 16:34:57.266[app:dbg]got nua_r_register : 200(OK)
Sep 2 16:34:57 TAU-8 user.debug syslog: 16:34:57.266[app:dbg]sip: endpoint 5: REGISTER: 200 OK
Sep 2 16:34:57 TAU-8 user.debug syslog: 16:34:57.266[app:dbg]Port 5: user port 3, old state talking, new state
Sep 2 16:34:57 TAU-8 user.debug syslog: 16:34:57.266[app:dbg]sip: endpoint 5: successfully registered
Sep 2 16:34:57 TAU-8 user.debug syslog: 16:34:57.316[app:dbg]... preparing to read from pipe
Sep 2 16:34:57 TAU-8 user.warn syslog: 16:34:57.316[app:WARN]__REPEAT
Sep 2 16:34:58 TAU-8 user.debug syslog: 16:34:58.396[app:dbg]... preparing to read from pipe
Sep 2 16:34:58 TAU-8 user.warn syslog: 16:34:58.396[app:WARN]__REPEAT
Sep 2 16:34:58 TAU-8 user.notice syslog: 16:34:58.926[sip]send 847 bytes to tcp/[95.213.198.99]:5060 at 09:42:08.220000: ------------------------------------------------------------------------
Sep 2 16:34:58 TAU-8 user.notice syslog: 16:34:58.926[sip] Supported: timer, 100rel, replaces, path
Sep 2 16:34:58 TAU-8 user.notice syslog: 16:34:58.926[sip] Proxy-Authorization: Digest username="phone1", realm="voximplant.com", nonce="38223714003926da", opaque="051509a338cef4f2", algorithm=MD5, uri="sip:ip
Sep 2 16:34:58 TAU-8 user.notice syslog: 16:34:58.926[sip] .b24-9983-1528359928.bitrixphone.com", response="3393613b048384274b5b66633502ba95"
Sep 2 16:34:58 TAU-8 user.notice syslog: 16:34:58.926[sip] Content-Length: 0
Sep 2 16:34:58 TAU-8 user.notice syslog: 16:34:58.926[sip]
Sep 2 16:34:58 TAU-8 user.notice syslog: 16:34:58.926[sip] ------------------------------------------------------------------------
Sep 2 16:34:59 TAU-8 user.notice syslog: 16:34:59.266[sip]recv 392 bytes from tcp/[95.213.198.99]:5060 at 09:42:08.560000: --------------------------
Sep 2 16:35:01 TAU-8 user.notice syslog: 16:35:01.166[sip] Supported: timer, 100rel, replaces
Sep 2 16:35:01 TAU-8 user.notice syslog: 16:35:01.166[sip] Session-Expires: 1800;refresher=uas
Sep 2 16:35:01 TAU-8 user.notice syslog: 16:35:01.166[sip] Min-SE: 120
Sep 2 16:35:01 TAU-8 user.notice syslog: 16:35:01.166[sip] Content-Type: application/sdp
Sep 2 16:35:01 TAU-8 user.notice syslog: 16:35:01.166[sip] Content-Disposition: session
Sep 2 16:35:01 TAU-8 user.notice syslog: 16:35:01.166[sip] Content-Length: 210
Sep 2 16:35:01 TAU-8 user.notice syslog: 16:35:01.166[sip]
Sep 2 16:35:01 TAU-8 user.notice syslog: 16:35:01.166[sip] v=0
Sep 2 16:35:01 TAU-8 user.notice syslog: 16:35:01.166[sip] o=- 6718197144190623291 2316302827016473515 IN IP4 192.168.5.227
Sep 2 16:35:01 TAU-8 user.notice syslog: 16:35:01.166[sip] s=Session SDP
Sep 2 16:35:01 TAU-8 user.notice syslog: 16:35:01.166[sip] c=IN IP4 192.168.5.227
Sep 2 16:35:01 TAU-8 user.notice syslog: 16:35:01.166[sip] t=0 0
Sep 2 16:35:01 TAU-8 user.notice syslog: 16:35:01.166[sip] m=audio 12004 RTP/AVP 8 101
Sep 2 16:35:01 TAU-8 user.notice syslog: 16:35:01.166[sip] a=rtpmap:101 telephone-event/8000
Sep 2 16:35:01 TAU-8 user.notice syslog: 16:35:01.166[sip] a=fmtp:101 0-15
Sep 2 16:35:01 TAU-8 user.notice syslog: 16:35:01.166[sip] a=ptime:20
Sep 2 16:35:01 TAU-8 user.notice syslog: 16:35:01.166[sip] ------------------------------------------------------------------------
Sep 2 16:35:01 TAU-8 user.debug syslog: 16:35:01.636[app:dbg]... preparing to read from pipe
Sep 2 16:35:01 TAU-8 user.warn syslog: 16:35:01.636[app:WARN]__REPEAT
Sep 2 16:35:02 TAU-8 user.debug syslog: 16:35:02.716[app:dbg]... preparing to read from pipe
Sep 2 16:35:02 TAU-8 user.warn syslog: 16:35:02.716[app:WARN]__REPEAT
Sep 2 16:35:03 TAU-8 user.debug syslog: 16:35:03.796[app:dbg]... preparing to read from pipe
Sep 2 16:35:03 TAU-8 user.warn syslog: 16:35:03.796[app:WARN]__REPEAT
Sep 2 16:35:04 TAU-8 user.debug syslog: 16:35:04.876[app:dbg]... preparing to read from pipe
Sep 2 16:35:04 TAU-8 user.warn syslog: 16:35:04.876[app:WARN]__REPEAT
Sep 2 16:35:05 TAU-8 user.notice syslog: 16:35:05.176[sip]send 1138 bytes to tcp/[95.213.198.99]:5060 at 09:42:14.470000: ------------------------------------------------------------------------
Sep 2 16:35:05 TAU-8 user.notice syslog: 16:35:05.176[sip] Supported: timer, 100rel, replaces
Sep 2 16:35:05 TAU-8 user.notice syslog: 16:35:05.176[sip] Session-Expires: 1800;refresher=uas
Sep 2 16:35:05 TAU-8 user.notice syslog: 16:35:05.176[sip] Min-SE: 120
Sep 2 16:35:05 TAU-8 user.notice syslog: 16:35:05.176[sip] Content-Type: application/sdp
Sep 2 16:35:05 TAU-8 user.notice syslog: 16:35:05.176[sip] Content-Disposition: session
Sep 2 16:35:05 TAU-8 user.notice syslog: 16:35:05.176[sip] Content-Length: 210
Sep 2 16:35:05 TAU-8 user.notice syslog: 16:35:05.176[sip]
Sep 2 16:35:05 TAU-8 user.notice syslog: 16:35:05.176[sip] v=0
Sep 2 16:35:05 TAU-8 user.notice syslog: 16:35:05.176[sip] o=- 6718197144190623291 2316302827016473515 IN IP4 192.168.5.227
Sep 2 16:35:05 TAU-8 user.notice syslog: 16:35:05.176[sip] s=Session SDP
Sep 2 16:35:05 TAU-8 user.notice syslog: 16:35:05.176[sip] c=IN IP4 192.168.5.227
Sep 2 16:35:05 TAU-8 user.notice syslog: 16:35:05.176[sip] t=0 0
Sep 2 16:35:05 TAU-8 user.notice syslog: 16:35:05.176[sip] m=audio 12004 RTP/AVP 8 101
Sep 2 16:35:05 TAU-8 user.notice syslog: 16:35:05.176[sip] a=rtpmap:101 telephone-event/8000
Sep 2 16:35:05 TAU-8 user.notice syslog: 16:35:05.176[sip] a=fmtp:101 0-15
Sep 2 16:35:05 TAU-8 user.notice syslog: 16:35:05.176[sip] a=ptime:20
Sep 2 16:35:05 TAU-8 user.notice syslog: 16:35:05.176[sip] ------------------------------------------------------------------------
Sep 2 16:35:05 TAU-8 user.debug syslog: 16:35:05.956[app:dbg]... preparing to read from pipe
Sep 2 16:35:05 TAU-8 user.warn syslog: 16:35:05.956[app:WARN]__REPEAT
Sep 2 16:35:07 TAU-8 user.debug syslog: 16:35:07.036[app:dbg]... preparing to read from pipe
Sep 2 16:35:07 TAU-8 user.warn syslog: 16:35:07.036[app:WARN]__REPEAT
Sep 2 16:35:08 TAU-8 user.debug syslog: 16:35:08.116[app:dbg]... preparing to read from pipe
Sep 2 16:35:08 TAU-8 user.warn syslog: 16:35:08.116[app:WARN]__REPEAT
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.186[sip]send 1138 bytes to tcp/[95.213.198.99]:5060 at 09:42:18.480000: ---------------------------
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.186[sip] Supported: timer, 100rel, replaces
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.186[sip] Session-Expires: 1800;refresher=uas
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.186[sip] Min-SE: 120
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.186[sip] Content-Type: application/sdp
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.186[sip] Content-Disposition: session
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.186[sip] Content-Length: 210
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.186[sip]
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.186[sip] v=0
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.186[sip] o=- 6718197144190623291 2316302827016473515 IN IP4 192.168.5.227
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.186[sip] s=Session SDP
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.186[sip] c=IN IP4 192.168.5.227
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.186[sip] t=0 0
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.186[sip] m=audio 12004 RTP/AVP 8 101
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.186[sip] a=rtpmap:101 telephone-event/8000
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.186[sip] a=fmtp:101 0-15
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.186[sip] a=ptime:20
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.186[sip] ------------------------------------------------------------------------
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.196[app:dbg]... preparing to read from pipe
Sep 2 16:35:09 TAU-8 user.warn syslog: 16:35:09.196[app:WARN]__REPEAT
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.596[app:dbg]got nua_i_error : 408(ACK Timeout)
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.596[app:dbg]NO SIP IN nua_i_error == 408 : ACK Timeout
Sep 2 16:35:09 TAU-8 user.err syslog: 16:35:09.596[app:ERR]sip: sip library error nua_i_error (0), status: 408 ACK Timeout!
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.596[sip]send 737 bytes to tcp/[95.213.198.99]:5060 at 09:42:18.890000: ------------------------------------------------------------------------
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.596[sip] BYE sip:185.164.149.20:5090;transport=tcp SIP/2.0
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.596[sip] Via: SIP/2.0/TCP 192.168.5.227;branch=z9hG4bK7ac9S1vH9XFpD
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.596[sip] Route: <sip:95.213.198.99:5060;transport=TCP;lr>
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.596[sip] Max-Forwards: 70
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.596[sip] From: <sip:phone150@ip.b24-9983-1528359928.bitrixphone.com>;tag=evS8yZ6DS4QHN
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.596[sip] To: <sip:79818915737@ip.b24-9983-1528359928.bitrixphone.com>;tag=VVVVV185.164.149.20_5090_1ad68efe740ec4fd80ba0c2d46c3f86c
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.596[sip] Call-ID: 1dc54YnUPB33m0BVtv6A8aATi0UR-0P0
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.596[sip] CSeq: 421 BYE
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.596[sip] Contact: <sip:phone150@192.168.5.227:5060>
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.596[sip] User-Agent: TAU-8.IP/2.6.7 SN/VI33028492 sofia-sip/1.9
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.596[sip] Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, INFO
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.596[sip] Supported: timer, 100rel, replaces
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.596[sip] Reason: SIP;cause=408;text="ACK Timeout"
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.596[sip] Content-Length: 0
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.596[sip]
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.596[sip] ------------------------------------------------------------------------
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.596[app:dbg]got nua_i_state : 0(ACK Timeout)
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.596[app:dbg]NO SIP IN nua_i_state == 0 : ACK Timeout
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.596[app:dbg]self_i_state(): call state 9: : : sdp_init have_oc
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.636[sip]recv 416 bytes from tcp/[95.213.198.99]:5060 at 09:42:18.930000: ------------------------------------------------------------------------
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.636[sip] SIP/2.0 200 OK
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.636[sip] v: SIP/2.0/TCP 192.168.5.227;rport=50825;received=95.161.222.61;branch=z9hG4bK7ac9S1vH9XFpD
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.636[sip] i: 1dc54YnUPB33m0BVtv6A8aATi0UR-0P0
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.636[sip] f: <sip:phone150@ip.b24-9983-1528359928.bitrixphone.com>;tag=evS8yZ6DS4QHN
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.636[sip] t: <sip:79818915737@ip.b24-9983-1528359928.bitrixphone.com>;tag=VVVVV185.164.149.20_5090_1ad68efe740ec4fd80ba0c2d46c3f86c
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.636[sip] CSeq: 421 BYE
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.636[sip] User-Agent: VIMS
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.636[sip] m: <sip:185.164.149.20:5090>
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.636[sip] l: 0
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.636[sip]
Sep 2 16:35:09 TAU-8 user.notice syslog: 16:35:09.646[sip] ------------------------------------------------------------------------
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.646[app:dbg]got nua_r_bye : 200(OK)
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.646[app:dbg]sip: call 02050000: BYE/INFO: 200 OK
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.646[app:dbg]got nua_i_state : 200(to BYE)
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.646[app:dbg]NO SIP IN nua_i_state == 200 : to BYE
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.646[app:dbg]self_i_state(): call state 10: : : sdp_init have_oc
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.646[app:dbg]sip: call 02050000: terminated
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.646[app:dbg]8186: endpoint 5 set to ready
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.646[app:dbg]sip -[msg_clear]-> pbx
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.646[app:dbg]self_callstate_terminated: call id = 02050000 need_exchange_at_answer = 0
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.646[app:dbg]ITC: [msg_clear] -> pbx
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.646[app:dbg]dump_port_calls() SLIC 5:
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.646[app:dbg]Q:(0x33ec00,0x02050000,(nil))
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.646[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.646[app:dbg]SLIC 5: peer cleared(02050000)
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.646[app:dbg]SLIC 5: current call cleared
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.646[app:dbg]SLIC 5: -> busy - no hold call, no wait call
Sep 2 16:35:09 TAU-8 user.info syslog: 16:35:09.646[app:info]SLIC 5: from state 'talking' to state 'busy'
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.646[app:dbg]port_start_tone(5 22 0 0)
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.646[app:dbg]CMD_START_TONE: port = 5
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.646[app:dbg]Port 5: check vapi queue ('free') at [vapi_chan.c:1425, function vapi_start_tone_chan()]
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.646[app:dbg]Chan 5: current state is CREATED
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.646[app:dbg]Port 5: set vapi queue MSP to 'busy' with 'start_tone' at [vapi_chan.c:1462, function vapi_start_tone_chan()]
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.646[app:dbg]VQ Conn 5 = MSP : 'start_tone' =
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.646[app:dbg]Conn 5, tone config: tone_high: 425Hz, tone_low: 0Hz, tone_t_on1: 330ms, tone_t_off1: 330ms, tone_t_on2: 0ms, tone_t_off2: 0ms
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.646[app:dbg]chan 5 start tone, id=22, direction=TDM
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.646[app:dbg]Port 5: user port 3, old state busy, new state
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.646[app:dbg]pbx -[msg_fxs_state]-> group
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.646[app:dbg]vapi: chan 5: connection STATISTIC
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.646[app:dbg]vapi: chan 5: Rx_pack = 1519
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.646[app:dbg]vapi: chan 5: Rx_oct = 261268
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.646[app:dbg]vapi: chan 5: Lost_pack = 0
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.646[app:dbg]vapi: chan 5: Tx_pack = 1341
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.646[app:dbg]vapi: chan 5: Tx_oct = 218727
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.646[app:dbg]vapi: chan 5: peak_jiter = 11
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.646[app:dbg]SLIC 5: Common port statistic
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.646[app:dbg]SLIC 5: Rx_pack = 1519
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.646[app:dbg]SLIC 5: Rx_oct = 261268
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.646[app:dbg]SLIC 5: Lost_pack = 0
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.646[app:dbg]SLIC 5: Tx_pack = 1341
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.646[app:dbg]SLIC 5: Tx_oct = 218727
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.646[app:dbg]SLIC 5: peak_jiter = 11
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.646[app:dbg]SLIC 5: reset call 0x02050000 (active)
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.646[app:dbg]CMD_SET_VOICE: port = 5
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.646[app:dbg]Port 5: check vapi queue ('busy''start_tone') at [vapi_chan.c:1665, function vapi_start_stop_chan()]
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.646[app:dbg]Port 5 put cmd 'set voice',cur 'start_tone' to queue at (vapi_start_stop_chan:1672)
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.656[app:dbg]VQ Conn 5 = MSP : 'start_tone' =
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.656[app:dbg]VQ Conn 5 + 00 : 'set voice' + <-get_ptr
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.656[app:dbg]incom_calls_set_media_started() call 0x02050000, group -1, task <sip> media stopped
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.656[app:dbg]incom_calls_rem() rem call 0x02050000, group -1, task <sip> from list
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.656[app:dbg]... preparing to read from pipe
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.656[app:dbg]Delete all RX-TX medias from SLIC 5
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.656[app:dbg]dump_port_calls() SLIC 5:
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.656[app:dbg]Q:NONE
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.656[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.656[app:dbg]received signal or msg for updating stats
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.656[app:dbg]vapi_cb_req: 5 0 result 0x00000000 requid 0x00000923
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.656[app:dbg]ITC: [msg_fxs_state] -> group
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.666[app:dbg]-----[GM] self_fxs_state()
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.666[app:dbg]Port 5: new state is busy
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.666[app:dbg]vapi_proc_event: VAPI_CB
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.666[app:dbg]vapi_cb_chan: chan 5 reqest_id 0x00000923 result 0x00000000
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.666[app:dbg]Conn 5: Start tone - Successfull
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.666[app:dbg]Port 5: check vapi queue ('busy''start_tone') at [vapi_chan.c:2612, function vapi_next_ops()]
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.666[app:dbg]Port 5 get cmd 'set voice' from queue at [vapi_chan.c:2631, function vapi_next_ops()]
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.666[app:dbg]Port 5: check vapi queue ('free') at [vapi_chan.c:1665, function vapi_start_stop_chan()]
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.666[app:dbg]Chan 5: current state is CREATED
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.666[app:dbg]vapi: Conn 5. start_stop voice chan, TX stop, RX stop
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.666[app:dbg]Port 5: set vapi queue MSP to 'busy' with 'set voice' at [vapi_chan.c:1708, function vapi_start_stop_chan()]
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.666[app:dbg]VQ Conn 5 = MSP : 'set voice' =
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.676[app:dbg]vapi_cb_req: 5 0 result 0x00000000 requid 0x00000401
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.676[app:dbg]vapi_proc_event: VAPI_CB
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.676[app:dbg]vapi_cb_chan: chan 5 reqest_id 0x00000401 result 0x00000000
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.676[app:dbg]vapi: conn 5. RTCP disabled
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.676[app:dbg]vapi_cb_req: 5 0 result 0x00000000 requid 0x000004ff
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.676[app:dbg]vapi_proc_event: VAPI_CB
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.676[app:dbg]vapi_cb_chan: chan 5 reqest_id 0x000004ff result 0x00000000
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.676[app:dbg]Conn 5: Set voice mode successeful
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.676[app:dbg]Stop all medias on chan 5
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.676[app:dbg]... preparing to read from pipe
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.676[app:dbg]Mute all RX-TX medias on SLIC 5
Sep 2 16:35:09 TAU-8 user.debug syslog: 16:35:09.676[app:dbg]Port 5: check vapi queue ('busy''set voice') at [vapi_chan.c:2612, function vapi_next_ops()]
Sep 2 16:35:10 TAU-8 user.notice syslog: 16:35:10.036[sip]send 851 bytes to tcp/[95.213.198.99]:5060 at 09:42:19.330000: ------------------------------------------------------------------------
Sep 2 16:35:10 TAU-8 user.notice syslog: 16:35:10.036[sip] REGISTER sip:ip.b24-9983-1528359928.bitrixphone.com SIP/2.0
Sep 2 16:35:10 TAU-8 user.notice syslog: 16:35:10.036[sip] Via: SIP/2.0/TCP 192.168.5.227;branch=z9hG4bK8K51UvDN6658r
Sep 2 16:35:10 TAU-8 user.notice syslog: 16:35:10.036[sip] Max-Forwards: 70
Sep 2 16:35:10 TAU-8 user.notice syslog: 16:35:10.036[sip] From: <sip:phone14@ip.b24-9983-1528359928.bitrixphone.com>;tag=6KF2g7ZHgX5Ur
Sep 2 16:35:10 TAU-8 user.notice syslog: 16:35:10.036[sip] To: <sip:phone14@ip.b24-9983-1528359928.bitrixphone.com>
Sep 2 16:35:10 TAU-8 user.notice syslog: 16:35:10.036[sip] Call-ID: 10fe1dfd-a565-123b-dfb9-a8f94b15f392
Sep 2 16:35:10 TAU-8 user.notice syslog: 16:35:10.036[sip] CSeq: 36 REGISTER
Sep 2 16:35:10 TAU-8 user.notice syslog: 16:35:10.036[sip] Contact: <sip:phone14@192.168.5.227:5060>
Sep 2 16:35:10 TAU-8 user.notice syslog: 16:35:10.036[sip] Expires: 1800
Sep 2 16:35:10 TAU-8 user.notice syslog: 16:35:10.036[sip] User-Agent: TAU-8.IP/2.6.7 SN/VI33028492 sofia-sip/1.9
Sep 2 16:35:10 TAU-8 user.notice syslog: 16:35:10.036[sip] Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, INFO
Sep 2 16:35:10 TAU-8 user.notice syslog: 16:35:10.036[sip] Supported: timer, 100rel, replaces, path
Sep 2 16:35:10 TAU-8 user.notice syslog: 16:35:10.036[sip] Proxy-Authorization: Digest username="phone14", realm="voximplant.com", nonce="0f18ef2f2cc80865", opaque="474de71e451d7a85", algorithm=MD5, uri="sip:i
Sep 2 16:35:10 TAU-8 user.notice syslog: 16:35:10.036[sip] p.b24-9983-1528359928.bitrixphone.com", response="cd751bc5fac57994f046a4afec56397e"
Sep 2 16:35:10 TAU-8 user.notice syslog: 16:35:10.036[sip] Content-Length: 0
Sep 2 16:35:10 TAU-8 user.notice syslog: 16:35:10.036[sip]
Sep 2 16:35:10 TAU-8 user.notice syslog: 16:35:10.036[sip] ------------------------------------------------------------------------
Sep 2 16:35:10 TAU-8 user.notice syslog: 16:35:10.326[sip]recv 395 bytes from tcp/[95.213.198.99]:5060 at 09:42:19.620000: ------------------------------------------------------------------------
Sep 2 16:35:10 TAU-8 user.notice syslog: 16:35:10.326[sip] SIP/2.0 200 OK
Sep 2 16:35:10 TAU-8 user.notice syslog: 16:35:10.326[sip] v: SIP/2.0/TCP 192.168.5.227;rport=50825;received=95.161.222.61;branch=z9hG4bK8K51UvDN6658r
Sep 2 16:35:10 TAU-8 user.notice syslog: 16:35:10.326[sip] i: 10fe1dfd-a565-123b-dfb9-a8f94b15f392
Sep 2 16:35:10 TAU-8 user.notice syslog: 16:35:10.326[sip] f: <sip:phone14@ip.b24-9983-1528359928.bitrixphone.com>;tag=6KF2g7ZHgX5Ur
Sep 2 16:35:10 TAU-8 user.notice syslog: 16:35:10.326[sip] t: <sip:phone14@ip.b24-9983-1528359928.bitrixphone.com>;tag=z9hG4bK8K51UvDN6658r
Sep 2 16:35:10 TAU-8 user.notice syslog: 16:35:10.326[sip] CSeq: 36 REGISTER
Sep 2 16:35:10 TAU-8 user.notice syslog: 16:35:10.326[sip] m: <sip:phone14@10.25.158.2:5060>;expires=130
Sep 2 16:35:10 TAU-8 user.notice syslog: 16:35:10.326[sip] Expires: 130
Sep 2 16:35:10 TAU-8 user.notice syslog: 16:35:10.326[sip] l: 0
Sep 2 16:35:10 TAU-8 user.notice syslog: 16:35:10.326[sip]
Sep 2 16:35:10 TAU-8 user.notice syslog: 16:35:10.326[sip] ------------------------------------------------------------------------
Sep 2 16:35:10 TAU-8 user.debug syslog: 16:35:10.326[app:dbg]got nua_r_register : 200(OK)
Sep 2 16:35:10 TAU-8 user.debug syslog: 16:35:10.326[app:dbg]sip: endpoint 7: REGISTER: 200 OK
Sep 2 16:35:10 TAU-8 user.debug syslog: 16:35:10.326[app:dbg]Port 7: user port 1, old state hangup, new state
Sep 2 16:35:10 TAU-8 user.debug syslog: 16:35:10.326[app:dbg]sip: endpoint 7: successfully registered
Sep 2 16:35:13 TAU-8 user.notice syslog: 16:35:13.066[sip]send 851 bytes to tcp/[95.213.198.99]:5060 at 09:42:22.360000: ------------------------------------------------------------------------
Sep 2 16:35:13 TAU-8 user.notice syslog: 16:35:13.066[sip] REGISTER sip:ip.b24-9983-1528359928.bitrixphone.com SIP/2.0
Sep 2 16:35:13 TAU-8 user.notice syslog: 16:35:13.066[sip] Via: SIP/2.0/TCP 192.168.5.227;branch=z9hG4bK9vytXQyr3FvUm
Sep 2 16:35:13 TAU-8 user.notice syslog: 16:35:13.066[sip] Max-Forwards: 70
Sep 2 16:35:13 TAU-8 user.notice syslog: 16:35:13.066[sip] From: <sip:phone42@ip.b24-9983-1528359928.bitrixphone.com>;tag=3r3QBpD7r223N
Sep 2 16:35:13 TAU-8 user.notice syslog: 16:35:13.066[sip] To: <sip:phone42@ip.b24-9983-1528359928.bitrixphone.com>
Sep 2 16:35:13 TAU-8 user.notice syslog: 16:35:13.066[sip] Call-ID: 1017b59d-a565-123b-dcb9-a8f94b15f392
Sep 2 16:35:13 TAU-8 user.notice syslog: 16:35:13.066[sip] CSeq: 35 REGISTER
Sep 2 16:35:13 TAU-8 user.notice syslog: 16:35:13.066[sip] Contact: <sip:phone42@192.168.5.227:5060>
Sep 2 16:35:13 TAU-8 user.notice syslog: 16:35:13.066[sip] Expires: 1800
Sep 2 16:35:13 TAU-8 user.notice syslog: 16:35:13.066[sip] User-Agent: TAU-8.IP/2.6.7 SN/VI33028492 sofia-sip/1.9
Sep 2 16:35:13 TAU-8 user.notice syslog: 16:35:13.066[sip] Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, INFO
Sep 2 16:35:13 TAU-8 user.notice syslog: 16:35:13.066[sip] Supported: timer, 100rel, replaces, path
Sep 2 16:35:13 TAU-8 user.notice syslog: 16:35:13.066[sip] Proxy-Authorization: Digest username="phone42", realm="voximplant.com", nonce="50a28b1677966a00", opaque="2f22cbb126347281", algorithm=MD5, uri="sip:i
Sep 2 16:35:13 TAU-8 user.notice syslog: 16:35:13.066[sip] p.b24-9983-1528359928.bitrixphone.com", response="d7fe15cbabf877e8c6f467de2c76575a"
Sep 2 16:35:13 TAU-8 user.notice syslog: 16:35:13.066[sip] Content-Length: 0
Sep 2 16:35:13 TAU-8 user.notice syslog: 16:35:13.066[sip]
Sep 2 16:35:13 TAU-8 user.notice syslog: 16:35:13.066[sip] ------------------------------------------------------------------------
Sep 2 16:35:13 TAU-8 user.notice syslog: 16:35:13.346[sip]recv 395 bytes from tcp/[95.213.198.99]:5060 at 09:42:22.640000: ------------------------------------------------------------------------
Sep 2 16:35:13 TAU-8 user.notice syslog: 16:35:13.346[sip] SIP/2.0 200 OK
Sep 2 16:35:13 TAU-8 user.notice syslog: 16:35:13.346[sip] v: SIP/2.0/TCP 192.168.5.227;rport=50825;received=95.161.222.61;branch=z9hG4bK9vytXQyr3FvUm
Sep 2 16:35:13 TAU-8 user.notice syslog: 16:35:13.346[sip] i: 1017b59d-a565-123b-dcb9-a8f94b15f392
Sep 2 16:35:13 TAU-8 user.notice syslog: 16:35:13.346[sip] f: <sip:phone42@ip.b24-9983-1528359928.bitrixphone.com>;tag=3r3QBpD7r223N
Sep 2 16:35:13 TAU-8 user.notice syslog: 16:35:13.346[sip] t: <sip:phone42@ip.b24-9983-1528359928.bitrixphone.com>;tag=z9hG4bK9vytXQyr3FvUm
Sep 2 16:35:13 TAU-8 user.notice syslog: 16:35:13.346[sip] CSeq: 35 REGISTER
Sep 2 16:35:13 TAU-8 user.notice syslog: 16:35:13.346[sip] m: <sip:phone42@10.25.158.2:5060>;expires=130
Sep 2 16:35:13 TAU-8 user.notice syslog: 16:35:13.346[sip] Expires: 130
Sep 2 16:35:13 TAU-8 user.notice syslog: 16:35:13.346[sip] l: 0
Sep 2 16:35:13 TAU-8 user.notice syslog: 16:35:13.346[sip]
Sep 2 16:35:13 TAU-8 user.notice syslog: 16:35:13.346[sip] ------------------------------------------------------------------------
Sep 2 16:35:13 TAU-8 user.debug syslog: 16:35:13.346[app:dbg]got nua_r_register : 200(OK)
Sep 2 16:35:13 TAU-8 user.debug syslog: 16:35:13.346[app:dbg]sip: endpoint 4: REGISTER: 200 OK
Sep 2 16:35:13 TAU-8 user.debug syslog: 16:35:13.346[app:dbg]Port 4: user port 2, old state hangup, new state
Sep 2 16:35:13 TAU-8 user.debug syslog: 16:35:13.346[app:dbg]sip: endpoint 4: successfully registered
Sep 2 16:35:13 TAU-8 user.debug syslog: 16:35:13.606[app:dbg]slic5. Event 8.
Sep 2 16:35:13 TAU-8 user.debug syslog: 16:35:13.606[app:dbg]slic 5. Pre-On-hook event
Sep 2 16:35:13 TAU-8 user.debug syslog: 16:35:13.606[app:dbg]HIO: preonhook TDM port '5', port enabled 1
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]slic5. Event 1.
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]slic 5. On-hook event
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]Set port 5 led to state 'LED_OFF'
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]HIO: onhook TDM port '5', port enabled 1
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]SLIC 5 (phone150): onhook state: busy
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]regex ID 5: dial reset
Sep 2 16:35:14 TAU-8 user.info syslog: 16:35:14.116[app:info]SLIC 5: from state 'busy' to state 'hangup'
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]CMD_STOP_TONE: port = 5
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]Port 5: check vapi queue ('free') at [vapi_chan.c:1516, function vapi_stop_tone_chan()]
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]Chan 5: current state is CREATED
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]Port 5: set vapi queue MSP to 'busy' with 'stop_tone' at [vapi_chan.c:1562, function vapi_stop_tone_chan()]
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]VQ Conn 5 = MSP : 'stop_tone' =
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]chan 5 stop tone
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]SLIC 5: reset
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]dump_port_calls() SLIC 5:
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]Q:NONE
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]free_final_mx: final_mx was NULL for SLIC 5
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]CMD_DESTROY_CONN: port = 5
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]Port 5: check vapi queue ('busy''stop_tone') at [vapi_chan.c:904, function vapi_destroy_chan()]
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg][vapi_chan.c:906] vapi_destroy_chan(): Clear vapi queue of Port 5/chan 5
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]Port 5 put cmd 'destroy',cur 'stop_tone' to queue at (vapi_destroy_chan:911)
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]VQ Conn 5 = MSP : 'stop_tone' =
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]VQ Conn 5 + 00 : 'destroy' + <-get_ptr
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]CMD_DESTROY_IPONLY_CONN: port = 5
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]Port 5: check vapi queue ('busy''stop_tone') at [vapi_chan.c:904, function vapi_destroy_chan()]
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg][vapi_chan.c:906] vapi_destroy_chan(): Clear vapi queue of Port 5/chan 13
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]Port 5 put cmd 'destroy',cur 'stop_tone' to queue at (vapi_destroy_chan:911)
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]VQ Conn 13 = MSP : 'stop_tone' =
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]VQ Conn 13 + 00 : 'destroy' + <-get_ptr
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]VQ Conn 13 + 01 : 'destroy' (hold) +
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]Port 5: user port 3, old state hangup, new state
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]pbx -[msg_fxs_state]-> group
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]dump_port_calls() SLIC 5:
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]Q:NONE
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]Set port 5 led to state 'LED_OFF'
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]... preparing to read from pipe
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]Delete all RX-TX medias from SLIC 5
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]vapi_cb_req: 5 0 result 0x00000000 requid 0x00000924
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]ITC: [msg_fxs_state] -> group
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]-----[GM] self_fxs_state()
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]Port 5: new state is hangup
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]vapi_proc_event: VAPI_CB
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]vapi_cb_chan: chan 5 reqest_id 0x00000924 result 0x00000000
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]Conn 5: Stop tone - Successfull
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]Port 5: check vapi queue ('busy''stop_tone') at [vapi_chan.c:2612, function vapi_next_ops()]
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]Port 5 get cmd 'destroy' from queue at [vapi_chan.c:2631, function vapi_next_ops()]
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]VQ Conn 5 + 01 : 'destroy' (hold) + <-get_ptr
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]Port 5: check vapi queue ('free') at [vapi_chan.c:904, function vapi_destroy_chan()]
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]Destroying connection 5...
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]Chan 5: current state is CREATED
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]Port 5: set vapi queue MSP to 'busy' with 'destroy' at [vapi_chan.c:930, function vapi_destroy_chan()]
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]VQ Conn 5 = MSP : 'destroy' =
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]VQ Conn 5 + 01 : 'destroy' (hold) + <-get_ptr
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.116[app:dbg]Chan 5: CREATED -> DESTROYING
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.126[app:dbg]... preparing to read from pipe
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.126[app:dbg]Delete all RX-TX medias from SLIC 13
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.126[app:dbg]vapi_cb_req: 5 0 result 0x00000000 requid 0x0000014c
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.126[app:dbg]vapi_proc_event: VAPI_CB
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.126[app:dbg]vapi_cb_chan: chan 5 reqest_id 0x0000014c result 0x00000000
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.126[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, conn 5
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.136[app:dbg]... preparing to read from pipe
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.136[app:dbg]Delete all RX-TX medias from SLIC 5
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.136[app:dbg]vapi_cb_req: 5 0 result 0x00000000 requid 0x00000103
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.136[app:dbg]vapi_proc_event: VAPI_CB
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.136[app:dbg]vapi_cb_chan: chan 5 reqest_id 0x00000103 result 0x00000000
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.136[app:dbg]Conn 5 destroyed
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.136[app:dbg]Chan 5: DESTROYING -> INITIAL
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.136[app:dbg]Port 5: check vapi queue ('busy''destroy') at [vapi_chan.c:2612, function vapi_next_ops()]
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.136[app:dbg]Port 5 get cmd 'destroy' from queue at [vapi_chan.c:2631, function vapi_next_ops()]
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.136[app:dbg]Port 5: check vapi queue ('free') at [vapi_chan.c:904, function vapi_destroy_chan()]
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.136[app:dbg]Destroying connection 13...
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.136[app:dbg]Chan 13: current state is INITIAL
Sep 2 16:35:14 TAU-8 user.err syslog: 16:35:14.136[app:ERR]vapi_destroy_chan() chan 13: current state initial: duplicate destroying connection!
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.136[app:dbg]Port 5: check vapi queue ('free') at [vapi_chan.c:2774, function vapi_next_ops()]
Sep 2 16:35:14 TAU-8 user.debug syslog: 16:35:14.136[app:dbg]Port 5: check vapi queue ('free') at [vapi_chan.c:2612, function vapi_next_ops()]
Sep 2 16:36:08 TAU-8 user.notice syslog: 16:36:08.616[sip]send 851 bytes to tcp/[95.213.198.99]:5060 at 09:43:17.910000: ------------------------------------------------------------------------
Sep 2 16:36:08 TAU-8 user.notice syslog: 16:36:08.616[sip] REGISTER sip:ip.b24-9983-1528359928.bitrixphone.com SIP/2.0
Sep 2 16:36:08 TAU-8 user.notice syslog: 16:36:08.616[sip] Via: SIP/2.0/TCP 192.168.5.227;branch=z9hG4bKa6QKZjFv0rjeg
Sep 2 16:36:08 TAU-8 user.notice syslog: 16:36:08.616[sip] Max-Forwards: 70
Sep 2 16:36:08 TAU-8 user.notice syslog: 16:36:08.616[sip] From: <sip:phone40@ip.b24-9983-1528359928.bitrixphone.com>;tag=5ap9ecFeKmF9c
Sep 2 16:36:08 TAU-8 user.notice syslog: 16:36:08.616[sip] To: <sip:phone40@ip.b24-9983-1528359928.bitrixphone.com>
Sep 2 16:36:08 TAU-8 user.notice syslog: 16:36:08.616[sip] Call-ID: 10b1d2bd-a565-123b-deb9-a8f94b15f392
Sep 2 16:36:08 TAU-8 user.notice syslog: 16:36:08.616[sip] CSeq: 37 REGISTER
Sep 2 16:36:08 TAU-8 user.notice syslog: 16:36:08.616[sip] Contact: <sip:phone40@192.168.5.227:5060>
Sep 2 16:36:08 TAU-8 user.notice syslog: 16:36:08.616[sip] Expires: 1800
Sep 2 16:36:08 TAU-8 user.notice syslog: 16:36:08.616[sip] User-Agent: TAU-8.IP/2.6.7 SN/VI33028492 sofia-sip/1.9
Sep 2 16:36:08 TAU-8 user.notice syslog: 16:36:08.616[sip] Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, INFO
Sep 2 16:36:08 TAU-8 user.notice syslog: 16:36:08.616[sip] Supported: timer, 100rel, replaces, path
Sep 2 16:36:08 TAU-8 user.notice syslog: 16:36:08.616[sip] Proxy-Authorization: Digest username="phone40", realm="voximplant.com", nonce="5d453f2d1a41016d", opaque="5182789635749e85", algorithm=MD5, uri="sip:i
Sep 2 16:36:08 TAU-8 user.notice syslog: 16:36:08.616[sip] p.b24-9983-1528359928.bitrixphone.com", response="0ebade5b975b80d070f06e856335ae2d"
Sep 2 16:36:08 TAU-8 user.notice syslog: 16:36:08.616[sip] Content-Length: 0
Sep 2 16:36:08 TAU-8 user.notice syslog: 16:36:08.616[sip]
Sep 2 16:36:08 TAU-8 user.notice syslog: 16:36:08.616[sip] ------------------------------------------------------------------------
Sep 2 16:36:08 TAU-8 user.notice syslog: 16:36:08.896[sip]recv 395 bytes from tcp/[95.213.198.99]:5060 at 09:43:18.190000: ------------------------------------------------------------------------
Sep 2 16:36:08 TAU-8 user.notice syslog: 16:36:08.896[sip] SIP/2.0 200 OK
Sep 2 16:36:08 TAU-8 user.notice syslog: 16:36:08.896[sip] v: SIP/2.0/TCP 192.168.5.227;rport=50825;received=95.161.222.61;branch=z9hG4bKa6QKZjFv0rjeg
Sep 2 16:36:08 TAU-8 user.notice syslog: 16:36:08.896[sip] i: 10b1d2bd-a565-123b-deb9-a8f94b15f392
Sep 2 16:36:08 TAU-8 user.notice syslog: 16:36:08.896[sip] f: <sip:phone40@ip.b24-9983-1528359928.bitrixphone.com>;tag=5ap9ecFeKmF9c
Sep 2 16:36:08 TAU-8 user.notice syslog: 16:36:08.896[sip] t: <sip:phone40@ip.b24-9983-1528359928.bitrixphone.com>;tag=z9hG4bKa6QKZjFv0rjeg
Sep 2 16:36:08 TAU-8 user.notice syslog: 16:36:08.896[sip] CSeq: 37 REGISTER
Sep 2 16:36:08 TAU-8 user.notice syslog: 16:36:08.896[sip] m: <sip:phone40@10.25.158.2:5060>;expires=129
Sep 2 16:36:08 TAU-8 user.notice syslog: 16:36:08.896[sip] Expires: 129
Sep 2 16:36:08 TAU-8 user.notice syslog: 16:36:08.896[sip] l: 0
Sep 2 16:36:08 TAU-8 user.notice syslog: 16:36:08.896[sip]
Sep 2 16:36:08 TAU-8 user.notice syslog: 16:36:08.896[sip] ------------------------------------------------------------------------
Sep 2 16:36:08 TAU-8 user.debug syslog: 16:36:08.896[app:dbg]got nua_r_register : 200(OK)
Sep 2 16:36:08 TAU-8 user.debug syslog: 16:36:08.896[app:dbg]sip: endpoint 6: REGISTER: 200 OK
Sep 2 16:36:08 TAU-8 user.debug syslog: 16:36:08.896[app:dbg]Port 6: user port 0, old state hangup, new state
Sep 2 16:36:08 TAU-8 user.debug syslog: 16:36:08.896[app:dbg]sip: endpoint 6: successfully registered