Without doing any changes, some time call will be recorded but some other time it does not record. Below is the debugging. Please advice.
Not recording the call:
asterisk13CLI>
[2016-05-12 14:48:41] DEBUG[1703]: pjproject:0 <?>: sip_endpoint.c Processing incoming message: Request msg ACK/cseq=20 (rdata0x7f7a1800f958)
[2016-05-12 14:48:41] DEBUG[1703]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting ‘172.16.30.151:58357’ into…
[2016-05-12 14:48:41] DEBUG[1703]: netsock2.c:226 ast_sockaddr_split_hostport: …host ‘172.16.30.151’ and port ‘58357’.
[2016-05-12 14:48:41] DEBUG[1703]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting ‘0.0.0.0:5060’ into…
[2016-05-12 14:48:41] DEBUG[1703]: netsock2.c:226 ast_sockaddr_split_hostport: …host ‘0.0.0.0’ and port ‘5060’.
[2016-05-12 14:48:41] DEBUG[17044]: pjproject:0 <?>: sip_endpoint.c Distributing rdata to modules: Request msg ACK/cseq=20 (rdata0x7f7a18023008)
[2016-05-12 14:48:41] DEBUG[17044]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting ‘172.16.30.151’ into…
[2016-05-12 14:48:41] DEBUG[17044]: netsock2.c:226 ast_sockaddr_split_hostport: …host ‘172.16.30.151’ and port ‘’.
[2016-05-12 14:48:41] DEBUG[17044]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 172.16.30.151:58357 does not match identify ‘1994-identify’
[2016-05-12 14:48:41] DEBUG[17044]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 172.16.30.151:58357 does not match identify ‘1995-identify’
[2016-05-12 14:48:41] DEBUG[17044]: res_pjsip_endpoint_identifier_ip.c:137 ip_identify: ‘172.16.30.151:58357’ did not match any identify section rules
[2016-05-12 14:48:41] DEBUG[17044]: res_pjsip_endpoint_identifier_user.c:106 username_identify: Retrieved endpoint 1994
[2016-05-12 14:48:50] DEBUG[1703]: pjproject:0 <?>: sip_endpoint.c Processing incoming message: Request msg BYE/cseq=21 (rdata0x7f7a1800f958)
[2016-05-12 14:48:50] DEBUG[1703]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting ‘172.16.30.151:58357’ into…
[2016-05-12 14:48:50] DEBUG[1703]: netsock2.c:226 ast_sockaddr_split_hostport: …host ‘172.16.30.151’ and port ‘58357’.
[2016-05-12 14:48:50] DEBUG[1703]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting ‘0.0.0.0:5060’ into…
[2016-05-12 14:48:50] DEBUG[1703]: netsock2.c:226 ast_sockaddr_split_hostport: …host ‘0.0.0.0’ and port ‘5060’.
[2016-05-12 14:48:50] DEBUG[1703]: pjproject:0 <?>: endpoint .Response msg 481/BYE/cseq=21 (tdta0x2e21280) created
[2016-05-12 14:48:50] DEBUG[1703]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting ‘0.0.0.0:5060’ into…
[2016-05-12 14:48:50] DEBUG[1703]: netsock2.c:226 ast_sockaddr_split_hostport: …host ‘0.0.0.0’ and port ‘5060’.
[2016-05-12 14:48:50] DEBUG[1703]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting ‘172.16.30.151:58357’ into…
[2016-05-12 14:48:50] DEBUG[1703]: netsock2.c:226 ast_sockaddr_split_hostport: …host ‘172.16.30.151’ and port ‘58357’.
[2016-05-12 14:48:50] DEBUG[1703]: pjproject:0 <?>: tdta0x2e21280 .Destroying txdata Response msg 481/BYE/cseq=21 (tdta0x2e21280)
asterisk13CLI>
Recording the call:
asterisk13*CLI>
[2016-05-12 15:00:14] DEBUG[1703]: pjproject:0 <?>: sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=97 (rdata0x7f7a1800f958)
[2016-05-12 15:00:14] DEBUG[1703]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting ‘172.16.30.151:5060’ into…
[2016-05-12 15:00:14] DEBUG[1703]: netsock2.c:226 ast_sockaddr_split_hostport: …host ‘172.16.30.151’ and port ‘5060’.
[2016-05-12 15:00:14] DEBUG[1703]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting ‘0.0.0.0:5060’ into…
[2016-05-12 15:00:14] DEBUG[1703]: netsock2.c:226 ast_sockaddr_split_hostport: …host ‘0.0.0.0’ and port ‘5060’.
[2016-05-12 15:00:14] DEBUG[17044]: pjproject:0 <?>: sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=97 (rdata0x7f7a180244e8)
[2016-05-12 15:00:14] DEBUG[17044]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting ‘172.16.30.151’ into…
[2016-05-12 15:00:14] DEBUG[17044]: netsock2.c:226 ast_sockaddr_split_hostport: …host ‘172.16.30.151’ and port ‘’.
[2016-05-12 15:00:14] DEBUG[17044]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 172.16.30.151:5060 does not match identify ‘1994-identify’
[2016-05-12 15:00:14] DEBUG[17044]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 172.16.30.151:5060 does not match identify ‘1995-identify’
[2016-05-12 15:00:14] DEBUG[17044]: res_pjsip_endpoint_identifier_ip.c:137 ip_identify: ‘172.16.30.151:5060’ did not match any identify section rules
[2016-05-12 15:00:14] DEBUG[17044]: res_pjsip_endpoint_identifier_user.c:106 username_identify: Retrieved endpoint 1995
[2016-05-12 15:00:14] DEBUG[17044]: pjproject:0 <?>: endpoint .Response msg 401/INVITE/cseq=97 (tdta0x7f7a20032f20) created
[2016-05-12 15:00:14] DEBUG[17044]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting ‘172.16.30.86’ into…
[2016-05-12 15:00:14] DEBUG[17044]: netsock2.c:226 ast_sockaddr_split_hostport: …host ‘172.16.30.86’ and port ‘’.
[2016-05-12 15:00:14] DEBUG[17044]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting ‘172.16.30.151’ into…
[2016-05-12 15:00:14] DEBUG[17044]: netsock2.c:226 ast_sockaddr_split_hostport: …host ‘172.16.30.151’ and port ‘’.
[2016-05-12 15:00:14] DEBUG[17044]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting ‘0.0.0.0:5060’ into…
[2016-05-12 15:00:14] DEBUG[17044]: netsock2.c:226 ast_sockaddr_split_hostport: …host ‘0.0.0.0’ and port ‘5060’.
[2016-05-12 15:00:14] DEBUG[17044]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting ‘172.16.30.151:5060’ into…
[2016-05-12 15:00:14] DEBUG[17044]: netsock2.c:226 ast_sockaddr_split_hostport: …host ‘172.16.30.151’ and port ‘5060’.
[2016-05-12 15:00:14] DEBUG[17044]: pjproject:0 <?>: tdta0x7f7a2003 .Destroying txdata Response msg 401/INVITE/cseq=97 (tdta0x7f7a20032f20)
[2016-05-12 15:00:14] SECURITY[1741]: res_security_log.c:116 security_event_stasis_cb: SecurityEvent=“ChallengeSent”,EventTV=“2016-05-12T15:00:14.704+0800”,Severity=“Informational”,Service=“PJSIP”,EventVersion=“1”,AccountID=“1995”,SessionID="0066FCD6-7C16-E611-BC8E-2A1F3C58C911@172.16.30.151",LocalAddress=“IPV4/UDP/172.16.30.86/5060”,RemoteAddress=“IPV4/UDP/172.16.30.151/5060”,Challenge=""
[2016-05-12 15:00:14] DEBUG[1703]: pjproject:0 <?>: sip_endpoint.c Processing incoming message: Request msg ACK/cseq=97 (rdata0x7f7a1800f958)
[2016-05-12 15:00:14] DEBUG[1703]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting ‘172.16.30.151:5060’ into…
[2016-05-12 15:00:14] DEBUG[1703]: netsock2.c:226 ast_sockaddr_split_hostport: …host ‘172.16.30.151’ and port ‘5060’.
[2016-05-12 15:00:14] DEBUG[1703]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting ‘0.0.0.0:5060’ into…
[2016-05-12 15:00:14] DEBUG[1703]: netsock2.c:226 ast_sockaddr_split_hostport: …host ‘0.0.0.0’ and port ‘5060’.
[2016-05-12 15:00:14] DEBUG[17044]: pjproject:0 <?>: sip_endpoint.c Distributing rdata to modules: Request msg ACK/cseq=97 (rdata0x7f7a180244e8)
[2016-05-12 15:00:14] DEBUG[17044]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting ‘172.16.30.151’ into…
[2016-05-12 15:00:14] DEBUG[17044]: netsock2.c:226 ast_sockaddr_split_hostport: …host ‘172.16.30.151’ and port ‘’.
[2016-05-12 15:00:14] DEBUG[17044]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 172.16.30.151:5060 does not match identify ‘1994-identify’
[2016-05-12 15:00:14] DEBUG[17044]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 172.16.30.151:5060 does not match identify ‘1995-identify’
[2016-05-12 15:00:14] DEBUG[17044]: res_pjsip_endpoint_identifier_ip.c:137 ip_identify: ‘172.16.30.151:5060’ did not match any identify section rules
[2016-05-12 15:00:14] DEBUG[17044]: res_pjsip_endpoint_identifier_user.c:106 username_identify: Retrieved endpoint 1995
[2016-05-12 15:00:14] DEBUG[1703]: pjproject:0 <?>: sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=98 (rdata0x7f7a1800f958)
[2016-05-12 15:00:14] DEBUG[1703]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting ‘172.16.30.151:5060’ into…
[2016-05-12 15:00:14] DEBUG[1703]: netsock2.c:226 ast_sockaddr_split_hostport: …host ‘172.16.30.151’ and port ‘5060’.
[2016-05-12 15:00:14] DEBUG[1703]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting ‘0.0.0.0:5060’ into…
[2016-05-12 15:00:14] DEBUG[1703]: netsock2.c:226 ast_sockaddr_split_hostport: …host ‘0.0.0.0’ and port ‘5060’.
[2016-05-12 15:00:14] DEBUG[17044]: pjproject:0 <?>: sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=98 (rdata0x7f7a180252d8)
[2016-05-12 15:00:14] DEBUG[17044]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting ‘172.16.30.151’ into…
[2016-05-12 15:00:14] DEBUG[17044]: netsock2.c:226 ast_sockaddr_split_hostport: …host ‘172.16.30.151’ and port ‘’.
[2016-05-12 15:00:14] DEBUG[17044]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 172.16.30.151:5060 does not match identify ‘1994-identify’
[2016-05-12 15:00:14] DEBUG[17044]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 172.16.30.151:5060 does not match identify ‘1995-identify’
[2016-05-12 15:00:14] DEBUG[17044]: res_pjsip_endpoint_identifier_ip.c:137 ip_identify: ‘172.16.30.151:5060’ did not match any identify section rules
[2016-05-12 15:00:14] DEBUG[17044]: res_pjsip_endpoint_identifier_user.c:106 username_identify: Retrieved endpoint 1995
[2016-05-12 15:00:14] DEBUG[17044]: pjproject:0 <?>: endpoint .Response msg 401/INVITE/cseq=98 (tdta0x7f7a20032f20) created
[2016-05-12 15:00:14] DEBUG[17044]: res_pjsip_authenticator_digest.c:250 check_nonce: Calculated nonce 1463036414/fd9f5f1c17cac9ceab12eb0c461d1fb8. Actual nonce is 1463036414/fd9f5f1c17cac9ceab12eb0c461d1fb8
[2016-05-12 15:00:14] DEBUG[17044]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting ‘172.16.30.86’ into…
[2016-05-12 15:00:14] DEBUG[17044]: netsock2.c:226 ast_sockaddr_split_hostport: …host ‘172.16.30.86’ and port ‘’.
[2016-05-12 15:00:14] DEBUG[17044]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting ‘172.16.30.151’ into…
[2016-05-12 15:00:14] DEBUG[17044]: netsock2.c:226 ast_sockaddr_split_hostport: …host ‘172.16.30.151’ and port ‘’.
[2016-05-12 15:00:14] SECURITY[1741]: res_security_log.c:116 security_event_stasis_cb: SecurityEvent=“SuccessfulAuth”,EventTV=“2016-05-12T15:00:14.711+0800”,Severity=“Informational”,Service=“PJSIP”,EventVersion=“1”,AccountID=“1995”,SessionID="0066FCD6-7C16-E611-BC8E-2A1F3C58C911@172.16.30.151",LocalAddress=“IPV4/UDP/172.16.30.86/5060”,RemoteAddress=“IPV4/UDP/172.16.30.151/5060”,UsingPassword=“1”
[2016-05-12 15:00:14] DEBUG[17044]: pjproject:0 <?>: tdta0x7f7a2003 .Destroying txdata Response msg 401/INVITE/cseq=98 (tdta0x7f7a20032f20)
[2016-05-12 15:00:14] DEBUG[17044]: pjproject:0 <?>: tsx0x7f7a200a6 …Transaction created for Request msg INVITE/cseq=98 (rdata0x7f7a180252d8)
[2016-05-12 15:00:14] DEBUG[17044]: pjproject:0 <?>: tsx0x7f7a200a6 .Incoming Request msg INVITE/cseq=98 (rdata0x7f7a180252d8) in state Null
[2016-05-12 15:00:14] DEBUG[17044]: pjproject:0 <?>: tsx0x7f7a200a6 …State changed from Null to Trying, event=RX_MSG
[2016-05-12 15:00:14] DEBUG[17044]: pjproject:0 <?>: dlg0x2d136e8 …Transaction tsx0x7f7a200a67b8 state changed to Trying
[2016-05-12 15:00:14] DEBUG[17044]: pjproject:0 <?>: dlg0x2d136e8 .UAS dialog created
[2016-05-12 15:00:14] DEBUG[17044]: pjproject:0 <?>: dlg0x2d136e8 .Module mod-invite added as dialog usage, data=0x7f7a1c638ec8
[2016-05-12 15:00:14] DEBUG[17044]: pjproject:0 <?>: dlg0x2d136e8 …Session count inc to 2 by mod-invite
[2016-05-12 15:00:14] DEBUG[17044]: pjproject:0 <?>: inv0x2d136e8 .UAS invite session created for dialog dlg0x2d136e8
[2016-05-12 15:00:14] DEBUG[17044]: pjproject:0 <?>: dlg0x2d136e8 .Module Session Module added as dialog usage, data=(nil)
[2016-05-12 15:00:14] DEBUG[17044]: pjproject:0 <?>: dlg0x2d136e8 …Session count inc to 2 by Session Module
[2016-05-12 15:00:14] DEBUG[17044]: dsp.c:482 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[2016-05-12 15:00:14] DEBUG[17044]: dsp.c:482 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[2016-05-12 15:00:14] DEBUG[1702]: threadpool.c:517 grow: Increasing threadpool SIP’s size by 5
[2016-05-12 15:00:14] DEBUG[17044]: res_pjsip_session.c:264 handle_incoming_sdp: Negotiating incoming SDP media stream ‘audio’ using audio SDP handler
[2016-05-12 15:00:14] DEBUG[17044]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting ‘172.16.30.151’ into…
[2016-05-12 15:00:14] DEBUG[17044]: netsock2.c:226 ast_sockaddr_split_hostport: …host ‘172.16.30.151’ and port ‘’.
[2016-05-12 15:00:14] DEBUG[17044]: rtp_engine.c:435 ast_rtp_instance_new: Using engine ‘asterisk’ for RTP instance ‘0x7f7a1c302938’
[2016-05-12 15:00:14] DEBUG[17044]: res_rtp_asterisk.c:2585 ast_rtp_new: Allocated port 11698 for RTP instance ‘0x7f7a1c302938’
[2016-05-12 15:00:14] DEBUG[17044]: res_rtp_asterisk.c:2612 ast_rtp_new: Creating ICE session 0.0.0.0:11698 (11698) for RTP instance ‘0x7f7a1c302938’
[2016-05-12 15:00:14] DEBUG[17044]: pjproject:0 <?>: icess0x7f7a1c7 ICE session created, comp_cnt=2, role is Unknown agent
[2016-05-12 15:00:14] DEBUG[17044]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting ‘172.16.30.86’ into…
[2016-05-12 15:00:14] DEBUG[17044]: netsock2.c:226 ast_sockaddr_split_hostport: …host ‘172.16.30.86’ and port ‘’.
[2016-05-12 15:00:14] DEBUG[17044]: pjproject:0 <?>: icess0x7f7a1c7 Candidate 0 added: comp_id=1, type=host, foundation=Hac101e56, addr=172.16.30.86:11698, base=172.16.30.86:11698, prio=0x7effffff (2130706431)
[2016-05-12 15:00:14] DEBUG[17044]: rtp_engine.c:444 ast_rtp_instance_new: RTP instance ‘0x7f7a1c302938’ is setup and ready to go
[2016-05-12 15:00:14] DEBUG[17044]: res_rtp_asterisk.c:4825 ast_rtp_prop_set: Setup RTCP on RTP instance ‘0x7f7a1c302938’
[2016-05-12 15:00:14] DEBUG[17044]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting ‘172.16.30.86’ into…
[2016-05-12 15:00:14] DEBUG[17044]: netsock2.c:226 ast_sockaddr_split_hostport: …host ‘172.16.30.86’ and port ‘’.
[2016-05-12 15:00:14] DEBUG[17044]: pjproject:0 <?>: icess0x7f7a1c7 Candidate 1 added: comp_id=2, type=host, foundation=Hac101e56, addr=172.16.30.86:11699, base=172.16.30.86:11699, prio=0x7efffffe (2130706430)
[2016-05-12 15:00:14] DEBUG[17044]: pjproject:0 <?>: icess0x7f7a1c7 Destroying ICE session 0x7f7a1c73deb8
[2016-05-12 15:00:14] DEBUG[17044]: pjproject:0 <?>: stuse0x7f7a1c5 STUN session 0x7f7a1c6b52d8 destroy request, ref_cnt=4
[2016-05-12 15:00:14] DEBUG[17044]: pjproject:0 <?>: stuse0x7f7a1c6 STUN session 0x7f7a1c6f4a38 destroy request, ref_cnt=3
[2016-05-12 15:00:14] DEBUG[17044]: pjproject:0 <?>: ice_session.c ICE session 0x7f7a1c73deb8 destroyed
[2016-05-12 15:00:14] DEBUG[17044]: pjproject:0 <?>: stun_session.c STUN session 0x7f7a1c6b52d8 destroyed
[2016-05-12 15:00:14] DEBUG[17044]: pjproject:0 <?>: stun_session.c STUN session 0x7f7a1c6f4a38 destroyed
[2016-05-12 15:00:14] DEBUG[17044]: rtp_engine.c:670 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 107 based on m type on 0x7f7a04f24580
[2016-05-12 15:00:14] DEBUG[17044]: rtp_engine.c:670 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 8 based on m type on 0x7f7a04f24580
[2016-05-12 15:00:14] DEBUG[17044]: rtp_engine.c:670 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 0 based on m type on 0x7f7a04f24580
[2016-05-12 15:00:14] DEBUG[17044]: rtp_engine.c:665 ast_rtp_codecs_payloads_set_m_type: Don’t have a default tx payload type 2 format for m type on 0x7f7a04f24580
[2016-05-12 15:00:14] DEBUG[17044]: rtp_engine.c:670 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 3 based on m type on 0x7f7a04f24580
[2016-05-12 15:00:14] DEBUG[17044]: rtp_engine.c:670 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 97 based on m type on 0x7f7a04f24580
[2016-05-12 15:00:14] DEBUG[17044]: rtp_engine.c:670 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 110 based on m type on 0x7f7a04f24580
[2016-05-12 15:00:14] DEBUG[17044]: rtp_engine.c:670 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 111 based on m type on 0x7f7a04f24580
[2016-05-12 15:00:14] DEBUG[17044]: rtp_engine.c:670 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 9 based on m type on 0x7f7a04f24580
[2016-05-12 15:00:14] DEBUG[17044]: rtp_engine.c:670 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 101 based on m type on 0x7f7a04f24580
[2016-05-12 15:00:14] DEBUG[17044]: rtp_engine.c:639 ast_rtp_codecs_payloads_copy: Copying payload 0 (0x7f7a1c4acdb0) from 0x7f7a04f24580 to 0x7f7a1c302b00
[2016-05-12 15:00:14] DEBUG[17044]: rtp_engine.c:639 ast_rtp_codecs_payloads_copy: Copying payload 2 (0x7f7a1c0713d0) from 0x7f7a04f24580 to 0x7f7a1c302b00
[2016-05-12 15:00:14] DEBUG[17044]: rtp_engine.c:639 ast_rtp_codecs_payloads_copy: Copying payload 3 (0x7f7a1c251ae0) from 0x7f7a04f24580 to 0x7f7a1c302b00
[2016-05-12 15:00:14] DEBUG[17044]: rtp_engine.c:639 ast_rtp_codecs_payloads_copy: Copying payload 8 (0x7f7a1c238760) from 0x7f7a04f24580 to 0x7f7a1c302b00
[2016-05-12 15:00:14] DEBUG[17044]: rtp_engine.c:639 ast_rtp_codecs_payloads_copy: Copying payload 9 (0x7f7a1c467a10) from 0x7f7a04f24580 to 0x7f7a1c302b00
[2016-05-12 15:00:14] DEBUG[17044]: rtp_engine.c:639 ast_rtp_codecs_payloads_copy: Copying payload 97 (0x7f7a1c59ee40) from 0x7f7a04f24580 to 0x7f7a1c302b00
[2016-05-12 15:00:14] DEBUG[17044]: rtp_engine.c:639 ast_rtp_codecs_payloads_copy: Copying payload 101 (0x7f7a1c417810) from 0x7f7a04f24580 to 0x7f7a1c302b00
[2016-05-12 15:00:14] DEBUG[17044]: rtp_engine.c:639 ast_rtp_codecs_payloads_copy: Copying payload 107 (0x7f7a1c4d7020) from 0x7f7a04f24580 to 0x7f7a1c302b00
[2016-05-12 15:00:14] DEBUG[17044]: rtp_engine.c:639 ast_rtp_codecs_payloads_copy: Copying payload 110 (0x7f7a1c085800) from 0x7f7a04f24580 to 0x7f7a1c302b00
[2016-05-12 15:00:14] DEBUG[17044]: rtp_engine.c:639 ast_rtp_codecs_payloads_copy: Copying payload 111 (0x7f7a1c2b37f0) from 0x7f7a04f24580 to 0x7f7a1c302b00
[2016-05-12 15:00:14] DEBUG[17044]: res_pjsip_session.c:274 handle_incoming_sdp: Media stream ‘audio’ handled by audio
[2016-05-12 15:00:14] DEBUG[17044]: res_pjsip_t38.c:734 create_outgoing_sdp_stream: Not creating outgoing SDP stream: T.38 not enabled
[2016-05-12 15:00:14] DEBUG[17044]: pjproject:0 <?>: endpoint .Response msg 100/INVITE/cseq=98 (tdta0x7f7a2006ba60) created
[2016-05-12 15:00:14] DEBUG[17044]: pjproject:0 <?>: dlg0x2d136e8 .Initial answer Response msg 100/INVITE/cseq=98 (tdta0x7f7a2006ba60)
[2016-05-12 15:00:14] DEBUG[17044]: res_pjsip_session.c:2410 handle_outgoing_response: Method is INVITE, Response is 100 Trying
[2016-05-12 15:00:14] DEBUG[17044]: pjproject:0 <?>: inv0x2d136e8 .Sending Response msg 100/INVITE/cseq=98 (tdta0x7f7a2006ba60)
[2016-05-12 15:00:14] DEBUG[17044]: pjproject:0 <?>: dlg0x2d136e8 …Sending Response msg 100/INVITE/cseq=98 (tdta0x7f7a2006ba60)
[2016-05-12 15:00:14] DEBUG[17044]: pjproject:0 <?>: tsx0x7f7a200a6 …Sending Response msg 100/INVITE/cseq=98 (tdta0x7f7a2006ba60) in state Trying
[2016-05-12 15:00:14] DEBUG[17044]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting ‘0.0.0.0:5060’ into…
[2016-05-12 15:00:14] DEBUG[17044]: netsock2.c:226 ast_sockaddr_split_hostport: …host ‘0.0.0.0’ and port ‘5060’.
[2016-05-12 15:00:14] DEBUG[17044]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting ‘172.16.30.151:5060’ into…
[2016-05-12 15:00:14] DEBUG[17044]: netsock2.c:226 ast_sockaddr_split_hostport: …host ‘172.16.30.151’ and port ‘5060’.
[2016-05-12 15:00:14] DEBUG[17044]: pjproject:0 <?>: tsx0x7f7a200a6 …State changed from Trying to Proceeding, event=TX_MSG
[2016-05-12 15:00:14] DEBUG[17044]: pjproject:0 <?>: dlg0x2d136e8 …Transaction tsx0x7f7a200a67b8 state changed to Proceeding
[2016-05-12 15:00:14] DEBUG[17044]: res_pjsip_session.c:2302 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE
[2016-05-12 15:00:14] DEBUG[17044]: res_pjsip_session.c:2314 __print_debug_details: The state change pertains to the endpoint ‘1995()’
[2016-05-12 15:00:14] DEBUG[17044]: res_pjsip_session.c:2319 __print_debug_details: The inv session still has an invite_tsx (0x7f7a200a67b8)
[2016-05-12 15:00:14] DEBUG[17044]: res_pjsip_session.c:2334 __print_debug_details: There is no transaction involved in this state change
[2016-05-12 15:00:14] DEBUG[17044]: res_pjsip_session.c:2336 __print_debug_details: The current inv state is INCOMING
[2016-05-12 15:00:14] DEBUG[17044]: res_pjsip_session.c:2492 session_inv_on_state_changed: Source of transaction state change is TX_MSG
[2016-05-12 15:00:14] DEBUG[17044]: res_pjsip_session.c:2422 handle_outgoing: Sending response
[2016-05-12 15:00:14] DEBUG[17044]: res_pjsip_session.c:2410 handle_outgoing_response: Method is INVITE, Response is 100 Trying
[2016-05-12 15:00:14] DEBUG[17044]: res_pjsip_session.c:2302 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[2016-05-12 15:00:14] DEBUG[17044]: res_pjsip_session.c:2314 __print_debug_details: The state change pertains to the endpoint ‘1995()’
[2016-05-12 15:00:14] DEBUG[17044]: res_pjsip_session.c:2319 __print_debug_details: The inv session still has an invite_tsx (0x7f7a200a67b8)
[2016-05-12 15:00:14] DEBUG[17044]: res_pjsip_session.c:2325 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x7f7a200a67b8
[2016-05-12 15:00:14] DEBUG[17044]: res_pjsip_session.c:2329 __print_debug_details: The current transaction state is Proceeding
[2016-05-12 15:00:14] DEBUG[17044]: res_pjsip_session.c:2331 __print_debug_details: The transaction state change event is TX_MSG
[2016-05-12 15:00:14] DEBUG[17044]: res_pjsip_session.c:2336 __print_debug_details: The current inv state is INCOMING
[2016-05-12 15:00:14] DEBUG[17044]: res_pjsip_session.c:2422 handle_outgoing: Sending response
[2016-05-12 15:00:14] DEBUG[17044]: res_pjsip_session.c:2410 handle_outgoing_response: Method is INVITE, Response is 100 Trying
[2016-05-12 15:00:14] DEBUG[17044]: res_pjsip_session.c:2346 handle_incoming_request: Method is INVITE
[2016-05-12 15:00:14] DEBUG[17044]: pjproject:0 <?>: dlg0x2d136e8 Module NAT added as dialog usage, data=(nil)
[2016-05-12 15:00:14] DEBUG[1643]: threadpool.c:517 grow: Increasing threadpool stasis-core’s size by 1
[2016-05-12 15:00:14] DEBUG[1660]: res_odbc.c:790 odbc_obj_connect: Connecting asteriskcdrdb(0x7f7a10171228)
[2016-05-12 15:00:14] DEBUG[17044]: chan_pjsip.c:2266 pbx_start_incoming_request: Started PBX on new PJSIP channel PJSIP/1995-00000028
[2016-05-12 15:00:14] DEBUG[1660]: res_odbc.c:828 odbc_obj_connect: res_odbc: Connected to asteriskcdrdb [MySQL-asteriskcdrdb (0x7f7a10171228)]
[2016-05-12 15:00:14] DEBUG[1660]: cel_odbc.c:765 odbc_log: Executing SQL statement: [INSERT INTO cel (eventtype,eventtime,cid_name,cid_num,cid_ani,cid_rdnis,cid_dnid,exten,context,channame,appname,appdata,amaflags,accountcode,uniqueid,linkedid,peer,userdeftype,extra) VALUES (‘CHAN_START’,{ts ‘2016-05-12 15:00:14.718267’},‘device’,‘1995’,’’,’’,’’,‘1994’,‘from-internal’,‘PJSIP/1995-00000028’,’’,’’,3,’’,‘1463036414.40’,‘1463036414.40’,’’,’’,’’)]
[2016-05-12 15:00:14] DEBUG[1660]: res_odbc.c:681 ast_odbc_release_obj: Releasing ODBC handle 0x7f7a10171228
[2016-05-12 15:00:14] DEBUG[1660]: res_odbc.c:767 odbc_obj_disconnect: Database handle 0x7f7a10171228 (connection 0x7f7a10273a00) deallocated
[2016-05-12 15:00:14] DEBUG[17653][C-00000014]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function DB(AMPUSER/1994/ringtimer) result is ‘0’
[2016-05-12 15:00:14] DEBUG[17653][C-00000014]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is ‘0’
[2016-05-12 15:00:14] DEBUG[17653][C-00000014]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function DB(AMPUSER/1994/ringtimer) result is ‘0’
[2016-05-12 15:00:14] DEBUG[17653][C-00000014]: pbx_variables.c:381 ast_str_retrieve_variable: Result of ‘RINGTIMER_DEFAULT’ is ‘15’
[2016-05-12 15:00:14] DEBUG[17653][C-00000014]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function IF(0?0:15) result is ‘15’
[2016-05-12 15:00:14] DEBUG[17653][C-00000014]: pbx.c:2825 pbx_extension_helper: Launching ‘Set’
– Executing [1994@from-internal:1] Set(“PJSIP/1995-00000028”, “__RINGTIMER=15”) in new stack
[2016-05-12 15:00:14] DEBUG[17653][C-00000014]: pbx.c:2825 pbx_extension_helper: Launching ‘Macro’
– Executing [1994@from-internal:2] Macro(“PJSIP/1995-00000028”, “exten-vm,novm,1994,0,0,0”) in new stack
[2016-05-12 15:00:14] DEBUG[17653][C-00000014]: pbx.c:2825 pbx_extension_helper: Launching ‘Macro’