Intermittent issue with cdr (call detail record)

chzefung · May 13, 2016, 1:14am

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’

ambiorixg12 · May 13, 2016, 2:52am

It seems you are using FreePBX, but what could be posible is that you are having some kind of conection issues.

odbc conector seems to be conected just fine on the recorded calls

2016-05-12 15:00:14] DEBUG[1660]: res_odbc.c:828 odbc_obj_connect: res_odbc: Connected to asteriskcdrdb [MySQL-asteriskcdrdb (0x7f7a10171228)]

chzefung · May 13, 2016, 3:21am

Yes, the database connection is OK.
However, seem like the pjsip is missing INVITE.

[2016-05-12 15:00:14] DEBUG[17044]: pjproject:0 <?>: endpoint .Response msg 401/INVITE/cseq=97 (tdta0x7f7a20032f20) created

Any idea why does that happen?

ambiorixg12 · May 13, 2016, 3:41am

“it sems you’ve configured the endpoint to require authentication for inbound requests. You’ll want to remove the “auth” option from the endpoint to stop this. http://forums.asterisk.org/viewtopic.php?p=211777”

these pice of log is relevant to the cdr logs

[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:

chzefung · May 13, 2016, 8:16am

There is no issue with the “auth”.
Have remove the “auth” but sometime I still could not get the call report in the cdr and cel.

Below is the debug for when the call is not recorded into CDR:
asterisk13CLI>
[2016-05-13 16:04:55] DEBUG[6708]: pjproject:0 <?>: endpoint Request msg OPTIONS/cseq=19085 (tdta0x7f629c004d20) created.
[2016-05-13 16:04:55] DEBUG[6708]: config.c:3564 ast_parse_arg: extract int from [3] in [-2147483648, 2147483647] gives 3
[2016-05-13 16:04:55] DEBUG[6708]: config.c:3564 ast_parse_arg: extract int from [0] in [-2147483648, 2147483647] gives 0
[2016-05-13 16:04:55] DEBUG[6708]: config.c:3564 ast_parse_arg: extract int from [2] in [-2147483648, 2147483647] gives 2
[2016-05-13 16:04:55] DEBUG[6708]: res_pjsip.c:3215 endpt_send_request: 0x7f62ac238498: Wrapper created
[2016-05-13 16:04:55] DEBUG[6708]: res_pjsip.c:3232 endpt_send_request: 0x7f62ac238498: Set timer to 3000 msec
[2016-05-13 16:04:55] DEBUG[6708]: pjproject:0 <?>: tsx0x7f629c166 .Transaction created for Request msg OPTIONS/cseq=19085 (tdta0x7f629c004d20)
[2016-05-13 16:04:55] DEBUG[6708]: pjproject:0 <?>: tsx0x7f629c166 Sending Request msg OPTIONS/cseq=19085 (tdta0x7f629c004d20) in state Null
[2016-05-13 16:04:55] DEBUG[6708]: pjproject:0 <?>: sip_resolve.c .Target ‘172.16.30.151:5060’ type=Unspecified resolved to ‘172.16.30.151:5060’ type=UDP (UDP transport)
[2016-05-13 16:04:55] DEBUG[6708]: res_pjsip_multihomed.c:151 multihomed_on_tx_message: Re-wrote Contact URI host/port to 172.16.30.96:5060
[2016-05-13 16:04:55] DEBUG[6708]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting ‘0.0.0.0:5060’ into…
[2016-05-13 16:04:55] DEBUG[6708]: netsock2.c:226 ast_sockaddr_split_hostport: …host ‘0.0.0.0’ and port ‘5060’.
[2016-05-13 16:04:55] DEBUG[6708]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting ‘172.16.30.151:5060’ into…
[2016-05-13 16:04:55] DEBUG[6708]: netsock2.c:226 ast_sockaddr_split_hostport: …host ‘172.16.30.151’ and port ‘5060’.
[2016-05-13 16:04:55] DEBUG[6708]: pjproject:0 <?>: tsx0x7f629c166 .State changed from Null to Calling, event=TX_MSG
[2016-05-13 16:04:55] DEBUG[3149]: pjproject:0 <?>: sip_endpoint.c Processing incoming message: Response msg 200/OPTIONS/cseq=19085 (rdata0x7f6290001fa8)
[2016-05-13 16:04:55] DEBUG[3149]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting ‘172.16.30.151:5060’ into…
[2016-05-13 16:04:55] DEBUG[3149]: netsock2.c:226 ast_sockaddr_split_hostport: …host ‘172.16.30.151’ and port ‘5060’.
[2016-05-13 16:04:55] DEBUG[3149]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting ‘0.0.0.0:5060’ into…
[2016-05-13 16:04:55] DEBUG[3149]: netsock2.c:226 ast_sockaddr_split_hostport: …host ‘0.0.0.0’ and port ‘5060’.
[2016-05-13 16:04:55] DEBUG[3149]: res_pjsip/pjsip_distributor.c:280 distributor: No dialog serializer for response Response msg 200/OPTIONS/cseq=19085 (rdata0x7f6290001fa8). Using request transaction as basis
[2016-05-13 16:04:55] DEBUG[3149]: res_pjsip/pjsip_distributor.c:110 find_request_serializer: Found serializer pjsip/default-0000000f on transaction tsx0x7f629c166ea8
[2016-05-13 16:04:55] DEBUG[6129]: pjproject:0 <?>: sip_endpoint.c Distributing rdata to modules: Response msg 200/OPTIONS/cseq=19085 (rdata0x7f6290005408)
[2016-05-13 16:04:55] DEBUG[6129]: pjproject:0 <?>: tsx0x7f629c166 .Incoming Response msg 200/OPTIONS/cseq=19085 (rdata0x7f6290005408) in state Calling
[2016-05-13 16:04:55] DEBUG[6129]: pjproject:0 <?>: tsx0x7f629c166 …State changed from Calling to Completed, event=RX_MSG
[2016-05-13 16:04:55] DEBUG[6129]: res_pjsip.c:3105 endpt_send_request_cb: 0x7f62ac238498: PJSIP tsx response received
[2016-05-13 16:04:55] DEBUG[6129]: res_pjsip.c:3118 endpt_send_request_cb: 0x7f62ac238498: Cancelling timer
[2016-05-13 16:04:55] DEBUG[6129]: res_pjsip.c:3128 endpt_send_request_cb: 0x7f62ac238498: Timer cancelled
[2016-05-13 16:04:55] DEBUG[6129]: config.c:3564 ast_parse_arg: extract int from [3] in [-2147483648, 2147483647] gives 3
[2016-05-13 16:04:55] DEBUG[6129]: config.c:3564 ast_parse_arg: extract int from [0] in [-2147483648, 2147483647] gives 0
[2016-05-13 16:04:55] DEBUG[6129]: config.c:3564 ast_parse_arg: extract int from [2] in [-2147483648, 2147483647] gives 2
[2016-05-13 16:04:55] DEBUG[6129]: res_pjsip.c:3147 endpt_send_request_cb: 0x7f62ac238498: Callbacks executed
[2016-05-13 16:04:55] DEBUG[6129]: res_pjsip.c:3198 send_request_wrapper_destructor: 0x7f62ac238498: wrapper destroyed
[2016-05-13 16:04:55] DEBUG[7144]: res_pjsip/pjsip_configuration.c:245 persistent_endpoint_contact_status_observer: Contact 1995/sip:1995@172.16.30.151:5060 status didn’t change: Reachable, RTT: 1.173 msec
asterisk13CLI>

jcolp · May 13, 2016, 9:59am

In the first case we got a BYE but there was no channel, so we sent a 481. Without more logging to see if there really was one then the behavior is correct.

In the second case you provide an OPTIONS request, which is not a call. It’s Asterisk sending a message to see if the other side is reachable. Same here - behavior is correct.