[2015-05-21 15:51:28] DEBUG[27467][C-00000020] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] sip/reqresp_parser.c: Begin: parsing SIP "Supported: replaces, path, timer, eventlist"
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] sip/reqresp_parser.c: Found SIP option: -replaces-
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] sip/reqresp_parser.c: Matched SIP option: replaces
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] sip/reqresp_parser.c: Found SIP option: -path-
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] sip/reqresp_parser.c: Matched SIP option: path
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] sip/reqresp_parser.c: Found SIP option: -timer-
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] sip/reqresp_parser.c: Matched SIP option: timer
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] sip/reqresp_parser.c: Found SIP option: -eventlist-
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] sip/reqresp_parser.c: Matched SIP option: eventlist
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] netsock2.c: Splitting '192.168.1.22:3545' into...
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] netsock2.c: ...host '192.168.1.22' and port '3545'.
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] chan_sip.c: NAT detected for 192.168.1.22 / 213.230.73.9
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] netsock2.c: Splitting 'talk37.ru:5061' into...
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] netsock2.c: ...host 'talk37.ru' and port ''.
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] chan_sip.c: Trying to put 'SIP/2.0 401' onto TLS socket destined for 213.230.73.9:3545
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] chan_sip.c: Stopping retransmission on '2116297354-50500-4@BJC.BGI.B.CC' of Response 30: Match Not Found
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] netsock2.c: Splitting '192.168.1.22:3545' into...
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] netsock2.c: ...host '192.168.1.22' and port '3545'.
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] chan_sip.c: NAT detected for 192.168.1.22 / 213.230.73.9
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] netsock2.c: Splitting 'talk37.ru:5061' into...
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] netsock2.c: ...host 'talk37.ru' and port ''.
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fbd900058f8'
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] res_rtp_asterisk.c: Allocated port 25564 for RTP instance '0x7fbd900058f8'
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] pjsip: 	icess0x7fbd900 ICE session created, comp_cnt=2, role is Unknown agent
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] netsock2.c: Splitting '85.142.148.80' into...
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] netsock2.c: ...host '85.142.148.80' and port ''.
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] pjsip: 	icess0x7fbd900 Candidate 0 added: comp_id=1, type=host, foundation=H558e9450, addr=85.142.148.80:25564, base=85.142.148.80:25564, prio=0x7effffff (2130706431)
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] netsock2.c: Splitting '85.142.148.80' into...
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] netsock2.c: ...host '85.142.148.80' and port ''.
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] netsock2.c: Splitting '85.142.148.80' into...
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] netsock2.c: ...host '85.142.148.80' and port ''.
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] pjsip: 	icess0x7fbd900 Candidate 1 added: comp_id=1, type=srflx, foundation=S558e9450, addr=85.142.148.80:25564, base=85.142.148.80:25564, prio=0x64ffffff (1694498815)
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] rtp_engine.c: RTP instance '0x7fbd900058f8' is setup and ready to go
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] pjsip: 	icess0x7fbd900 Destroying ICE session 0x7fbd90011868
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] pjsip: 	stuse0x7fbd900 STUN session 0x7fbd9000ab08 destroy request, ref_cnt=4
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] pjsip: 	stuse0x7fbd900 STUN session 0x7fbd90014098 destroy request, ref_cnt=3
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] pjsip: 	 ice_session.c ICE session 0x7fbd90011868 destroyed
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] pjsip: 	stun_session.c STUN session 0x7fbd9000ab08 destroyed
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] pjsip: 	stun_session.c STUN session 0x7fbd90014098 destroyed
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fbd9000ab38'
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] res_rtp_asterisk.c: Allocated port 29276 for RTP instance '0x7fbd9000ab38'
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] pjsip: 	icess0x7fbd900 ICE session created, comp_cnt=2, role is Unknown agent
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] netsock2.c: Splitting '85.142.148.80' into...
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] netsock2.c: ...host '85.142.148.80' and port ''.
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] pjsip: 	icess0x7fbd900 Candidate 0 added: comp_id=1, type=host, foundation=H558e9450, addr=85.142.148.80:29276, base=85.142.148.80:29276, prio=0x7effffff (2130706431)
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] netsock2.c: Splitting '85.142.148.80' into...
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] netsock2.c: ...host '85.142.148.80' and port ''.
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] netsock2.c: Splitting '85.142.148.80' into...
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] netsock2.c: ...host '85.142.148.80' and port ''.
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] pjsip: 	icess0x7fbd900 Candidate 1 added: comp_id=1, type=srflx, foundation=S558e9450, addr=85.142.148.80:29276, base=85.142.148.80:29276, prio=0x64ffffff (1694498815)
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] rtp_engine.c: RTP instance '0x7fbd9000ab38' is setup and ready to go
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] pjsip: 	icess0x7fbd900 Destroying ICE session 0x7fbd900148f8
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] pjsip: 	stuse0x7fbd900 STUN session 0x7fbd90016908 destroy request, ref_cnt=4
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] pjsip: 	stuse0x7fbd900 STUN session 0x7fbd900174f8 destroy request, ref_cnt=3
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] pjsip: 	 ice_session.c ICE session 0x7fbd900148f8 destroyed
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] pjsip: 	stun_session.c STUN session 0x7fbd90016908 destroyed
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] pjsip: 	stun_session.c STUN session 0x7fbd900174f8 destroyed
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fbd9000ab38'
[2015-05-21 15:51:28] VERBOSE[27467][C-00000020] netsock2.c: Using SIP VIDEO CoS mark 6
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fbd90018ce8'
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] res_rtp_asterisk.c: Allocated port 30200 for RTP instance '0x7fbd90018ce8'
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] pjsip: 	icess0x7fbd900 ICE session created, comp_cnt=2, role is Unknown agent
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] netsock2.c: Splitting '85.142.148.80' into...
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] netsock2.c: ...host '85.142.148.80' and port ''.
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] pjsip: 	icess0x7fbd900 Candidate 0 added: comp_id=1, type=host, foundation=H558e9450, addr=85.142.148.80:30200, base=85.142.148.80:30200, prio=0x7effffff (2130706431)
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] netsock2.c: Splitting '85.142.148.80' into...
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] netsock2.c: ...host '85.142.148.80' and port ''.
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] netsock2.c: Splitting '85.142.148.80' into...
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] netsock2.c: ...host '85.142.148.80' and port ''.
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] pjsip: 	icess0x7fbd900 Candidate 1 added: comp_id=1, type=srflx, foundation=S558e9450, addr=85.142.148.80:30200, base=85.142.148.80:30200, prio=0x64ffffff (1694498815)
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] rtp_engine.c: RTP instance '0x7fbd90018ce8' is setup and ready to go
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] pjsip: 	icess0x7fbd900 Destroying ICE session 0x7fbd900197c8
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] pjsip: 	stuse0x7fbd900 STUN session 0x7fbd9001b7d8 destroy request, ref_cnt=4
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] pjsip: 	stuse0x7fbd900 STUN session 0x7fbd9001c3c8 destroy request, ref_cnt=3
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] pjsip: 	 ice_session.c ICE session 0x7fbd900197c8 destroyed
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] pjsip: 	stun_session.c STUN session 0x7fbd9001b7d8 destroyed
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] pjsip: 	stun_session.c STUN session 0x7fbd9001c3c8 destroyed
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fbd90018ce8'
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fbd900058f8'
[2015-05-21 15:51:28] VERBOSE[27467][C-00000020] netsock2.c: Using SIP RTP CoS mark 5
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] chan_sip.c: Setting NAT on RTP to On
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] chan_sip.c: Setting NAT on VRTP to On
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] chan_sip.c: Setting NAT on TRTP to On
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED.
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] chan_sip.c: Processing session-level SDP o=5312 8000 8000 IN IP4 192.168.1.22... OK.
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] chan_sip.c: Processing session-level SDP s=SIP Call... UNSUPPORTED OR FAILED.
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] netsock2.c: Splitting '192.168.1.22' into...
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] netsock2.c: ...host '192.168.1.22' and port ''.
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] chan_sip.c: Processing session-level SDP c=IN IP4 192.168.1.22... OK.
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED.
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] rtp_engine.c: Setting payload 8 (0x7fbd9000b268) based on m type on 0x7fbcf9a412a0
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] rtp_engine.c: Setting payload 101 (0x7fbd900014d8) based on m type on 0x7fbcf9a412a0
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK.
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK.
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED OR FAILED.
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fbd900058f8'
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] rtp_engine.c: Copying payload 8 (0x7fbd9001aaa8) from 0x7fbcf9a412a0 to 0x7fbd90005ac0
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] rtp_engine.c: Copying payload 101 (0x7fbd9000b268) from 0x7fbcf9a412a0 to 0x7fbd90005ac0
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7fbd900058f8'
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fbd9000ab38'
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fbd90018ce8'
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] chan_sip.c: We're settling with these formats: (alaw)
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] chan_sip.c: Checking SIP call limits for device 5312
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] chan_sip.c: Updating call counter for incoming call
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] netsock2.c: Splitting 'talk37.ru:5061' into...
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] netsock2.c: ...host 'talk37.ru' and port ''.
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] netsock2.c: Splitting 'talk37.ru:5061' into...
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] netsock2.c: ...host 'talk37.ru' and port ''.
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] chan_sip.c: Incoming INVITE with 'timer' option supported
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] chan_sip.c: *** Our native formats are (alaw) 
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] chan_sip.c: *** Joint capabilities are (alaw) 
[2015-05-21 15:51:28] VERBOSE[27467][C-00000020] strings.c: ailed to extend rom 64 to 99
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] chan_sip.c: *** Our capabilities are (alaw|g722|ulaw|slin|speex|gsm|g729|vp8|h264|h263|h263p|h261|) 
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] chan_sip.c: *** AST_CODEC_CHOOSE formats are alaw 
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] chan_sip.c: This channel can handle video! HOLLYWOOD next!
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] chan_sip.c: SIP/5312-00000034: New call is still down.... Trying... 
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] chan_sip.c: Trying to put 'SIP/2.0 100' onto TLS socket destined for 213.230.73.9:3545
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Function CALLERID(num) result is '5312'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'EXTEN' is '0101'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'SIPDOMAIN' is 'talk37.ru'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'Macro'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [0101@context-user:1] Macro("SIP/5312-00000034", "outgoing-from-user,5312,0101,talk37.ru") in new stack
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Function CDR(accountcode) result is '5312'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'NoOp'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@macro-outgoing-from-user:1] NoOp("SIP/5312-00000034", "Accountcode 5312") in new stack
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] app_macro.c: Executed application: NoOp
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'CHANNEL' is 'SIP/5312-00000034'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Expression result is '0'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'GotoIf'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@macro-outgoing-from-user:2] GotoIf("SIP/5312-00000034", "0?end") in new stack
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Not taking any branch
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] app_macro.c: Executed application: GotoIf
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Function CALLERID(all) result is '"" <5312>'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'NoOp'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@macro-outgoing-from-user:3] NoOp("SIP/5312-00000034", "CallerID: "" <5312>") in new stack
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] app_macro.c: Executed application: NoOp
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'Set'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@macro-outgoing-from-user:4] Set("SIP/5312-00000034", "CHANNEL(language)=ru") in new stack
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] app_macro.c: Executed application: Set
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'ARG1' is '5312'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'Set'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@macro-outgoing-from-user:5] Set("SIP/5312-00000034", "agi_call_from=5312") in new stack
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] app_macro.c: Executed application: Set
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'agi_call_from' is '5312'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'Set'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@macro-outgoing-from-user:6] Set("SIP/5312-00000034", "CDR(src2)=5312") in new stack
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] app_macro.c: Executed application: Set
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Function CHANNEL(recvip) result is '213.230.73.9'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'Set'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@macro-outgoing-from-user:7] Set("SIP/5312-00000034", "fromIP=213.230.73.9") in new stack
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] app_macro.c: Executed application: Set
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'fromIP' is '213.230.73.9'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'Set'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@macro-outgoing-from-user:8] Set("SIP/5312-00000034", "CDR(remote_signal_ip)=213.230.73.9") in new stack
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] app_macro.c: Executed application: Set
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'Set'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@macro-outgoing-from-user:9] Set("SIP/5312-00000034", "CDR(direction)=o") in new stack
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] app_macro.c: Executed application: Set
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'accountcode' is NULL
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Expression result is '1'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'GotoIf'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@macro-outgoing-from-user:10] GotoIf("SIP/5312-00000034", "1?set1") in new stack
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Goto (macro-outgoing-from-user,s,12)
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] app_macro.c: Executed application: GotoIf
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'NoOp'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@macro-outgoing-from-user:12] NoOp("SIP/5312-00000034", "") in new stack
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] app_macro.c: Executed application: NoOp
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'fromDeviceId' is '2142'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'Set'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@macro-outgoing-from-user:13] Set("SIP/5312-00000034", "CDR(fromDeviceId)=2142") in new stack
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] app_macro.c: Executed application: Set
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'fromUserId' is '3828'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'Set'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@macro-outgoing-from-user:14] Set("SIP/5312-00000034", "CDR(fromUserId)=3828") in new stack
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] app_macro.c: Executed application: Set
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'ARG2' is '0101'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'Set'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@macro-outgoing-from-user:15] Set("SIP/5312-00000034", "agi_call_exten=0101") in new stack
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] app_macro.c: Executed application: Set
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'ARG3' is 'talk37.ru'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'Set'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@macro-outgoing-from-user:16] Set("SIP/5312-00000034", "agi_call_domain=talk37.ru") in new stack
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] app_macro.c: Executed application: Set
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'Macro'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@macro-outgoing-from-user:17] Macro("SIP/5312-00000034", "check-domain") in new stack
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'agi_call_domain' is 'talk37.ru'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Expression result is '1'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Evaluating 'agi_call_exten' (from 'agi_call_exten}' len 14)
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'agi_call_exten' is '0101'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Function CUT(agi_call_exten,@,2) result is ''
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Expression result is '1'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Expression result is '1'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'GotoIf'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@macro-check-domain:1] GotoIf("SIP/5312-00000034", "1?skip-set-domain") in new stack
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Goto (macro-check-domain,s,4)
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] app_macro.c: Executed application: GotoIf
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'NoOp'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@macro-check-domain:4] NoOp("SIP/5312-00000034", "") in new stack
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] app_macro.c: Executed application: NoOp
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] app_macro.c: Executed application: Macro
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'agi_call_exten' is '0101'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Expression result is '0'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'GotoIf'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@macro-outgoing-from-user:18] GotoIf("SIP/5312-00000034", "0?dial-voice") in new stack
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Not taking any branch
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] app_macro.c: Executed application: GotoIf
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'CHANNEL' is 'SIP/5312-00000034'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'fromUserId' is '3828'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'fromDeviceId' is '2142'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Function CALLERID(num) result is '5312'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'agi_call_exten' is '0101'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'agi_call_domain' is 'talk37.ru'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'prior_mode' is NULL
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'AGI'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@macro-outgoing-from-user:19] AGI("SIP/5312-00000034", "agi-talk37.php,outgoing/check_callback_speeddial,SIP/5312-00000034,3828,2142,5312,0101,talk37.ru,") in new stack
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/agi-talk37.php
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] res_agi.c: <SIP/5312-00000034>AGI Script agi-talk37.php completed, returning 0
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] app_macro.c: Executed application: agi
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'agi_call_src' is '5312'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'Set'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@macro-outgoing-from-user:20] Set("SIP/5312-00000034", "CDR(src2)=5312") in new stack
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] app_macro.c: Executed application: Set
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'agi_user_id' is '3828'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'Set'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@macro-outgoing-from-user:21] Set("SIP/5312-00000034", "agi_outgoing_user_id=3828") in new stack
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] app_macro.c: Executed application: Set
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'Macro'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@macro-outgoing-from-user:22] Macro("SIP/5312-00000034", "check-domain") in new stack
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'agi_call_domain' is ''
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Expression result is '0'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Evaluating 'agi_call_exten' (from 'agi_call_exten}' len 14)
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'agi_call_exten' is '0101'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Function CUT(agi_call_exten,@,2) result is ''
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Expression result is '1'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Expression result is '1'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'GotoIf'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@macro-check-domain:1] GotoIf("SIP/5312-00000034", "1?skip-set-domain") in new stack
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Goto (macro-check-domain,s,4)
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] app_macro.c: Executed application: GotoIf
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'NoOp'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@macro-check-domain:4] NoOp("SIP/5312-00000034", "") in new stack
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] app_macro.c: Executed application: NoOp
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] app_macro.c: Executed application: Macro
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'agi_call_domain' is ''
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Expression result is '1'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'agi_call_exten' is '0101'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'agi_call_exten' is '0101'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'agi_call_domain' is ''
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Function IF(1?0101:0101@) result is '0101'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'Set'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@macro-outgoing-from-user:23] Set("SIP/5312-00000034", "CDR(dst2)=0101") in new stack
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] app_macro.c: Executed application: Set
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'agi_call_mode' is 'dial'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Expression result is '0'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'GotoIf'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@macro-outgoing-from-user:24] GotoIf("SIP/5312-00000034", "0?dial-callback") in new stack
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Not taking any branch
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] app_macro.c: Executed application: GotoIf
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'agi_call_domain_external' is NULL
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Expression result is '0'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'GotoIf'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@macro-outgoing-from-user:25] GotoIf("SIP/5312-00000034", "0?dial-via-srv") in new stack
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Not taking any branch
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] app_macro.c: Executed application: GotoIf
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'agi_call_context' is 'context-user'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'context_postfix' is NULL
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Evaluating 'agi_call_exten' (from 'agi_call_exten}' len 14)
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'agi_call_exten' is '0101'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Function CUT(agi_call_exten,@,1) result is '0101'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'Goto'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@macro-outgoing-from-user:26] Goto("SIP/5312-00000034", "context-user-int,0101,1") in new stack
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Goto (context-user-int,0101,1)
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] app_macro.c: Executed application: Goto
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] app_macro.c: Channel 'SIP/5312-00000034' jumping out of macro 'outgoing-from-user'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'EXTEN' is '0101'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'Macro'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [0101@context-user-int:1] Macro("SIP/5312-00000034", "outgoing-via-server,0101") in new stack
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'NoOp'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@macro-outgoing-via-server:1] NoOp("SIP/5312-00000034", "Starting...") in new stack
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] app_macro.c: Executed application: NoOp
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'MACRO_CONTEXT' is 'context-user-int'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'Set'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@macro-outgoing-via-server:2] Set("SIP/5312-00000034", "CALL_CONTEXT=context-user-int") in new stack
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] app_macro.c: Executed application: Set
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'Goto'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@macro-outgoing-via-server:3] Goto("SIP/5312-00000034", "outgoing-via-server,s,1") in new stack
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Goto (outgoing-via-server,s,1)
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] app_macro.c: Executed application: Goto
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] app_macro.c: Channel 'SIP/5312-00000034' jumping out of macro 'outgoing-via-server'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'NoOp'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@outgoing-via-server:1] NoOp("SIP/5312-00000034", "Starting...") in new stack
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'Set'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@outgoing-via-server:2] Set("SIP/5312-00000034", "CheckCount=0") in new stack
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Function CHANNEL(recvip) result is '213.230.73.9'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'Set'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@outgoing-via-server:3] Set("SIP/5312-00000034", "fromIP=213.230.73.9") in new stack
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Function CALLERID(num) result is '5312'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'Set'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@outgoing-via-server:4] Set("SIP/5312-00000034", "fromCallerID=5312") in new stack
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'fromIP' is '213.230.73.9'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'Set'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@outgoing-via-server:5] Set("SIP/5312-00000034", "CDR(remote_signal_ip)=213.230.73.9") in new stack
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'CHANNEL' is 'SIP/5312-00000034'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'agi_outgoing_user_id' is '3828'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'fromDeviceId' is '2142'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'fromIP' is '213.230.73.9'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'fromCallerID' is '5312'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'agi_call_exten' is '0101'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'agi_call_domain' is ''
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'prior_mode' is NULL
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'AGI'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@outgoing-via-server:6] AGI("SIP/5312-00000034", "agi-talk37.php,outgoing/choose_actions,SIP/5312-00000034,3828,2142,213.230.73.9,5312,0101,,") in new stack
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/agi-talk37.php
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] res_agi.c: <SIP/5312-00000034>AGI Script agi-talk37.php completed, returning 0
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Function CALLERID(num) result is '5312'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'NoOp'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@outgoing-via-server:7] NoOp("SIP/5312-00000034", "CallerID:5312") in new stack
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'agi_call_dialplan' is NULL
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'Set'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@outgoing-via-server:8] Set("SIP/5312-00000034", "CDR(acc_code)=") in new stack
)[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'agi_call_direction_id' is NULL
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'Set'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@outgoing-via-server:9] Set("SIP/5312-00000034", "CDR(direction_id)=") in new stack
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'globalFileLogOutgoing' is '/var/log/asterisk/logOutgoing'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'EPOCH' is '1432212688'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Function STRFTIME(1432212688,,%Y-%m-%d %H:%M:%S) result is '2015-05-21 15:51:28'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Function CALLERID(num) result is '5312'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'fromIP' is '213.230.73.9'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'fromDeviceId' is '2142'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'agi_call_exten' is '0101'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'agi_call_domain' is ''
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'CHANNEL' is 'SIP/5312-00000034'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'Set'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@outgoing-via-server:10] Set("SIP/5312-00000034", "FILE(/var/log/asterisk/logOutgoing,,,al,u)=[2015-05-21 15:51:28] Outgoing from '5312' (ip '213.230.73.9', deviceId '2142') to '0101' domain ''. Channel: 'SIP/5312-00000034'") in new stack
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'agi_call_status' is 'allow-dial-service'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Expression result is '0'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'GotoIf'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@outgoing-via-server:11] GotoIf("SIP/5312-00000034", "0?loop-start") in new stack
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Not taking any branch
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'agi_call_status' is 'allow-dial-service'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Expression result is '0'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'GotoIf'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@outgoing-via-server:12] GotoIf("SIP/5312-00000034", "0?dial-to-domain") in new stack
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Not taking any branch
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'agi_call_status' is 'allow-dial-service'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Expression result is '1'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'GotoIf'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@outgoing-via-server:13] GotoIf("SIP/5312-00000034", "1?dial-to-service") in new stack
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Goto (outgoing-via-server,s,28)
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'Set'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@outgoing-via-server:28] Set("SIP/5312-00000034", "CDR(direction_id)=357") in new stack
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'agi_call_item_id' is 'service-int'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'agi_call_exten' is '0101'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'Goto'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@outgoing-via-server:29] Goto("SIP/5312-00000034", "service-int,0101,1") in new stack
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Goto (service-int,0101,1)
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'Macro'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [0101@service-int:1] Macro("SIP/5312-00000034", "check-mail") in new stack
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'fromUserId' is '3828'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Expression result is '0'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'GotoIf'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@macro-check-mail:1] GotoIf("SIP/5312-00000034", "0?hangup") in new stack
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Not taking any branch
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] app_macro.c: Executed application: GotoIf
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'fromDeviceId' is '2142'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Expression result is '0'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'GotoIf'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@macro-check-mail:2] GotoIf("SIP/5312-00000034", "0?hangup") in new stack
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Not taking any branch
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] app_macro.c: Executed application: GotoIf
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'fromUserId' is '3828'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'fromDeviceId' is '2142'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'AGI'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@macro-check-mail:3] AGI("SIP/5312-00000034", "agi-talk37.php,incoming/vmail_check,3828,2142") in new stack
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/agi-talk37.php
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] res_agi.c: <SIP/5312-00000034>AGI Script agi-talk37.php completed, returning 0
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] app_macro.c: Executed application: agi
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Result of 'agi_mailbox' is '5312'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Expression result is '0'
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'GotoIf'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@macro-check-mail:4] GotoIf("SIP/5312-00000034", "0?hangup") in new stack
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Not taking any branch
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] app_macro.c: Executed application: GotoIf
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] pbx.c: Launching 'Answer'
[2015-05-21 15:51:28] VERBOSE[27953][C-00000020] pbx.c: Executing [s@macro-check-mail:5] Answer("SIP/5312-00000034", "") in new stack
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] chan_sip.c: SIP answering channel: SIP/5312-00000034
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] res_rtp_asterisk.c: Setting the marker bit due to a source update
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] chan_sip.c: Setting framing from config on incoming call
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] chan_sip.c: ** Our capability: (alaw) Video flag: True Text flag: True
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] chan_sip.c: ** Our prefcodec: (nothing) 
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] chan_sip.c: -- Done with adding codecs to SDP
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] chan_sip.c: Done building SDP. Settling with this capability: (alaw)
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] chan_sip.c: Trying to put 'SIP/2.0 200' onto TLS socket destined for 213.230.73.9:3545
[2015-05-21 15:51:28] DEBUG[27953][C-00000020] chan_sip.c: Session timer started: 166742 - 2116297354-50500-4@BJC.BGI.B.CC 900000ms
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[2015-05-21 15:51:28] DEBUG[27467][C-00000020] chan_sip.c: Stopping retransmission on '2116297354-50500-4@BJC.BGI.B.CC' of Response 31: Match Not Found
[2015-05-21 15:51:29] DEBUG[27953][C-00000020] res_rtp_asterisk.c: 0x7fbd9000ede0 -- Probation learning mode pass with source address 213.230.73.9:6698
[2015-05-21 15:51:29] DEBUG[27953][C-00000020] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fbd900058f8'
[2015-05-21 15:51:29] DEBUG[27953][C-00000020] app_macro.c: Executed application: Answer
[2015-05-21 15:51:29] DEBUG[27953][C-00000020] pbx.c: Launching 'Wait'
[2015-05-21 15:51:29] VERBOSE[27953][C-00000020] pbx.c: Executing [s@macro-check-mail:6] Wait("SIP/5312-00000034", "1") in new stack
[2015-05-21 15:51:29] DEBUG[27953][C-00000020] channel.c: Channel SIP/5312-00000034 setting write format path: slin -> alaw
[2015-05-21 15:51:29] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2015-05-21 15:51:29] DEBUG[27953][C-00000020] channel.c: Started silence generator on 'SIP/5312-00000034'
[2015-05-21 15:51:29] DEBUG[27953][C-00000020] res_rtp_asterisk.c: Ooh, format changed from none to alaw
[2015-05-21 15:51:29] DEBUG[27953][C-00000020] res_rtp_asterisk.c: 0x7fbd9000ede0 -- Probation learning mode pass with source address 213.230.73.9:6698
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] channel.c: Stopped silence generator on 'SIP/5312-00000034'
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] channel.c: Channel SIP/5312-00000034 setting write format path: alaw -> alaw
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] app_macro.c: Executed application: Wait
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] pbx.c: Result of 'agi_mailbox' is '5312'
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] pbx.c: Launching 'VoiceMailMain'
[2015-05-21 15:51:30] VERBOSE[27953][C-00000020] pbx.c: Executing [s@macro-check-mail:7] VoiceMailMain("SIP/5312-00000034", "5312@local") in new stack
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] res_config_mysql.c: MySQL RealTime: Connection okay.
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM voicemail WHERE mailbox = '5312' AND context = 'local'
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] app_voicemail.c: Before find user for mailbox 5312
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] res_config_mysql.c: MySQL RealTime: Connection okay.
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM voicemail WHERE mailbox = '5312' AND context = 'local'
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] app_voicemail.c: After vm_authenticate
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] app_voicemail.c: Before open_mailbox
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] app.c: Locked path '/var/spool/asterisk/voicemail/local/5312/Old'
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] app.c: Unlocked path '/var/spool/asterisk/voicemail/local/5312/Old'
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] app.c: Locked path '/var/spool/asterisk/voicemail/local/5312/Old'
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] app.c: Unlocked path '/var/spool/asterisk/voicemail/local/5312/Old'
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] app_voicemail.c: Number of old messages: 0
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] app.c: Locked path '/var/spool/asterisk/voicemail/local/5312/INBOX'
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] app.c: Unlocked path '/var/spool/asterisk/voicemail/local/5312/INBOX'
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] app.c: Locked path '/var/spool/asterisk/voicemail/local/5312/INBOX'
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] app_voicemail.c: /var/spool/asterisk/voicemail/local/5312/INBOX map[0] = 1, count = 1
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] app.c: Unlocked path '/var/spool/asterisk/voicemail/local/5312/INBOX'
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] app_voicemail.c: Number of new messages: 1
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] app.c: Locked path '/var/spool/asterisk/voicemail/local/5312/Urgent'
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] app.c: Unlocked path '/var/spool/asterisk/voicemail/local/5312/Urgent'
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] app.c: Locked path '/var/spool/asterisk/voicemail/local/5312/Urgent'
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] app.c: Unlocked path '/var/spool/asterisk/voicemail/local/5312/Urgent'
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] app_voicemail.c: Number of urgent messages: 0
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] app.c: Locked path '/var/spool/asterisk/voicemail/local/5312/INBOX'
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] app.c: Unlocked path '/var/spool/asterisk/voicemail/local/5312/INBOX'
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] app.c: Locked path '/var/spool/asterisk/voicemail/local/5312/INBOX'
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] app_voicemail.c: /var/spool/asterisk/voicemail/local/5312/INBOX map[0] = 1, count = 1
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] app.c: Unlocked path '/var/spool/asterisk/voicemail/local/5312/INBOX'
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2015-05-21 15:51:30] VERBOSE[27953][C-00000020] file.c: <SIP/5312-00000034> Playing 'vm-youhave.alaw' (language 'ru')
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (52 requested / 52 actual) timer ticks per second
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] app_playback.c: string <num:1> depth <0>
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] app_playback.c: try <num:1> in <ru>
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] app_playback.c: value is <1>
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] pbx.c: Result of 'SAY' is '1'
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] app_playback.c: doing [digits/1]
[2015-05-21 15:51:30] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2015-05-21 15:51:30] VERBOSE[27953][C-00000020] file.c: <SIP/5312-00000034> Playing 'digits/1.alaw' (language 'ru')
[2015-05-21 15:51:31] DEBUG[27953][C-00000020] res_rtp_asterisk.c: Got RTCP report of 92 bytes
[2015-05-21 15:51:31] DEBUG[27953][C-00000020] acl.c: Not an IPv4 nor IPv6 address, cannot get port.
[2015-05-21 15:51:31] DEBUG[27953][C-00000020] acl.c: Attached to given IP address
[2015-05-21 15:51:31] DEBUG[27953][C-00000020] acl.c: Not an IPv4 nor IPv6 address, cannot get port.
[2015-05-21 15:51:31] DEBUG[27953][C-00000020] acl.c: Attached to given IP address
[2015-05-21 15:51:31] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (88 requested / 88 actual) timer ticks per second
[2015-05-21 15:51:31] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:31] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:31] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:31] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2015-05-21 15:51:31] VERBOSE[27953][C-00000020] file.c: <SIP/5312-00000034> Playing 'vm-newn.alaw' (language 'ru')
[2015-05-21 15:51:32] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (57 requested / 57 actual) timer ticks per second
[2015-05-21 15:51:32] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:32] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:32] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:32] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2015-05-21 15:51:32] VERBOSE[27953][C-00000020] file.c: <SIP/5312-00000034> Playing 'vm-message.alaw' (language 'ru')
[2015-05-21 15:51:33] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (308 requested / 308 actual) timer ticks per second
[2015-05-21 15:51:33] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:33] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:33] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:33] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2015-05-21 15:51:33] VERBOSE[27953][C-00000020] file.c: <SIP/5312-00000034> Playing 'vm-onefor.alaw' (language 'ru')
[2015-05-21 15:51:33] DEBUG[27953][C-00000020] res_rtp_asterisk.c: Got RTCP report of 92 bytes
[2015-05-21 15:51:33] DEBUG[27953][C-00000020] acl.c: Not an IPv4 nor IPv6 address, cannot get port.
[2015-05-21 15:51:33] DEBUG[27953][C-00000020] acl.c: Attached to given IP address
[2015-05-21 15:51:33] DEBUG[27953][C-00000020] acl.c: Not an IPv4 nor IPv6 address, cannot get port.
[2015-05-21 15:51:33] DEBUG[27953][C-00000020] acl.c: Attached to given IP address
[2015-05-21 15:51:35] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (68 requested / 68 actual) timer ticks per second
[2015-05-21 15:51:35] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:35] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:35] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:35] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2015-05-21 15:51:35] VERBOSE[27953][C-00000020] file.c: <SIP/5312-00000034> Playing 'vm-INBOX.alaw' (language 'ru')
[2015-05-21 15:51:36] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (57 requested / 57 actual) timer ticks per second
[2015-05-21 15:51:36] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:36] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:36] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:36] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2015-05-21 15:51:36] VERBOSE[27953][C-00000020] file.c: <SIP/5312-00000034> Playing 'vm-messages.alaw' (language 'ru')
[2015-05-21 15:51:36] DEBUG[27953][C-00000020] res_rtp_asterisk.c: Got RTCP report of 92 bytes
[2015-05-21 15:51:36] DEBUG[27953][C-00000020] acl.c: Not an IPv4 nor IPv6 address, cannot get port.
[2015-05-21 15:51:36] DEBUG[27953][C-00000020] acl.c: Attached to given IP address
[2015-05-21 15:51:36] DEBUG[27953][C-00000020] acl.c: Not an IPv4 nor IPv6 address, cannot get port.
[2015-05-21 15:51:36] DEBUG[27953][C-00000020] acl.c: Attached to given IP address
[2015-05-21 15:51:37] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (91 requested / 91 actual) timer ticks per second
[2015-05-21 15:51:37] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:37] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:37] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:37] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2015-05-21 15:51:37] VERBOSE[27953][C-00000020] file.c: <SIP/5312-00000034> Playing 'vm-opts.alaw' (language 'ru')
[2015-05-21 15:51:41] DEBUG[27953][C-00000020] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 49 (1), at 213.230.73.9:6698
[2015-05-21 15:51:41] DEBUG[27953][C-00000020] res_rtp_asterisk.c: Creating END DTMF Frame: 49 (1), at 213.230.73.9:6698
[2015-05-21 15:51:41] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:41] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:41] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2015-05-21 15:51:41] VERBOSE[27953][C-00000020] file.c: <SIP/5312-00000034> Playing 'vm-first.alaw' (language 'ru')
[2015-05-21 15:51:42] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (190 requested / 190 actual) timer ticks per second
[2015-05-21 15:51:42] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:42] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:42] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:42] DEBUG[27953][C-00000020] config.c: Parsing /var/spool/asterisk/voicemail/local/5312/INBOX/msg0000.txt
[2015-05-21 15:51:42] VERBOSE[27953][C-00000020] config.c: Parsing '/var/spool/asterisk/voicemail/local/5312/INBOX/msg0000.txt': Found
[2015-05-21 15:51:42] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2015-05-21 15:51:42] VERBOSE[27953][C-00000020] file.c: <SIP/5312-00000034> Playing 'vm-message.alaw' (language 'ru')
[2015-05-21 15:51:43] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (308 requested / 308 actual) timer ticks per second
[2015-05-21 15:51:43] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:43] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:43] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:43] DEBUG[27953][C-00000020] app_playback.c: string <datetime:'vm-received' q k 'ru/hours' M 'ru/minutes':201505171116.22-0-136> depth <0>
[2015-05-21 15:51:43] DEBUG[27953][C-00000020] app_playback.c: try <datetime:'vm-received' q k 'ru/hours' M 'ru/minutes':201505171116.22-0-136> in <ru>
[2015-05-21 15:51:43] DEBUG[27953][C-00000020] app_voicemail.c: VM-CID: composite caller ID received: "demon" <9000>, context: outgoing-via-server
[2015-05-21 15:51:43] DEBUG[27953][C-00000020] app_voicemail.c: VM-CID: comparing internalcontext: 
[2015-05-21 15:51:43] DEBUG[27953][C-00000020] app_voicemail.c: VM-CID: comparing internalcontext: 
[2015-05-21 15:51:43] DEBUG[27953][C-00000020] app_voicemail.c: VM-CID: comparing internalcontext: 
[2015-05-21 15:51:43] DEBUG[27953][C-00000020] app_voicemail.c: VM-CID: comparing internalcontext: 
[2015-05-21 15:51:43] DEBUG[27953][C-00000020] app_voicemail.c: VM-CID: comparing internalcontext: 
[2015-05-21 15:51:43] DEBUG[27953][C-00000020] app_voicemail.c: VM-CID: comparing internalcontext: 
[2015-05-21 15:51:43] DEBUG[27953][C-00000020] app_voicemail.c: VM-CID: comparing internalcontext: 
[2015-05-21 15:51:43] DEBUG[27953][C-00000020] app_voicemail.c: VM-CID: comparing internalcontext: 
[2015-05-21 15:51:43] DEBUG[27953][C-00000020] app_voicemail.c: VM-CID: comparing internalcontext: 
[2015-05-21 15:51:43] DEBUG[27953][C-00000020] app_voicemail.c: VM-CID: comparing internalcontext: 
[2015-05-21 15:51:43] DEBUG[27953][C-00000020] app_voicemail.c: VM-CID: Numeric caller id: (9000)
[2015-05-21 15:51:43] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2015-05-21 15:51:43] VERBOSE[27953][C-00000020] file.c: <SIP/5312-00000034> Playing 'vm-from-phonenumber.alaw' (language 'ru')
[2015-05-21 15:51:45] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (79 requested / 79 actual) timer ticks per second
[2015-05-21 15:51:45] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:45] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:45] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:45] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2015-05-21 15:51:45] VERBOSE[27953][C-00000020] file.c: <SIP/5312-00000034> Playing 'digits/9.alaw' (language 'ru')
[2015-05-21 15:51:46] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (63 requested / 63 actual) timer ticks per second
[2015-05-21 15:51:46] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:46] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:46] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:46] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2015-05-21 15:51:46] VERBOSE[27953][C-00000020] file.c: <SIP/5312-00000034> Playing 'digits/0.alaw' (language 'ru')
[2015-05-21 15:51:46] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (400 requested / 400 actual) timer ticks per second
[2015-05-21 15:51:46] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:46] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:46] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:46] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2015-05-21 15:51:46] VERBOSE[27953][C-00000020] file.c: <SIP/5312-00000034> Playing 'digits/0.alaw' (language 'ru')
[2015-05-21 15:51:47] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (400 requested / 400 actual) timer ticks per second
[2015-05-21 15:51:47] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:47] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:47] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:47] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2015-05-21 15:51:47] VERBOSE[27953][C-00000020] file.c: <SIP/5312-00000034> Playing 'digits/0.alaw' (language 'ru')
[2015-05-21 15:51:47] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (400 requested / 400 actual) timer ticks per second
[2015-05-21 15:51:47] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:47] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:47] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:47] DEBUG[27953][C-00000020] app_voicemail.c: VM-Duration: duration is: 7 seconds converted to: 0 minutes
[2015-05-21 15:51:47] DEBUG[27953][C-00000020] channel.c: Channel SIP/5312-00000034 setting write format path: slin -> alaw
[2015-05-21 15:51:47] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2015-05-21 15:51:47] VERBOSE[27953][C-00000020] file.c: <SIP/5312-00000034> Playing '/var/spool/asterisk/voicemail/local/5312/INBOX/msg0000.slin' (language 'ru')
[2015-05-21 15:51:55] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (58 requested / 58 actual) timer ticks per second
[2015-05-21 15:51:55] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:55] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:55] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:55] DEBUG[27953][C-00000020] channel.c: Channel SIP/5312-00000034 setting write format path: alaw -> alaw
[2015-05-21 15:51:55] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2015-05-21 15:51:55] VERBOSE[27953][C-00000020] file.c: <SIP/5312-00000034> Playing 'vm-advopts.alaw' (language 'ru')
[2015-05-21 15:51:58] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (111 requested / 111 actual) timer ticks per second
[2015-05-21 15:51:58] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:58] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:58] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:51:58] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2015-05-21 15:51:58] VERBOSE[27953][C-00000020] file.c: <SIP/5312-00000034> Playing 'vm-repeat.alaw' (language 'ru')
[2015-05-21 15:52:00] DEBUG[27953][C-00000020] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 49 (1), at 213.230.73.9:6698
[2015-05-21 15:52:00] DEBUG[27953][C-00000020] res_rtp_asterisk.c: Creating END DTMF Frame: 49 (1), at 213.230.73.9:6698
[2015-05-21 15:52:00] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:52:00] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:52:00] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2015-05-21 15:52:00] VERBOSE[27953][C-00000020] file.c: <SIP/5312-00000034> Playing 'vm-first.alaw' (language 'ru')
[2015-05-21 15:52:01] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (190 requested / 190 actual) timer ticks per second
[2015-05-21 15:52:01] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:52:01] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:52:01] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:52:01] DEBUG[27953][C-00000020] config.c: Parsing /var/spool/asterisk/voicemail/local/5312/INBOX/msg0000.txt
[2015-05-21 15:52:01] VERBOSE[27953][C-00000020] config.c: Parsing '/var/spool/asterisk/voicemail/local/5312/INBOX/msg0000.txt': Found
[2015-05-21 15:52:01] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2015-05-21 15:52:01] VERBOSE[27953][C-00000020] file.c: <SIP/5312-00000034> Playing 'vm-message.alaw' (language 'ru')
[2015-05-21 15:52:01] DEBUG[27953][C-00000020] res_rtp_asterisk.c: Got RTCP report of 92 bytes
[2015-05-21 15:52:01] DEBUG[27953][C-00000020] acl.c: Not an IPv4 nor IPv6 address, cannot get port.
[2015-05-21 15:52:01] DEBUG[27953][C-00000020] acl.c: Attached to given IP address
[2015-05-21 15:52:01] DEBUG[27953][C-00000020] acl.c: Not an IPv4 nor IPv6 address, cannot get port.
[2015-05-21 15:52:01] DEBUG[27953][C-00000020] acl.c: Attached to given IP address
[2015-05-21 15:52:02] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (308 requested / 308 actual) timer ticks per second
[2015-05-21 15:52:02] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:52:02] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:52:02] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:52:02] DEBUG[27953][C-00000020] app_playback.c: string <datetime:'vm-received' q k 'ru/hours' M 'ru/minutes':201505171116.22-0-136> depth <0>
[2015-05-21 15:52:02] DEBUG[27953][C-00000020] app_playback.c: try <datetime:'vm-received' q k 'ru/hours' M 'ru/minutes':201505171116.22-0-136> in <ru>
[2015-05-21 15:52:02] DEBUG[27953][C-00000020] app_voicemail.c: VM-CID: composite caller ID received: "demon" <9000>, context: outgoing-via-server
[2015-05-21 15:52:02] DEBUG[27953][C-00000020] app_voicemail.c: VM-CID: comparing internalcontext: 
[2015-05-21 15:52:02] DEBUG[27953][C-00000020] app_voicemail.c: VM-CID: comparing internalcontext: 
[2015-05-21 15:52:02] DEBUG[27953][C-00000020] app_voicemail.c: VM-CID: comparing internalcontext: 
[2015-05-21 15:52:02] DEBUG[27953][C-00000020] app_voicemail.c: VM-CID: comparing internalcontext: 
[2015-05-21 15:52:02] DEBUG[27953][C-00000020] app_voicemail.c: VM-CID: comparing internalcontext: 
[2015-05-21 15:52:02] DEBUG[27953][C-00000020] app_voicemail.c: VM-CID: comparing internalcontext: 
[2015-05-21 15:52:02] DEBUG[27953][C-00000020] app_voicemail.c: VM-CID: comparing internalcontext: 
[2015-05-21 15:52:02] DEBUG[27953][C-00000020] app_voicemail.c: VM-CID: comparing internalcontext: 
[2015-05-21 15:52:02] DEBUG[27953][C-00000020] app_voicemail.c: VM-CID: comparing internalcontext: 
[2015-05-21 15:52:02] DEBUG[27953][C-00000020] app_voicemail.c: VM-CID: comparing internalcontext: 
[2015-05-21 15:52:02] DEBUG[27953][C-00000020] app_voicemail.c: VM-CID: Numeric caller id: (9000)
[2015-05-21 15:52:02] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2015-05-21 15:52:02] VERBOSE[27953][C-00000020] file.c: <SIP/5312-00000034> Playing 'vm-from-phonenumber.alaw' (language 'ru')
[2015-05-21 15:52:03] DEBUG[27953][C-00000020] res_rtp_asterisk.c: Got RTCP report of 92 bytes
[2015-05-21 15:52:03] DEBUG[27953][C-00000020] acl.c: Not an IPv4 nor IPv6 address, cannot get port.
[2015-05-21 15:52:03] DEBUG[27953][C-00000020] acl.c: Attached to given IP address
[2015-05-21 15:52:03] DEBUG[27953][C-00000020] acl.c: Not an IPv4 nor IPv6 address, cannot get port.
[2015-05-21 15:52:03] DEBUG[27953][C-00000020] acl.c: Attached to given IP address
[2015-05-21 15:52:04] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (79 requested / 79 actual) timer ticks per second
[2015-05-21 15:52:04] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:52:04] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:52:04] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:52:04] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2015-05-21 15:52:04] VERBOSE[27953][C-00000020] file.c: <SIP/5312-00000034> Playing 'digits/9.alaw' (language 'ru')
[2015-05-21 15:52:05] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (63 requested / 63 actual) timer ticks per second
[2015-05-21 15:52:05] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:52:05] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:52:05] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:52:05] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2015-05-21 15:52:05] VERBOSE[27953][C-00000020] file.c: <SIP/5312-00000034> Playing 'digits/0.alaw' (language 'ru')
[2015-05-21 15:52:06] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (400 requested / 400 actual) timer ticks per second
[2015-05-21 15:52:06] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:52:06] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:52:06] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:52:06] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2015-05-21 15:52:06] VERBOSE[27953][C-00000020] file.c: <SIP/5312-00000034> Playing 'digits/0.alaw' (language 'ru')
[2015-05-21 15:52:06] DEBUG[27953][C-00000020] res_rtp_asterisk.c: Got RTCP report of 92 bytes
[2015-05-21 15:52:06] DEBUG[27953][C-00000020] acl.c: Not an IPv4 nor IPv6 address, cannot get port.
[2015-05-21 15:52:06] DEBUG[27953][C-00000020] acl.c: Attached to given IP address
[2015-05-21 15:52:06] DEBUG[27953][C-00000020] acl.c: Not an IPv4 nor IPv6 address, cannot get port.
[2015-05-21 15:52:06] DEBUG[27953][C-00000020] acl.c: Attached to given IP address
[2015-05-21 15:52:06] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (400 requested / 400 actual) timer ticks per second
[2015-05-21 15:52:06] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:52:06] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:52:06] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:52:06] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2015-05-21 15:52:06] VERBOSE[27953][C-00000020] file.c: <SIP/5312-00000034> Playing 'digits/0.alaw' (language 'ru')
[2015-05-21 15:52:07] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (400 requested / 400 actual) timer ticks per second
[2015-05-21 15:52:07] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:52:07] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:52:07] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:52:07] DEBUG[27953][C-00000020] app_voicemail.c: VM-Duration: duration is: 7 seconds converted to: 0 minutes
[2015-05-21 15:52:07] DEBUG[27953][C-00000020] channel.c: Channel SIP/5312-00000034 setting write format path: slin -> alaw
[2015-05-21 15:52:07] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2015-05-21 15:52:07] VERBOSE[27953][C-00000020] file.c: <SIP/5312-00000034> Playing '/var/spool/asterisk/voicemail/local/5312/INBOX/msg0000.slin' (language 'ru')
[2015-05-21 15:52:14] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (58 requested / 58 actual) timer ticks per second
[2015-05-21 15:52:14] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:52:14] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:52:14] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:52:14] DEBUG[27953][C-00000020] channel.c: Channel SIP/5312-00000034 setting write format path: alaw -> alaw
[2015-05-21 15:52:14] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2015-05-21 15:52:14] VERBOSE[27953][C-00000020] file.c: <SIP/5312-00000034> Playing 'vm-advopts.alaw' (language 'ru')
[2015-05-21 15:52:17] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (111 requested / 111 actual) timer ticks per second
[2015-05-21 15:52:17] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:52:17] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:52:17] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:52:17] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2015-05-21 15:52:17] VERBOSE[27953][C-00000020] file.c: <SIP/5312-00000034> Playing 'vm-repeat.alaw' (language 'ru')
[2015-05-21 15:52:20] DEBUG[27953][C-00000020] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 35 (#), at 213.230.73.9:6698
[2015-05-21 15:52:20] DEBUG[27953][C-00000020] res_rtp_asterisk.c: Creating END DTMF Frame: 35 (#), at 213.230.73.9:6698
[2015-05-21 15:52:20] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:52:20] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:52:20] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2015-05-21 15:52:20] VERBOSE[27953][C-00000020] file.c: <SIP/5312-00000034> Playing 'vm-goodbye.alaw' (language 'ru')
[2015-05-21 15:52:21] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (91 requested / 91 actual) timer ticks per second
[2015-05-21 15:52:21] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:52:21] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:52:21] DEBUG[27953][C-00000020] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-05-21 15:52:21] DEBUG[27953][C-00000020] app.c: Locked path '/var/spool/asterisk/voicemail/local/5312/INBOX'
[2015-05-21 15:52:21] DEBUG[27953][C-00000020] app_voicemail.c: /var/spool/asterisk/voicemail/local/5312/INBOX map[0] = 1, count = 1
[2015-05-21 15:52:21] DEBUG[27953][C-00000020] app.c: Locked path '/var/spool/asterisk/voicemail/local/5312/Old'
[2015-05-21 15:52:21] DEBUG[27953][C-00000020] res_config_mysql.c: MySQL RealTime: Connection okay.
[2015-05-21 15:52:21] DEBUG[27953][C-00000020] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM voicemail_data WHERE filename = '/var/spool/asterisk/voicemail/local/5312/INBOX/msg0000'