*CLI> [Mar 1 13:11:41] DEBUG[3242931]: threadpool.c:1169 worker_idle: Worker thread idle timeout reached. Dying. [Mar 1 13:11:41] DEBUG[3242054]: threadpool.c:1028 worker_thread_destroy: Destroying worker thread 19 [Mar 1 13:11:42] DEBUG[3242095]: res_pjsip_registrar.c:1293 check_expiration_thread: Expiring 0 contacts originate PJSIP/s705 application Playback demo-congrats [Mar 1 13:11:44] DEBUG[3242052]: chan_pjsip.c:2671 chan_pjsip_request_with_stream_topology: s705 Topology: <0:audio-0:audio:sendrecv (slin)> [Mar 1 13:11:44] DEBUG[3242084]: chan_pjsip.c:2570 request: s705 [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:3329 ast_sip_session_create_outgoing: s705 (null) Topology: <0:audio-0:audio:sendrecv (slin)> [Mar 1 13:11:44] DEBUG[3242084]: config.c:3847 ast_parse_arg: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [Mar 1 13:11:44] DEBUG[3242084]: config.c:3760 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [Mar 1 13:11:44] DEBUG[3242084]: config.c:3847 ast_parse_arg: extract double from [3.000000] in [-inf, inf] gives [3.000000](0) [Mar 1 13:11:44] DEBUG[3242084]: config.c:3760 ast_parse_arg: extract uint from [5160] in [0, 4294967295] gives [5160](0) [Mar 1 13:11:44] DEBUG[3242084]: config.c:3760 ast_parse_arg: extract uint from [60] in [0, 86400] gives [60](0) [Mar 1 13:11:44] DEBUG[3242084]: chan_pjsip.c:2953 chan_pjsip_session_begin: s705 [Mar 1 13:11:44] DEBUG[3242084]: chan_pjsip.c:2957 chan_pjsip_session_begin: Direct media no glare mitigation [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session/pjsip_session_caps.c:146 ast_sip_session_create_joint_call_stream: 's705' Caps for outgoing audio call with pref 'remote_merge' - remote: (slin) local: (g722|gsm) joint: (g722|gsm) [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:3445 ast_sip_session_create_outgoing: [Mar 1 13:11:44] DEBUG[3242084]: chan_pjsip.c:2663 request: [Mar 1 13:11:44] DEBUG[3242052]: chan_pjsip.c:555 chan_pjsip_new: s705 [Mar 1 13:11:44] DEBUG[3242052]: channel_internal_api.c:680 ast_channel_nativeformats_set: : Formats: (none) [Mar 1 13:11:44] DEBUG[3242052]: channel_internal_api.c:692 ast_channel_nativeformats_set: Channel is being initialized or destroyed [Mar 1 13:11:44] DEBUG[3242052]: stasis.c:578 stasis_topic_create_with_detail: Creating topic. name: channel:1614618704.27, detail: [Mar 1 13:11:44] DEBUG[3242052]: stasis.c:612 stasis_topic_create_with_detail: Topic 'channel:1614618704.27': 0x5582f8c22bb0 created [Mar 1 13:11:44] DEBUG[3242052]: channel.c:951 __ast_channel_alloc_ap: Channel 0x5582f8ab5c40 'PJSIP/s705-00000004' allocated [Mar 1 13:11:44] DEBUG[3242054]: threadpool.c:535 grow: Increasing threadpool stasis/pool's size by 1 [Mar 1 13:11:44] DEBUG[3242052]: chan_pjsip.c:530 compatible_formats_exist: Topology: <0:audio-0:audio:sendrecv (g722|gsm)> Formats: (g722|gsm) [Mar 1 13:11:44] DEBUG[3242052]: chan_pjsip.c:543 compatible_formats_exist: Compatible? yes [Mar 1 13:11:44] DEBUG[3242052]: channel_internal_api.c:680 ast_channel_nativeformats_set: PJSIP/s705-00000004: MultistreamFormats: (g722|gsm) [Mar 1 13:11:44] DEBUG[3242052]: channel_internal_api.c:702 ast_channel_nativeformats_set: Set native formats but not topology [Mar 1 13:11:44] DEBUG[3242052]: channel_internal_api.c:1595 ast_channel_set_stream_topology: PJSIP/s705-00000004: <0:audio-0:audio:sendrecv (g722|gsm)> [Mar 1 13:11:44] DEBUG[3242052]: channel_internal_api.c:1616 ast_channel_set_stream_topology: Used provided topology [Mar 1 13:11:44] DEBUG[3242075]: stasis.c:578 stasis_topic_create_with_detail: Creating topic. name: channel:1614618704.28, detail: [Mar 1 13:11:44] DEBUG[3242075]: stasis.c:612 stasis_topic_create_with_detail: Topic 'channel:1614618704.28': 0x7fde38007a90 created [Mar 1 13:11:44] DEBUG[3242052]: chan_pjsip.c:674 chan_pjsip_new: *CLI> [Mar 1 13:11:44] DEBUG[3242052]: chan_pjsip.c:2691 chan_pjsip_request_with_stream_topology: Channel: PJSIP/s705-00000004 [Mar 1 13:11:44] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE(CHAN_START) result is '"CHAN_START"' [Mar 1 13:11:44] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE(1614618704.315059) result is '"1614618704.315059"' [Mar 1 13:11:44] ERROR[3242075]: pbx_functions.c:651 ast_func_read2: Function CALLERID not registered [Mar 1 13:11:44] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CALLERID(name) result is '' [Mar 1 13:11:44] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Mar 1 13:11:44] ERROR[3242075]: pbx_functions.c:651 ast_func_read2: Function CALLERID not registered [Mar 1 13:11:44] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CALLERID(num) result is '' [Mar 1 13:11:44] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Mar 1 13:11:44] ERROR[3242075]: pbx_functions.c:651 ast_func_read2: Function CALLERID not registered [Mar 1 13:11:44] DEBUG[3243072]: chan_pjsip.c:2388 chan_pjsip_call: PJSIP/s705-00000004 Topology: <0:audio-0:audio:sendrecv (g722|gsm)> [Mar 1 13:11:44] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CALLERID(ANI) result is '' [Mar 1 13:11:44] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Mar 1 13:11:44] ERROR[3242075]: pbx_functions.c:651 ast_func_read2: Function CALLERID not registered [Mar 1 13:11:44] DEBUG[3243072]: chan_pjsip.c:2398 chan_pjsip_call: 'call' task pushed [Mar 1 13:11:44] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CALLERID(RDNIS) result is '' [Mar 1 13:11:44] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Mar 1 13:11:44] ERROR[3242075]: pbx_functions.c:651 ast_func_read2: Function CALLERID not registered [Mar 1 13:11:44] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CALLERID(DNID) result is '' [Mar 1 13:11:44] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Mar 1 13:11:44] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CHANNEL(exten) result is 's' [Mar 1 13:11:44] DEBUG[3242084]: chan_pjsip.c:2364 call: PJSIP/s705-00000004 Topology: <0:audio-0:audio:sendrecv (g722|gsm)> -- Called s705 [Mar 1 13:11:44] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE(s) result is '"s"' [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:2850 ast_sip_session_create_invite: PJSIP/s705-00000004 [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:5067 create_local_sdp: PJSIP/s705-00000004 [Mar 1 13:11:44] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CHANNEL(context) result is 'users' [Mar 1 13:11:44] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE(users) result is '"users"' [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:5104 create_local_sdp: PJSIP/s705-00000004: Processing streams [Mar 1 13:11:44] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CHANNEL(channame) result is 'PJSIP/s705-00000004' [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:495 ast_sip_session_media_state_add: PJSIP/s705-00000004 Adding position 0 [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:541 ast_sip_session_media_state_add: Creating new media session [Mar 1 13:11:44] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE(PJSIP/s705-00000004) result is '"PJSIP/s705-00000004"' [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:584 ast_sip_session_media_state_add: Setting media session as default for audio [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:589 ast_sip_session_media_state_add: Done [Mar 1 13:11:44] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CHANNEL(appname) result is '' [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:4943 add_sdp_streams: PJSIP/s705-00000004 Stream: 0:audio-0:audio:sendrecv (g722|gsm) [Mar 1 13:11:44] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Mar 1 13:11:44] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CHANNEL(appdata) result is '' [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_sdp_rtp.c:1690 create_outgoing_sdp_stream: PJSIP/s705-00000004 Type: audio 0:audio-0:audio:sendrecv (g722|gsm) [Mar 1 13:11:44] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Mar 1 13:11:44] DEBUG[3242084]: rtp_engine.c:526 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7fde180e6de0' [Mar 1 13:11:44] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CHANNEL(amaflags) result is '3' [Mar 1 13:11:44] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE(3) result is '"3"' [Mar 1 13:11:44] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CHANNEL(accountcode) result is '' [Mar 1 13:11:44] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Mar 1 13:11:44] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CHANNEL(uniqueid) result is '1614618704.27' [Mar 1 13:11:44] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE(1614618704.27) result is '"1614618704.27"' [Mar 1 13:11:44] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CHANNEL(linkedid) result is '1614618704.27' [Mar 1 13:11:44] DEBUG[3242084]: res_rtp_asterisk.c:3835 rtp_allocate_transport: (0x7fde180e6de0) RTP allocated port 16310 [Mar 1 13:11:44] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE(1614618704.27) result is '"1614618704.27"' [Mar 1 13:11:44] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CHANNEL(peer) result is '' [Mar 1 13:11:44] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Mar 1 13:11:44] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CHANNEL(userfield) result is '' [Mar 1 13:11:44] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Mar 1 13:11:44] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Mar 1 13:11:44] DEBUG[3242084]: res_rtp_asterisk.c:3865 rtp_allocate_transport: (0x7fde180e6de0) ICE creating session [::]:16310 (16310) [Mar 1 13:11:44] DEBUG[3242084]: res_rtp_asterisk.c:3750 ice_create: (0x7fde180e6de0) ICE create [Mar 1 13:11:44] DEBUG[3242075]: stasis.c:440 topic_dtor: Destroying topic. name: channel:1614618704.28, detail: [Mar 1 13:11:44] DEBUG[3242075]: stasis.c:449 topic_dtor: Topic 'channel:1614618704.28': 0x7fde38007a90 destroyed [Mar 1 13:11:44] DEBUG[3242084]: res_rtp_asterisk.c:3532 rtp_add_candidates_to_ice: (0x7fde180e6de0) ICE add system candidates [Mar 1 13:11:44] DEBUG[3242084]: res_rtp_asterisk.c:1287 ast_rtp_ice_add_cand: (0x7fde180e6de0) ICE add candidate: 172.16.1.100:16310, 2130706431 [Mar 1 13:11:44] DEBUG[3242084]: res_rtp_asterisk.c:1287 ast_rtp_ice_add_cand: (0x7fde180e6de0) ICE add candidate: 172.17.0.1:16310, 2130706431 [Mar 1 13:11:44] DEBUG[3242084]: res_rtp_asterisk.c:1287 ast_rtp_ice_add_cand: (0x7fde180e6de0) ICE add candidate: [2a06:e881:102:1:2856:bb51:4ac2:7826]:16310, 2130706431 [Mar 1 13:11:44] DEBUG[3242084]: res_rtp_asterisk.c:1287 ast_rtp_ice_add_cand: (0x7fde180e6de0) ICE add candidate: [2a06:e881:102:1:660c:9404:be65:f2f7]:16310, 2130706431 [Mar 1 13:11:44] DEBUG[3242084]: res_rtp_asterisk.c:1287 ast_rtp_ice_add_cand: (0x7fde180e6de0) ICE add candidate: [2a06:e881:102:1:e19f:5fa8:fa6f:bd9f]:16310, 2130706431 [Mar 1 13:11:44] DEBUG[3242084]: res_rtp_asterisk.c:1287 ast_rtp_ice_add_cand: (0x7fde180e6de0) ICE add candidate: [2a06:e881:102:1:c566:6384:f7f9:124]:16310, 2130706431 [Mar 1 13:11:44] DEBUG[3242084]: res_rtp_asterisk.c:1287 ast_rtp_ice_add_cand: (0x7fde180e6de0) ICE add candidate: [2a06:e881:102:1:422c:bb13:ecfb:ab70]:16310, 2130706431 [Mar 1 13:11:44] DEBUG[3242084]: res_rtp_asterisk.c:1287 ast_rtp_ice_add_cand: (0x7fde180e6de0) ICE add candidate: [2a06:e881:102:1:5b66:7203:6a08:1a7f]:16310, 2130706431 [Mar 1 13:11:44] DEBUG[3242084]: res_rtp_asterisk.c:1287 ast_rtp_ice_add_cand: (0x7fde180e6de0) ICE add candidate: [2a06:e881:102:1:e504:67c1:11eb:6345]:16310, 2130706431 [Mar 1 13:11:44] DEBUG[3242084]: res_rtp_asterisk.c:1287 ast_rtp_ice_add_cand: (0x7fde180e6de0) ICE add candidate: [2a06:e881:102:1::a:4a07]:16310, 2130706431 [Mar 1 13:11:44] DEBUG[3242084]: res_rtp_asterisk.c:1287 ast_rtp_ice_add_cand: (0x7fde180e6de0) ICE add candidate: [2a06:e881:102:1:b372:5cd9:828a:b209]:16310, 2130706431 [Mar 1 13:11:44] DEBUG[3242084]: res_rtp_asterisk.c:1287 ast_rtp_ice_add_cand: (0x7fde180e6de0) ICE add candidate: [fe80::47bf:713f:5e24:2201]:16310, 2130706431 [Mar 1 13:11:44] DEBUG[3242084]: rtp_engine.c:543 ast_rtp_instance_new: RTP instance '0x7fde180e6de0' is setup and ready to go [Mar 1 13:11:44] DEBUG[3242084]: res_rtp_asterisk.c:876 ast_rtp_ice_stop: (0x7fde180e6de0) ICE stopped [Mar 1 13:11:44] DEBUG[3242084]: res_rtp_asterisk.c:8279 ast_rtp_prop_set: (0x7fde180e6de0) RTCP setup on RTP instance [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_sdp_rtp.c:1975 create_outgoing_sdp_stream: RC: 1 [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:4973 add_sdp_streams: Handled [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:5161 create_local_sdp: PJSIP/s705-00000004: Adding bundle groups (if available) [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:5167 create_local_sdp: PJSIP/s705-00000004: Copying connection details [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:5211 create_local_sdp: PJSIP/s705-00000004 [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:2875 ast_sip_session_create_invite: [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:4463 handle_outgoing_request: PJSIP/s705-00000004: Method is INVITE [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:4473 handle_outgoing_request: PJSIP/s705-00000004 [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip/pjsip_resolver.c:479 sip_resolve: Performing SIP DNS resolution of target '172.16.20.130' [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip/pjsip_resolver.c:506 sip_resolve: Transport type for target '172.16.20.130' is 'UDP transport' [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip/pjsip_resolver.c:527 sip_resolve: Target '172.16.20.130' is an IP address, skipping resolution [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip/pjsip_message_filter.c:174 print_sanitize_debug: Sanitizing Request: sip:s705@172.16.20.130:5160;transport=UDP [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip/pjsip_message_filter.c:174 print_sanitize_debug: Sanitizing From/To header: sip:anonymous@anonymous.invalid [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip/pjsip_message_filter.c:174 print_sanitize_debug: Sanitizing From/To header: sip:s705@172.16.20.130 [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip/pjsip_message_filter.c:174 print_sanitize_debug: Sanitizing Contact header: sip:asterisk@172.16.1.100:5060 <--- Transmitting SIP request (960 bytes) to UDP:172.16.20.130:5160 ---> INVITE sip:s705@172.16.20.130:5160;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:5060;rport;branch=z9hG4bKPja93e35cb-5876-4b68-921c-7ca7f6fdf38b From: "Anonymous" ;tag=a37afe7d-b79b-44e0-b8cc-7b784abf1287 To: Contact: Call-ID: 470166d5-6f9a-4c04-a4ea-4fc153fc48cd CSeq: 2178 INVITE Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER Supported: 100rel, timer, replaces, norefersub, histinfo Session-Expires: 1800 Min-SE: 90 Max-Forwards: 70 User-Agent: Asterisk PBX GIT-18-6673c1b177 Content-Type: application/sdp Content-Length: 258 v=0 o=- 802505438 802505438 IN IP4 172.16.1.100 s=Asterisk c=IN IP4 172.16.1.100 t=0 0 m=audio 16310 RTP/AVP 9 3 101 a=rtpmap:9 G722/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:4597 session_inv_on_state_changed: PJSIP/s705-00000004 Event: TSX_STATE Inv State: CALLING [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:4623 session_inv_on_state_changed: PJSIP/s705-00000004: Source of transaction state change is TX_MSG [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:4671 session_inv_on_state_changed: [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:4715 session_inv_on_tsx_state_changed: PJSIP/s705-00000004 TSX State: Calling Inv State: CALLING [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:4903 session_inv_on_tsx_state_changed: Nothing delayed [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:4169 session_on_tsx_state: PJSIP/s705-00000004 TSX State: Calling Inv State: CALLING [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:4173 session_on_tsx_state: Topology: Pending: <0:audio-0:audio:sendrecv (g722|gsm)> Active: (null topology) [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:4178 session_on_tsx_state: [Mar 1 13:11:44] DEBUG[3242084]: chan_pjsip.c:2381 call: RC: 0 <--- Received SIP response (484 bytes) from UDP:172.16.20.130:5160 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 127.0.0.1:5060;rport=5060;branch=z9hG4bKPja93e35cb-5876-4b68-921c-7ca7f6fdf38b;received=172.16.1.100 From: "Anonymous" ;tag=a37afe7d-b79b-44e0-b8cc-7b784abf1287 To: Call-ID: 470166d5-6f9a-4c04-a4ea-4fc153fc48cd CSeq: 2178 INVITE User-Agent: Sangoma S705 V3.0.4.75 Allow: INVITE, ACK, UPDATE, INFO, CANCEL, BYE, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, PRACK Content-Length: 0 [Mar 1 13:11:44] DEBUG[3242083]: res_pjsip/pjsip_distributor.c:502 distributor: Searching for serializer associated with dialog dlg0x7fde180a4638 for Response msg 100/INVITE/cseq=2178 (rdata0x7fdd400023d8) [Mar 1 13:11:44] DEBUG[3242083]: res_pjsip/pjsip_distributor.c:510 distributor: Found serializer pjsip/outsess/s705-0000007b associated with dialog dlg0x7fde180a4638 [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:4192 session_on_rx_response: PJSIP/s705-00000004 Method: INVITE Status: 100 [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:4195 session_on_rx_response: [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:4715 session_inv_on_tsx_state_changed: PJSIP/s705-00000004 TSX State: Proceeding Inv State: CALLING [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:4432 handle_incoming_response: PJSIP/s705-00000004: Response is 100 Trying [Mar 1 13:11:44] DEBUG[3242084]: chan_pjsip.c:3189 chan_pjsip_incoming_response: PJSIP/s705-00000004: Status: 100 [Mar 1 13:11:44] DEBUG[3242084]: chan_pjsip.c:3225 chan_pjsip_incoming_response: PJSIP/s705-00000004: Not queueing anything [Mar 1 13:11:44] DEBUG[3242084]: chan_pjsip.c:3229 chan_pjsip_incoming_response: PJSIP/s705-00000004 [Mar 1 13:11:44] DEBUG[3242084]: chan_pjsip.c:3161 chan_pjsip_incoming_response_update_cause: PJSIP/s705-00000004: Status: 100 [Mar 1 13:11:44] DEBUG[3242084]: chan_pjsip.c:3182 chan_pjsip_incoming_response_update_cause: PJSIP/s705-00000004 [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:4444 handle_incoming_response: PJSIP/s705-00000004 [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:4903 session_inv_on_tsx_state_changed: Nothing delayed [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:4169 session_on_tsx_state: PJSIP/s705-00000004 TSX State: Proceeding Inv State: CALLING [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:4173 session_on_tsx_state: Topology: Pending: <0:audio-0:audio:sendrecv (g722|gsm)> Active: (null topology) [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:4178 session_on_tsx_state: <--- Received SIP response (559 bytes) from UDP:172.16.20.130:5160 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 127.0.0.1:5060;rport=5060;branch=z9hG4bKPja93e35cb-5876-4b68-921c-7ca7f6fdf38b;received=172.16.1.100 From: "Anonymous" ;tag=a37afe7d-b79b-44e0-b8cc-7b784abf1287 To: ;tag=f9f13d9485b8604 Call-ID: 470166d5-6f9a-4c04-a4ea-4fc153fc48cd CSeq: 2178 INVITE Contact: User-Agent: Sangoma S705 V3.0.4.75 Allow: INVITE, ACK, UPDATE, INFO, CANCEL, BYE, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, PRACK Content-Length: 0 [Mar 1 13:11:44] DEBUG[3242083]: res_pjsip/pjsip_distributor.c:502 distributor: Searching for serializer associated with dialog dlg0x7fde180a4638 for Response msg 180/INVITE/cseq=2178 (rdata0x7fdd400023d8) [Mar 1 13:11:44] DEBUG[3242083]: res_pjsip/pjsip_distributor.c:510 distributor: Found serializer pjsip/outsess/s705-0000007b associated with dialog dlg0x7fde180a4638 [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:4192 session_on_rx_response: PJSIP/s705-00000004 Method: INVITE Status: 180 [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:4195 session_on_rx_response: [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:4597 session_inv_on_state_changed: PJSIP/s705-00000004 Event: TSX_STATE Inv State: EARLY [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:4623 session_inv_on_state_changed: PJSIP/s705-00000004: Source of transaction state change is RX_MSG [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:4565 handle_incoming_before_media: PJSIP/s705-00000004: Received response [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:4432 handle_incoming_response: PJSIP/s705-00000004: Response is 180 Ringing [Mar 1 13:11:44] DEBUG[3242084]: chan_pjsip.c:3161 chan_pjsip_incoming_response_update_cause: PJSIP/s705-00000004: Status: 180 [Mar 1 13:11:44] DEBUG[3242084]: chan_pjsip.c:3182 chan_pjsip_incoming_response_update_cause: PJSIP/s705-00000004 [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:4444 handle_incoming_response: PJSIP/s705-00000004 [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:4671 session_inv_on_state_changed: [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:4715 session_inv_on_tsx_state_changed: PJSIP/s705-00000004 TSX State: Proceeding Inv State: EARLY [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:4432 handle_incoming_response: PJSIP/s705-00000004: Response is 180 Ringing [Mar 1 13:11:44] DEBUG[3242084]: chan_pjsip.c:3189 chan_pjsip_incoming_response: PJSIP/s705-00000004: Status: 180 [Mar 1 13:11:44] DEBUG[3242084]: chan_pjsip.c:3197 chan_pjsip_incoming_response: PJSIP/s705-00000004: Queueing RINGING [Mar 1 13:11:44] DEBUG[3242084]: chan_pjsip.c:3229 chan_pjsip_incoming_response: PJSIP/s705-00000004 [Mar 1 13:11:44] DEBUG[3242084]: chan_pjsip.c:3161 chan_pjsip_incoming_response_update_cause: PJSIP/s705-00000004: Status: 180 [Mar 1 13:11:44] DEBUG[3242084]: chan_pjsip.c:3182 chan_pjsip_incoming_response_update_cause: PJSIP/s705-00000004 [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:4444 handle_incoming_response: PJSIP/s705-00000004 [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:4903 session_inv_on_tsx_state_changed: Nothing delayed [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:4169 session_on_tsx_state: PJSIP/s705-00000004 TSX State: Proceeding Inv State: EARLY [Mar 1 13:11:44] DEBUG[3242066]: devicestate.c:466 do_state_change: Changing state for PJSIP/s705 - state 6 (Ringing) [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:4173 session_on_tsx_state: Topology: Pending: <0:audio-0:audio:sendrecv (g722|gsm)> Active: (null topology) -- PJSIP/s705-00000004 is ringing [Mar 1 13:11:44] DEBUG[3242084]: res_pjsip_session.c:4178 session_on_tsx_state: [Mar 1 13:11:44] DEBUG[3242134]: app_queue.c:2583 device_state_cb: Device 'PJSIP/s705' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. <--- Received SIP request (496 bytes) from UDP:172.16.20.130:5160 ---> REGISTER sip:172.16.1.100:5060 SIP/2.0 Via: SIP/2.0/UDP 172.16.20.130:5160;branch=z9hG4bK8997e1b8 From: ;tag=4a92f3fbb25da2e To: Call-ID: 293743ed5e84d4b@172.16.20.130 CSeq: 22 REGISTER Contact: Max-Forwards: 70 Supported: path User-Agent: Sangoma S705 V3.0.4.75 Expires: 60 Allow: INVITE, ACK, UPDATE, INFO, CANCEL, BYE, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, PRACK Content-Length: 0 [Mar 1 13:11:45] DEBUG[3242083]: res_pjsip/pjsip_distributor.c:393 find_dialog: Could not find matching transaction for Request msg REGISTER/cseq=22 (rdata0x7fdd400023d8) [Mar 1 13:11:45] DEBUG[3242083]: res_pjsip/pjsip_distributor.c:471 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-00000042 to use for Request msg REGISTER/cseq=22 (rdata0x7fdd400023d8) [Mar 1 13:11:45] DEBUG[3242084]: res_pjsip_endpoint_identifier_user.c:148 username_identify: Attempting identify by From username 's705' domain '172.16.1.100' [Mar 1 13:11:45] DEBUG[3242084]: res_pjsip_endpoint_identifier_user.c:160 username_identify: Identified by From username 's705' domain '172.16.1.100' [Mar 1 13:11:45] DEBUG[3242084]: res_pjsip_registrar.c:952 match_aor: Matched id 's705' to aor 's705' [Mar 1 13:11:45] DEBUG[3242084]: res_pjsip_registrar.c:1051 find_registrar_aor: Matched aor 's705' by To username [Mar 1 13:11:45] DEBUG[3242084]: config.c:3847 ast_parse_arg: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [Mar 1 13:11:45] DEBUG[3242084]: config.c:3760 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [Mar 1 13:11:45] DEBUG[3242084]: config.c:3847 ast_parse_arg: extract double from [3.000000] in [-inf, inf] gives [3.000000](0) [Mar 1 13:11:45] DEBUG[3242084]: config.c:3760 ast_parse_arg: extract uint from [5160] in [0, 4294967295] gives [5160](0) [Mar 1 13:11:45] DEBUG[3242084]: config.c:3760 ast_parse_arg: extract uint from [60] in [0, 86400] gives [60](0) [Mar 1 13:11:45] DEBUG[3242084]: config.c:3847 ast_parse_arg: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [Mar 1 13:11:45] DEBUG[3242084]: config.c:3760 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [Mar 1 13:11:45] DEBUG[3242084]: config.c:3847 ast_parse_arg: extract double from [3.000000] in [-inf, inf] gives [3.000000](0) [Mar 1 13:11:45] DEBUG[3242084]: config.c:3760 ast_parse_arg: extract uint from [5160] in [0, 4294967295] gives [5160](0) [Mar 1 13:11:45] DEBUG[3242084]: config.c:3760 ast_parse_arg: extract uint from [60] in [0, 86400] gives [60](0) [Mar 1 13:11:45] DEBUG[3242084]: res_pjsip_registrar.c:848 register_aor_core: Refreshed contact 'sip:s705@172.16.20.130:5160;transport=UDP' on AOR 's705' with new expiration of 60 seconds [Mar 1 13:11:45] DEBUG[3242084]: res_pjsip/pjsip_resolver.c:479 sip_resolve: Performing SIP DNS resolution of target '172.16.20.130' [Mar 1 13:11:45] DEBUG[3242084]: res_pjsip/pjsip_resolver.c:506 sip_resolve: Transport type for target '172.16.20.130' is 'UDP transport' [Mar 1 13:11:45] DEBUG[3242084]: res_pjsip/pjsip_resolver.c:527 sip_resolve: Target '172.16.20.130' is an IP address, skipping resolution [Mar 1 13:11:45] DEBUG[3242084]: res_pjsip/pjsip_message_filter.c:174 print_sanitize_debug: Sanitizing From/To header: sip:s705@172.16.1.100 [Mar 1 13:11:45] DEBUG[3242084]: res_pjsip/pjsip_message_filter.c:174 print_sanitize_debug: Sanitizing From/To header: sip:s705@172.16.1.100 [Mar 1 13:11:45] DEBUG[3242084]: res_pjsip/pjsip_message_filter.c:174 print_sanitize_debug: Sanitizing Contact header: sip:s705@172.16.20.130:5160;transport=UDP <--- Transmitting SIP response (431 bytes) to UDP:172.16.20.130:5160 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 172.16.20.130:5160;received=172.16.20.130;branch=z9hG4bK8997e1b8 Call-ID: 293743ed5e84d4b@172.16.20.130 From: ;tag=4a92f3fbb25da2e To: ;tag=z9hG4bK8997e1b8 CSeq: 22 REGISTER Date: Mon, 01 Mar 2021 17:11:45 GMT Contact: ;expires=59 Expires: 60 Server: Asterisk PBX GIT-18-6673c1b177 Content-Length: 0 <--- Received SIP response (740 bytes) from UDP:172.16.20.130:5160 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 127.0.0.1:5060;rport=5060;branch=z9hG4bKPja93e35cb-5876-4b68-921c-7ca7f6fdf38b;received=172.16.1.100 From: "Anonymous" ;tag=a37afe7d-b79b-44e0-b8cc-7b784abf1287 To: ;tag=f9f13d9485b8604 Call-ID: 470166d5-6f9a-4c04-a4ea-4fc153fc48cd CSeq: 2178 INVITE Contact: User-Agent: Sangoma S705 V3.0.4.75 Allow: INVITE, ACK, UPDATE, INFO, CANCEL, BYE, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, PRACK Content-Type: application/sdp Content-Length: 153 v=0 o=- 6666 78 IN IP4 172.16.20.130 s=SIP Call c=IN IP4 172.16.20.130 t=0 0 m=audio 12182 RTP/AVP 9 a=sendrecv a=rtpmap:9 G722/8000 a=ptime:20 [Mar 1 13:11:46] DEBUG[3242083]: res_pjsip/pjsip_distributor.c:502 distributor: Searching for serializer associated with dialog dlg0x7fde180a4638 for Response msg 200/INVITE/cseq=2178 (rdata0x7fdd400023d8) [Mar 1 13:11:46] DEBUG[3242083]: res_pjsip/pjsip_distributor.c:510 distributor: Found serializer pjsip/outsess/s705-0000007b associated with dialog dlg0x7fde180a4638 [Mar 1 13:11:46] DEBUG[3242084]: res_pjsip_session.c:4192 session_on_rx_response: PJSIP/s705-00000004 Method: INVITE Status: 200 [Mar 1 13:11:46] DEBUG[3242084]: res_pjsip_session.c:4195 session_on_rx_response: [Mar 1 13:11:46] DEBUG[3242084]: res_pjsip_session.c:4597 session_inv_on_state_changed: PJSIP/s705-00000004 Event: TSX_STATE Inv State: CONNECTING [Mar 1 13:11:46] DEBUG[3242084]: res_pjsip_session.c:4623 session_inv_on_state_changed: PJSIP/s705-00000004: Source of transaction state change is RX_MSG [Mar 1 13:11:46] DEBUG[3242084]: res_pjsip_session.c:4565 handle_incoming_before_media: PJSIP/s705-00000004: Received response [Mar 1 13:11:46] DEBUG[3242084]: res_pjsip_session.c:4432 handle_incoming_response: PJSIP/s705-00000004: Response is 200 OK [Mar 1 13:11:46] DEBUG[3242084]: chan_pjsip.c:3161 chan_pjsip_incoming_response_update_cause: PJSIP/s705-00000004: Status: 200 [Mar 1 13:11:46] DEBUG[3242084]: chan_pjsip.c:3182 chan_pjsip_incoming_response_update_cause: PJSIP/s705-00000004 [Mar 1 13:11:46] DEBUG[3242084]: res_pjsip_session.c:4444 handle_incoming_response: PJSIP/s705-00000004 [Mar 1 13:11:46] DEBUG[3242084]: res_pjsip_session.c:4671 session_inv_on_state_changed: [Mar 1 13:11:46] DEBUG[3242084]: res_pjsip_session.c:5306 session_inv_on_media_update: PJSIP/s705-00000004 [Mar 1 13:11:46] DEBUG[3242084]: res_pjsip_session.c:1068 handle_negotiated_sdp: PJSIP/s705-00000004 [Mar 1 13:11:46] DEBUG[3242084]: res_pjsip_session.c:974 handle_negotiated_sdp_session_media: PJSIP/s705-00000004 [Mar 1 13:11:46] DEBUG[3242084]: res_pjsip_sdp_rtp.c:2033 apply_negotiated_sdp_stream: PJSIP/s705-00000004 Stream: 0:audio-0:audio:sendrecv (g722|gsm) [Mar 1 13:11:46] DEBUG[3242084]: res_rtp_asterisk.c:8178 ast_rtp_prop_set: (0x7fde180e6de0) RTCP ignoring duplicate property [Mar 1 13:11:46] DEBUG[3242084]: acl.c:1045 ast_ouraddrfor: For destination '172.16.20.130', our source address is '172.16.1.100'. [Mar 1 13:11:46] DEBUG[3242084]: res_rtp_asterisk.c:8381 ast_rtp_remote_address_set: (0x7fde180e6de0) RTCP setting address on RTP instance > 0x7fde1809be10 -- Strict RTP learning after remote address set to: 172.16.20.130:12182 [Mar 1 13:11:46] DEBUG[3242084]: res_pjsip_sdp_rtp.c:500 set_caps: PJSIP/s705-00000004 ANSWER [Mar 1 13:11:46] DEBUG[3242084]: res_pjsip_sdp_rtp.c:328 get_codecs: PJSIP/s705-00000004 [Mar 1 13:11:46] DEBUG[3242084]: rtp_engine.c:1318 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 9 based on m type on 0x7fde496b3fc0 [Mar 1 13:11:46] DEBUG[3242084]: res_pjsip_sdp_rtp.c:404 get_codecs: [Mar 1 13:11:46] DEBUG[3242084]: rtp_engine.c:1204 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 9 (0x7fde180098f8) from 0x7fde496b3fc0 to 0x7fde180e6fb8 [Mar 1 13:11:46] DEBUG[3242084]: channel_internal_api.c:680 ast_channel_nativeformats_set: PJSIP/s705-00000004: MultistreamFormats: (g722) [Mar 1 13:11:46] DEBUG[3242084]: channel_internal_api.c:702 ast_channel_nativeformats_set: Set native formats but not topology [Mar 1 13:11:46] DEBUG[3242084]: channel.c:5730 set_format: Channel PJSIP/s705-00000004 setting read format path: g722 -> g722 [Mar 1 13:11:46] DEBUG[3242084]: channel.c:5730 set_format: Channel PJSIP/s705-00000004 setting write format path: g722 -> g722 [Mar 1 13:11:46] DEBUG[3242084]: res_pjsip_sdp_rtp.c:611 set_caps: [Mar 1 13:11:46] DEBUG[3242084]: res_rtp_asterisk.c:8877 ast_rtp_activate: (0x7fde180e6de0) DTLS - ast_rtp_activate rtp=0x7fde1809be10 - setup and perform DTLS' [Mar 1 13:11:46] DEBUG[3242084]: res_rtp_asterisk.c:2503 dtls_perform_handshake: (0x7fde1809be10) DTLS perform handshake - ssl = (nil), setup = 0 [Mar 1 13:11:46] DEBUG[3242084]: res_rtp_asterisk.c:2503 dtls_perform_handshake: (0x7fde1809be10) DTLS perform handshake - ssl = (nil), setup = 0 [Mar 1 13:11:46] DEBUG[3242084]: res_pjsip_sdp_rtp.c:2180 apply_negotiated_sdp_stream: Handled [Mar 1 13:11:46] DEBUG[3242084]: res_pjsip_session.c:1013 handle_negotiated_sdp_session_media: PJSIP/s705-00000004: Applied negotiated SDP media stream 'audio' using audio SDP handler [Mar 1 13:11:46] DEBUG[3242084]: channel_internal_api.c:1595 ast_channel_set_stream_topology: PJSIP/s705-00000004: <0:audio-0:audio:sendrecv (g722)> [Mar 1 13:11:46] DEBUG[3242084]: channel_internal_api.c:1616 ast_channel_set_stream_topology: Used provided topology [Mar 1 13:11:46] DEBUG[3242084]: res_pjsip_session.c:1223 handle_negotiated_sdp: [Mar 1 13:11:46] DEBUG[3242084]: res_pjsip_session.c:5370 session_inv_on_media_update: PJSIP/s705-00000004 [Mar 1 13:11:46] DEBUG[3242084]: res_pjsip/pjsip_resolver.c:479 sip_resolve: Performing SIP DNS resolution of target '172.16.20.130' [Mar 1 13:11:46] DEBUG[3242084]: res_pjsip/pjsip_resolver.c:506 sip_resolve: Transport type for target '172.16.20.130' is 'UDP transport' [Mar 1 13:11:46] DEBUG[3242084]: res_pjsip/pjsip_resolver.c:527 sip_resolve: Target '172.16.20.130' is an IP address, skipping resolution [Mar 1 13:11:46] DEBUG[3242084]: res_pjsip/pjsip_message_filter.c:174 print_sanitize_debug: Sanitizing Request: sip:s705@172.16.20.130:5160;transport=UDP [Mar 1 13:11:46] DEBUG[3242084]: res_pjsip/pjsip_message_filter.c:174 print_sanitize_debug: Sanitizing From/To header: sip:anonymous@anonymous.invalid [Mar 1 13:11:46] DEBUG[3242084]: res_pjsip/pjsip_message_filter.c:174 print_sanitize_debug: Sanitizing From/To header: sip:s705@172.16.20.130 <--- Transmitting SIP request (438 bytes) to UDP:172.16.20.130:5160 ---> ACK sip:s705@172.16.20.130:5160;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:5060;rport;branch=z9hG4bKPj5d7c91da-0918-4422-a3d9-54a0519e23d1 From: "Anonymous" ;tag=a37afe7d-b79b-44e0-b8cc-7b784abf1287 To: ;tag=f9f13d9485b8604 Call-ID: 470166d5-6f9a-4c04-a4ea-4fc153fc48cd CSeq: 2178 ACK Max-Forwards: 70 User-Agent: Asterisk PBX GIT-18-6673c1b177 Content-Length: 0 [Mar 1 13:11:46] DEBUG[3242084]: res_pjsip_session.c:4597 session_inv_on_state_changed: PJSIP/s705-00000004 Event: TX_MSG Inv State: CONFIRMED [Mar 1 13:11:46] DEBUG[3242084]: res_pjsip_session.c:4671 session_inv_on_state_changed: [Mar 1 13:11:46] DEBUG[3242084]: res_pjsip_session.c:4715 session_inv_on_tsx_state_changed: PJSIP/s705-00000004 TSX State: Terminated Inv State: CONFIRMED [Mar 1 13:11:46] DEBUG[3242084]: res_pjsip_session.c:4432 handle_incoming_response: PJSIP/s705-00000004: Response is 200 OK [Mar 1 13:11:46] DEBUG[3242084]: chan_pjsip.c:3189 chan_pjsip_incoming_response: PJSIP/s705-00000004: Status: 200 [Mar 1 13:11:46] DEBUG[3242084]: chan_pjsip.c:3221 chan_pjsip_incoming_response: PJSIP/s705-00000004: Queueing ANSWER [Mar 1 13:11:46] DEBUG[3242084]: chan_pjsip.c:3229 chan_pjsip_incoming_response: PJSIP/s705-00000004 [Mar 1 13:11:46] DEBUG[3242084]: chan_pjsip.c:3161 chan_pjsip_incoming_response_update_cause: PJSIP/s705-00000004: Status: 200 -- PJSIP/s705-00000004 answered [Mar 1 13:11:46] DEBUG[3242075]: stasis.c:578 stasis_topic_create_with_detail: Creating topic. name: channel:1614618706.29, detail: [Mar 1 13:11:46] DEBUG[3242066]: devicestate.c:466 do_state_change: Changing state for PJSIP/s705 - state 2 (In use) [Mar 1 13:11:46] DEBUG[3242084]: chan_pjsip.c:3182 chan_pjsip_incoming_response_update_cause: PJSIP/s705-00000004 [Mar 1 13:11:46] DEBUG[3242084]: res_pjsip_session.c:4444 handle_incoming_response: PJSIP/s705-00000004 [Mar 1 13:11:46] DEBUG[3242075]: stasis.c:612 stasis_topic_create_with_detail: Topic 'channel:1614618706.29': 0x7fde38007a90 created [Mar 1 13:11:46] DEBUG[3242084]: res_pjsip_session.c:4903 session_inv_on_tsx_state_changed: Nothing delayed [Mar 1 13:11:46] DEBUG[3242084]: res_pjsip_session.c:4169 session_on_tsx_state: PJSIP/s705-00000004 TSX State: Terminated Inv State: CONFIRMED [Mar 1 13:11:46] DEBUG[3242084]: res_pjsip_session.c:4173 session_on_tsx_state: Topology: Pending: (null topology) Active: <0:audio-0:audio:sendrecv (g722)> [Mar 1 13:11:46] DEBUG[3242084]: res_pjsip_session.c:4178 session_on_tsx_state: > Launching Playback(demo-congrats) on PJSIP/s705-00000004 [Mar 1 13:11:46] DEBUG[3242134]: app_queue.c:2583 device_state_cb: Device 'PJSIP/s705' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Mar 1 13:11:46] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE(ANSWER) result is '"ANSWER"' [Mar 1 13:11:46] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE(1614618706.139821) result is '"1614618706.139821"' [Mar 1 13:11:46] ERROR[3242075]: pbx_functions.c:651 ast_func_read2: Function CALLERID not registered [Mar 1 13:11:46] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CALLERID(name) result is '' [Mar 1 13:11:46] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Mar 1 13:11:46] ERROR[3242075]: pbx_functions.c:651 ast_func_read2: Function CALLERID not registered [Mar 1 13:11:46] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CALLERID(num) result is '' [Mar 1 13:11:46] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Mar 1 13:11:46] ERROR[3242075]: pbx_functions.c:651 ast_func_read2: Function CALLERID not registered [Mar 1 13:11:46] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CALLERID(ANI) result is '' [Mar 1 13:11:46] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Mar 1 13:11:46] ERROR[3242075]: pbx_functions.c:651 ast_func_read2: Function CALLERID not registered [Mar 1 13:11:46] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CALLERID(RDNIS) result is '' [Mar 1 13:11:46] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Mar 1 13:11:46] ERROR[3242075]: pbx_functions.c:651 ast_func_read2: Function CALLERID not registered [Mar 1 13:11:46] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CALLERID(DNID) result is '' [Mar 1 13:11:46] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Mar 1 13:11:46] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CHANNEL(exten) result is 's' [Mar 1 13:11:46] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE(s) result is '"s"' [Mar 1 13:11:46] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CHANNEL(context) result is 'users' [Mar 1 13:11:46] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE(users) result is '"users"' [Mar 1 13:11:46] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CHANNEL(channame) result is 'PJSIP/s705-00000004' [Mar 1 13:11:46] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE(PJSIP/s705-00000004) result is '"PJSIP/s705-00000004"' [Mar 1 13:11:46] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CHANNEL(appname) result is 'AppDial2' [Mar 1 13:11:46] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE(AppDial2) result is '"AppDial2"' [Mar 1 13:11:46] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CHANNEL(appdata) result is '(Outgoing Line)' [Mar 1 13:11:46] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE((Outgoing Line)) result is '"(Outgoing Line)"' [Mar 1 13:11:46] DEBUG[3243072]: channel.c:5730 set_format: Channel PJSIP/s705-00000004 setting write format path: gsm -> g722 [Mar 1 13:11:46] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CHANNEL(amaflags) result is '3' [Mar 1 13:11:46] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE(3) result is '"3"' [Mar 1 13:11:46] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CHANNEL(accountcode) result is '' [Mar 1 13:11:46] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Mar 1 13:11:46] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CHANNEL(uniqueid) result is '1614618704.27' [Mar 1 13:11:46] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE(1614618704.27) result is '"1614618704.27"' [Mar 1 13:11:46] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CHANNEL(linkedid) result is '1614618704.27' [Mar 1 13:11:46] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE(1614618704.27) result is '"1614618704.27"' [Mar 1 13:11:46] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CHANNEL(peer) result is '' [Mar 1 13:11:46] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Mar 1 13:11:46] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CHANNEL(userfield) result is '' [Mar 1 13:11:46] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Mar 1 13:11:46] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Mar 1 13:11:46] DEBUG[3242075]: stasis.c:440 topic_dtor: Destroying topic. name: channel:1614618706.29, detail: [Mar 1 13:11:46] DEBUG[3242075]: stasis.c:449 topic_dtor: Topic 'channel:1614618706.29': 0x7fde38007a90 destroyed [Mar 1 13:11:46] DEBUG[3243072]: res_rtp_asterisk.c:5333 ast_rtp_write: (0x7fde180e6de0) RTP ooh, format changed from none to g722 [Mar 1 13:11:46] DEBUG[3243072]: res_rtp_asterisk.c:5075 rtp_raw_write: (0x7fde180e6de0) RTCP starting transmission [Mar 1 13:11:46] DEBUG[3243072]: channel.c:3201 ast_settimeout_full: Scheduling timer at (50 requested / 50 actual) timer ticks per second -- Playing 'demo-congrats.gsm' (language 'en') > 0x7fde1809be10 -- Strict RTP switching to RTP target address 172.16.20.130:12182 as source [Mar 1 13:11:47] DEBUG[3242095]: res_pjsip_registrar.c:1293 check_expiration_thread: Expiring 0 contacts <--- Received SIP request (770 bytes) from UDP:172.16.20.130:5160 ---> INVITE sip:asterisk@127.0.0.1:5060 SIP/2.0 Via: SIP/2.0/UDP 172.16.20.130:5160;branch=z9hG4bK309341120 From: ;tag=f9f13d9485b8604 To: "Anonymous" ;tag=a37afe7d-b79b-44e0-b8cc-7b784abf1287 Call-ID: 470166d5-6f9a-4c04-a4ea-4fc153fc48cd CSeq: 2179 INVITE Contact: Max-Forwards: 70 Session-Expires: 180;refresher=uas Min-SE: 90 User-Agent: Sangoma S705 V3.0.4.75 Allow: INVITE, ACK, UPDATE, INFO, CANCEL, BYE, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, PRACK Content-Type: application/sdp Content-Length: 147 v=0 o=- 6666 79 IN IP4 172.16.20.130 s=SIP Call c=IN IP4 0.0.0.0 t=0 0 m=audio 12182 RTP/AVP 9 a=sendonly a=rtpmap:9 G722/8000 a=ptime:20 [Mar 1 13:11:47] DEBUG[3242083]: res_pjsip/pjsip_distributor.c:502 distributor: Searching for serializer associated with dialog dlg0x7fde180a4638 for Request msg INVITE/cseq=2179 (rdata0x7fdd400023d8) [Mar 1 13:11:47] DEBUG[3242083]: res_pjsip/pjsip_distributor.c:510 distributor: Found serializer pjsip/outsess/s705-0000007b associated with dialog dlg0x7fde180a4638 [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session.c:495 ast_sip_session_media_state_add: PJSIP/s705-00000004 Adding position 0 [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session.c:513 ast_sip_session_media_state_add: Reusing existing media session [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session.c:584 ast_sip_session_media_state_add: Setting media session as default for audio [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session.c:589 ast_sip_session_media_state_add: Done [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session.c:5218 session_inv_on_rx_offer: PJSIP/s705-00000004 [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session.c:769 handle_incoming_sdp: PJSIP/s705-00000004: Media count: 1 [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session.c:495 ast_sip_session_media_state_add: PJSIP/s705-00000004 Adding position 0 [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session.c:503 ast_sip_session_media_state_add: Using existing media_session [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_sdp_rtp.c:1437 negotiate_incoming_sdp_stream: PJSIP/s705-00000004 [Mar 1 13:11:47] DEBUG[3242084]: res_rtp_asterisk.c:8178 ast_rtp_prop_set: (0x7fde180e6de0) RTCP ignoring duplicate property [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_sdp_rtp.c:446 set_incoming_call_offer_cap: PJSIP/s705-00000004 [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_sdp_rtp.c:328 get_codecs: PJSIP/s705-00000004 [Mar 1 13:11:47] DEBUG[3242084]: rtp_engine.c:1318 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 9 based on m type on 0x7fde496b3cb0 [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_sdp_rtp.c:404 get_codecs: [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session/pjsip_session_caps.c:161 ast_sip_session_create_joint_call_cap: 'PJSIP/s705-00000004' Caps for outgoing audio call with pref 'remote_merge' - remote: (g722) local: (g722|gsm) joint: (g722|gsm) [Mar 1 13:11:47] DEBUG[3242084]: rtp_engine.c:1282 ast_rtp_codecs_payloads_xover: Crossover copying tx to rx payload mapping 9 (0x7fde180a0298) from 0x7fde496b3cb0 to 0x7fde496b3cb0 [Mar 1 13:11:47] DEBUG[3242084]: rtp_engine.c:1119 rtp_codecs_payloads_copy_rx: Copying rx payload mapping 9 (0x7fde180a0298) from 0x7fde496b3cb0 to 0x7fde180e6fb8 [Mar 1 13:11:47] DEBUG[3242084]: rtp_engine.c:1204 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 9 (0x7fde180a0298) from 0x7fde496b3cb0 to 0x7fde180e6fb8 [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_sdp_rtp.c:482 set_incoming_call_offer_cap: [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_sdp_rtp.c:1535 negotiate_incoming_sdp_stream: [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session.c:960 handle_incoming_sdp: PJSIP/s705-00000004: Handled? yes [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session.c:5067 create_local_sdp: PJSIP/s705-00000004 [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session.c:5104 create_local_sdp: PJSIP/s705-00000004: Processing streams [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session.c:495 ast_sip_session_media_state_add: PJSIP/s705-00000004 Adding position 0 [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session.c:503 ast_sip_session_media_state_add: Using existing media_session [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session.c:4943 add_sdp_streams: PJSIP/s705-00000004 Stream: 0:audio-0:audio:sendrecv (g722|gsm) [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_sdp_rtp.c:1690 create_outgoing_sdp_stream: PJSIP/s705-00000004 Type: audio 0:audio-0:audio:sendrecv (g722|gsm) [Mar 1 13:11:47] DEBUG[3242084]: res_rtp_asterisk.c:8178 ast_rtp_prop_set: (0x7fde180e6de0) RTCP ignoring duplicate property [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_sdp_rtp.c:1975 create_outgoing_sdp_stream: RC: 1 [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session.c:4952 add_sdp_streams: Had handler [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session.c:5161 create_local_sdp: PJSIP/s705-00000004: Adding bundle groups (if available) [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session.c:5167 create_local_sdp: PJSIP/s705-00000004: Copying connection details [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session.c:5211 create_local_sdp: PJSIP/s705-00000004 [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session.c:5232 session_inv_on_rx_offer: PJSIP/s705-00000004: Set SDP answer [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session.c:5306 session_inv_on_media_update: PJSIP/s705-00000004 [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session.c:1068 handle_negotiated_sdp: PJSIP/s705-00000004 [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session.c:974 handle_negotiated_sdp_session_media: PJSIP/s705-00000004 [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_sdp_rtp.c:2033 apply_negotiated_sdp_stream: PJSIP/s705-00000004 Stream: 0:audio-0:audio:sendrecv (g722|gsm) [Mar 1 13:11:47] DEBUG[3242084]: res_rtp_asterisk.c:8178 ast_rtp_prop_set: (0x7fde180e6de0) RTCP ignoring duplicate property [Mar 1 13:11:47] DEBUG[3242084]: acl.c:1045 ast_ouraddrfor: For destination '0.0.0.0', our source address is '127.0.0.1'. [Mar 1 13:11:47] DEBUG[3242084]: res_rtp_asterisk.c:8381 ast_rtp_remote_address_set: (0x7fde180e6de0) RTCP setting address on RTP instance > 0x7fde1809be10 -- Strict RTP learning after remote address set to: 0.0.0.0:12182 [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_sdp_rtp.c:500 set_caps: PJSIP/s705-00000004 ANSWER [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_sdp_rtp.c:328 get_codecs: PJSIP/s705-00000004 [Mar 1 13:11:47] DEBUG[3242084]: rtp_engine.c:1318 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 9 based on m type on 0x7fde496b3ed0 [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_sdp_rtp.c:404 get_codecs: [Mar 1 13:11:47] DEBUG[3242084]: rtp_engine.c:1204 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 9 (0x7fde180159f8) from 0x7fde496b3ed0 to 0x7fde180e6fb8 [Mar 1 13:11:47] DEBUG[3242084]: channel_internal_api.c:680 ast_channel_nativeformats_set: PJSIP/s705-00000004: MultistreamFormats: (g722) [Mar 1 13:11:47] DEBUG[3242084]: channel_internal_api.c:702 ast_channel_nativeformats_set: Set native formats but not topology [Mar 1 13:11:47] DEBUG[3242084]: channel.c:5730 set_format: Channel PJSIP/s705-00000004 setting read format path: g722 -> g722 [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_sdp_rtp.c:611 set_caps: [Mar 1 13:11:47] DEBUG[3242084]: res_rtp_asterisk.c:8877 ast_rtp_activate: (0x7fde180e6de0) DTLS - ast_rtp_activate rtp=0x7fde1809be10 - setup and perform DTLS' [Mar 1 13:11:47] DEBUG[3242084]: res_rtp_asterisk.c:2503 dtls_perform_handshake: (0x7fde1809be10) DTLS perform handshake - ssl = (nil), setup = 0 [Mar 1 13:11:47] DEBUG[3242084]: res_rtp_asterisk.c:2503 dtls_perform_handshake: (0x7fde1809be10) DTLS perform handshake - ssl = (nil), setup = 0 [Mar 1 13:11:47] DEBUG[3242084]: res_rtp_asterisk.c:2828 dtls_srtp_stop_timeout_timer: (0x7fde180e6de0) DTLS srtp - stopped timeout timer' [Mar 1 13:11:47] DEBUG[3242084]: res_rtp_asterisk.c:2828 dtls_srtp_stop_timeout_timer: (0x7fde180e6de0) DTLS srtp - stopped timeout timer' [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_sdp_rtp.c:2180 apply_negotiated_sdp_stream: Handled [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session.c:1013 handle_negotiated_sdp_session_media: PJSIP/s705-00000004: Applied negotiated SDP media stream 'audio' using audio SDP handler [Mar 1 13:11:47] DEBUG[3242084]: channel_internal_api.c:1595 ast_channel_set_stream_topology: PJSIP/s705-00000004: <0:audio-0:audio:sendrecv (g722)> [Mar 1 13:11:47] DEBUG[3242084]: channel_internal_api.c:1616 ast_channel_set_stream_topology: Used provided topology [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session.c:1223 handle_negotiated_sdp: [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session.c:5370 session_inv_on_media_update: PJSIP/s705-00000004 [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip/pjsip_resolver.c:479 sip_resolve: Performing SIP DNS resolution of target '172.16.20.130' [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip/pjsip_resolver.c:506 sip_resolve: Transport type for target '172.16.20.130' is 'UDP transport' [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip/pjsip_resolver.c:527 sip_resolve: Target '172.16.20.130' is an IP address, skipping resolution [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip/pjsip_message_filter.c:174 print_sanitize_debug: Sanitizing From/To header: sip:s705@172.16.20.130 [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip/pjsip_message_filter.c:174 print_sanitize_debug: Sanitizing From/To header: sip:anonymous@anonymous.invalid [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip/pjsip_message_filter.c:174 print_sanitize_debug: Sanitizing Contact header: sip:asterisk@172.16.1.100:5060 <--- Transmitting SIP response (820 bytes) to UDP:172.16.20.130:5160 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 172.16.20.130:5160;received=172.16.20.130;branch=z9hG4bK309341120 Call-ID: 470166d5-6f9a-4c04-a4ea-4fc153fc48cd From: ;tag=f9f13d9485b8604 To: "Anonymous" ;tag=a37afe7d-b79b-44e0-b8cc-7b784abf1287 CSeq: 2179 INVITE Session-Expires: 180;refresher=uas Contact: Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER Supported: 100rel, timer, replaces, norefersub Server: Asterisk PBX GIT-18-6673c1b177 Content-Type: application/sdp Content-Length: 179 v=0 o=- 802505438 802505439 IN IP4 172.16.1.100 s=Asterisk c=IN IP4 172.16.1.100 t=0 0 m=audio 16310 RTP/AVP 9 a=rtpmap:9 G722/8000 a=ptime:20 a=maxptime:150 a=recvonly [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session.c:4715 session_inv_on_tsx_state_changed: PJSIP/s705-00000004 TSX State: Completed Inv State: CONFIRMED [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session.c:4903 session_inv_on_tsx_state_changed: Nothing delayed [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session.c:4169 session_on_tsx_state: PJSIP/s705-00000004 TSX State: Completed Inv State: CONFIRMED [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session.c:4173 session_on_tsx_state: Topology: Pending: (null topology) Active: <0:audio-0:audio:sendrecv (g722)> [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session.c:4178 session_on_tsx_state: [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session.c:4715 session_inv_on_tsx_state_changed: PJSIP/s705-00000004 TSX State: Completed Inv State: CONFIRMED [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session.c:4380 handle_incoming_request: PJSIP/s705-00000004: Method is INVITE [Mar 1 13:11:47] DEBUG[3242084]: chan_pjsip.c:3012 chan_pjsip_incoming_request: PJSIP/s705-00000004 [Mar 1 13:11:47] DEBUG[3242084]: chan_pjsip.c:3015 chan_pjsip_incoming_request: PJSIP/s705-00000004: No channel [Mar 1 13:11:47] DEBUG[3242084]: chan_pjsip.c:3118 pbx_start_incoming_request: PJSIP/s705-00000004 [Mar 1 13:11:47] DEBUG[3242084]: chan_pjsip.c:3123 pbx_start_incoming_request: Reinvite [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session.c:4390 handle_incoming_request: PJSIP/s705-00000004 [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session.c:4903 session_inv_on_tsx_state_changed: Nothing delayed [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session.c:4169 session_on_tsx_state: PJSIP/s705-00000004 TSX State: Completed Inv State: CONFIRMED [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session.c:4173 session_on_tsx_state: Topology: Pending: (null topology) Active: <0:audio-0:audio:sendrecv (g722)> [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session.c:4178 session_on_tsx_state: [Mar 1 13:11:47] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame <--- Received SIP request (439 bytes) from UDP:172.16.20.130:5160 ---> ACK sip:asterisk@127.0.0.1:5060 SIP/2.0 Via: SIP/2.0/UDP 172.16.20.130:5160;branch=z9hG4bK2173590333 From: ;tag=f9f13d9485b8604 To: "Anonymous" ;tag=a37afe7d-b79b-44e0-b8cc-7b784abf1287 Call-ID: 470166d5-6f9a-4c04-a4ea-4fc153fc48cd CSeq: 2179 ACK Contact: Max-Forwards: 70 User-Agent: Sangoma S705 V3.0.4.75 Content-Length: 0 [Mar 1 13:11:47] DEBUG[3242083]: res_pjsip/pjsip_distributor.c:502 distributor: Searching for serializer associated with dialog dlg0x7fde180a4638 for Request msg ACK/cseq=2179 (rdata0x7fdd400023d8) [Mar 1 13:11:47] DEBUG[3242083]: res_pjsip/pjsip_distributor.c:510 distributor: Found serializer pjsip/outsess/s705-0000007b associated with dialog dlg0x7fde180a4638 [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session.c:4715 session_inv_on_tsx_state_changed: PJSIP/s705-00000004 TSX State: Terminated Inv State: CONFIRMED [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session.c:4903 session_inv_on_tsx_state_changed: Nothing delayed [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session.c:4169 session_on_tsx_state: PJSIP/s705-00000004 TSX State: Terminated Inv State: CONFIRMED [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session.c:4173 session_on_tsx_state: Topology: Pending: (null topology) Active: <0:audio-0:audio:sendrecv (g722)> [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session.c:4178 session_on_tsx_state: [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session.c:4224 session_on_rx_request: PJSIP/s705-00000004 Request: ACK [Mar 1 13:11:47] DEBUG[3242084]: res_pjsip_session.c:4243 session_on_rx_request: PJSIP/s705-00000004 Handled request ACK ? yes [Mar 1 13:11:47] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:47] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:47] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:47] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:47] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:47] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:47] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:47] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:47] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:47] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:47] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:47] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:47] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:47] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:47] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:47] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:48] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:49] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:49] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:49] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:49] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:49] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:49] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:49] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:49] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:49] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:49] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:49] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:49] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:49] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:49] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:49] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:49] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:49] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:49] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:49] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:49] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:49] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:49] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:49] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:49] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:49] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:49] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:49] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:49] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:49] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:49] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:49] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame [Mar 1 13:11:49] DEBUG[3243072]: res_rtp_asterisk.c:5284 ast_rtp_write: (0x7fde180e6de0) RTP no remote address on instance, so dropping frame <--- Received SIP request (920 bytes) from UDP:172.16.20.130:5160 ---> INVITE sip:asterisk@127.0.0.1:5060 SIP/2.0 Via: SIP/2.0/UDP 172.16.20.130:5160;branch=z9hG4bK3081793179 From: ;tag=f9f13d9485b8604 To: "Anonymous" ;tag=a37afe7d-b79b-44e0-b8cc-7b784abf1287 Call-ID: 470166d5-6f9a-4c04-a4ea-4fc153fc48cd CSeq: 2180 INVITE Contact: Max-Forwards: 70 Session-Expires: 180;refresher=uas Min-SE: 90 User-Agent: Sangoma S705 V3.0.4.75 Allow: INVITE, ACK, UPDATE, INFO, CANCEL, BYE, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, PRACK Content-Type: application/sdp Content-Length: 296 v=0 o=- 6666 80 IN IP4 172.16.20.130 s=SIP Call c=IN IP4 172.16.20.130 t=0 0 m=audio 12182 RTP/AVP 0 8 9 97 3 2 a=sendrecv a=rtpmap:0 PCMU/8000 a=ptime:20 a=rtpmap:8 PCMA/8000 a=rtpmap:9 G722/8000 a=rtpmap:97 iLBC/8000 a=fmtp:97 mode=20 a=rtpmap:3 GSM/8000 a=rtpmap:2 G726-32/8000 [Mar 1 13:11:49] DEBUG[3242083]: res_pjsip/pjsip_distributor.c:502 distributor: Searching for serializer associated with dialog dlg0x7fde180a4638 for Request msg INVITE/cseq=2180 (rdata0x7fdd400023d8) [Mar 1 13:11:49] DEBUG[3242083]: res_pjsip/pjsip_distributor.c:510 distributor: Found serializer pjsip/outsess/s705-0000007b associated with dialog dlg0x7fde180a4638 [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session.c:495 ast_sip_session_media_state_add: PJSIP/s705-00000004 Adding position 0 [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session.c:513 ast_sip_session_media_state_add: Reusing existing media session [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session.c:584 ast_sip_session_media_state_add: Setting media session as default for audio [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session.c:589 ast_sip_session_media_state_add: Done [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session.c:5218 session_inv_on_rx_offer: PJSIP/s705-00000004 [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session.c:769 handle_incoming_sdp: PJSIP/s705-00000004: Media count: 1 [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session.c:495 ast_sip_session_media_state_add: PJSIP/s705-00000004 Adding position 0 [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session.c:503 ast_sip_session_media_state_add: Using existing media_session [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_sdp_rtp.c:1437 negotiate_incoming_sdp_stream: PJSIP/s705-00000004 [Mar 1 13:11:49] DEBUG[3242084]: res_rtp_asterisk.c:8178 ast_rtp_prop_set: (0x7fde180e6de0) RTCP ignoring duplicate property [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_sdp_rtp.c:446 set_incoming_call_offer_cap: PJSIP/s705-00000004 [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_sdp_rtp.c:328 get_codecs: PJSIP/s705-00000004 [Mar 1 13:11:49] DEBUG[3242084]: rtp_engine.c:1318 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 0 based on m type on 0x7fde496b3cb0 [Mar 1 13:11:49] DEBUG[3242084]: rtp_engine.c:1318 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 8 based on m type on 0x7fde496b3cb0 [Mar 1 13:11:49] DEBUG[3242084]: rtp_engine.c:1318 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 9 based on m type on 0x7fde496b3cb0 [Mar 1 13:11:49] DEBUG[3242084]: rtp_engine.c:1318 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 3 based on m type on 0x7fde496b3cb0 [Mar 1 13:11:49] DEBUG[3242084]: rtp_engine.c:1313 ast_rtp_codecs_payloads_set_m_type: Don't have a default tx payload type 2 format for m type on 0x7fde496b3cb0 [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_sdp_rtp.c:404 get_codecs: [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session/pjsip_session_caps.c:161 ast_sip_session_create_joint_call_cap: 'PJSIP/s705-00000004' Caps for outgoing audio call with pref 'remote_merge' - remote: (ulaw|g726|gsm|alaw|g722|ilbc) local: (g722|gsm) joint: (gsm|g722) [Mar 1 13:11:49] DEBUG[3242084]: rtp_engine.c:1282 ast_rtp_codecs_payloads_xover: Crossover copying tx to rx payload mapping 0 (0x7fde180a0e08) from 0x7fde496b3cb0 to 0x7fde496b3cb0 [Mar 1 13:11:49] DEBUG[3242084]: rtp_engine.c:1282 ast_rtp_codecs_payloads_xover: Crossover copying tx to rx payload mapping 2 (0x7fde18095ef8) from 0x7fde496b3cb0 to 0x7fde496b3cb0 [Mar 1 13:11:49] DEBUG[3242084]: rtp_engine.c:1282 ast_rtp_codecs_payloads_xover: Crossover copying tx to rx payload mapping 3 (0x7fde18095f48) from 0x7fde496b3cb0 to 0x7fde496b3cb0 [Mar 1 13:11:49] DEBUG[3242084]: rtp_engine.c:1282 ast_rtp_codecs_payloads_xover: Crossover copying tx to rx payload mapping 8 (0x7fde18098f88) from 0x7fde496b3cb0 to 0x7fde496b3cb0 [Mar 1 13:11:49] DEBUG[3242084]: rtp_engine.c:1282 ast_rtp_codecs_payloads_xover: Crossover copying tx to rx payload mapping 9 (0x7fde1800c5d8) from 0x7fde496b3cb0 to 0x7fde496b3cb0 [Mar 1 13:11:49] DEBUG[3242084]: rtp_engine.c:1282 ast_rtp_codecs_payloads_xover: Crossover copying tx to rx payload mapping 97 (0x7fde180e5ee8) from 0x7fde496b3cb0 to 0x7fde496b3cb0 [Mar 1 13:11:49] DEBUG[3242084]: rtp_engine.c:1119 rtp_codecs_payloads_copy_rx: Copying rx payload mapping 0 (0x7fde180a0e08) from 0x7fde496b3cb0 to 0x7fde180e6fb8 [Mar 1 13:11:49] DEBUG[3242084]: rtp_engine.c:1119 rtp_codecs_payloads_copy_rx: Copying rx payload mapping 2 (0x7fde18095ef8) from 0x7fde496b3cb0 to 0x7fde180e6fb8 [Mar 1 13:11:49] DEBUG[3242084]: rtp_engine.c:1119 rtp_codecs_payloads_copy_rx: Copying rx payload mapping 3 (0x7fde18095f48) from 0x7fde496b3cb0 to 0x7fde180e6fb8 [Mar 1 13:11:49] DEBUG[3242084]: rtp_engine.c:1119 rtp_codecs_payloads_copy_rx: Copying rx payload mapping 8 (0x7fde18098f88) from 0x7fde496b3cb0 to 0x7fde180e6fb8 [Mar 1 13:11:49] DEBUG[3242084]: rtp_engine.c:1119 rtp_codecs_payloads_copy_rx: Copying rx payload mapping 9 (0x7fde1800c5d8) from 0x7fde496b3cb0 to 0x7fde180e6fb8 [Mar 1 13:11:49] DEBUG[3242084]: rtp_engine.c:1119 rtp_codecs_payloads_copy_rx: Copying rx payload mapping 97 (0x7fde180e5ee8) from 0x7fde496b3cb0 to 0x7fde180e6fb8 [Mar 1 13:11:49] DEBUG[3242084]: rtp_engine.c:1204 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 0 (0x7fde180a0e08) from 0x7fde496b3cb0 to 0x7fde180e6fb8 [Mar 1 13:11:49] DEBUG[3242084]: rtp_engine.c:1204 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 2 (0x7fde18095ef8) from 0x7fde496b3cb0 to 0x7fde180e6fb8 [Mar 1 13:11:49] DEBUG[3242084]: rtp_engine.c:1204 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 3 (0x7fde18095f48) from 0x7fde496b3cb0 to 0x7fde180e6fb8 [Mar 1 13:11:49] DEBUG[3242084]: rtp_engine.c:1204 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 8 (0x7fde18098f88) from 0x7fde496b3cb0 to 0x7fde180e6fb8 [Mar 1 13:11:49] DEBUG[3242084]: rtp_engine.c:1204 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 9 (0x7fde1800c5d8) from 0x7fde496b3cb0 to 0x7fde180e6fb8 [Mar 1 13:11:49] DEBUG[3242084]: rtp_engine.c:1204 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 97 (0x7fde180e5ee8) from 0x7fde496b3cb0 to 0x7fde180e6fb8 [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_sdp_rtp.c:482 set_incoming_call_offer_cap: [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_sdp_rtp.c:1535 negotiate_incoming_sdp_stream: [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session.c:960 handle_incoming_sdp: PJSIP/s705-00000004: Handled? yes [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session.c:5067 create_local_sdp: PJSIP/s705-00000004 [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session.c:5104 create_local_sdp: PJSIP/s705-00000004: Processing streams [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session.c:495 ast_sip_session_media_state_add: PJSIP/s705-00000004 Adding position 0 [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session.c:503 ast_sip_session_media_state_add: Using existing media_session [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session.c:4943 add_sdp_streams: PJSIP/s705-00000004 Stream: 0:audio-0:audio:sendrecv (gsm|g722) [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_sdp_rtp.c:1690 create_outgoing_sdp_stream: PJSIP/s705-00000004 Type: audio 0:audio-0:audio:sendrecv (gsm|g722) [Mar 1 13:11:49] DEBUG[3242084]: res_rtp_asterisk.c:8178 ast_rtp_prop_set: (0x7fde180e6de0) RTCP ignoring duplicate property [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_sdp_rtp.c:1975 create_outgoing_sdp_stream: RC: 1 [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session.c:4952 add_sdp_streams: Had handler [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session.c:5161 create_local_sdp: PJSIP/s705-00000004: Adding bundle groups (if available) [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session.c:5167 create_local_sdp: PJSIP/s705-00000004: Copying connection details [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session.c:5211 create_local_sdp: PJSIP/s705-00000004 [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session.c:5232 session_inv_on_rx_offer: PJSIP/s705-00000004: Set SDP answer [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session.c:5306 session_inv_on_media_update: PJSIP/s705-00000004 [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session.c:1068 handle_negotiated_sdp: PJSIP/s705-00000004 [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session.c:974 handle_negotiated_sdp_session_media: PJSIP/s705-00000004 [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_sdp_rtp.c:2033 apply_negotiated_sdp_stream: PJSIP/s705-00000004 Stream: 0:audio-0:audio:sendrecv (gsm|g722) [Mar 1 13:11:49] DEBUG[3242084]: res_rtp_asterisk.c:8178 ast_rtp_prop_set: (0x7fde180e6de0) RTCP ignoring duplicate property [Mar 1 13:11:49] DEBUG[3242084]: acl.c:1045 ast_ouraddrfor: For destination '172.16.20.130', our source address is '172.16.1.100'. [Mar 1 13:11:49] DEBUG[3242084]: res_rtp_asterisk.c:8381 ast_rtp_remote_address_set: (0x7fde180e6de0) RTCP setting address on RTP instance [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_sdp_rtp.c:500 set_caps: PJSIP/s705-00000004 ANSWER [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_sdp_rtp.c:328 get_codecs: PJSIP/s705-00000004 [Mar 1 13:11:49] DEBUG[3242084]: rtp_engine.c:1318 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 0 based on m type on 0x7fde496b3ed0 [Mar 1 13:11:49] DEBUG[3242084]: rtp_engine.c:1318 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 8 based on m type on 0x7fde496b3ed0 [Mar 1 13:11:49] DEBUG[3242084]: rtp_engine.c:1318 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 9 based on m type on 0x7fde496b3ed0 [Mar 1 13:11:49] DEBUG[3242084]: rtp_engine.c:1318 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 3 based on m type on 0x7fde496b3ed0 [Mar 1 13:11:49] DEBUG[3242084]: rtp_engine.c:1313 ast_rtp_codecs_payloads_set_m_type: Don't have a default tx payload type 2 format for m type on 0x7fde496b3ed0 [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_sdp_rtp.c:404 get_codecs: [Mar 1 13:11:49] DEBUG[3242084]: rtp_engine.c:1204 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 0 (0x7fde180a0298) from 0x7fde496b3ed0 to 0x7fde180e6fb8 [Mar 1 13:11:49] DEBUG[3242084]: rtp_engine.c:1204 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 2 (0x7fde180159c8) from 0x7fde496b3ed0 to 0x7fde180e6fb8 [Mar 1 13:11:49] DEBUG[3242084]: rtp_engine.c:1204 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 3 (0x7fde18092ef8) from 0x7fde496b3ed0 to 0x7fde180e6fb8 [Mar 1 13:11:49] DEBUG[3242084]: rtp_engine.c:1204 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 8 (0x7fde180a41b8) from 0x7fde496b3ed0 to 0x7fde180e6fb8 [Mar 1 13:11:49] DEBUG[3242084]: rtp_engine.c:1204 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 9 (0x7fde180af098) from 0x7fde496b3ed0 to 0x7fde180e6fb8 [Mar 1 13:11:49] DEBUG[3242084]: rtp_engine.c:1204 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 97 (0x7fde1801a258) from 0x7fde496b3ed0 to 0x7fde180e6fb8 [Mar 1 13:11:49] DEBUG[3242084]: channel_internal_api.c:680 ast_channel_nativeformats_set: PJSIP/s705-00000004: MultistreamFormats: (g722) [Mar 1 13:11:49] DEBUG[3242084]: channel_internal_api.c:702 ast_channel_nativeformats_set: Set native formats but not topology [Mar 1 13:11:49] DEBUG[3242084]: channel.c:5730 set_format: Channel PJSIP/s705-00000004 setting read format path: g722 -> g722 [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_sdp_rtp.c:611 set_caps: [Mar 1 13:11:49] DEBUG[3242084]: res_rtp_asterisk.c:8877 ast_rtp_activate: (0x7fde180e6de0) DTLS - ast_rtp_activate rtp=0x7fde1809be10 - setup and perform DTLS' [Mar 1 13:11:49] DEBUG[3242084]: res_rtp_asterisk.c:2503 dtls_perform_handshake: (0x7fde1809be10) DTLS perform handshake - ssl = (nil), setup = 0 [Mar 1 13:11:49] DEBUG[3242084]: res_rtp_asterisk.c:2503 dtls_perform_handshake: (0x7fde1809be10) DTLS perform handshake - ssl = (nil), setup = 0 [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_sdp_rtp.c:2180 apply_negotiated_sdp_stream: Handled [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session.c:1013 handle_negotiated_sdp_session_media: PJSIP/s705-00000004: Applied negotiated SDP media stream 'audio' using audio SDP handler [Mar 1 13:11:49] DEBUG[3242084]: channel_internal_api.c:1595 ast_channel_set_stream_topology: PJSIP/s705-00000004: <0:audio-0:audio:sendrecv (g722|gsm)> [Mar 1 13:11:49] DEBUG[3242084]: channel_internal_api.c:1616 ast_channel_set_stream_topology: Used provided topology [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session.c:1223 handle_negotiated_sdp: [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session.c:5370 session_inv_on_media_update: PJSIP/s705-00000004 [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip/pjsip_resolver.c:479 sip_resolve: Performing SIP DNS resolution of target '172.16.20.130' [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip/pjsip_resolver.c:506 sip_resolve: Transport type for target '172.16.20.130' is 'UDP transport' [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip/pjsip_resolver.c:527 sip_resolve: Target '172.16.20.130' is an IP address, skipping resolution [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip/pjsip_message_filter.c:174 print_sanitize_debug: Sanitizing From/To header: sip:s705@172.16.20.130 [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip/pjsip_message_filter.c:174 print_sanitize_debug: Sanitizing From/To header: sip:anonymous@anonymous.invalid [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip/pjsip_message_filter.c:174 print_sanitize_debug: Sanitizing Contact header: sip:asterisk@172.16.1.100:5060 <--- Transmitting SIP response (844 bytes) to UDP:172.16.20.130:5160 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 172.16.20.130:5160;received=172.16.20.130;branch=z9hG4bK3081793179 Call-ID: 470166d5-6f9a-4c04-a4ea-4fc153fc48cd From: ;tag=f9f13d9485b8604 To: "Anonymous" ;tag=a37afe7d-b79b-44e0-b8cc-7b784abf1287 CSeq: 2180 INVITE Session-Expires: 180;refresher=uas Contact: Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER Supported: 100rel, timer, replaces, norefersub Server: Asterisk PBX GIT-18-6673c1b177 Content-Type: application/sdp Content-Length: 202 v=0 o=- 802505438 802505440 IN IP4 172.16.1.100 s=Asterisk c=IN IP4 172.16.1.100 t=0 0 m=audio 16310 RTP/AVP 3 9 a=rtpmap:3 GSM/8000 a=rtpmap:9 G722/8000 a=ptime:20 a=maxptime:150 a=sendrecv [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session.c:4715 session_inv_on_tsx_state_changed: PJSIP/s705-00000004 TSX State: Completed Inv State: CONFIRMED [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session.c:4903 session_inv_on_tsx_state_changed: Nothing delayed [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session.c:4169 session_on_tsx_state: PJSIP/s705-00000004 TSX State: Completed Inv State: CONFIRMED [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session.c:4173 session_on_tsx_state: Topology: Pending: (null topology) Active: <0:audio-0:audio:sendrecv (g722|gsm)> [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session.c:4178 session_on_tsx_state: [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session.c:4715 session_inv_on_tsx_state_changed: PJSIP/s705-00000004 TSX State: Completed Inv State: CONFIRMED [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session.c:4380 handle_incoming_request: PJSIP/s705-00000004: Method is INVITE [Mar 1 13:11:49] DEBUG[3242084]: chan_pjsip.c:3012 chan_pjsip_incoming_request: PJSIP/s705-00000004 [Mar 1 13:11:49] DEBUG[3242084]: chan_pjsip.c:3015 chan_pjsip_incoming_request: PJSIP/s705-00000004: No channel [Mar 1 13:11:49] DEBUG[3242084]: chan_pjsip.c:3118 pbx_start_incoming_request: PJSIP/s705-00000004 [Mar 1 13:11:49] DEBUG[3242084]: chan_pjsip.c:3123 pbx_start_incoming_request: Reinvite [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session.c:4390 handle_incoming_request: PJSIP/s705-00000004 [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session.c:4903 session_inv_on_tsx_state_changed: Nothing delayed [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session.c:4169 session_on_tsx_state: PJSIP/s705-00000004 TSX State: Completed Inv State: CONFIRMED [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session.c:4173 session_on_tsx_state: Topology: Pending: (null topology) Active: <0:audio-0:audio:sendrecv (g722|gsm)> [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session.c:4178 session_on_tsx_state: [Mar 1 13:11:49] DEBUG[3243072]: res_rtp_asterisk.c:4914 rtp_raw_write: (0x7fde180e6de0) RTP audio difference is 15832, ms is 1999 [Mar 1 13:11:49] DEBUG[3243072]: res_rtp_asterisk.c:5075 rtp_raw_write: (0x7fde180e6de0) RTCP starting transmission <--- Received SIP request (438 bytes) from UDP:172.16.20.130:5160 ---> ACK sip:asterisk@127.0.0.1:5060 SIP/2.0 Via: SIP/2.0/UDP 172.16.20.130:5160;branch=z9hG4bK894076185 From: ;tag=f9f13d9485b8604 To: "Anonymous" ;tag=a37afe7d-b79b-44e0-b8cc-7b784abf1287 Call-ID: 470166d5-6f9a-4c04-a4ea-4fc153fc48cd CSeq: 2180 ACK Contact: Max-Forwards: 70 User-Agent: Sangoma S705 V3.0.4.75 Content-Length: 0 [Mar 1 13:11:49] DEBUG[3242083]: res_pjsip/pjsip_distributor.c:502 distributor: Searching for serializer associated with dialog dlg0x7fde180a4638 for Request msg ACK/cseq=2180 (rdata0x7fdd400023d8) [Mar 1 13:11:49] DEBUG[3242083]: res_pjsip/pjsip_distributor.c:510 distributor: Found serializer pjsip/outsess/s705-0000007b associated with dialog dlg0x7fde180a4638 [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session.c:4715 session_inv_on_tsx_state_changed: PJSIP/s705-00000004 TSX State: Terminated Inv State: CONFIRMED [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session.c:4903 session_inv_on_tsx_state_changed: Nothing delayed [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session.c:4169 session_on_tsx_state: PJSIP/s705-00000004 TSX State: Terminated Inv State: CONFIRMED [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session.c:4173 session_on_tsx_state: Topology: Pending: (null topology) Active: <0:audio-0:audio:sendrecv (g722|gsm)> [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session.c:4178 session_on_tsx_state: [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session.c:4224 session_on_rx_request: PJSIP/s705-00000004 Request: ACK [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip_session.c:4243 session_on_rx_request: PJSIP/s705-00000004 Handled request ACK ? yes [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip/pjsip_options.c:927 sip_options_qualify_aor: Qualifying all contacts on AOR 'mytrunk_aor' [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip/pjsip_options.c:856 sip_options_qualify_contact: Qualifying contact 'mytrunk_aor@@4f92004b06dedb30d19bf97c96fd68a5' on AOR 'mytrunk_aor' [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip.c:4656 endpt_send_request: 0x7fde1808c8f0: Wrapper created [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip.c:4671 endpt_send_request: 0x7fde1808c8f0: Set timer to 3000 msec [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip/pjsip_resolver.c:479 sip_resolve: Performing SIP DNS resolution of target '172.16.1.95' [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip/pjsip_resolver.c:506 sip_resolve: Transport type for target '172.16.1.95' is 'UDP transport' [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip/pjsip_resolver.c:527 sip_resolve: Target '172.16.1.95' is an IP address, skipping resolution [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip/pjsip_message_filter.c:174 print_sanitize_debug: Sanitizing Request: sip:172.16.1.95 [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip/pjsip_message_filter.c:174 print_sanitize_debug: Sanitizing From/To header: sip:muon@172.16.1.100 [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip/pjsip_message_filter.c:174 print_sanitize_debug: Sanitizing From/To header: sip:172.16.1.95 [Mar 1 13:11:49] DEBUG[3242084]: res_pjsip/pjsip_message_filter.c:174 print_sanitize_debug: Sanitizing Contact header: sip:muon@172.16.1.100:5060 <--- Transmitting SIP request (408 bytes) to UDP:172.16.1.95:5060 ---> OPTIONS sip:172.16.1.95 SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:5060;rport;branch=z9hG4bKPj0eefd5cb-a22a-4693-a5cc-b2a9a1f4d010 From: ;tag=c3272fb1-50b7-425c-9a86-647305f346b5 To: Contact: Call-ID: 68e7b4a1-a96d-4fd2-a3fe-35841bb9013b CSeq: 41055 OPTIONS Max-Forwards: 70 User-Agent: Asterisk PBX GIT-18-6673c1b177 Content-Length: 0 [Mar 1 13:11:50] DEBUG[3242083]: res_pjsip/pjsip_message_filter.c:174 print_sanitize_debug: Sanitizing Request: sip:172.16.1.95 [Mar 1 13:11:50] DEBUG[3242083]: res_pjsip/pjsip_message_filter.c:174 print_sanitize_debug: Sanitizing From/To header: sip:muon@172.16.1.100 [Mar 1 13:11:50] DEBUG[3242083]: res_pjsip/pjsip_message_filter.c:174 print_sanitize_debug: Sanitizing From/To header: sip:172.16.1.95 [Mar 1 13:11:50] DEBUG[3242083]: res_pjsip/pjsip_message_filter.c:174 print_sanitize_debug: Sanitizing Contact header: sip:muon@127.0.0.1:5060 <--- Transmitting SIP request (408 bytes) to UDP:172.16.1.95:5060 ---> OPTIONS sip:172.16.1.95 SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:5060;rport;branch=z9hG4bKPj0eefd5cb-a22a-4693-a5cc-b2a9a1f4d010 From: ;tag=c3272fb1-50b7-425c-9a86-647305f346b5 To: Contact: Call-ID: 68e7b4a1-a96d-4fd2-a3fe-35841bb9013b CSeq: 41055 OPTIONS Max-Forwards: 70 User-Agent: Asterisk PBX GIT-18-6673c1b177 Content-Length: 0 <--- Received SIP request (439 bytes) from UDP:172.16.20.130:5160 ---> BYE sip:asterisk@127.0.0.1:5060 SIP/2.0 Via: SIP/2.0/UDP 172.16.20.130:5160;branch=z9hG4bK2499167266 From: ;tag=f9f13d9485b8604 To: "Anonymous" ;tag=a37afe7d-b79b-44e0-b8cc-7b784abf1287 Call-ID: 470166d5-6f9a-4c04-a4ea-4fc153fc48cd CSeq: 2181 BYE Contact: Max-Forwards: 70 User-Agent: Sangoma S705 V3.0.4.75 Content-Length: 0 [Mar 1 13:11:51] DEBUG[3242083]: res_pjsip/pjsip_distributor.c:502 distributor: Searching for serializer associated with dialog dlg0x7fde180a4638 for Request msg BYE/cseq=2181 (rdata0x7fdd400023d8) [Mar 1 13:11:51] DEBUG[3242083]: res_pjsip/pjsip_distributor.c:510 distributor: Found serializer pjsip/outsess/s705-0000007b associated with dialog dlg0x7fde180a4638 [Mar 1 13:11:51] DEBUG[3242084]: res_pjsip/pjsip_resolver.c:479 sip_resolve: Performing SIP DNS resolution of target '172.16.20.130' [Mar 1 13:11:51] DEBUG[3242084]: res_pjsip/pjsip_resolver.c:506 sip_resolve: Transport type for target '172.16.20.130' is 'UDP transport' [Mar 1 13:11:51] DEBUG[3242084]: res_pjsip/pjsip_resolver.c:527 sip_resolve: Target '172.16.20.130' is an IP address, skipping resolution [Mar 1 13:11:51] DEBUG[3242084]: res_pjsip/pjsip_message_filter.c:174 print_sanitize_debug: Sanitizing From/To header: sip:s705@172.16.20.130 [Mar 1 13:11:51] DEBUG[3242084]: res_pjsip/pjsip_message_filter.c:174 print_sanitize_debug: Sanitizing From/To header: sip:anonymous@anonymous.invalid <--- Transmitting SIP response (370 bytes) to UDP:172.16.20.130:5160 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 172.16.20.130:5160;received=172.16.20.130;branch=z9hG4bK2499167266 Call-ID: 470166d5-6f9a-4c04-a4ea-4fc153fc48cd From: ;tag=f9f13d9485b8604 To: "Anonymous" ;tag=a37afe7d-b79b-44e0-b8cc-7b784abf1287 CSeq: 2181 BYE Server: Asterisk PBX GIT-18-6673c1b177 Content-Length: 0 [Mar 1 13:11:51] DEBUG[3242084]: res_pjsip_session.c:4715 session_inv_on_tsx_state_changed: PJSIP/s705-00000004 TSX State: Completed Inv State: CONFIRMED [Mar 1 13:11:51] DEBUG[3242084]: res_pjsip_session.c:4903 session_inv_on_tsx_state_changed: Nothing delayed [Mar 1 13:11:51] DEBUG[3242084]: res_pjsip_session.c:4169 session_on_tsx_state: PJSIP/s705-00000004 TSX State: Completed Inv State: CONFIRMED [Mar 1 13:11:51] DEBUG[3242084]: res_pjsip_session.c:4173 session_on_tsx_state: Topology: Pending: (null topology) Active: <0:audio-0:audio:sendrecv (g722|gsm)> [Mar 1 13:11:51] DEBUG[3242084]: res_pjsip_session.c:4178 session_on_tsx_state: [Mar 1 13:11:51] DEBUG[3242084]: res_pjsip_session.c:4597 session_inv_on_state_changed: PJSIP/s705-00000004 Event: TSX_STATE Inv State: DISCONNCTD [Mar 1 13:11:51] DEBUG[3242084]: res_pjsip_session.c:4623 session_inv_on_state_changed: PJSIP/s705-00000004: Source of transaction state change is RX_MSG [Mar 1 13:11:51] DEBUG[3242084]: res_pjsip_session.c:4565 handle_incoming_before_media: PJSIP/s705-00000004: Received request [Mar 1 13:11:51] DEBUG[3242084]: res_pjsip_session.c:4380 handle_incoming_request: PJSIP/s705-00000004: Method is BYE [Mar 1 13:11:51] DEBUG[3242084]: res_pjsip_session.c:4390 handle_incoming_request: PJSIP/s705-00000004 [Mar 1 13:11:51] DEBUG[3242084]: res_pjsip_session.c:4671 session_inv_on_state_changed: [Mar 1 13:11:51] DEBUG[3242084]: res_pjsip_session.c:4715 session_inv_on_tsx_state_changed: PJSIP/s705-00000004 TSX State: Completed Inv State: DISCONNCTD [Mar 1 13:11:51] DEBUG[3242084]: res_pjsip_session.c:4903 session_inv_on_tsx_state_changed: Nothing delayed [Mar 1 13:11:51] DEBUG[3242084]: res_pjsip_session.c:4169 session_on_tsx_state: PJSIP/s705-00000004 TSX State: Completed Inv State: DISCONNCTD [Mar 1 13:11:51] DEBUG[3242084]: res_pjsip_session.c:4173 session_on_tsx_state: Topology: Pending: (null topology) Active: <0:audio-0:audio:sendrecv (g722|gsm)> [Mar 1 13:11:51] DEBUG[3242084]: res_pjsip_session.c:4178 session_on_tsx_state: [Mar 1 13:11:51] DEBUG[3242084]: chan_pjsip.c:2974 chan_pjsip_session_end: PJSIP/s705-00000004 [Mar 1 13:11:51] DEBUG[3242084]: chan_pjsip.c:2991 chan_pjsip_session_end: [Mar 1 13:11:51] DEBUG[3243072]: channel.c:3201 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Mar 1 13:11:51] DEBUG[3243072]: channel.c:3201 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Mar 1 13:11:51] DEBUG[3243072]: channel.c:5730 set_format: Channel PJSIP/s705-00000004 setting write format path: g722 -> g722 [Mar 1 13:11:51] DEBUG[3243072]: channel.c:2541 ast_hangup: Channel 0x5582f8ab5c40 'PJSIP/s705-00000004' hanging up. Refs: 2 [Mar 1 13:11:51] DEBUG[3243072]: chan_pjsip.c:2521 chan_pjsip_hangup: PJSIP/s705-00000004 [Mar 1 13:11:51] DEBUG[3243072]: chan_pjsip.c:2441 hangup_cause2sip: AST hangup cause 16 (no match found in PJSIP) [Mar 1 13:11:51] DEBUG[3243072]: chan_pjsip.c:2539 chan_pjsip_hangup: Cause: 0 [Mar 1 13:11:51] DEBUG[3242084]: chan_pjsip.c:2488 hangup: PJSIP/s705-00000004 [Mar 1 13:11:51] DEBUG[3242084]: res_pjsip_session.c:3455 ast_sip_session_terminate: PJSIP/s705-00000004 Response 0 [Mar 1 13:11:51] DEBUG[3242084]: res_rtp_asterisk.c:2828 dtls_srtp_stop_timeout_timer: (0x7fde180e6de0) DTLS srtp - stopped timeout timer' [Mar 1 13:11:51] DEBUG[3242084]: res_rtp_asterisk.c:2828 dtls_srtp_stop_timeout_timer: (0x7fde180e6de0) DTLS srtp - stopped timeout timer' [Mar 1 13:11:51] DEBUG[3242084]: res_rtp_asterisk.c:2230 ast_rtp_dtls_stop: (0x7fde180e6de0) DTLS stop [Mar 1 13:11:51] DEBUG[3242084]: res_rtp_asterisk.c:2828 dtls_srtp_stop_timeout_timer: (0x7fde180e6de0) DTLS srtp - stopped timeout timer' [Mar 1 13:11:51] DEBUG[3242084]: res_rtp_asterisk.c:2828 dtls_srtp_stop_timeout_timer: (0x7fde180e6de0) DTLS srtp - stopped timeout timer' [Mar 1 13:11:51] DEBUG[3242084]: res_rtp_asterisk.c:3945 rtp_deallocate_transport: (0x7fde180e6de0) ICE RTP transport deallocating [Mar 1 13:11:51] DEBUG[3242084]: rtp_engine.c:455 instance_destructor: Destroyed RTP instance '0x7fde180e6de0' [Mar 1 13:11:51] DEBUG[3242084]: res_pjsip_session.c:3527 ast_sip_session_terminate: [Mar 1 13:11:51] DEBUG[3242084]: channel.c:2188 ast_channel_destructor: Channel 0x5582f8ab5c40 'PJSIP/s705-00000004' destroying [Mar 1 13:11:51] DEBUG[3242074]: cdr.c:1460 cdr_object_finalize: Finalized CDR for PJSIP/s705-00000004 - start 1614618704.315059 answer 1614618706.139821 end 1614618711.276289 dur 6.961 bill 5.136 dispo ANSWERED [Mar 1 13:11:51] DEBUG[3242074]: stasis.c:578 stasis_topic_create_with_detail: Creating topic. name: channel:1614618711.30, detail: [Mar 1 13:11:51] DEBUG[3242074]: stasis.c:612 stasis_topic_create_with_detail: Topic 'channel:1614618711.30': 0x7fde340085c0 created [Mar 1 13:11:51] DEBUG[3242084]: stasis.c:440 topic_dtor: Destroying topic. name: channel:1614618704.27, detail: [Mar 1 13:11:51] DEBUG[3242084]: stasis.c:449 topic_dtor: Topic 'channel:1614618704.27': 0x5582f8c22bb0 destroyed [Mar 1 13:11:51] DEBUG[3242075]: stasis.c:578 stasis_topic_create_with_detail: Creating topic. name: channel:1614618711.31, detail: [Mar 1 13:11:51] DEBUG[3242084]: channel_internal_api.c:680 ast_channel_nativeformats_set: : MultistreamFormats: (nothing) [Mar 1 13:11:51] DEBUG[3242084]: channel_internal_api.c:692 ast_channel_nativeformats_set: Channel is being initialized or destroyed [Mar 1 13:11:51] DEBUG[3242075]: stasis.c:612 stasis_topic_create_with_detail: Topic 'channel:1614618711.31': 0x7fde38007a90 created [Mar 1 13:11:51] DEBUG[3242084]: chan_pjsip.c:2512 hangup: [Mar 1 13:11:51] DEBUG[3242074]: pbx_variables.c:759 pbx_substitute_variables_helper_full: Function CDR(start) result is '2021-03-01 13:11:44' [Mar 1 13:11:51] DEBUG[3242066]: devicestate.c:466 do_state_change: Changing state for PJSIP/s705 - state 1 (Not in use) [Mar 1 13:11:51] DEBUG[3242074]: pbx_variables.c:759 pbx_substitute_variables_helper_full: Function CDR(clid) result is '"" <>' [Mar 1 13:11:51] DEBUG[3242074]: pbx_variables.c:759 pbx_substitute_variables_helper_full: Function CDR(dcontext) result is 'users' [Mar 1 13:11:51] DEBUG[3242074]: pbx_variables.c:759 pbx_substitute_variables_helper_full: Function CDR(channel) result is 'PJSIP/s705-00000004' [Mar 1 13:11:51] DEBUG[3242074]: pbx_variables.c:759 pbx_substitute_variables_helper_full: Function CDR(dstchannel) result is '' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE(HANGUP) result is '"HANGUP"' [Mar 1 13:11:51] DEBUG[3242074]: pbx_variables.c:759 pbx_substitute_variables_helper_full: Function CDR(lastapp) result is 'Playback' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE(1614618711.276289) result is '"1614618711.276289"' [Mar 1 13:11:51] DEBUG[3242074]: pbx_variables.c:759 pbx_substitute_variables_helper_full: Function CDR(lastdata) result is 'demo-congrats' [Mar 1 13:11:51] ERROR[3242075]: pbx_functions.c:651 ast_func_read2: Function CALLERID not registered [Mar 1 13:11:51] DEBUG[3242134]: app_queue.c:2583 device_state_cb: Device 'PJSIP/s705' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CALLERID(name) result is '' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Mar 1 13:11:51] DEBUG[3242074]: pbx_variables.c:759 pbx_substitute_variables_helper_full: Function CDR(duration) result is '6' [Mar 1 13:11:51] ERROR[3242075]: pbx_functions.c:651 ast_func_read2: Function CALLERID not registered [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CALLERID(num) result is '' [Mar 1 13:11:51] DEBUG[3242074]: pbx_variables.c:759 pbx_substitute_variables_helper_full: Function CDR(billsec) result is '5' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Mar 1 13:11:51] ERROR[3242075]: pbx_functions.c:651 ast_func_read2: Function CALLERID not registered [Mar 1 13:11:51] DEBUG[3242074]: pbx_variables.c:759 pbx_substitute_variables_helper_full: Function CDR(disposition) result is 'ANSWERED' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CALLERID(ANI) result is '' [Mar 1 13:11:51] DEBUG[3242074]: pbx_variables.c:759 pbx_substitute_variables_helper_full: Function CDR(amaflags) result is 'DOCUMENTATION' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Mar 1 13:11:51] ERROR[3242075]: pbx_functions.c:651 ast_func_read2: Function CALLERID not registered [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CALLERID(RDNIS) result is '' [Mar 1 13:11:51] DEBUG[3242074]: pbx_variables.c:759 pbx_substitute_variables_helper_full: Function CDR(accountcode) result is '' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Mar 1 13:11:51] DEBUG[3242074]: pbx_variables.c:759 pbx_substitute_variables_helper_full: Function CDR(uniqueid) result is '1614618704.27' [Mar 1 13:11:51] ERROR[3242075]: pbx_functions.c:651 ast_func_read2: Function CALLERID not registered [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CALLERID(DNID) result is '' [Mar 1 13:11:51] DEBUG[3242074]: pbx_variables.c:759 pbx_substitute_variables_helper_full: Function CDR(userfield) result is '' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Mar 1 13:11:51] DEBUG[3242074]: pbx_variables.c:759 pbx_substitute_variables_helper_full: Function CDR(test) result is '' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CHANNEL(exten) result is 's' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE(s) result is '"s"' [Mar 1 13:11:51] DEBUG[3242074]: cdr_sqlite3_custom.c:269 write_cdr: About to log: INSERT INTO cdr (calldate,clid,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield,test) VALUES ('2021-03-01 13:11:44','"" <>','users','PJSIP/s705-00000004','','Playback','demo-congrats','6','5','ANSWERED','DOCUMENTATION','','1614618704.27','','') [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CHANNEL(context) result is 'users' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE(users) result is '"users"' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CHANNEL(channame) result is 'PJSIP/s705-00000004' [Mar 1 13:11:51] DEBUG[3242074]: stasis.c:440 topic_dtor: Destroying topic. name: channel:1614618711.30, detail: [Mar 1 13:11:51] DEBUG[3242074]: stasis.c:449 topic_dtor: Topic 'channel:1614618711.30': 0x7fde340085c0 destroyed [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE(PJSIP/s705-00000004) result is '"PJSIP/s705-00000004"' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CHANNEL(appname) result is 'AppDial2' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE(AppDial2) result is '"AppDial2"' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CHANNEL(appdata) result is '(Outgoing Line)' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE((Outgoing Line)) result is '"(Outgoing Line)"' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CHANNEL(amaflags) result is '3' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE(3) result is '"3"' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CHANNEL(accountcode) result is '' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CHANNEL(uniqueid) result is '1614618704.27' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE(1614618704.27) result is '"1614618704.27"' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CHANNEL(linkedid) result is '1614618704.27' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE(1614618704.27) result is '"1614618704.27"' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CHANNEL(peer) result is '' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CHANNEL(userfield) result is '' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE({"hangupcause":16,"hangupsource":"PJSIP/s705-00000004","dialstatus":""}) result is '"{""hangupcause"":16,""hangupsource"":""PJSIP/s705-00000004"",""dialstatus"":""""}"' [Mar 1 13:11:51] DEBUG[3242075]: stasis.c:440 topic_dtor: Destroying topic. name: channel:1614618711.31, detail: [Mar 1 13:11:51] DEBUG[3242075]: stasis.c:449 topic_dtor: Topic 'channel:1614618711.31': 0x7fde38007a90 destroyed [Mar 1 13:11:51] DEBUG[3242075]: stasis.c:578 stasis_topic_create_with_detail: Creating topic. name: channel:1614618711.32, detail: [Mar 1 13:11:51] DEBUG[3242075]: stasis.c:612 stasis_topic_create_with_detail: Topic 'channel:1614618711.32': 0x7fde38007a90 created [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE(CHAN_END) result is '"CHAN_END"' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE(1614618711.276289) result is '"1614618711.276289"' [Mar 1 13:11:51] ERROR[3242075]: pbx_functions.c:651 ast_func_read2: Function CALLERID not registered [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CALLERID(name) result is '' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Mar 1 13:11:51] ERROR[3242075]: pbx_functions.c:651 ast_func_read2: Function CALLERID not registered [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CALLERID(num) result is '' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Mar 1 13:11:51] ERROR[3242075]: pbx_functions.c:651 ast_func_read2: Function CALLERID not registered [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CALLERID(ANI) result is '' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Mar 1 13:11:51] ERROR[3242075]: pbx_functions.c:651 ast_func_read2: Function CALLERID not registered [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CALLERID(RDNIS) result is '' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Mar 1 13:11:51] ERROR[3242075]: pbx_functions.c:651 ast_func_read2: Function CALLERID not registered [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CALLERID(DNID) result is '' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CHANNEL(exten) result is 's' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE(s) result is '"s"' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CHANNEL(context) result is 'users' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE(users) result is '"users"' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CHANNEL(channame) result is 'PJSIP/s705-00000004' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE(PJSIP/s705-00000004) result is '"PJSIP/s705-00000004"' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CHANNEL(appname) result is 'AppDial2' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE(AppDial2) result is '"AppDial2"' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CHANNEL(appdata) result is '(Outgoing Line)' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE((Outgoing Line)) result is '"(Outgoing Line)"' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CHANNEL(amaflags) result is '3' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE(3) result is '"3"' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CHANNEL(accountcode) result is '' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CHANNEL(uniqueid) result is '1614618704.27' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE(1614618704.27) result is '"1614618704.27"' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CHANNEL(linkedid) result is '1614618704.27' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE(1614618704.27) result is '"1614618704.27"' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CHANNEL(peer) result is '' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CHANNEL(userfield) result is '' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Mar 1 13:11:51] DEBUG[3242075]: pbx_variables.c:539 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Mar 1 13:11:51] DEBUG[3242075]: stasis.c:440 topic_dtor: Destroying topic. name: channel:1614618711.32, detail: [Mar 1 13:11:51] DEBUG[3242075]: stasis.c:449 topic_dtor: Topic 'channel:1614618711.32': 0x7fde38007a90 destroyed [Mar 1 13:11:51] DEBUG[3242074]: stasis.c:578 stasis_topic_create_with_detail: Creating topic. name: channel:1614618711.33, detail: [Mar 1 13:11:51] DEBUG[3242074]: stasis.c:612 stasis_topic_create_with_detail: Topic 'channel:1614618711.33': 0x7fde34009a80 created [Mar 1 13:11:51] DEBUG[3242074]: stasis.c:440 topic_dtor: Destroying topic. name: channel:1614618711.33, detail: [Mar 1 13:11:51] DEBUG[3242074]: stasis.c:449 topic_dtor: Topic 'channel:1614618711.33': 0x7fde34009a80 destroyed [Mar 1 13:11:51] DEBUG[3242083]: res_pjsip/pjsip_message_filter.c:174 print_sanitize_debug: Sanitizing Request: sip:172.16.1.95 [Mar 1 13:11:51] DEBUG[3242083]: res_pjsip/pjsip_message_filter.c:174 print_sanitize_debug: Sanitizing From/To header: sip:muon@172.16.1.100 [Mar 1 13:11:51] DEBUG[3242083]: res_pjsip/pjsip_message_filter.c:174 print_sanitize_debug: Sanitizing From/To header: sip:172.16.1.95 [Mar 1 13:11:51] DEBUG[3242083]: res_pjsip/pjsip_message_filter.c:174 print_sanitize_debug: Sanitizing Contact header: sip:muon@127.0.0.1:5060 <--- Transmitting SIP request (408 bytes) to UDP:172.16.1.95:5060 ---> OPTIONS sip:172.16.1.95 SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:5060;rport;branch=z9hG4bKPj0eefd5cb-a22a-4693-a5cc-b2a9a1f4d010 From: ;tag=c3272fb1-50b7-425c-9a86-647305f346b5 To: Contact: Call-ID: 68e7b4a1-a96d-4fd2-a3fe-35841bb9013b CSeq: 41055 OPTIONS Max-Forwards: 70 User-Agent: Asterisk PBX GIT-18-6673c1b177 Content-Length: 0 [Mar 1 13:11:52] DEBUG[3242095]: res_pjsip_registrar.c:1293 check_expiration_thread: Expiring 0 contacts [Mar 1 13:11:52] DEBUG[3242083]: res_pjsip.c:4593 send_request_timer_callback: 0x7fde1808c8f0: Internal tsx timer expired after 3000 msec [Mar 1 13:11:52] DEBUG[3242083]: res_pjsip.c:4609 send_request_timer_callback: 0x7fde1808c8f0: Timer handled here [Mar 1 13:11:52] DEBUG[3242083]: res_pjsip.c:4622 send_request_timer_callback: 0x7fde1808c8f0: Callbacks executed [Mar 1 13:11:52] DEBUG[3242084]: res_pjsip/pjsip_options.c:755 sip_options_contact_status_notify_task: Contact mytrunk_aor/sip:172.16.1.95 status didn't change: Unreachable, RTT: 0.000 msec [Mar 1 13:11:52] DEBUG[3242084]: res_pjsip/pjsip_options.c:775 sip_options_contact_status_notify_task: AOR 'mytrunk_aor' now has 0 available contacts pjs[Mar 1 13:11:53] DEBUG[3242083]: res_pjsip/pjsip_message_filter.c:174 print_sanitize_debug: Sanitizing Request: sip:172.16.1.95 [Mar 1 13:11:53] DEBUG[3242083]: res_pjsip/pjsip_message_filter.c:174 print_sanitize_debug: Sanitizing From/To header: sip:muon@172.16.1.100 [Mar 1 13:11:53] DEBUG[3242083]: res_pjsip/pjsip_message_filter.c:174 print_sanitize_debug: Sanitizing From/To header: sip:172.16.1.95 [Mar 1 13:11:53] DEBUG[3242083]: res_pjsip/pjsip_message_filter.c:174 print_sanitize_debug: Sanitizing Contact header: sip:muon@127.0.0.1:5060 <--- Transmitting SIP request (408 bytes) to UDP:172.16.1.95:5060 ---> OPTIONS sip:172.16.1.95 SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:5060;rport;branch=z9hG4bKPj0eefd5cb-a22a-4693-a5cc-b2a9a1f4d010 From: ;tag=c3272fb1-50b7-425c-9a86-647305f346b5 To: Contact: Call-ID: 68e7b4a1-a96d-4fd2-a3fe-35841bb9013b CSeq: 41055 OPTIONS Max-Forwards: 70 User-Agent: Asterisk PBX GIT-18-6673c1b177 Content-Length: 0 ip s[Mar 1 13:11:53] DEBUG[3242083]: res_pjsip_session.c:4715 session_inv_on_tsx_state_changed: s705 TSX State: Terminated Inv State: DISCONNCTD [Mar 1 13:11:53] DEBUG[3242083]: res_pjsip_session.c:4891 session_inv_on_tsx_state_changed: Disconnected [Mar 1 13:11:53] DEBUG[3242083]: res_pjsip_session.c:4169 session_on_tsx_state: (null session) TSX State: Terminated Inv State: DISCONNCTD [Mar 1 13:11:53] DEBUG[3242083]: res_pjsip_session.c:4178 session_on_tsx_state: [Mar 1 13:11:53] DEBUG[3242084]: res_pjsip_session.c:2911 session_destructor: s705: Destroying SIP session