[Dec 8 17:59:51] Asterisk 16.15.0 built by root @ node1 on a x86_64 running Linux on 2020-12-08 13:59:26 UTC [Dec 8 17:59:51] NOTICE[62961] loader.c: 308 modules will be loaded. [Dec 8 17:59:51] NOTICE[62961] cdr.c: CDR simple logging enabled. [Dec 8 17:59:51] DEBUG[62961] pjproject: pjlib epoll I/O Queue created (0x7f8b8049a130) [Dec 8 17:59:51] DEBUG[62961] pjproject: sip_endpoint.c Module "mod-msg-print" registered [Dec 8 17:59:51] DEBUG[62961] pjproject: sip_endpoint.c Module "mod-tsx-layer" registered [Dec 8 17:59:51] DEBUG[62961] pjproject: sip_endpoint.c Module "mod-stateful-util" registered [Dec 8 17:59:51] DEBUG[62961] pjproject: sip_endpoint.c Module "mod-ua" registered [Dec 8 17:59:51] DEBUG[62991] pjproject: sip_endpoint.c Module "Global header" registered [Dec 8 17:59:51] DEBUG[62961] pjproject: udp0x55e9afea1890 SIP UDP transport started, published address is 10.9.8.151:5061 [Dec 8 17:59:51] DEBUG[62991] pjproject: sip_endpoint.c Module "idle monitor module" registered [Dec 8 17:59:51] DEBUG[62991] pjproject: sip_endpoint.c Module "Request Distributor" registered [Dec 8 17:59:51] DEBUG[62991] pjproject: sip_endpoint.c Module "Endpoint Identifier" registered [Dec 8 17:59:51] DEBUG[62991] pjproject: sip_endpoint.c Module "Request Authenticator" registered [Dec 8 17:59:51] DEBUG[62991] pjproject: sip_endpoint.c Module "Out of dialog supplement hook" registered [Dec 8 17:59:51] DEBUG[62961] pjproject: sip_endpoint.c Module "Options Module" registered [Dec 8 17:59:51] DEBUG[62991] pjproject: sip_endpoint.c Module "Message Filtering Transport" registered [Dec 8 17:59:51] DEBUG[62991] pjproject: sip_endpoint.c Module "Message Filtering TSX" registered [Dec 8 17:59:51] DEBUG[62991] pjproject: sip_endpoint.c Module "Registrar" registered [Dec 8 17:59:51] WARNING[62961] res_phoneprov.c: Unable to find a valid server address or name. [Dec 8 17:59:51] NOTICE[62961] res_smdi.c: No SMDI interfaces are available to listen on, not starting SMDI listener. [Dec 8 17:59:51] DEBUG[63002] pjproject: pjlib epoll I/O Queue created (0x7f8b24000f68) [Dec 8 17:59:51] DEBUG[62991] pjproject: sip_endpoint.c Module "PubSub Module" registered [Dec 8 17:59:51] DEBUG[62961] pjproject: sip_endpoint.c Module "mod-evsub" registered [Dec 8 17:59:51] NOTICE[62961] chan_skinny.c: Configuring skinny from skinny.conf [Dec 8 17:59:51] VERBOSE[62961] chan_sip.c: SIP channel loading... [Dec 8 17:59:51] DEBUG[62961] pjproject: sip_endpoint.c Module "mod-invite" registered [Dec 8 17:59:51] DEBUG[62961] pjproject: sip_endpoint.c Module "mod-100rel" registered [Dec 8 17:59:51] DEBUG[62991] pjproject: sip_endpoint.c Module "Session Module" registered [Dec 8 17:59:51] DEBUG[62991] pjproject: sip_endpoint.c Module "Session Re-Invite Module" registered [Dec 8 17:59:51] DEBUG[62991] pjproject: sip_endpoint.c Module "Outbound INVITE Auth" registered [Dec 8 17:59:51] DEBUG[62991] pjproject: sip_endpoint.c Module "REFER Callback" registered [Dec 8 17:59:51] DEBUG[62991] pjproject: sip_endpoint.c Module "ACL Module" registered [Dec 8 17:59:51] DEBUG[62991] pjproject: sip_endpoint.c Module "Messaging Module" registered [Dec 8 17:59:51] DEBUG[62961] pjproject: sip_endpoint.c Module "mod-refer" registered [Dec 8 17:59:51] DEBUG[62991] pjproject: sip_endpoint.c Module "REFER Progress" registered [Dec 8 17:59:51] DEBUG[62991] pjproject: sip_endpoint.c Module "History Module" registered [Dec 8 17:59:51] DEBUG[62991] pjproject: sip_endpoint.c Module "SIPS Contact" registered [Dec 8 17:59:51] DEBUG[62991] pjproject: sip_endpoint.c Module "Logging Module" registered [Dec 8 17:59:51] DEBUG[62991] pjproject: sip_endpoint.c Module "NAT" registered [Dec 8 17:59:51] DEBUG[62991] pjproject: sip_endpoint.c Module "WebSocket Transport Module" registered [Dec 8 17:59:51] DEBUG[62991] pjproject: sip_endpoint.c Module "WebSocket Transport Module" unregistered [Dec 8 17:59:51] ERROR[62961] ari/config.c: No configured users for ARI [Dec 8 17:59:51] NOTICE[62961] confbridge/conf_config_parser.c: Adding default_menu menu to app_confbridge [Dec 8 17:59:51] NOTICE[62961] cel_custom.c: No mappings found in cel_custom.conf. Not logging CEL to custom CSVs. [Dec 8 17:59:52] WARNING[62961] loader.c: Some non-required modules failed to load. [Dec 8 17:59:52] ERROR[62961] loader.c: res_pjsip_transport_websocket declined to load. [Dec 8 17:59:52] ERROR[62961] loader.c: cel_sqlite3_custom declined to load. [Dec 8 17:59:52] ERROR[62961] loader.c: cdr_sqlite3_custom declined to load. [Dec 8 17:59:52] VERBOSE[62961] asterisk.c: Asterisk Ready. [Dec 8 17:59:56] VERBOSE[63044] manager.c: Manager 'test' logged on from 10.9.9.100 [Dec 8 18:00:03] VERBOSE[62990] res_pjsip_logger.c: <--- Received SIP request (886 bytes) from UDP:10.9.9.132:5063 ---> INVITE sip:8000@10.9.9.151:5061 SIP/2.0 Via: SIP/2.0/UDP 10.9.9.132:5063;branch=z9hG4bK-1bac0c4a From: "8002" ;tag=f1b573d0566e145ao3 To: Call-ID: fc714988-3bb17a02@10.9.9.132 CSeq: 101 INVITE Max-Forwards: 70 Contact: "8002" Expires: 240 User-Agent: Linksys/SPA942-6.1.5(a) Content-Length: 393 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: replaces Content-Type: application/sdp v=0 o=- 7095147 7095147 IN IP4 10.9.9.132 s=- c=IN IP4 10.9.9.132 t=0 0 m=audio 16458 RTP/AVP 0 2 4 8 18 96 97 98 101 a=rtpmap:0 PCMU/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:4 G723/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729a/8000 a=rtpmap:96 G726-40/8000 a=rtpmap:97 G726-24/8000 a=rtpmap:98 G726-16/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 a=sendrecv [Dec 8 18:00:03] DEBUG[62990] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg INVITE/cseq=101 (rdata0x55e9aff058c8) [Dec 8 18:00:03] DEBUG[62990] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000002e to use for Request msg INVITE/cseq=101 (rdata0x55e9aff058c8) [Dec 8 18:00:03] DEBUG[62991] res_pjsip_endpoint_identifier_ip.c: Source address 10.9.9.132:5063 matches identify '8002' [Dec 8 18:00:03] DEBUG[62991] res_pjsip_endpoint_identifier_ip.c: Identify '8002' SIP message matched to endpoint 8002 [Dec 8 18:00:03] DEBUG[62991] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000002e to use for Request msg INVITE/cseq=101 (rdata0x7f8b500035f8) [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: 8002 [Dec 8 18:00:03] VERBOSE[62991] pbx_variables.c: Setting global variable 'SIPDOMAIN' to '10.9.9.151' [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: 8002: Call (UDP:10.9.9.132:5063) to extension '8000' sending 100 Trying [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: 8002: Method is INVITE, Response is 100 Trying [Dec 8 18:00:03] DEBUG[63044] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: none Uniqueid: none Variable: SIPDOMAIN Value: 10.9.9.151 [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: 8002 [Dec 8 18:00:03] VERBOSE[62991] res_pjsip_logger.c: <--- Transmitting SIP response (304 bytes) to UDP:10.9.9.132:5063 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.9.9.132:5063;rport=5063;received=10.9.9.132;branch=z9hG4bK-1bac0c4a Call-ID: fc714988-3bb17a02@10.9.9.132 From: "8002" ;tag=f1b573d0566e145ao3 To: CSeq: 101 INVITE Server: Asterisk PBX 16.15.0 Content-Length: 0 [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: 8002: Source of transaction state change is TX_MSG [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: 8002: Media count: 1 [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: 8002: Processing stream 0 [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: 8002: Using audio-0 for new stream name [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: 8002: Using new stream 0:audio-0:audio:sendrecv (nothing) [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: 8002 Adding position 0 [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: Creating new media session [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: Setting media session as default for audio [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: Done [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: 8002: Negotiating incoming SDP media stream 0:audio-0:audio:sendrecv (nothing) using audio SDP handler [Dec 8 18:00:03] DEBUG[62991] res_pjsip_sdp_rtp.c: Transport udp bound to 0.0.0.0: Using it for RTP media. [Dec 8 18:00:03] DEBUG[62991] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f8b08032090' [Dec 8 18:00:03] DEBUG[62991] res_rtp_asterisk.c: (0x7f8b08032090) RTP allocated port 15356 [Dec 8 18:00:03] DEBUG[62991] res_rtp_asterisk.c: (0x7f8b08032090) ICE creating session 0.0.0.0:15356 (15356) [Dec 8 18:00:03] DEBUG[62991] res_rtp_asterisk.c: (0x7f8b08032090) ICE create [Dec 8 18:00:03] DEBUG[62991] pjproject: icess0x7f8b800150c8 .ICE session created, comp_cnt=2, role is Unknown agent [Dec 8 18:00:03] DEBUG[62991] res_rtp_asterisk.c: (0x7f8b08032090) ICE add system candidates [Dec 8 18:00:03] DEBUG[62991] pjproject: icess0x7f8b800150c8 .Candidate 0 added: comp_id=1, type=host, foundation=Ha090997, addr=10.9.9.151:15356, base=10.9.9.151:15356, prio=0x7effffff (2130706431) [Dec 8 18:00:03] DEBUG[62991] res_rtp_asterisk.c: (0x7f8b08032090) ICE add candidate: 10.9.9.151:15356, 2130706431 [Dec 8 18:00:03] DEBUG[62991] pjproject: icess0x7f8b800150c8 .Candidate 1 added: comp_id=1, type=host, foundation=Ha090897, addr=10.9.8.151:15356, base=10.9.8.151:15356, prio=0x7effffff (2130706431) [Dec 8 18:00:03] DEBUG[62991] res_rtp_asterisk.c: (0x7f8b08032090) ICE add candidate: 10.9.8.151:15356, 2130706431 [Dec 8 18:00:03] DEBUG[62991] rtp_engine.c: RTP instance '0x7f8b08032090' is setup and ready to go [Dec 8 18:00:03] DEBUG[62991] pjproject: icess0x7f8b800150c8 .Destroying ICE session 0x7f8b800150c8 [Dec 8 18:00:03] DEBUG[62991] pjproject: ice_session.c .ICE session 0x7f8b800150c8 destroyed [Dec 8 18:00:03] DEBUG[62991] res_rtp_asterisk.c: (0x7f8b08032090) ICE stopped [Dec 8 18:00:03] DEBUG[62991] res_rtp_asterisk.c: (0x7f8b08032090) RTCP setup on RTP instance [Dec 8 18:00:03] DEBUG[62991] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7f8b8026c120 [Dec 8 18:00:03] DEBUG[62991] rtp_engine.c: Don't have a default tx payload type 2 format for m type on 0x7f8b8026c120 [Dec 8 18:00:03] DEBUG[62991] rtp_engine.c: Setting tx payload type 4 based on m type on 0x7f8b8026c120 [Dec 8 18:00:03] DEBUG[62991] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7f8b8026c120 [Dec 8 18:00:03] DEBUG[62991] rtp_engine.c: Setting tx payload type 18 based on m type on 0x7f8b8026c120 [Dec 8 18:00:03] DEBUG[62991] rtp_engine.c: Crossover copying tx to rx payload mapping 0 (0x7f8b0803fee8) from 0x7f8b8026c120 to 0x7f8b8026c120 [Dec 8 18:00:03] DEBUG[62991] rtp_engine.c: Crossover copying tx to rx payload mapping 2 (0x7f8b080404e8) from 0x7f8b8026c120 to 0x7f8b8026c120 [Dec 8 18:00:03] DEBUG[62991] rtp_engine.c: Crossover copying tx to rx payload mapping 4 (0x7f8b08040ae8) from 0x7f8b8026c120 to 0x7f8b8026c120 [Dec 8 18:00:03] DEBUG[62991] rtp_engine.c: Crossover copying tx to rx payload mapping 8 (0x7f8b080410e8) from 0x7f8b8026c120 to 0x7f8b8026c120 [Dec 8 18:00:03] DEBUG[62991] rtp_engine.c: Crossover copying tx to rx payload mapping 18 (0x7f8b08041888) from 0x7f8b8026c120 to 0x7f8b8026c120 [Dec 8 18:00:03] DEBUG[62991] rtp_engine.c: Crossover copying tx to rx payload mapping 101 (0x7f8b08041b08) from 0x7f8b8026c120 to 0x7f8b8026c120 [Dec 8 18:00:03] DEBUG[62991] rtp_engine.c: Copying rx payload mapping 0 (0x7f8b0803fee8) from 0x7f8b8026c120 to 0x7f8b08032268 [Dec 8 18:00:03] DEBUG[62991] rtp_engine.c: Copying rx payload mapping 2 (0x7f8b080404e8) from 0x7f8b8026c120 to 0x7f8b08032268 [Dec 8 18:00:03] DEBUG[62991] rtp_engine.c: Copying rx payload mapping 4 (0x7f8b08040ae8) from 0x7f8b8026c120 to 0x7f8b08032268 [Dec 8 18:00:03] DEBUG[62991] rtp_engine.c: Copying rx payload mapping 8 (0x7f8b080410e8) from 0x7f8b8026c120 to 0x7f8b08032268 [Dec 8 18:00:03] DEBUG[62991] rtp_engine.c: Copying rx payload mapping 18 (0x7f8b08041888) from 0x7f8b8026c120 to 0x7f8b08032268 [Dec 8 18:00:03] DEBUG[62991] rtp_engine.c: Copying rx payload mapping 101 (0x7f8b08041b08) from 0x7f8b8026c120 to 0x7f8b08032268 [Dec 8 18:00:03] DEBUG[62991] rtp_engine.c: Copying tx payload mapping 0 (0x7f8b0803fee8) from 0x7f8b8026c120 to 0x7f8b08032268 [Dec 8 18:00:03] DEBUG[62991] rtp_engine.c: Copying tx payload mapping 2 (0x7f8b080404e8) from 0x7f8b8026c120 to 0x7f8b08032268 [Dec 8 18:00:03] DEBUG[62991] rtp_engine.c: Copying tx payload mapping 4 (0x7f8b08040ae8) from 0x7f8b8026c120 to 0x7f8b08032268 [Dec 8 18:00:03] DEBUG[62991] rtp_engine.c: Copying tx payload mapping 8 (0x7f8b080410e8) from 0x7f8b8026c120 to 0x7f8b08032268 [Dec 8 18:00:03] DEBUG[62991] rtp_engine.c: Copying tx payload mapping 18 (0x7f8b08041888) from 0x7f8b8026c120 to 0x7f8b08032268 [Dec 8 18:00:03] DEBUG[62991] rtp_engine.c: Copying tx payload mapping 101 (0x7f8b08041b08) from 0x7f8b8026c120 to 0x7f8b08032268 [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: 8002: Media stream 0:audio-0:audio:sendrecv (ulaw|alaw|g726) handled by audio [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: 8002: Done with stream 0:audio-0:audio:sendrecv (ulaw|alaw|g726) [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: 8002: Handled? yes [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: 8002 [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: 8002: Processing streams [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: 8002: Processing stream 0:audio-0:audio:sendrecv (ulaw|alaw|g726) [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: 8002 Adding position 0 [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: Using existing media_session [Dec 8 18:00:03] DEBUG[62991] res_rtp_asterisk.c: (0x7f8b08032090) RTCP ignoring duplicate property [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: 8002: Stream 0:audio-0:audio:sendrecv (ulaw|alaw|g726) added [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: 8002: Done with 0:audio-0:audio:sendrecv (ulaw|alaw|g726) [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: 8002: Adding bundle groups (if available) [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: 8002: Copying connection details [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: 8002: Processing media 0 [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: 8002: Media 0 reset [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: 8002 [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: 8002: Method is INVITE [Dec 8 18:00:03] DEBUG[62991] chan_pjsip.c: 8002 [Dec 8 18:00:03] DEBUG[62991] stasis.c: Creating topic. name: channel:1607450403.0, detail: [Dec 8 18:00:03] DEBUG[62991] stasis.c: Topic 'channel:1607450403.0': 0x55e9b024d750 created [Dec 8 18:00:03] DEBUG[62991] stasis.c: Creating topic. name: cache:7/channel:1607450403.0, detail: [Dec 8 18:00:03] DEBUG[62991] stasis.c: Topic 'cache:7/channel:1607450403.0': 0x55e9b024cf90 created [Dec 8 18:00:03] DEBUG[62991] channel.c: Channel 0x7f8b08052a10 'PJSIP/8002-00000000' allocated [Dec 8 18:00:03] DEBUG[63044] manager.c: Examining AMI event: Event: Newchannel Privilege: call,all Channel: PJSIP/8002-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8002 CallerIDName: 8002 ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.0 Linkedid: 1607450403.0 [Dec 8 18:00:03] DEBUG[62991] chan_pjsip.c: PJSIP/8002-00000000 [Dec 8 18:00:03] DEBUG[62991] chan_pjsip.c: Started PBX on new PJSIP channel PJSIP/8002-00000000 [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: PJSIP/8002-00000000 [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: PJSIP/8002-00000000 [Dec 8 18:00:03] DEBUG[63045][C-00000001] pbx.c: Launching 'Dial' [Dec 8 18:00:03] VERBOSE[63045][C-00000001] pbx.c: Executing [8000@pjsip_context:1] Dial("PJSIP/8002-00000000", "PJSIP/8000@ast150") in new stack [Dec 8 18:00:03] DEBUG[63044] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/8002-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8002 CallerIDName: 8002 ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.0 Linkedid: 1607450403.0 Extension: 8000 Application: Dial AppData: PJSIP/8000@ast150 [Dec 8 18:00:03] DEBUG[63044] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/8002-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8002 CallerIDName: 8002 ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.0 Linkedid: 1607450403.0 Variable: DIALSTATUS Value: [Dec 8 18:00:03] DEBUG[63044] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/8002-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8002 CallerIDName: 8002 ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.0 Linkedid: 1607450403.0 Variable: DIALEDPEERNUMBER Value: [Dec 8 18:00:03] DEBUG[63045][C-00000001] stasis.c: Creating topic. name: channel:1607450403.1, detail: [Dec 8 18:00:03] DEBUG[63044] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/8002-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8002 CallerIDName: 8002 ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.0 Linkedid: 1607450403.0 Variable: DIALEDPEERNAME Value: [Dec 8 18:00:03] DEBUG[63045][C-00000001] stasis.c: Topic 'channel:1607450403.1': 0x7f8b4c010bb0 created [Dec 8 18:00:03] DEBUG[63045][C-00000001] stasis.c: Creating topic. name: cache:8/channel:1607450403.1, detail: [Dec 8 18:00:03] DEBUG[63044] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/8002-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8002 CallerIDName: 8002 ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.0 Linkedid: 1607450403.0 Variable: ANSWEREDTIME Value: [Dec 8 18:00:03] DEBUG[63045][C-00000001] stasis.c: Topic 'cache:8/channel:1607450403.1': 0x7f8b4c011ca0 created [Dec 8 18:00:03] DEBUG[63044] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/8002-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8002 CallerIDName: 8002 ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.0 Linkedid: 1607450403.0 Variable: ANSWEREDTIME_MS Value: [Dec 8 18:00:03] DEBUG[63044] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/8002-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8002 CallerIDName: 8002 ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.0 Linkedid: 1607450403.0 Variable: DIALEDTIME Value: [Dec 8 18:00:03] DEBUG[63044] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/8002-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8002 CallerIDName: 8002 ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.0 Linkedid: 1607450403.0 Variable: DIALEDTIME_MS Value: [Dec 8 18:00:03] DEBUG[63044] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/8002-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8002 CallerIDName: 8002 ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.0 Linkedid: 1607450403.0 Variable: RINGTIME Value: [Dec 8 18:00:03] DEBUG[63044] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/8002-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8002 CallerIDName: 8002 ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.0 Linkedid: 1607450403.0 Variable: RINGTIME_MS Value: [Dec 8 18:00:03] DEBUG[63044] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/8002-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8002 CallerIDName: 8002 ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.0 Linkedid: 1607450403.0 Variable: PROGRESSTIME Value: [Dec 8 18:00:03] DEBUG[63044] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/8002-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8002 CallerIDName: 8002 ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.0 Linkedid: 1607450403.0 Variable: PROGRESSTIME_MS Value: [Dec 8 18:00:03] DEBUG[63045][C-00000001] channel.c: Channel 0x7f8b4c00d7e0 'PJSIP/ast150-00000001' allocated [Dec 8 18:00:03] DEBUG[63044] manager.c: Examining AMI event: Event: Newchannel Privilege: call,all Channel: PJSIP/ast150-00000001 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: pjsip_context Exten: s Priority: 1 Uniqueid: 1607450403.1 Linkedid: 1607450403.0 [Dec 8 18:00:03] DEBUG[63044] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/ast150-00000001 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: pjsip_context Exten: s Priority: 1 Uniqueid: 1607450403.1 Linkedid: 1607450403.0 Variable: DIALEDPEERNUMBER Value: 8000@ast150 [Dec 8 18:00:03] DEBUG[63044] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/ast150-00000001 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 8000 CallerIDName: ConnectedLineNum: 8002 ConnectedLineName: 8002 Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.1 Linkedid: 1607450403.0 Extension: 8000 Application: AppDial AppData: (Outgoing Line) [Dec 8 18:00:03] DEBUG[63044] manager.c: Examining AMI event: Event: NewCallerid Privilege: call,all Channel: PJSIP/ast150-00000001 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 8000 CallerIDName: ConnectedLineNum: 8002 ConnectedLineName: 8002 Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.1 Linkedid: 1607450403.0 CID-CallingPres: 0 (Presentation Allowed, Not Screened) [Dec 8 18:00:03] DEBUG[63044] manager.c: Examining AMI event: Event: NewConnectedLine Privilege: call,all Channel: PJSIP/ast150-00000001 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 8000 CallerIDName: ConnectedLineNum: 8002 ConnectedLineName: 8002 Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.1 Linkedid: 1607450403.0 [Dec 8 18:00:03] VERBOSE[63045][C-00000001] app_dial.c: Called PJSIP/8000@ast150 [Dec 8 18:00:03] DEBUG[63045][C-00000001] channel.c: Channel PJSIP/ast150-00000001 setting read format path: ulaw -> ulaw [Dec 8 18:00:03] DEBUG[63044] manager.c: Examining AMI event: Event: DialBegin Privilege: call,all Channel: PJSIP/8002-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8002 CallerIDName: 8002 ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.0 Linkedid: 1607450403.0 DestChannel: PJSIP/ast150-00000001 DestChannelState: 0 DestChannelStateDesc: Down DestCallerIDNum: 8000 DestCallerIDName: DestConnectedLineNum: 8002 DestConnectedLineName: 8002 DestLanguage: en DestAccountCode: DestContext: pjsip_context DestExten: 8000 DestPriority: 1 DestUniqueid: 1607450403.1 DestLinkedid: 1607450403.0 DialString: 8000@ast150 [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: PJSIP/ast150-00000001 [Dec 8 18:00:03] DEBUG[63045][C-00000001] channel.c: Channel PJSIP/8002-00000000 setting write format path: ulaw -> ulaw [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: PJSIP/ast150-00000001: Processing streams [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: PJSIP/ast150-00000001: Processing stream 0:audio-0:audio:sendrecv (ulaw|alaw|g726|gsm|g726aal2|adpcm|g722) [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: PJSIP/ast150-00000001 Adding position 0 [Dec 8 18:00:03] DEBUG[63045][C-00000001] channel.c: Channel PJSIP/8002-00000000 setting read format path: ulaw -> ulaw [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: Creating new media session [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: Setting media session as default for audio [Dec 8 18:00:03] DEBUG[63045][C-00000001] channel.c: Channel PJSIP/ast150-00000001 setting write format path: ulaw -> ulaw [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: Done [Dec 8 18:00:03] DEBUG[62991] res_pjsip_sdp_rtp.c: Transport udp bound to 0.0.0.0: Using it for RTP media. [Dec 8 18:00:03] DEBUG[62991] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f8b08069260' [Dec 8 18:00:03] DEBUG[62991] res_rtp_asterisk.c: (0x7f8b08069260) RTP allocated port 16484 [Dec 8 18:00:03] DEBUG[62991] res_rtp_asterisk.c: (0x7f8b08069260) ICE creating session 0.0.0.0:16484 (16484) [Dec 8 18:00:03] DEBUG[62991] res_rtp_asterisk.c: (0x7f8b08069260) ICE create [Dec 8 18:00:03] DEBUG[62991] pjproject: icess0x7f8b102a90c8 ICE session created, comp_cnt=2, role is Unknown agent [Dec 8 18:00:03] DEBUG[62991] res_rtp_asterisk.c: (0x7f8b08069260) ICE add system candidates [Dec 8 18:00:03] DEBUG[62991] pjproject: icess0x7f8b102a90c8 Candidate 0 added: comp_id=1, type=host, foundation=Ha090997, addr=10.9.9.151:16484, base=10.9.9.151:16484, prio=0x7effffff (2130706431) [Dec 8 18:00:03] DEBUG[62991] res_rtp_asterisk.c: (0x7f8b08069260) ICE add candidate: 10.9.9.151:16484, 2130706431 [Dec 8 18:00:03] DEBUG[62991] pjproject: icess0x7f8b102a90c8 Candidate 1 added: comp_id=1, type=host, foundation=Ha090897, addr=10.9.8.151:16484, base=10.9.8.151:16484, prio=0x7effffff (2130706431) [Dec 8 18:00:03] DEBUG[62991] res_rtp_asterisk.c: (0x7f8b08069260) ICE add candidate: 10.9.8.151:16484, 2130706431 [Dec 8 18:00:03] DEBUG[62991] rtp_engine.c: RTP instance '0x7f8b08069260' is setup and ready to go [Dec 8 18:00:03] DEBUG[62991] pjproject: icess0x7f8b102a90c8 Destroying ICE session 0x7f8b102a90c8 [Dec 8 18:00:03] DEBUG[62991] pjproject: ice_session.c ICE session 0x7f8b102a90c8 destroyed [Dec 8 18:00:03] DEBUG[62991] res_rtp_asterisk.c: (0x7f8b08069260) ICE stopped [Dec 8 18:00:03] DEBUG[62991] res_rtp_asterisk.c: (0x7f8b08069260) RTCP setup on RTP instance [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: PJSIP/ast150-00000001: Stream 0:audio-0:audio:sendrecv (ulaw|alaw|g726|gsm|g726aal2|adpcm|g722) added [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: PJSIP/ast150-00000001: Done with 0:audio-0:audio:sendrecv (ulaw|alaw|g726|gsm|g726aal2|adpcm|g722) [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: PJSIP/ast150-00000001: Adding bundle groups (if available) [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: PJSIP/ast150-00000001: Copying connection details [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: PJSIP/ast150-00000001: Processing media 0 [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: PJSIP/ast150-00000001: Media 0 reset [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: PJSIP/ast150-00000001 [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: PJSIP/ast150-00000001: Method is INVITE [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: PJSIP/ast150-00000001 [Dec 8 18:00:03] DEBUG[62991] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '10.9.9.151' [Dec 8 18:00:03] DEBUG[62991] res_pjsip/pjsip_resolver.c: Transport type for target '10.9.9.151' is 'UDP transport' [Dec 8 18:00:03] DEBUG[62991] res_pjsip/pjsip_resolver.c: Target '10.9.9.151' is an IP address, skipping resolution [Dec 8 18:00:03] DEBUG[63045][C-00000001] chan_pjsip.c: PJSIP/8002-00000000: Indicated Connected line update [Dec 8 18:00:03] DEBUG[63045][C-00000001] chan_pjsip.c: PJSIP/8002-00000000 [Dec 8 18:00:03] DEBUG[63044] manager.c: Examining AMI event: Event: NewConnectedLine Privilege: call,all Channel: PJSIP/8002-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8002 CallerIDName: 8002 ConnectedLineNum: 8000 ConnectedLineName: Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.0 Linkedid: 1607450403.0 [Dec 8 18:00:03] VERBOSE[62991] res_pjsip_logger.c: <--- Transmitting SIP request (1083 bytes) to UDP:10.9.9.151:5060 ---> INVITE sip:8000@10.9.9.150:5061 SIP/2.0 Via: SIP/2.0/UDP 10.9.9.151:5061;rport;branch=z9hG4bKPj33f87c5d-f7d4-4872-9446-7e8732878e3c From: "8002" ;tag=e40f373c-93f5-45ec-bf6b-e16978266a05 To: Contact: Call-ID: 6e75a4f3-db8f-4b65-961f-8490edad3d7a CSeq: 8856 INVITE Route: 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 16.15.0 Content-Type: application/sdp Content-Length: 393 v=0 o=- 408912038 408912038 IN IP4 10.9.9.151 s=Asterisk c=IN IP4 10.9.9.151 t=0 0 m=audio 16484 RTP/AVP 0 8 111 3 112 5 9 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:111 G726-32/8000 a=rtpmap:3 GSM/8000 a=rtpmap:112 AAL2-G726-32/8000 a=rtpmap:5 DVI4/8000 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: PJSIP/ast150-00000001: Source of transaction state change is TX_MSG [Dec 8 18:00:03] VERBOSE[62990] res_pjsip_logger.c: <--- Received SIP response (370 bytes) from UDP:10.9.9.151:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.9.9.151:5061;rport=5061;branch=z9hG4bKPj33f87c5d-f7d4-4872-9446-7e8732878e3c;received=10.9.9.151 From: "8002" ;tag=e40f373c-93f5-45ec-bf6b-e16978266a05 To: Call-ID: 6e75a4f3-db8f-4b65-961f-8490edad3d7a CSeq: 8856 INVITE Server: kamailio (5.4.1 (x86_64/linux)) Content-Length: 0 [Dec 8 18:00:03] DEBUG[62990] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f8b0805ec18 for Response msg 100/INVITE/cseq=8856 (rdata0x7f8b50014328) [Dec 8 18:00:03] DEBUG[62990] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/ast150-0000005f associated with dialog dlg0x7f8b0805ec18 [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: PJSIP/ast150-00000001: Response is 100 Trying [Dec 8 18:00:03] DEBUG[62991] chan_pjsip.c: PJSIP/ast150-00000001: Status: 100 [Dec 8 18:00:03] DEBUG[62991] chan_pjsip.c: PJSIP/ast150-00000001: Not queueing anything [Dec 8 18:00:03] DEBUG[62991] chan_pjsip.c: PJSIP/ast150-00000001 [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: PJSIP/ast150-00000001 [Dec 8 18:00:03] DEBUG[63045][C-00000001] chan_pjsip.c: PJSIP/8002-00000000: Indicated Private Cause Code [Dec 8 18:00:03] DEBUG[63045][C-00000001] chan_pjsip.c: PJSIP/8002-00000000 [Dec 8 18:00:03] VERBOSE[62990] res_pjsip_logger.c: <--- Received SIP response (621 bytes) from UDP:10.9.9.151:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.9.9.151:5061;rport=5061;received=10.9.9.151;branch=z9hG4bKPj33f87c5d-f7d4-4872-9446-7e8732878e3c Record-Route: Call-ID: 6e75a4f3-db8f-4b65-961f-8490edad3d7a From: "8002" ;tag=e40f373c-93f5-45ec-bf6b-e16978266a05 To: ;tag=60d365bd-0fc2-4c29-b82f-3c63962e47b1 CSeq: 8856 INVITE Server: Asterisk PBX 16.7.0 Contact: Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER Content-Length: 0 [Dec 8 18:00:03] DEBUG[62990] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f8b0805ec18 for Response msg 180/INVITE/cseq=8856 (rdata0x7f8b50037ec8) [Dec 8 18:00:03] DEBUG[62990] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/ast150-0000005f associated with dialog dlg0x7f8b0805ec18 [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: PJSIP/ast150-00000001: Source of transaction state change is RX_MSG [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: PJSIP/ast150-00000001: Received response [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: PJSIP/ast150-00000001: Response is 180 Ringing [Dec 8 18:00:03] DEBUG[62991] chan_pjsip.c: PJSIP/ast150-00000001: Status: 180 [Dec 8 18:00:03] DEBUG[62991] chan_pjsip.c: PJSIP/ast150-00000001: Queueing RINGING [Dec 8 18:00:03] DEBUG[63045][C-00000001] chan_pjsip.c: PJSIP/8002-00000000: Indicated Private Cause Code [Dec 8 18:00:03] DEBUG[63045][C-00000001] chan_pjsip.c: PJSIP/8002-00000000 [Dec 8 18:00:03] DEBUG[62991] chan_pjsip.c: PJSIP/ast150-00000001 [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: PJSIP/ast150-00000001 [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: PJSIP/ast150-00000001: Response is 180 Ringing [Dec 8 18:00:03] DEBUG[62991] chan_pjsip.c: PJSIP/ast150-00000001: Status: 180 [Dec 8 18:00:03] DEBUG[62991] chan_pjsip.c: PJSIP/ast150-00000001: Queueing RINGING [Dec 8 18:00:03] DEBUG[62991] chan_pjsip.c: PJSIP/ast150-00000001 [Dec 8 18:00:03] DEBUG[62975] devicestate.c: No provider found, checking channel drivers for PJSIP - ast150 [Dec 8 18:00:03] DEBUG[62991] res_pjsip_session.c: PJSIP/ast150-00000001 [Dec 8 18:00:03] DEBUG[63044] manager.c: Examining AMI event: Event: Newstate Privilege: call,all Channel: PJSIP/ast150-00000001 ChannelState: 5 ChannelStateDesc: Ringing CallerIDNum: 8000 CallerIDName: ConnectedLineNum: 8002 ConnectedLineName: 8002 Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.1 Linkedid: 1607450403.0 [Dec 8 18:00:03] DEBUG[62975] devicestate.c: Changing state for PJSIP/ast150 - state 6 (Ringing) [Dec 8 18:00:03] VERBOSE[63045][C-00000001] app_dial.c: PJSIP/ast150-00000001 is ringing [Dec 8 18:00:03] DEBUG[63045][C-00000001] chan_pjsip.c: PJSIP/8002-00000000: Indicated Ringing [Dec 8 18:00:03] DEBUG[62975] devicestate.c: No provider found, checking channel drivers for PJSIP - 8002 [Dec 8 18:00:03] DEBUG[62975] devicestate.c: Changing state for PJSIP/8002 - state 2 (In use) [Dec 8 18:00:03] DEBUG[63044] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: PJSIP/ast150 State: RINGING [Dec 8 18:00:03] DEBUG[63044] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: PJSIP/8002 State: INUSE [Dec 8 18:00:03] DEBUG[63040] app_queue.c: Device 'PJSIP/ast150' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Dec 8 18:00:03] DEBUG[63040] app_queue.c: Device 'PJSIP/8002' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Dec 8 18:00:03] DEBUG[62992] res_pjsip_session.c: PJSIP/8002-00000000: Method is INVITE, Response is 180 Ringing [Dec 8 18:00:03] DEBUG[63045][C-00000001] chan_pjsip.c: PJSIP/8002-00000000 [Dec 8 18:00:03] DEBUG[63044] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/8002-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8002 CallerIDName: 8002 ConnectedLineNum: 8000 ConnectedLineName: Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.0 Linkedid: 1607450403.0 Variable: RINGTIME Value: 0 [Dec 8 18:00:03] DEBUG[63045][C-00000001] chan_pjsip.c: PJSIP/8002-00000000: Indicated Private Cause Code [Dec 8 18:00:03] DEBUG[63044] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/8002-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8002 CallerIDName: 8002 ConnectedLineNum: 8000 ConnectedLineName: Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.0 Linkedid: 1607450403.0 Variable: RINGTIME_MS Value: 68 [Dec 8 18:00:03] DEBUG[63045][C-00000001] chan_pjsip.c: PJSIP/8002-00000000 [Dec 8 18:00:03] DEBUG[63044] manager.c: Examining AMI event: Event: DialState Privilege: call,all Channel: PJSIP/8002-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8002 CallerIDName: 8002 ConnectedLineNum: 8000 ConnectedLineName: Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.0 Linkedid: 1607450403.0 DestChannel: PJSIP/ast150-00000001 DestChannelState: 5 DestChannelStateDesc: Ringing DestCallerIDNum: 8000 DestCallerIDName: DestConnectedLineNum: 8002 DestConnectedLineName: 8002 DestLanguage: en DestAccountCode: DestContext: pjsip_context DestExten: 8000 DestPriority: 1 DestUniqueid: 1607450403.1 DestLinkedid: 1607450403.0 DialStatus: RINGING [Dec 8 18:00:03] VERBOSE[63045][C-00000001] app_dial.c: PJSIP/ast150-00000001 is ringing [Dec 8 18:00:03] DEBUG[62992] res_pjsip_session.c: PJSIP/8002-00000000 [Dec 8 18:00:03] DEBUG[63044] manager.c: Examining AMI event: Event: DialState Privilege: call,all Channel: PJSIP/8002-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8002 CallerIDName: 8002 ConnectedLineNum: 8000 ConnectedLineName: Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.0 Linkedid: 1607450403.0 DestChannel: PJSIP/ast150-00000001 DestChannelState: 5 DestChannelStateDesc: Ringing DestCallerIDNum: 8000 DestCallerIDName: DestConnectedLineNum: 8002 DestConnectedLineName: 8002 DestLanguage: en DestAccountCode: DestContext: pjsip_context DestExten: 8000 DestPriority: 1 DestUniqueid: 1607450403.1 DestLinkedid: 1607450403.0 DialStatus: RINGING [Dec 8 18:00:03] VERBOSE[62992] res_pjsip_logger.c: <--- Transmitting SIP response (489 bytes) to UDP:10.9.9.132:5063 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.9.9.132:5063;rport=5063;received=10.9.9.132;branch=z9hG4bK-1bac0c4a Call-ID: fc714988-3bb17a02@10.9.9.132 From: "8002" ;tag=f1b573d0566e145ao3 To: ;tag=966cecfc-6009-4b76-8883-5803f77d0db4 CSeq: 101 INVITE Server: Asterisk PBX 16.15.0 Contact: Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER Content-Length: 0 [Dec 8 18:00:03] DEBUG[62992] res_pjsip_session.c: PJSIP/8002-00000000: Source of transaction state change is TX_MSG [Dec 8 18:00:04] VERBOSE[62990] res_pjsip_logger.c: <--- Received SIP response (1144 bytes) from UDP:10.9.9.151:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.9.9.151:5061;rport=5061;received=10.9.9.151;branch=z9hG4bKPj33f87c5d-f7d4-4872-9446-7e8732878e3c Record-Route: Call-ID: 6e75a4f3-db8f-4b65-961f-8490edad3d7a From: "8002" ;tag=e40f373c-93f5-45ec-bf6b-e16978266a05 To: ;tag=60d365bd-0fc2-4c29-b82f-3c63962e47b1 CSeq: 8856 INVITE Server: Asterisk PBX 16.7.0 Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER Contact: Supported: 100rel, timer, replaces, norefersub Session-Expires: 1800;refresher=uac Require: timer Content-Type: application/sdp Content-Length: 393 v=0 o=- 408912038 408912040 IN IP4 10.9.9.150 s=Asterisk c=IN IP4 10.9.9.150 t=0 0 m=audio 19722 RTP/AVP 0 8 3 111 112 5 9 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:3 GSM/8000 a=rtpmap:111 G726-32/8000 a=rtpmap:112 AAL2-G726-32/8000 a=rtpmap:5 DVI4/8000 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [Dec 8 18:00:04] DEBUG[62990] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f8b0805ec18 for Response msg 200/INVITE/cseq=8856 (rdata0x7f8b5005bb28) [Dec 8 18:00:04] DEBUG[62990] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/ast150-0000005f associated with dialog dlg0x7f8b0805ec18 [Dec 8 18:00:04] DEBUG[62991] res_pjsip_session.c: PJSIP/ast150-00000001: Source of transaction state change is RX_MSG [Dec 8 18:00:04] DEBUG[62991] res_pjsip_session.c: PJSIP/ast150-00000001: Received response [Dec 8 18:00:04] DEBUG[62991] res_pjsip_session.c: PJSIP/ast150-00000001: Response is 200 OK [Dec 8 18:00:04] DEBUG[62991] chan_pjsip.c: PJSIP/ast150-00000001: Status: 200 [Dec 8 18:00:04] DEBUG[62991] chan_pjsip.c: PJSIP/ast150-00000001: Queueing ANSWER [Dec 8 18:00:04] DEBUG[63045][C-00000001] chan_pjsip.c: PJSIP/8002-00000000: Indicated Private Cause Code [Dec 8 18:00:04] DEBUG[62991] chan_pjsip.c: PJSIP/ast150-00000001 [Dec 8 18:00:04] DEBUG[63045][C-00000001] chan_pjsip.c: PJSIP/8002-00000000 [Dec 8 18:00:04] DEBUG[62991] res_pjsip_session.c: PJSIP/ast150-00000001 [Dec 8 18:00:04] DEBUG[62975] devicestate.c: No provider found, checking channel drivers for PJSIP - ast150 [Dec 8 18:00:04] DEBUG[62975] devicestate.c: Changing state for PJSIP/ast150 - state 2 (In use) [Dec 8 18:00:04] DEBUG[63044] manager.c: Examining AMI event: Event: Newstate Privilege: call,all Channel: PJSIP/ast150-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8000 CallerIDName: ConnectedLineNum: 8002 ConnectedLineName: 8002 Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.1 Linkedid: 1607450403.0 [Dec 8 18:00:04] DEBUG[63040] app_queue.c: Device 'PJSIP/ast150' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Dec 8 18:00:04] DEBUG[62991] pjproject: inv0x7f8b0805ec18 ....SDP negotiation done: Success [Dec 8 18:00:04] VERBOSE[63045][C-00000001] app_dial.c: PJSIP/ast150-00000001 answered PJSIP/8002-00000000 [Dec 8 18:00:04] DEBUG[62991] res_pjsip_session.c: PJSIP/ast150-00000001 [Dec 8 18:00:04] DEBUG[62991] res_pjsip_session.c: PJSIP/ast150-00000001: Applying negotiated SDP media stream 'audio' using audio SDP handler [Dec 8 18:00:04] DEBUG[62991] res_rtp_asterisk.c: (0x7f8b08069260) RTCP ignoring duplicate property [Dec 8 18:00:04] DEBUG[62991] acl.c: For destination '10.9.9.150', our source address is '10.9.9.151'. [Dec 8 18:00:04] DEBUG[62991] res_rtp_asterisk.c: (0x7f8b08069260) RTCP setting address on RTP instance [Dec 8 18:00:04] VERBOSE[62991] res_rtp_asterisk.c: 0x7f8b0806a4f0 -- Strict RTP learning after remote address set to: 10.9.9.150:19722 [Dec 8 18:00:04] DEBUG[63045][C-00000001] channel.c: Channel PJSIP/ast150-00000001 setting read format path: ulaw -> ulaw [Dec 8 18:00:04] DEBUG[62991] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7f8b8026c060 [Dec 8 18:00:04] DEBUG[63045][C-00000001] channel.c: Channel PJSIP/8002-00000000 setting write format path: ulaw -> ulaw [Dec 8 18:00:04] DEBUG[62991] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7f8b8026c060 [Dec 8 18:00:04] DEBUG[63044] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: PJSIP/ast150 State: INUSE [Dec 8 18:00:04] DEBUG[62991] rtp_engine.c: Setting tx payload type 3 based on m type on 0x7f8b8026c060 [Dec 8 18:00:04] DEBUG[63044] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/8002-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8002 CallerIDName: 8002 ConnectedLineNum: 8000 ConnectedLineName: Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.0 Linkedid: 1607450403.0 Variable: DIALSTATUS Value: ANSWER [Dec 8 18:00:04] DEBUG[62991] rtp_engine.c: Setting tx payload type 5 based on m type on 0x7f8b8026c060 [Dec 8 18:00:04] DEBUG[63045][C-00000001] channel.c: Channel PJSIP/8002-00000000 setting read format path: ulaw -> ulaw [Dec 8 18:00:04] DEBUG[63044] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/8002-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8002 CallerIDName: 8002 ConnectedLineNum: 8000 ConnectedLineName: Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.0 Linkedid: 1607450403.0 Variable: DIALEDPEERNAME Value: PJSIP/ast150-00000001 [Dec 8 18:00:04] DEBUG[62991] rtp_engine.c: Setting tx payload type 9 based on m type on 0x7f8b8026c060 [Dec 8 18:00:04] DEBUG[63044] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/8002-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8002 CallerIDName: 8002 ConnectedLineNum: 8000 ConnectedLineName: Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.0 Linkedid: 1607450403.0 Variable: DIALEDPEERNUMBER Value: 8000@ast150 [Dec 8 18:00:04] DEBUG[63045][C-00000001] channel.c: Channel PJSIP/ast150-00000001 setting write format path: ulaw -> ulaw [Dec 8 18:00:04] DEBUG[63044] manager.c: Examining AMI event: Event: DialEnd Privilege: call,all Channel: PJSIP/8002-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8002 CallerIDName: 8002 ConnectedLineNum: 8000 ConnectedLineName: Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.0 Linkedid: 1607450403.0 DestChannel: PJSIP/ast150-00000001 DestChannelState: 6 DestChannelStateDesc: Up DestCallerIDNum: 8000 DestCallerIDName: DestConnectedLineNum: 8002 DestConnectedLineName: 8002 DestLanguage: en DestAccountCode: DestContext: pjsip_context DestExten: DestPriority: 1 DestUniqueid: 1607450403.1 DestLinkedid: 1607450403.0 DialStatus: ANSWER [Dec 8 18:00:04] DEBUG[62975] devicestate.c: No provider found, checking channel drivers for PJSIP - 8002 [Dec 8 18:00:04] DEBUG[62991] rtp_engine.c: Copying tx payload mapping 0 (0x55e9aff02f38) from 0x7f8b8026c060 to 0x7f8b08069438 [Dec 8 18:00:04] DEBUG[62991] rtp_engine.c: Copying tx payload mapping 3 (0x55e9b0138ca8) from 0x7f8b8026c060 to 0x7f8b08069438 [Dec 8 18:00:04] DEBUG[62975] devicestate.c: Changing state for PJSIP/8002 - state 2 (In use) [Dec 8 18:00:04] DEBUG[62991] rtp_engine.c: Copying tx payload mapping 5 (0x55e9afb97598) from 0x7f8b8026c060 to 0x7f8b08069438 [Dec 8 18:00:04] DEBUG[62991] rtp_engine.c: Copying tx payload mapping 8 (0x55e9b00c0518) from 0x7f8b8026c060 to 0x7f8b08069438 [Dec 8 18:00:04] DEBUG[62991] rtp_engine.c: Copying tx payload mapping 9 (0x7f8b080a9938) from 0x7f8b8026c060 to 0x7f8b08069438 [Dec 8 18:00:04] DEBUG[62991] rtp_engine.c: Copying tx payload mapping 101 (0x7f8b080a9a18) from 0x7f8b8026c060 to 0x7f8b08069438 [Dec 8 18:00:04] DEBUG[62991] rtp_engine.c: Copying tx payload mapping 111 (0x55e9b00c78d8) from 0x7f8b8026c060 to 0x7f8b08069438 [Dec 8 18:00:04] DEBUG[62991] rtp_engine.c: Copying tx payload mapping 112 (0x55e9afefbe28) from 0x7f8b8026c060 to 0x7f8b08069438 [Dec 8 18:00:04] DEBUG[62991] channel.c: Channel PJSIP/ast150-00000001 setting read format path: ulaw -> ulaw [Dec 8 18:00:04] DEBUG[63044] manager.c: Examining AMI event: Event: Newstate Privilege: call,all Channel: PJSIP/8002-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8002 CallerIDName: 8002 ConnectedLineNum: 8000 ConnectedLineName: Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.0 Linkedid: 1607450403.0 [Dec 8 18:00:04] DEBUG[62991] channel.c: Channel PJSIP/ast150-00000001 setting write format path: ulaw -> ulaw [Dec 8 18:00:04] DEBUG[62992] pjproject: inv0x7f8b08003658 .SDP negotiation done: Success [Dec 8 18:00:04] DEBUG[62992] res_pjsip_session.c: PJSIP/8002-00000000 [Dec 8 18:00:04] DEBUG[62991] res_rtp_asterisk.c: (0x7f8b08069260) DTLS - ast_rtp_activate rtp=0x7f8b0806a4f0 - setup and perform DTLS' [Dec 8 18:00:04] DEBUG[62992] res_pjsip_session.c: PJSIP/8002-00000000: Applying negotiated SDP media stream 'audio' using audio SDP handler [Dec 8 18:00:04] DEBUG[62991] res_rtp_asterisk.c: (0x7f8b0806a4f0) DTLS perform handshake - ssl = (nil), setup = 0 [Dec 8 18:00:04] DEBUG[62992] res_rtp_asterisk.c: (0x7f8b08032090) RTCP ignoring duplicate property [Dec 8 18:00:04] DEBUG[62991] res_rtp_asterisk.c: (0x7f8b0806a4f0) DTLS perform handshake - ssl = (nil), setup = 0 [Dec 8 18:00:04] DEBUG[62991] res_pjsip_session.c: PJSIP/ast150-00000001: Applied negotiated SDP media stream 'audio' using audio SDP handler [Dec 8 18:00:04] DEBUG[62992] acl.c: For destination '10.9.9.132', our source address is '10.9.9.151'. [Dec 8 18:00:04] DEBUG[62992] res_rtp_asterisk.c: (0x7f8b08032090) RTCP setting address on RTP instance [Dec 8 18:00:04] DEBUG[62991] res_pjsip_session.c: PJSIP/ast150-00000001 [Dec 8 18:00:04] VERBOSE[62992] res_rtp_asterisk.c: 0x7f8b08033300 -- Strict RTP learning after remote address set to: 10.9.9.132:16458 [Dec 8 18:00:04] DEBUG[62992] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7f8b801ef2a0 [Dec 8 18:00:04] DEBUG[62991] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '10.9.9.151' [Dec 8 18:00:04] DEBUG[62992] rtp_engine.c: Don't have a default tx payload type 2 format for m type on 0x7f8b801ef2a0 [Dec 8 18:00:04] DEBUG[62991] res_pjsip/pjsip_resolver.c: Transport type for target '10.9.9.151' is 'UDP transport' [Dec 8 18:00:04] DEBUG[62991] res_pjsip/pjsip_resolver.c: Target '10.9.9.151' is an IP address, skipping resolution [Dec 8 18:00:04] DEBUG[62992] rtp_engine.c: Setting tx payload type 4 based on m type on 0x7f8b801ef2a0 [Dec 8 18:00:04] DEBUG[62992] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7f8b801ef2a0 [Dec 8 18:00:04] DEBUG[62992] rtp_engine.c: Setting tx payload type 18 based on m type on 0x7f8b801ef2a0 [Dec 8 18:00:04] DEBUG[62992] rtp_engine.c: Copying tx payload mapping 0 (0x55e9aff46138) from 0x7f8b801ef2a0 to 0x7f8b08032268 [Dec 8 18:00:04] DEBUG[62992] rtp_engine.c: Copying tx payload mapping 2 (0x55e9afc151c8) from 0x7f8b801ef2a0 to 0x7f8b08032268 [Dec 8 18:00:04] DEBUG[62992] rtp_engine.c: Copying tx payload mapping 4 (0x55e9b00cc308) from 0x7f8b801ef2a0 to 0x7f8b08032268 [Dec 8 18:00:04] DEBUG[62992] rtp_engine.c: Copying tx payload mapping 8 (0x55e9aff27978) from 0x7f8b801ef2a0 to 0x7f8b08032268 [Dec 8 18:00:04] DEBUG[62992] rtp_engine.c: Copying tx payload mapping 18 (0x55e9afefef08) from 0x7f8b801ef2a0 to 0x7f8b08032268 [Dec 8 18:00:04] DEBUG[62992] rtp_engine.c: Copying tx payload mapping 101 (0x55e9b0002ea8) from 0x7f8b801ef2a0 to 0x7f8b08032268 [Dec 8 18:00:04] DEBUG[62992] channel.c: Channel PJSIP/8002-00000000 setting read format path: ulaw -> ulaw [Dec 8 18:00:04] DEBUG[62992] channel.c: Channel PJSIP/8002-00000000 setting write format path: ulaw -> ulaw [Dec 8 18:00:04] VERBOSE[62991] res_pjsip_logger.c: <--- Transmitting SIP request (478 bytes) to UDP:10.9.9.151:5060 ---> ACK sip:10.9.9.150:5061 SIP/2.0 Via: SIP/2.0/UDP 10.9.9.151:5061;rport;branch=z9hG4bKPj83d6b7f5-aa03-4b92-9284-e0774feb549a From: "8002" ;tag=e40f373c-93f5-45ec-bf6b-e16978266a05 To: ;tag=60d365bd-0fc2-4c29-b82f-3c63962e47b1 Call-ID: 6e75a4f3-db8f-4b65-961f-8490edad3d7a CSeq: 8856 ACK Route: Max-Forwards: 70 User-Agent: Asterisk PBX 16.15.0 Content-Length: 0 [Dec 8 18:00:04] DEBUG[62992] res_rtp_asterisk.c: (0x7f8b08032090) DTLS - ast_rtp_activate rtp=0x7f8b08033300 - setup and perform DTLS' [Dec 8 18:00:04] DEBUG[62992] res_rtp_asterisk.c: (0x7f8b08033300) DTLS perform handshake - ssl = (nil), setup = 0 [Dec 8 18:00:04] DEBUG[62992] res_rtp_asterisk.c: (0x7f8b08033300) DTLS perform handshake - ssl = (nil), setup = 0 [Dec 8 18:00:04] DEBUG[62992] res_pjsip_session.c: PJSIP/8002-00000000: Applied negotiated SDP media stream 'audio' using audio SDP handler [Dec 8 18:00:04] DEBUG[62992] res_pjsip_session.c: PJSIP/8002-00000000 [Dec 8 18:00:04] DEBUG[62992] res_pjsip_session.c: PJSIP/8002-00000000: Method is INVITE, Response is 200 OK [Dec 8 18:00:04] DEBUG[62992] res_pjsip_session.c: PJSIP/8002-00000000 [Dec 8 18:00:04] VERBOSE[62992] res_pjsip_logger.c: <--- Transmitting SIP response (844 bytes) to UDP:10.9.9.132:5063 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.9.9.132:5063;rport=5063;received=10.9.9.132;branch=z9hG4bK-1bac0c4a Call-ID: fc714988-3bb17a02@10.9.9.132 From: "8002" ;tag=f1b573d0566e145ao3 To: ;tag=966cecfc-6009-4b76-8883-5803f77d0db4 CSeq: 101 INVITE Server: Asterisk PBX 16.15.0 Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER Contact: Supported: 100rel, timer, replaces, norefersub Content-Type: application/sdp Content-Length: 278 v=0 o=- 7095147 7095149 IN IP4 10.9.9.151 s=Asterisk c=IN IP4 10.9.9.151 t=0 0 m=audio 15356 RTP/AVP 0 8 2 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [Dec 8 18:00:04] DEBUG[62992] res_pjsip_session.c: PJSIP/8002-00000000: Source of transaction state change is TX_MSG [Dec 8 18:00:04] DEBUG[63045][C-00000001] chan_pjsip.c: PJSIP/8002-00000000: Indicated Stop generators [Dec 8 18:00:04] DEBUG[63045][C-00000001] chan_pjsip.c: PJSIP/8002-00000000 [Dec 8 18:00:04] DEBUG[62991] res_pjsip_session.c: PJSIP/ast150-00000001: Response is 200 OK [Dec 8 18:00:04] DEBUG[62991] chan_pjsip.c: PJSIP/ast150-00000001: Status: 200 [Dec 8 18:00:04] DEBUG[63045][C-00000001] stasis.c: Creating topic. name: bridge:95308782-5303-4090-8296-08b65686bfdc, detail: [Dec 8 18:00:04] DEBUG[62991] chan_pjsip.c: PJSIP/ast150-00000001: Queueing ANSWER [Dec 8 18:00:04] DEBUG[63045][C-00000001] stasis.c: Topic 'bridge:95308782-5303-4090-8296-08b65686bfdc': 0x55e9b0247220 created [Dec 8 18:00:04] DEBUG[62991] chan_pjsip.c: PJSIP/ast150-00000001 [Dec 8 18:00:04] DEBUG[63045][C-00000001] stasis.c: Creating topic. name: cache:9/bridge:95308782-5303-4090-8296-08b65686bfdc, detail: [Dec 8 18:00:04] DEBUG[62991] res_pjsip_session.c: PJSIP/ast150-00000001 [Dec 8 18:00:04] DEBUG[63045][C-00000001] stasis.c: Topic 'cache:9/bridge:95308782-5303-4090-8296-08b65686bfdc': 0x55e9b0249160 created [Dec 8 18:00:04] DEBUG[63045][C-00000001] bridge_native_rtp.c: Bridge '95308782-5303-4090-8296-08b65686bfdc' can not use native RTP bridge as two channels are required [Dec 8 18:00:04] DEBUG[63045][C-00000001] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Dec 8 18:00:04] DEBUG[63045][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Dec 8 18:00:04] DEBUG[63045][C-00000001] bridge.c: Bridge technology softmix has less preference than simple_bridge (10 <= 50). Skipping. [Dec 8 18:00:04] DEBUG[63045][C-00000001] bridge.c: Chose bridge technology simple_bridge [Dec 8 18:00:04] DEBUG[63045][C-00000001] bridge.c: Bridge 95308782-5303-4090-8296-08b65686bfdc: calling simple_bridge technology constructor [Dec 8 18:00:04] DEBUG[63045][C-00000001] bridge.c: Bridge 95308782-5303-4090-8296-08b65686bfdc: calling simple_bridge technology start [Dec 8 18:00:04] DEBUG[63044] manager.c: Examining AMI event: Event: BridgeCreate Privilege: call,all BridgeUniqueid: 95308782-5303-4090-8296-08b65686bfdc BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 0 BridgeVideoSourceMode: none [Dec 8 18:00:04] DEBUG[63046][C-00000001] bridge_channel.c: Bridge 95308782-5303-4090-8296-08b65686bfdc: 0x7f8b4c0459a0(PJSIP/ast150-00000001) is joining [Dec 8 18:00:04] DEBUG[63046][C-00000001] bridge_channel.c: Bridge 95308782-5303-4090-8296-08b65686bfdc: pushing 0x7f8b4c0459a0(PJSIP/ast150-00000001) [Dec 8 18:00:04] VERBOSE[63046][C-00000001] bridge_channel.c: Channel PJSIP/ast150-00000001 joined 'simple_bridge' basic-bridge <95308782-5303-4090-8296-08b65686bfdc> [Dec 8 18:00:04] DEBUG[63044] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/ast150-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8000 CallerIDName: ConnectedLineNum: 8002 ConnectedLineName: 8002 Language: en AccountCode: Context: pjsip_context Exten: Priority: 1 Uniqueid: 1607450403.1 Linkedid: 1607450403.0 Extension: Application: AppDial AppData: (Outgoing Line) [Dec 8 18:00:04] DEBUG[63046][C-00000001] bridge_native_rtp.c: Bridge '95308782-5303-4090-8296-08b65686bfdc' can not use native RTP bridge as two channels are required [Dec 8 18:00:04] DEBUG[63046][C-00000001] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Dec 8 18:00:04] DEBUG[63046][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Dec 8 18:00:04] DEBUG[63046][C-00000001] bridge.c: Bridge technology softmix does not have any capabilities we want. [Dec 8 18:00:04] DEBUG[63046][C-00000001] bridge.c: Chose bridge technology simple_bridge [Dec 8 18:00:04] DEBUG[63044] manager.c: Examining AMI event: Event: BridgeEnter Privilege: call,all BridgeUniqueid: 95308782-5303-4090-8296-08b65686bfdc BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 1 BridgeVideoSourceMode: none Channel: PJSIP/ast150-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8000 CallerIDName: ConnectedLineNum: 8002 ConnectedLineName: 8002 Language: en AccountCode: Context: pjsip_context Exten: Priority: 1 Uniqueid: 1607450403.1 Linkedid: 1607450403.0 [Dec 8 18:00:04] DEBUG[63046][C-00000001] bridge.c: Bridge 95308782-5303-4090-8296-08b65686bfdc is already using the new technology. [Dec 8 18:00:04] DEBUG[63046][C-00000001] bridge.c: Bridge 95308782-5303-4090-8296-08b65686bfdc: 0x7f8b4c0459a0(PJSIP/ast150-00000001) is joining simple_bridge technology [Dec 8 18:00:04] DEBUG[63046][C-00000001] chan_pjsip.c: PJSIP/ast150-00000001: Indicated Media SSRC change [Dec 8 18:00:04] DEBUG[63046][C-00000001] chan_pjsip.c: PJSIP/ast150-00000001 [Dec 8 18:00:04] DEBUG[63046][C-00000001] channel.c: Dropping duplicate answer! [Dec 8 18:00:04] DEBUG[63045][C-00000001] bridge_channel.c: Bridge 95308782-5303-4090-8296-08b65686bfdc: 0x7f8b4c045fd0(PJSIP/8002-00000000) is joining [Dec 8 18:00:04] DEBUG[63045][C-00000001] bridge_channel.c: Bridge 95308782-5303-4090-8296-08b65686bfdc: pushing 0x7f8b4c045fd0(PJSIP/8002-00000000) [Dec 8 18:00:04] VERBOSE[63045][C-00000001] bridge_channel.c: Channel PJSIP/8002-00000000 joined 'simple_bridge' basic-bridge <95308782-5303-4090-8296-08b65686bfdc> [Dec 8 18:00:04] DEBUG[63045][C-00000001] bridge_native_rtp.c: Bridge '95308782-5303-4090-8296-08b65686bfdc'. Checking compatability for channels 'PJSIP/ast150-00000001' and 'PJSIP/8002-00000000' [Dec 8 18:00:04] DEBUG[62983] cdr.c: Finalized CDR for PJSIP/ast150-00000001 - start 1607450403.372435 answer 1607450404.380093 end 1607450404.383393 dur 1.010 bill 0.003 dispo ANSWERED [Dec 8 18:00:04] DEBUG[63045][C-00000001] bridge_native_rtp.c: Symmetric ptimes on the two call legs (0). May be able to native bridge in RTP [Dec 8 18:00:04] DEBUG[63045][C-00000001] bridge_native_rtp.c: Bridge '95308782-5303-4090-8296-08b65686bfdc': Packetization comparison success between RTP streams (read_ptime0:20 == write_ptime1:20 and read_ptime1:20 == write_ptime0:20). [Dec 8 18:00:04] DEBUG[63045][C-00000001] bridge.c: Bridge technology simple_bridge has less preference than native_rtp (50 <= 90). Skipping. [Dec 8 18:00:04] DEBUG[63045][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Dec 8 18:00:04] DEBUG[63045][C-00000001] bridge.c: Bridge technology softmix does not have any capabilities we want. [Dec 8 18:00:04] DEBUG[63045][C-00000001] bridge.c: Chose bridge technology native_rtp [Dec 8 18:00:04] VERBOSE[63045][C-00000001] bridge.c: Bridge 95308782-5303-4090-8296-08b65686bfdc: switching from simple_bridge technology to native_rtp [Dec 8 18:00:04] DEBUG[63044] manager.c: Examining AMI event: Event: BridgeEnter Privilege: call,all BridgeUniqueid: 95308782-5303-4090-8296-08b65686bfdc BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 2 BridgeVideoSourceMode: none Channel: PJSIP/8002-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8002 CallerIDName: 8002 ConnectedLineNum: 8000 ConnectedLineName: Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.0 Linkedid: 1607450403.0 [Dec 8 18:00:04] DEBUG[63045][C-00000001] bridge.c: Bridge 95308782-5303-4090-8296-08b65686bfdc: calling native_rtp technology constructor [Dec 8 18:00:04] DEBUG[63045][C-00000001] bridge.c: Bridge 95308782-5303-4090-8296-08b65686bfdc: moving 0x7f8b4c0459a0(PJSIP/ast150-00000001) to dummy bridge temporarily [Dec 8 18:00:04] DEBUG[63045][C-00000001] bridge.c: Bridge 95308782-5303-4090-8296-08b65686bfdc: 0x7f8b4c0459a0(PJSIP/ast150-00000001) is leaving simple_bridge technology (dummy) [Dec 8 18:00:04] DEBUG[63045][C-00000001] bridge.c: Bridge 95308782-5303-4090-8296-08b65686bfdc: calling simple_bridge technology stop [Dec 8 18:00:04] DEBUG[63045][C-00000001] bridge.c: Bridge 95308782-5303-4090-8296-08b65686bfdc: 0x7f8b4c045fd0(PJSIP/8002-00000000) is joining native_rtp technology [Dec 8 18:00:04] DEBUG[63045][C-00000001] bridge_native_rtp.c: Bridge '95308782-5303-4090-8296-08b65686bfdc'. Channel 'PJSIP/8002-00000000' is joining bridge tech [Dec 8 18:00:04] DEBUG[63045][C-00000001] bridge_native_rtp.c: Bridge '95308782-5303-4090-8296-08b65686bfdc'. Attaching hook data 0x55e9b008e8a0 to 'PJSIP/8002-00000000' [Dec 8 18:00:04] DEBUG[63045][C-00000001] channel.c: PJSIP/ast150-00000001: Topologies already match. Current: <0:audio-0:audio:sendrecv (ulaw|alaw|gsm|g726|g726aal2|adpcm|g722)> Requested: <0:audio-0:audio:sendrecv (ulaw|alaw|gsm|g726|g726aal2|adpcm|g722)> [Dec 8 18:00:04] DEBUG[63045][C-00000001] channel.c: PJSIP/ast150-00000001: Topologies already match. Current: <0:audio-0:audio:sendrecv (ulaw|alaw|gsm|g726|g726aal2|adpcm|g722)> Requested: <0:audio-0:audio:sendrecv (ulaw|alaw|gsm|g726|g726aal2|adpcm|g722)> [Dec 8 18:00:04] DEBUG[63045][C-00000001] bridge.c: Bridge 95308782-5303-4090-8296-08b65686bfdc: 0x7f8b4c0459a0(PJSIP/ast150-00000001) is joining native_rtp technology [Dec 8 18:00:04] DEBUG[63045][C-00000001] bridge_native_rtp.c: Bridge '95308782-5303-4090-8296-08b65686bfdc'. Channel 'PJSIP/ast150-00000001' is joining bridge tech [Dec 8 18:00:04] DEBUG[63045][C-00000001] bridge_native_rtp.c: Bridge '95308782-5303-4090-8296-08b65686bfdc'. Attaching hook data 0x55e9b01f2c90 to 'PJSIP/ast150-00000001' [Dec 8 18:00:04] DEBUG[63045][C-00000001] channel.c: PJSIP/ast150-00000001: Topologies already match. Current: <0:audio-0:audio:sendrecv (ulaw|alaw|gsm|g726|g726aal2|adpcm|g722)> Requested: <0:audio-0:audio:sendrecv (ulaw|alaw|gsm|g726|g726aal2|adpcm|g722)> [Dec 8 18:00:04] DEBUG[63045][C-00000001] bridge_native_rtp.c: Bridge '95308782-5303-4090-8296-08b65686bfdc'. Tech starting 'PJSIP/8002-00000000' and 'PJSIP/ast150-00000001' with target 'none' [Dec 8 18:00:04] VERBOSE[63045][C-00000001] bridge_native_rtp.c: Locally RTP bridged 'PJSIP/8002-00000000' and 'PJSIP/ast150-00000001' in stack [Dec 8 18:00:04] DEBUG[63045][C-00000001] channel.c: PJSIP/8002-00000000: Topologies already match. Current: <0:audio-0:audio:sendrecv (ulaw|alaw|g726)> Requested: <0:audio-0:audio:sendrecv (ulaw|alaw|g726)> [Dec 8 18:00:04] DEBUG[63045][C-00000001] bridge.c: Bridge 95308782-5303-4090-8296-08b65686bfdc: calling native_rtp technology start [Dec 8 18:00:04] DEBUG[63045][C-00000001] bridge.c: Bridge 95308782-5303-4090-8296-08b65686bfdc: calling simple_bridge technology destructor [Dec 8 18:00:04] DEBUG[63044] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/8002-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8002 CallerIDName: 8002 ConnectedLineNum: 8000 ConnectedLineName: Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.0 Linkedid: 1607450403.0 Variable: BRIDGEPEER Value: PJSIP/ast150-00000001 [Dec 8 18:00:04] DEBUG[63044] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/8002-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8002 CallerIDName: 8002 ConnectedLineNum: 8000 ConnectedLineName: Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.0 Linkedid: 1607450403.0 Variable: BRIDGEPVTCALLID Value: 6e75a4f3-db8f-4b65-961f-8490edad3d7a [Dec 8 18:00:04] DEBUG[63044] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/ast150-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8000 CallerIDName: ConnectedLineNum: 8002 ConnectedLineName: 8002 Language: en AccountCode: Context: pjsip_context Exten: Priority: 1 Uniqueid: 1607450403.1 Linkedid: 1607450403.0 Variable: BRIDGEPEER Value: PJSIP/8002-00000000 [Dec 8 18:00:04] DEBUG[63044] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/ast150-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8000 CallerIDName: ConnectedLineNum: 8002 ConnectedLineName: 8002 Language: en AccountCode: Context: pjsip_context Exten: Priority: 1 Uniqueid: 1607450403.1 Linkedid: 1607450403.0 Variable: BRIDGEPVTCALLID Value: fc714988-3bb17a02@10.9.9.132 [Dec 8 18:00:04] DEBUG[63045][C-00000001] chan_pjsip.c: PJSIP/8002-00000000: Indicated Media SSRC change [Dec 8 18:00:04] DEBUG[63045][C-00000001] chan_pjsip.c: PJSIP/8002-00000000 [Dec 8 18:00:04] DEBUG[63046][C-00000001] bridge_native_rtp.c: Bridge '95308782-5303-4090-8296-08b65686bfdc'. Checking compatability for channels 'PJSIP/8002-00000000' and 'PJSIP/ast150-00000001' [Dec 8 18:00:04] DEBUG[63046][C-00000001] bridge_native_rtp.c: Symmetric ptimes on the two call legs (0). May be able to native bridge in RTP [Dec 8 18:00:04] DEBUG[63046][C-00000001] bridge_native_rtp.c: Bridge '95308782-5303-4090-8296-08b65686bfdc': Packetization comparison success between RTP streams (read_ptime0:20 == write_ptime1:20 and read_ptime1:20 == write_ptime0:20). [Dec 8 18:00:04] DEBUG[63046][C-00000001] bridge.c: Bridge technology simple_bridge has less preference than native_rtp (50 <= 90). Skipping. [Dec 8 18:00:04] DEBUG[63046][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Dec 8 18:00:04] DEBUG[63046][C-00000001] bridge.c: Bridge technology softmix does not have any capabilities we want. [Dec 8 18:00:04] DEBUG[63046][C-00000001] bridge.c: Chose bridge technology native_rtp [Dec 8 18:00:04] DEBUG[63046][C-00000001] bridge.c: Bridge 95308782-5303-4090-8296-08b65686bfdc is already using the new technology. [Dec 8 18:00:04] DEBUG[63045][C-00000001] bridge_native_rtp.c: Bridge '95308782-5303-4090-8296-08b65686bfdc'. Checking compatability for channels 'PJSIP/8002-00000000' and 'PJSIP/ast150-00000001' [Dec 8 18:00:04] DEBUG[63045][C-00000001] bridge_native_rtp.c: Symmetric ptimes on the two call legs (0). May be able to native bridge in RTP [Dec 8 18:00:04] DEBUG[63045][C-00000001] bridge_native_rtp.c: Bridge '95308782-5303-4090-8296-08b65686bfdc': Packetization comparison success between RTP streams (read_ptime0:20 == write_ptime1:20 and read_ptime1:20 == write_ptime0:20). [Dec 8 18:00:04] DEBUG[63045][C-00000001] bridge.c: Bridge technology simple_bridge has less preference than native_rtp (50 <= 90). Skipping. [Dec 8 18:00:04] DEBUG[63045][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Dec 8 18:00:04] DEBUG[63044] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/8002-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8002 CallerIDName: 8002 ConnectedLineNum: 8000 ConnectedLineName: Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.0 Linkedid: 1607450403.0 Variable: BRIDGEPEER Value: PJSIP/ast150-00000001 [Dec 8 18:00:04] DEBUG[63045][C-00000001] bridge.c: Bridge technology softmix does not have any capabilities we want. [Dec 8 18:00:04] DEBUG[63045][C-00000001] bridge.c: Chose bridge technology native_rtp [Dec 8 18:00:04] DEBUG[63045][C-00000001] bridge.c: Bridge 95308782-5303-4090-8296-08b65686bfdc is already using the new technology. [Dec 8 18:00:04] DEBUG[63044] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/8002-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8002 CallerIDName: 8002 ConnectedLineNum: 8000 ConnectedLineName: Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.0 Linkedid: 1607450403.0 Variable: BRIDGEPVTCALLID Value: 6e75a4f3-db8f-4b65-961f-8490edad3d7a [Dec 8 18:00:04] DEBUG[63044] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/ast150-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8000 CallerIDName: ConnectedLineNum: 8002 ConnectedLineName: 8002 Language: en AccountCode: Context: pjsip_context Exten: Priority: 1 Uniqueid: 1607450403.1 Linkedid: 1607450403.0 Variable: BRIDGEPEER Value: PJSIP/8002-00000000 [Dec 8 18:00:04] DEBUG[63044] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/ast150-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8000 CallerIDName: ConnectedLineNum: 8002 ConnectedLineName: 8002 Language: en AccountCode: Context: pjsip_context Exten: Priority: 1 Uniqueid: 1607450403.1 Linkedid: 1607450403.0 Variable: BRIDGEPVTCALLID Value: fc714988-3bb17a02@10.9.9.132 [Dec 8 18:00:04] DEBUG[63044] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/8002-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8002 CallerIDName: 8002 ConnectedLineNum: 8000 ConnectedLineName: Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.0 Linkedid: 1607450403.0 Variable: BRIDGEPEER Value: PJSIP/ast150-00000001 [Dec 8 18:00:04] DEBUG[63044] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/8002-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8002 CallerIDName: 8002 ConnectedLineNum: 8000 ConnectedLineName: Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.0 Linkedid: 1607450403.0 Variable: BRIDGEPVTCALLID Value: 6e75a4f3-db8f-4b65-961f-8490edad3d7a [Dec 8 18:00:04] DEBUG[63044] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/ast150-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8000 CallerIDName: ConnectedLineNum: 8002 ConnectedLineName: 8002 Language: en AccountCode: Context: pjsip_context Exten: Priority: 1 Uniqueid: 1607450403.1 Linkedid: 1607450403.0 Variable: BRIDGEPEER Value: PJSIP/8002-00000000 [Dec 8 18:00:04] DEBUG[63044] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/ast150-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8000 CallerIDName: ConnectedLineNum: 8002 ConnectedLineName: 8002 Language: en AccountCode: Context: pjsip_context Exten: Priority: 1 Uniqueid: 1607450403.1 Linkedid: 1607450403.0 Variable: BRIDGEPVTCALLID Value: fc714988-3bb17a02@10.9.9.132 [Dec 8 18:00:04] VERBOSE[62990] res_pjsip_logger.c: <--- Received SIP request (392 bytes) from UDP:10.9.9.132:5063 ---> ACK sip:10.9.9.151:5061 SIP/2.0 Via: SIP/2.0/UDP 10.9.9.132:5063;branch=z9hG4bK-e6eec68f From: "8002" ;tag=f1b573d0566e145ao3 To: ;tag=966cecfc-6009-4b76-8883-5803f77d0db4 Call-ID: fc714988-3bb17a02@10.9.9.132 CSeq: 101 ACK Max-Forwards: 70 Contact: "8002" User-Agent: Linksys/SPA942-6.1.5(a) Content-Length: 0 [Dec 8 18:00:04] DEBUG[62990] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f8b08003658 for Request msg ACK/cseq=101 (rdata0x7f8b50080368) [Dec 8 18:00:04] DEBUG[62990] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-0000002e associated with dialog dlg0x7f8b08003658 [Dec 8 18:00:04] DEBUG[62991] res_pjsip_session.c: PJSIP/8002-00000000: Received request [Dec 8 18:00:04] DEBUG[62991] res_pjsip_session.c: PJSIP/8002-00000000: Method is ACK [Dec 8 18:00:04] DEBUG[62991] chan_pjsip.c: PJSIP/8002-00000000 [Dec 8 18:00:04] DEBUG[62991] chan_pjsip.c: PJSIP/8002-00000000 [Dec 8 18:00:04] DEBUG[62991] res_pjsip_session.c: PJSIP/8002-00000000 [Dec 8 18:00:04] VERBOSE[63045][C-00000001] res_rtp_asterisk.c: 0x7f8b08033300 -- Strict RTP switching to RTP target address 10.9.9.132:16458 as source [Dec 8 18:00:04] VERBOSE[63046][C-00000001] res_rtp_asterisk.c: 0x7f8b0806a4f0 -- Strict RTP switching to RTP target address 10.9.9.150:19722 as source [Dec 8 18:00:09] VERBOSE[63046][C-00000001] res_rtp_asterisk.c: 0x7f8b0806a4f0 -- Strict RTP learning complete - Locking on source address 10.9.9.150:19722 [Dec 8 18:00:09] VERBOSE[63045][C-00000001] res_rtp_asterisk.c: 0x7f8b08033300 -- Strict RTP learning complete - Locking on source address 10.9.9.132:16458 [Dec 8 18:00:09] DEBUG[63046][C-00000001] res_rtp_asterisk.c: (0x7f8b08069260) RTCP got report of 100 bytes from 10.9.9.150:19723 [Dec 8 18:00:11] DEBUG[62967] threadpool.c: Worker thread idle timeout reached. Dying. [Dec 8 18:00:11] DEBUG[62968] threadpool.c: Worker thread idle timeout reached. Dying. [Dec 8 18:00:11] DEBUG[62969] threadpool.c: Worker thread idle timeout reached. Dying. [Dec 8 18:00:11] DEBUG[62963] threadpool.c: Destroying worker thread 2 [Dec 8 18:00:11] DEBUG[62963] threadpool.c: Destroying worker thread 3 [Dec 8 18:00:11] DEBUG[62963] threadpool.c: Destroying worker thread 4 [Dec 8 18:00:12] DEBUG[62964] threadpool.c: Worker thread idle timeout reached. Dying. [Dec 8 18:00:12] DEBUG[62963] threadpool.c: Destroying worker thread 0 [Dec 8 18:00:12] DEBUG[62966] threadpool.c: Worker thread idle timeout reached. Dying. [Dec 8 18:00:12] DEBUG[62963] threadpool.c: Destroying worker thread 1 [Dec 8 18:00:14] DEBUG[63044] manager.c: Running action 'Redirect' [Dec 8 18:00:14] DEBUG[63044] channel.c: Soft-Hanging (0x02) up channel 'PJSIP/ast150-00000001' [Dec 8 18:00:14] DEBUG[63046][C-00000001] bridge_channel.c: Setting 0x7f8b4c0459a0(PJSIP/ast150-00000001) state from:0 to:1 [Dec 8 18:00:14] DEBUG[63046][C-00000001] bridge_channel.c: Bridge 95308782-5303-4090-8296-08b65686bfdc: pulling 0x7f8b4c0459a0(PJSIP/ast150-00000001) [Dec 8 18:00:14] VERBOSE[63046][C-00000001] bridge_channel.c: Channel PJSIP/ast150-00000001 left 'native_rtp' basic-bridge <95308782-5303-4090-8296-08b65686bfdc> [Dec 8 18:00:14] DEBUG[63046][C-00000001] bridge_channel.c: Bridge 95308782-5303-4090-8296-08b65686bfdc: 0x7f8b4c0459a0(PJSIP/ast150-00000001) is leaving native_rtp technology [Dec 8 18:00:14] DEBUG[63046][C-00000001] bridge_native_rtp.c: Bridge '95308782-5303-4090-8296-08b65686bfdc'. Channel 'PJSIP/ast150-00000001' is leaving bridge tech [Dec 8 18:00:14] DEBUG[63046][C-00000001] bridge_native_rtp.c: Bridge '95308782-5303-4090-8296-08b65686bfdc'. Detaching hook data 0x55e9b0201688 from 'PJSIP/ast150-00000001' [Dec 8 18:00:14] DEBUG[63046][C-00000001] bridge_native_rtp.c: Bridge '95308782-5303-4090-8296-08b65686bfdc'. Tech stopping 'PJSIP/8002-00000000' and 'PJSIP/ast150-00000001' with target 'none' [Dec 8 18:00:14] DEBUG[63046][C-00000001] bridge_native_rtp.c: Discontinued RTP bridging of 'PJSIP/8002-00000000' and 'PJSIP/ast150-00000001' - media will flow through Asterisk core [Dec 8 18:00:14] DEBUG[63046][C-00000001] bridge_native_rtp.c: Destroying channel tech_pvt data 0x55e9b01f2c90 [Dec 8 18:00:14] DEBUG[63046][C-00000001] bridge.c: Bridge 95308782-5303-4090-8296-08b65686bfdc: dissolving bridge with cause 16(Normal Clearing) [Dec 8 18:00:14] DEBUG[63046][C-00000001] bridge_channel.c: Setting 0x7f8b4c045fd0(PJSIP/8002-00000000) state from:0 to:2 [Dec 8 18:00:14] DEBUG[63046][C-00000001] bridge.c: Bridge 95308782-5303-4090-8296-08b65686bfdc: queueing action type:13 sub:1001 [Dec 8 18:00:14] DEBUG[63046][C-00000001] bridge_channel.c: Channel PJSIP/ast150-00000001 will survive this bridge; clearing outgoing (dialed) flag [Dec 8 18:00:14] DEBUG[63046][C-00000001] bridge.c: Bridge 95308782-5303-4090-8296-08b65686bfdc is dissolved, not performing smart bridge operation. [Dec 8 18:00:14] DEBUG[63046][C-00000001] chan_pjsip.c: PJSIP/ast150-00000001: Indicated Media SSRC change [Dec 8 18:00:14] DEBUG[63046][C-00000001] chan_pjsip.c: PJSIP/ast150-00000001 [Dec 8 18:00:14] DEBUG[62983] cdr.c: Finalized CDR for PJSIP/8002-00000000 - start 1607450403.370607 answer 1607450404.380992 end 1607450414.045039 dur 10.674 bill 9.664 dispo ANSWERED [Dec 8 18:00:14] DEBUG[63046][C-00000001] pbx.c: Launching 'Transfer' [Dec 8 18:00:14] VERBOSE[63046][C-00000001] pbx.c: Executing [6000@pjsip_context:1] Transfer("PJSIP/ast150-00000001", "PJSIP/sip:8001@ast150") in new stack [Dec 8 18:00:14] DEBUG[63045][C-00000001] bridge_channel.c: Bridge 95308782-5303-4090-8296-08b65686bfdc: pulling 0x7f8b4c045fd0(PJSIP/8002-00000000) [Dec 8 18:00:14] VERBOSE[63045][C-00000001] bridge_channel.c: Channel PJSIP/8002-00000000 left 'native_rtp' basic-bridge <95308782-5303-4090-8296-08b65686bfdc> [Dec 8 18:00:14] DEBUG[63045][C-00000001] bridge_channel.c: Bridge 95308782-5303-4090-8296-08b65686bfdc: 0x7f8b4c045fd0(PJSIP/8002-00000000) is leaving native_rtp technology [Dec 8 18:00:14] DEBUG[63044] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/ast150-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8000 CallerIDName: ConnectedLineNum: 8002 ConnectedLineName: 8002 Language: en AccountCode: Context: pjsip_context Exten: Priority: 1 Uniqueid: 1607450403.1 Linkedid: 1607450403.0 Variable: BRIDGEPEER Value: [Dec 8 18:00:14] DEBUG[63044] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/ast150-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8000 CallerIDName: ConnectedLineNum: 8002 ConnectedLineName: 8002 Language: en AccountCode: Context: pjsip_context Exten: Priority: 1 Uniqueid: 1607450403.1 Linkedid: 1607450403.0 Variable: BRIDGEPVTCALLID Value: [Dec 8 18:00:14] DEBUG[63044] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/ast150-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8000 CallerIDName: ConnectedLineNum: 8002 ConnectedLineName: 8002 Language: en AccountCode: Context: pjsip_context Exten: 6000 Priority: 1 Uniqueid: 1607450403.1 Linkedid: 1607450403.0 Extension: 6000 Application: AppDial AppData: (Outgoing Line) [Dec 8 18:00:14] DEBUG[63044] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/8002-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8002 CallerIDName: 8002 ConnectedLineNum: 8000 ConnectedLineName: Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.0 Linkedid: 1607450403.0 Variable: BRIDGEPEER Value: [Dec 8 18:00:14] DEBUG[63044] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/8002-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8002 CallerIDName: 8002 ConnectedLineNum: 8000 ConnectedLineName: Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.0 Linkedid: 1607450403.0 Variable: BRIDGEPVTCALLID Value: [Dec 8 18:00:14] DEBUG[63044] manager.c: Examining AMI event: Event: BridgeLeave Privilege: call,all BridgeUniqueid: 95308782-5303-4090-8296-08b65686bfdc BridgeType: basic BridgeTechnology: native_rtp BridgeCreator: BridgeName: BridgeNumChannels: 1 BridgeVideoSourceMode: none Channel: PJSIP/ast150-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8000 CallerIDName: ConnectedLineNum: 8002 ConnectedLineName: 8002 Language: en AccountCode: Context: pjsip_context Exten: 6000 Priority: 1 Uniqueid: 1607450403.1 Linkedid: 1607450403.0 [Dec 8 18:00:14] DEBUG[62991] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '10.9.9.151' [Dec 8 18:00:14] DEBUG[62991] res_pjsip/pjsip_resolver.c: Transport type for target '10.9.9.151' is 'UDP transport' [Dec 8 18:00:14] DEBUG[62991] res_pjsip/pjsip_resolver.c: Target '10.9.9.151' is an IP address, skipping resolution [Dec 8 18:00:14] VERBOSE[62991] res_pjsip_logger.c: <--- Transmitting SIP request (764 bytes) to UDP:10.9.9.151:5060 ---> REFER sip:10.9.9.150:5061 SIP/2.0 Via: SIP/2.0/UDP 10.9.9.151:5061;rport;branch=z9hG4bKPj413e4068-97d1-4e71-880c-c9eeafd27b7a From: "8002" ;tag=e40f373c-93f5-45ec-bf6b-e16978266a05 To: ;tag=60d365bd-0fc2-4c29-b82f-3c63962e47b1 Contact: Call-ID: 6e75a4f3-db8f-4b65-961f-8490edad3d7a CSeq: 8857 REFER Route: Event: refer Expires: 120 Supported: 100rel, timer, replaces, norefersub Accept: message/sipfrag;version=2.0 Allow-Events: message-summary, presence, dialog, refer Refer-To: sip:8001@ast150 Referred-By: Max-Forwards: 70 User-Agent: Asterisk PBX 16.15.0 Content-Length: 0 [Dec 8 18:00:14] DEBUG[62991] pjproject: evsub0x7f8b08010ce8 ....Subscription state changed NULL --> SENT [Dec 8 18:00:14] DEBUG[63045][C-00000001] bridge_native_rtp.c: Bridge '95308782-5303-4090-8296-08b65686bfdc'. Channel 'PJSIP/8002-00000000' is leaving bridge tech [Dec 8 18:00:14] DEBUG[63045][C-00000001] bridge_native_rtp.c: Bridge '95308782-5303-4090-8296-08b65686bfdc'. Detaching hook data 0x7f8b00002ea8 from 'PJSIP/8002-00000000' [Dec 8 18:00:14] DEBUG[63045][C-00000001] bridge_native_rtp.c: Destroying channel tech_pvt data 0x55e9b008e8a0 [Dec 8 18:00:14] DEBUG[63044] manager.c: Examining AMI event: Event: BridgeLeave Privilege: call,all BridgeUniqueid: 95308782-5303-4090-8296-08b65686bfdc BridgeType: basic BridgeTechnology: native_rtp BridgeCreator: BridgeName: BridgeNumChannels: 0 BridgeVideoSourceMode: none Channel: PJSIP/8002-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8002 CallerIDName: 8002 ConnectedLineNum: 8000 ConnectedLineName: Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.0 Linkedid: 1607450403.0 [Dec 8 18:00:14] DEBUG[63045][C-00000001] bridge.c: Bridge 95308782-5303-4090-8296-08b65686bfdc is dissolved, not performing smart bridge operation. [Dec 8 18:00:14] DEBUG[63045][C-00000001] chan_pjsip.c: PJSIP/8002-00000000: Indicated Media SSRC change [Dec 8 18:00:14] DEBUG[63045][C-00000001] chan_pjsip.c: PJSIP/8002-00000000 [Dec 8 18:00:14] DEBUG[63045][C-00000001] bridge.c: Bridge 95308782-5303-4090-8296-08b65686bfdc: actually destroying basic bridge, nobody wants it anymore [Dec 8 18:00:14] DEBUG[63044] manager.c: Examining AMI event: Event: BridgeDestroy Privilege: call,all BridgeUniqueid: 95308782-5303-4090-8296-08b65686bfdc BridgeType: basic BridgeTechnology: native_rtp BridgeCreator: BridgeName: BridgeNumChannels: 0 BridgeVideoSourceMode: none [Dec 8 18:00:14] DEBUG[63045][C-00000001] bridge.c: Bridge 95308782-5303-4090-8296-08b65686bfdc: calling basic bridge destructor [Dec 8 18:00:14] DEBUG[63045][C-00000001] bridge.c: Bridge 95308782-5303-4090-8296-08b65686bfdc: calling native_rtp technology stop [Dec 8 18:00:14] DEBUG[63045][C-00000001] bridge.c: Bridge 95308782-5303-4090-8296-08b65686bfdc: calling native_rtp technology destructor [Dec 8 18:00:14] DEBUG[63045][C-00000001] stasis.c: Destroying topic. name: cache:9/bridge:95308782-5303-4090-8296-08b65686bfdc, detail: [Dec 8 18:00:14] DEBUG[63045][C-00000001] stasis.c: Topic 'cache:9/bridge:95308782-5303-4090-8296-08b65686bfdc': 0x55e9b0249160 destroyed [Dec 8 18:00:14] DEBUG[63045][C-00000001] stasis.c: Destroying topic. name: bridge:95308782-5303-4090-8296-08b65686bfdc, detail: [Dec 8 18:00:14] DEBUG[63045][C-00000001] stasis.c: Topic 'bridge:95308782-5303-4090-8296-08b65686bfdc': 0x55e9b0247220 destroyed [Dec 8 18:00:14] DEBUG[63045][C-00000001] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Dec 8 18:00:14] DEBUG[63045][C-00000001] pbx.c: Spawn extension (pjsip_context,8000,1) exited non-zero on 'PJSIP/8002-00000000' [Dec 8 18:00:14] VERBOSE[63045][C-00000001] pbx.c: Spawn extension (pjsip_context, 8000, 1) exited non-zero on 'PJSIP/8002-00000000' [Dec 8 18:00:14] DEBUG[63045][C-00000001] channel.c: Soft-Hanging (0x10) up channel 'PJSIP/8002-00000000' [Dec 8 18:00:14] DEBUG[63045][C-00000001] channel.c: Channel 0x7f8b08052a10 'PJSIP/8002-00000000' hanging up. Refs: 2 [Dec 8 18:00:14] DEBUG[63045][C-00000001] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP) [Dec 8 18:00:14] DEBUG[62991] res_rtp_asterisk.c: (0x7f8b08032090) DTLS srtp - stopped timeout timer' [Dec 8 18:00:14] DEBUG[62991] res_rtp_asterisk.c: (0x7f8b08032090) DTLS srtp - stopped timeout timer' [Dec 8 18:00:14] DEBUG[62991] res_rtp_asterisk.c: (0x7f8b08032090) DTLS stop [Dec 8 18:00:14] DEBUG[62991] res_rtp_asterisk.c: (0x7f8b08032090) DTLS srtp - stopped timeout timer' [Dec 8 18:00:14] DEBUG[62991] res_rtp_asterisk.c: (0x7f8b08032090) DTLS srtp - stopped timeout timer' [Dec 8 18:00:14] DEBUG[62991] res_rtp_asterisk.c: (0x7f8b08032090) ICE RTP transport deallocating [Dec 8 18:00:14] DEBUG[62991] rtp_engine.c: Destroyed RTP instance '0x7f8b08032090' [Dec 8 18:00:14] DEBUG[62991] res_pjsip_session.c: PJSIP/8002-00000000: Method is BYE [Dec 8 18:00:14] DEBUG[62991] res_pjsip_session.c: PJSIP/8002-00000000 [Dec 8 18:00:14] DEBUG[62991] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '10.9.9.132' [Dec 8 18:00:14] DEBUG[62991] res_pjsip/pjsip_resolver.c: Transport type for target '10.9.9.132' is 'UDP transport' [Dec 8 18:00:14] DEBUG[62991] res_pjsip/pjsip_resolver.c: Target '10.9.9.132' is an IP address, skipping resolution [Dec 8 18:00:14] VERBOSE[62991] res_pjsip_logger.c: <--- Transmitting SIP request (411 bytes) to UDP:10.9.9.132:5063 ---> BYE sip:8002@10.9.9.132:5063 SIP/2.0 Via: SIP/2.0/UDP 10.9.9.151:5061;rport;branch=z9hG4bKPj8fec5ab2-696a-41cb-824d-8fdb36ece6fe From: ;tag=966cecfc-6009-4b76-8883-5803f77d0db4 To: "8002" ;tag=f1b573d0566e145ao3 Call-ID: fc714988-3bb17a02@10.9.9.132 CSeq: 5626 BYE Reason: Q.850;cause=16 Max-Forwards: 70 User-Agent: Asterisk PBX 16.15.0 Content-Length: 0 [Dec 8 18:00:14] DEBUG[62991] channel.c: Channel 0x7f8b08052a10 'PJSIP/8002-00000000' destroying [Dec 8 18:00:14] DEBUG[62963] threadpool.c: Increasing threadpool stasis/pool's size by 1 [Dec 8 18:00:14] DEBUG[62991] stasis.c: Destroying topic. name: cache:7/channel:1607450403.0, detail: [Dec 8 18:00:14] DEBUG[62991] stasis.c: Topic 'cache:7/channel:1607450403.0': 0x55e9b024cf90 destroyed [Dec 8 18:00:14] DEBUG[62991] stasis.c: Destroying topic. name: channel:1607450403.0, detail: [Dec 8 18:00:14] VERBOSE[62990] res_pjsip_logger.c: <--- Received SIP response (683 bytes) from UDP:10.9.9.151:5060 ---> SIP/2.0 202 Accepted Via: SIP/2.0/UDP 10.9.9.151:5061;rport=5061;received=10.9.9.151;branch=z9hG4bKPj413e4068-97d1-4e71-880c-c9eeafd27b7a Record-Route: Call-ID: 6e75a4f3-db8f-4b65-961f-8490edad3d7a From: "8002" ;tag=e40f373c-93f5-45ec-bf6b-e16978266a05 To: ;tag=60d365bd-0fc2-4c29-b82f-3c63962e47b1 CSeq: 8857 REFER Expires: 120 Contact: Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER Supported: 100rel, timer, replaces, norefersub Server: Asterisk PBX 16.7.0 Content-Length: 0 [Dec 8 18:00:14] DEBUG[62991] stasis.c: Topic 'channel:1607450403.0': 0x55e9b024d750 destroyed [Dec 8 18:00:14] DEBUG[62990] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f8b0805ec18 for Response msg 202/REFER/cseq=8857 (rdata0x7f8b500a3e98) [Dec 8 18:00:14] DEBUG[62990] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/ast150-0000005f associated with dialog dlg0x7f8b0805ec18 [Dec 8 18:00:14] DEBUG[62975] devicestate.c: No provider found, checking channel drivers for PJSIP - 8002 [Dec 8 18:00:14] DEBUG[62975] devicestate.c: Changing state for PJSIP/8002 - state 1 (Not in use) [Dec 8 18:00:14] DEBUG[62983] stasis.c: Creating topic. name: channel:1607450414.2, detail: [Dec 8 18:00:14] DEBUG[62983] stasis.c: Topic 'channel:1607450414.2': 0x55e9b024c220 created [Dec 8 18:00:14] DEBUG[62983] stasis.c: Creating topic. name: cache:10/channel:1607450414.2, detail: [Dec 8 18:00:14] DEBUG[62983] stasis.c: Topic 'cache:10/channel:1607450414.2': 0x7f8b24006640 created [Dec 8 18:00:14] DEBUG[62983] stasis.c: Destroying topic. name: cache:10/channel:1607450414.2, detail: [Dec 8 18:00:14] DEBUG[62983] stasis.c: Topic 'cache:10/channel:1607450414.2': 0x7f8b24006640 destroyed [Dec 8 18:00:14] DEBUG[62983] stasis.c: Destroying topic. name: channel:1607450414.2, detail: [Dec 8 18:00:14] DEBUG[62983] stasis.c: Topic 'channel:1607450414.2': 0x55e9b024c220 destroyed [Dec 8 18:00:14] DEBUG[62992] res_pjsip_session.c: PJSIP/ast150-00000001: Response is 202 Accepted [Dec 8 18:00:14] DEBUG[62992] res_pjsip_session.c: PJSIP/ast150-00000001 [Dec 8 18:00:14] DEBUG[62992] res_pjsip_session.c: PJSIP/ast150-00000001: REFER received final response code 202 [Dec 8 18:00:14] DEBUG[62992] pjproject: evsub0x7f8b08010ce8 ....Subscription state changed SENT --> ACCEPTED [Dec 8 18:00:14] DEBUG[62992] chan_pjsip.c: Transfer accepted on channel PJSIP/ast150-00000001 [Dec 8 18:00:14] DEBUG[63044] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/8002-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8002 CallerIDName: 8002 ConnectedLineNum: 8000 ConnectedLineName: Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.0 Linkedid: 1607450403.0 Variable: ANSWEREDTIME Value: 9 [Dec 8 18:00:14] DEBUG[63044] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/8002-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8002 CallerIDName: 8002 ConnectedLineNum: 8000 ConnectedLineName: Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.0 Linkedid: 1607450403.0 Variable: ANSWEREDTIME_MS Value: 9667 [Dec 8 18:00:14] DEBUG[63044] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/8002-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8002 CallerIDName: 8002 ConnectedLineNum: 8000 ConnectedLineName: Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.0 Linkedid: 1607450403.0 Variable: DIALEDTIME Value: 10 [Dec 8 18:00:14] DEBUG[63040] app_queue.c: Device 'PJSIP/8002' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Dec 8 18:00:14] DEBUG[63044] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/8002-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8002 CallerIDName: 8002 ConnectedLineNum: 8000 ConnectedLineName: Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.0 Linkedid: 1607450403.0 Variable: DIALEDTIME_MS Value: 10677 [Dec 8 18:00:14] DEBUG[63044] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/8002-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8002 CallerIDName: 8002 ConnectedLineNum: 8000 ConnectedLineName: Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.0 Linkedid: 1607450403.0 Variable: DIALSTATUS Value: ANSWER [Dec 8 18:00:14] DEBUG[63044] manager.c: Examining AMI event: Event: SoftHangupRequest Privilege: call,all Channel: PJSIP/8002-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8002 CallerIDName: 8002 ConnectedLineNum: 8000 ConnectedLineName: Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.0 Linkedid: 1607450403.0 Cause: 16 [Dec 8 18:00:14] DEBUG[63044] manager.c: Examining AMI event: Event: Hangup Privilege: call,all Channel: PJSIP/8002-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8002 CallerIDName: 8002 ConnectedLineNum: 8000 ConnectedLineName: Language: en AccountCode: Context: pjsip_context Exten: 8000 Priority: 1 Uniqueid: 1607450403.0 Linkedid: 1607450403.0 Cause: 16 Cause-txt: Normal Clearing [Dec 8 18:00:14] DEBUG[63044] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: PJSIP/8002 State: NOT_INUSE [Dec 8 18:00:14] VERBOSE[62990] res_pjsip_logger.c: <--- Received SIP response (339 bytes) from UDP:10.9.9.132:5063 ---> SIP/2.0 200 OK To: "8002" ;tag=f1b573d0566e145ao3 From: ;tag=966cecfc-6009-4b76-8883-5803f77d0db4 Call-ID: fc714988-3bb17a02@10.9.9.132 CSeq: 5626 BYE Via: SIP/2.0/UDP 10.9.9.151:5061;branch=z9hG4bKPj8fec5ab2-696a-41cb-824d-8fdb36ece6fe Server: Linksys/SPA942-6.1.5(a) Content-Length: 0 [Dec 8 18:00:14] DEBUG[62990] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f8b08003658 for Response msg 200/BYE/cseq=5626 (rdata0x7f8b500c5318) [Dec 8 18:00:14] DEBUG[62990] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-0000002e associated with dialog dlg0x7f8b08003658 [Dec 8 18:00:14] DEBUG[62991] res_pjsip_session.c: 8002: Source of transaction state change is RX_MSG [Dec 8 18:00:14] DEBUG[62991] res_pjsip_session.c: 8002: Received response [Dec 8 18:00:14] DEBUG[62991] res_pjsip_session.c: 8002: Response is 200 OK [Dec 8 18:00:14] DEBUG[62991] res_pjsip_session.c: 8002 [Dec 8 18:00:14] DEBUG[62991] res_pjsip_session.c: 8002: Response is 200 OK [Dec 8 18:00:14] DEBUG[62991] res_pjsip_session.c: 8002 [Dec 8 18:00:14] DEBUG[62991] res_pjsip_session.c: 8002: BYE received final response code 200 [Dec 8 18:00:14] VERBOSE[62990] res_pjsip_logger.c: <--- Received SIP request (886 bytes) from UDP:10.9.9.151:5060 ---> NOTIFY sip:asterisk@10.9.9.151:5061 SIP/2.0 Record-Route: Via: SIP/2.0/UDP 10.9.9.151;branch=z9hG4bK8aab.d9ba7ed410d323c7c05882b345b10f57.0 Via: SIP/2.0/UDP 10.9.9.150:5061;received=10.9.9.150;rport=5061;branch=z9hG4bKPj308451ee-17d7-4e28-9e42-883de4b5353c From: ;tag=60d365bd-0fc2-4c29-b82f-3c63962e47b1 To: "8002" ;tag=e40f373c-93f5-45ec-bf6b-e16978266a05 Contact: Call-ID: 6e75a4f3-db8f-4b65-961f-8490edad3d7a CSeq: 18147 NOTIFY Route: Event: refer Subscription-State: active;expires=119 Allow-Events: message-summary, presence, dialog, refer Max-Forwards: 69 User-Agent: Asterisk PBX 16.7.0 Content-Type: message/sipfrag;version=2.0 Content-Length: 20 SIP/2.0 100 Trying [Dec 8 18:00:14] DEBUG[62990] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f8b0805ec18 for Request msg NOTIFY/cseq=18147 (rdata0x7f8b500e6798) [Dec 8 18:00:14] DEBUG[62990] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/ast150-0000005f associated with dialog dlg0x7f8b0805ec18 [Dec 8 18:00:14] DEBUG[62991] res_pjsip_session.c: PJSIP/ast150-00000001: Method is NOTIFY [Dec 8 18:00:14] DEBUG[62991] res_pjsip_session.c: PJSIP/ast150-00000001 [Dec 8 18:00:14] VERBOSE[62991] res_pjsip_logger.c: <--- Transmitting SIP response (789 bytes) to UDP:10.9.9.151:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.9.9.151;rport=5060;received=10.9.9.151;branch=z9hG4bK8aab.d9ba7ed410d323c7c05882b345b10f57.0 Via: SIP/2.0/UDP 10.9.9.150:5061;rport=5061;received=10.9.9.150;branch=z9hG4bKPj308451ee-17d7-4e28-9e42-883de4b5353c Record-Route: Call-ID: 6e75a4f3-db8f-4b65-961f-8490edad3d7a From: ;tag=60d365bd-0fc2-4c29-b82f-3c63962e47b1 To: "8002" ;tag=e40f373c-93f5-45ec-bf6b-e16978266a05 CSeq: 18147 NOTIFY Contact: Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER Supported: 100rel, timer, replaces, norefersub Server: Asterisk PBX 16.15.0 Content-Length: 0 [Dec 8 18:00:14] VERBOSE[62990] res_pjsip_logger.c: <--- Received SIP request (887 bytes) from UDP:10.9.9.151:5060 ---> NOTIFY sip:asterisk@10.9.9.151:5061 SIP/2.0 Record-Route: Via: SIP/2.0/UDP 10.9.9.151;branch=z9hG4bK6bab.2e27842bc712e5762bc924d4bfaeb96e.0 Via: SIP/2.0/UDP 10.9.9.150:5061;received=10.9.9.150;rport=5061;branch=z9hG4bKPja81d634a-8b01-4fdb-806e-1a1c36eea705 From: ;tag=60d365bd-0fc2-4c29-b82f-3c63962e47b1 To: "8002" ;tag=e40f373c-93f5-45ec-bf6b-e16978266a05 Contact: Call-ID: 6e75a4f3-db8f-4b65-961f-8490edad3d7a CSeq: 18148 NOTIFY Route: Event: refer Subscription-State: active;expires=119 Allow-Events: message-summary, presence, dialog, refer Max-Forwards: 69 User-Agent: Asterisk PBX 16.7.0 Content-Type: message/sipfrag;version=2.0 Content-Length: 21 SIP/2.0 180 Ringing [Dec 8 18:00:14] DEBUG[62990] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f8b0805ec18 for Request msg NOTIFY/cseq=18148 (rdata0x7f8b50107c18) [Dec 8 18:00:14] DEBUG[62990] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/ast150-0000005f associated with dialog dlg0x7f8b0805ec18 [Dec 8 18:00:14] DEBUG[62991] pjproject: evsub0x7f8b08010ce8 .....Subscription state changed ACCEPTED --> ACTIVE [Dec 8 18:00:14] DEBUG[62991] res_pjsip_session.c: PJSIP/ast150-00000001: Method is NOTIFY [Dec 8 18:00:14] DEBUG[62991] res_pjsip_session.c: PJSIP/ast150-00000001 [Dec 8 18:00:14] VERBOSE[62991] res_pjsip_logger.c: <--- Transmitting SIP response (789 bytes) to UDP:10.9.9.151:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.9.9.151;rport=5060;received=10.9.9.151;branch=z9hG4bK6bab.2e27842bc712e5762bc924d4bfaeb96e.0 Via: SIP/2.0/UDP 10.9.9.150:5061;rport=5061;received=10.9.9.150;branch=z9hG4bKPja81d634a-8b01-4fdb-806e-1a1c36eea705 Record-Route: Call-ID: 6e75a4f3-db8f-4b65-961f-8490edad3d7a From: ;tag=60d365bd-0fc2-4c29-b82f-3c63962e47b1 To: "8002" ;tag=e40f373c-93f5-45ec-bf6b-e16978266a05 CSeq: 18148 NOTIFY Contact: Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER Supported: 100rel, timer, replaces, norefersub Server: Asterisk PBX 16.15.0 Content-Length: 0 [Dec 8 18:00:14] DEBUG[62991] pjproject: evsub0x7f8b08010ce8 .....Subscription state changed ACTIVE --> ACTIVE [Dec 8 18:00:14] DEBUG[63046][C-00000001] res_rtp_asterisk.c: (0x7f8b08069260) RTCP got report of 100 bytes from 10.9.9.150:19723 [Dec 8 18:00:19] DEBUG[62991] res_pjsip_session.c: 8002: Destroying SIP session [Dec 8 18:00:19] DEBUG[63046][C-00000001] res_rtp_asterisk.c: (0x7f8b08069260) RTCP got report of 80 bytes from 10.9.9.150:19723 [Dec 8 18:00:21] DEBUG[63001] res_pjsip_registrar.c: Woke up at 1607450421 Interval: 30 [Dec 8 18:00:21] DEBUG[63001] res_pjsip_registrar.c: Expiring 0 contacts [Dec 8 18:00:24] DEBUG[63046][C-00000001] res_rtp_asterisk.c: (0x7f8b08069260) RTCP got report of 80 bytes from 10.9.9.150:19723 [Dec 8 18:00:29] DEBUG[63046][C-00000001] res_rtp_asterisk.c: (0x7f8b08069260) RTCP got report of 80 bytes from 10.9.9.150:19723 [Dec 8 18:00:34] DEBUG[63047] threadpool.c: Worker thread idle timeout reached. Dying. [Dec 8 18:00:34] DEBUG[62963] threadpool.c: Destroying worker thread 11 [Dec 8 18:00:34] DEBUG[63046][C-00000001] res_rtp_asterisk.c: (0x7f8b08069260) RTCP got report of 80 bytes from 10.9.9.150:19723 [Dec 8 18:00:39] DEBUG[63046][C-00000001] res_rtp_asterisk.c: (0x7f8b08069260) RTCP got report of 80 bytes from 10.9.9.150:19723 [Dec 8 18:00:44] DEBUG[63046][C-00000001] res_rtp_asterisk.c: (0x7f8b08069260) RTCP got report of 80 bytes from 10.9.9.150:19723 [Dec 8 18:00:49] DEBUG[63046][C-00000001] res_rtp_asterisk.c: (0x7f8b08069260) RTCP got report of 80 bytes from 10.9.9.150:19723 [Dec 8 18:00:51] DEBUG[62993] threadpool.c: Worker thread idle timeout reached. Dying. [Dec 8 18:00:51] DEBUG[62994] threadpool.c: Worker thread idle timeout reached. Dying. [Dec 8 18:00:51] DEBUG[62995] threadpool.c: Worker thread idle timeout reached. Dying. [Dec 8 18:00:51] DEBUG[62988] threadpool.c: Destroying worker thread 7 [Dec 8 18:00:51] DEBUG[62988] threadpool.c: Destroying worker thread 8 [Dec 8 18:00:51] DEBUG[62988] threadpool.c: Destroying worker thread 9 [Dec 8 18:00:51] DEBUG[63001] res_pjsip_registrar.c: Woke up at 1607450451 Interval: 30 [Dec 8 18:00:51] DEBUG[63001] res_pjsip_registrar.c: Expiring 0 contacts [Dec 8 18:00:51] DEBUG[62996] threadpool.c: Worker thread idle timeout reached. Dying. [Dec 8 18:00:51] DEBUG[62965] threadpool.c: Destroying worker thread 10 [Dec 8 18:00:54] DEBUG[63046][C-00000001] res_rtp_asterisk.c: (0x7f8b08069260) RTCP got report of 80 bytes from 10.9.9.150:19723 [Dec 8 18:00:59] DEBUG[63046][C-00000001] res_rtp_asterisk.c: (0x7f8b08069260) RTCP got report of 80 bytes from 10.9.9.150:19723 [Dec 8 18:01:04] DEBUG[63046][C-00000001] res_rtp_asterisk.c: (0x7f8b08069260) RTCP got report of 80 bytes from 10.9.9.150:19723 [Dec 8 18:01:09] DEBUG[63046][C-00000001] res_rtp_asterisk.c: (0x7f8b08069260) RTCP got report of 80 bytes from 10.9.9.150:19723 [Dec 8 18:01:14] DEBUG[62992] threadpool.c: Worker thread idle timeout reached. Dying. [Dec 8 18:01:14] VERBOSE[62990] res_pjsip_logger.c: <--- Received SIP request (672 bytes) from UDP:10.9.9.151:5060 ---> BYE sip:asterisk@10.9.9.151:5061 SIP/2.0 Record-Route: Via: SIP/2.0/UDP 10.9.9.151;branch=z9hG4bK5bab.f0126a26b1ad3e856414c48d3b8830ee.0 Via: SIP/2.0/UDP 10.9.9.150:5061;received=10.9.9.150;rport=5061;branch=z9hG4bKPj0e696eee-0a4d-4a4c-b87c-c0c8c4d2a8e2 From: ;tag=60d365bd-0fc2-4c29-b82f-3c63962e47b1 To: "8002" ;tag=e40f373c-93f5-45ec-bf6b-e16978266a05 Call-ID: 6e75a4f3-db8f-4b65-961f-8490edad3d7a CSeq: 18149 BYE Route: Max-Forwards: 69 User-Agent: Asterisk PBX 16.7.0 Content-Length: 0 [Dec 8 18:01:14] DEBUG[62988] threadpool.c: Destroying worker thread 6 [Dec 8 18:01:14] DEBUG[62990] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f8b0805ec18 for Request msg BYE/cseq=18149 (rdata0x7f8b50129098) [Dec 8 18:01:14] DEBUG[62990] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/ast150-0000005f associated with dialog dlg0x7f8b0805ec18 [Dec 8 18:01:14] VERBOSE[62991] res_pjsip_logger.c: <--- Transmitting SIP response (586 bytes) to UDP:10.9.9.151:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.9.9.151;rport=5060;received=10.9.9.151;branch=z9hG4bK5bab.f0126a26b1ad3e856414c48d3b8830ee.0 Via: SIP/2.0/UDP 10.9.9.150:5061;rport=5061;received=10.9.9.150;branch=z9hG4bKPj0e696eee-0a4d-4a4c-b87c-c0c8c4d2a8e2 Record-Route: Call-ID: 6e75a4f3-db8f-4b65-961f-8490edad3d7a From: ;tag=60d365bd-0fc2-4c29-b82f-3c63962e47b1 To: "8002" ;tag=e40f373c-93f5-45ec-bf6b-e16978266a05 CSeq: 18149 BYE Server: Asterisk PBX 16.15.0 Content-Length: 0 [Dec 8 18:01:14] DEBUG[62991] res_pjsip_session.c: PJSIP/ast150-00000001: Source of transaction state change is RX_MSG [Dec 8 18:01:14] DEBUG[62991] res_pjsip_session.c: PJSIP/ast150-00000001: Received request [Dec 8 18:01:14] DEBUG[62991] res_pjsip_session.c: PJSIP/ast150-00000001: Method is BYE [Dec 8 18:01:14] DEBUG[62991] res_pjsip_session.c: PJSIP/ast150-00000001 [Dec 8 18:01:14] DEBUG[63044] manager.c: Examining AMI event: Event: HangupRequest Privilege: call,all Channel: PJSIP/ast150-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8000 CallerIDName: ConnectedLineNum: 8002 ConnectedLineName: 8002 Language: en AccountCode: Context: pjsip_context Exten: 6000 Priority: 1 Uniqueid: 1607450403.1 Linkedid: 1607450403.0 [Dec 8 18:01:14] DEBUG[63046][C-00000001] pbx.c: Extension 6000, priority 1 returned normally even though call was hung up [Dec 8 18:01:14] DEBUG[63046][C-00000001] channel.c: Soft-Hanging (0x10) up channel 'PJSIP/ast150-00000001' [Dec 8 18:01:14] DEBUG[63046][C-00000001] channel.c: Channel 0x7f8b4c00d7e0 'PJSIP/ast150-00000001' hanging up. Refs: 2 [Dec 8 18:01:14] DEBUG[63046][C-00000001] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP) [Dec 8 18:01:14] DEBUG[63044] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/ast150-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8000 CallerIDName: ConnectedLineNum: 8002 ConnectedLineName: 8002 Language: en AccountCode: Context: pjsip_context Exten: 6000 Priority: 1 Uniqueid: 1607450403.1 Linkedid: 1607450403.0 Variable: TRANSFERSTATUS Value: FAILURE [Dec 8 18:01:14] DEBUG[63044] manager.c: Examining AMI event: Event: SoftHangupRequest Privilege: call,all Channel: PJSIP/ast150-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8000 CallerIDName: ConnectedLineNum: 8002 ConnectedLineName: 8002 Language: en AccountCode: Context: pjsip_context Exten: 6000 Priority: 1 Uniqueid: 1607450403.1 Linkedid: 1607450403.0 Cause: 16 [Dec 8 18:01:14] DEBUG[62991] res_rtp_asterisk.c: (0x7f8b08069260) DTLS srtp - stopped timeout timer' [Dec 8 18:01:14] DEBUG[62991] res_rtp_asterisk.c: (0x7f8b08069260) DTLS srtp - stopped timeout timer' [Dec 8 18:01:14] DEBUG[62991] res_rtp_asterisk.c: (0x7f8b08069260) DTLS stop [Dec 8 18:01:14] DEBUG[62991] res_rtp_asterisk.c: (0x7f8b08069260) DTLS srtp - stopped timeout timer' [Dec 8 18:01:14] DEBUG[62991] res_rtp_asterisk.c: (0x7f8b08069260) DTLS srtp - stopped timeout timer' [Dec 8 18:01:14] DEBUG[62991] res_rtp_asterisk.c: (0x7f8b08069260) ICE RTP transport deallocating [Dec 8 18:01:14] DEBUG[62991] rtp_engine.c: Destroyed RTP instance '0x7f8b08069260' [Dec 8 18:01:14] DEBUG[62991] channel.c: Channel 0x7f8b4c00d7e0 'PJSIP/ast150-00000001' destroying [Dec 8 18:01:14] DEBUG[63044] manager.c: Examining AMI event: Event: Hangup Privilege: call,all Channel: PJSIP/ast150-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8000 CallerIDName: ConnectedLineNum: 8002 ConnectedLineName: 8002 Language: en AccountCode: Context: pjsip_context Exten: 6000 Priority: 1 Uniqueid: 1607450403.1 Linkedid: 1607450403.0 Cause: 16 Cause-txt: Normal Clearing [Dec 8 18:01:14] DEBUG[62983] cdr.c: CDR for PJSIP/ast150-00000001 is dialed and has no Party B; discarding [Dec 8 18:01:14] DEBUG[62963] threadpool.c: Increasing threadpool stasis/pool's size by 1 [Dec 8 18:01:14] DEBUG[62991] stasis.c: Destroying topic. name: cache:8/channel:1607450403.1, detail: [Dec 8 18:01:14] DEBUG[62991] stasis.c: Topic 'cache:8/channel:1607450403.1': 0x7f8b4c011ca0 destroyed [Dec 8 18:01:14] DEBUG[62991] stasis.c: Destroying topic. name: channel:1607450403.1, detail: [Dec 8 18:01:14] DEBUG[62991] stasis.c: Topic 'channel:1607450403.1': 0x7f8b4c010bb0 destroyed [Dec 8 18:01:14] DEBUG[62975] devicestate.c: No provider found, checking channel drivers for PJSIP - ast150 [Dec 8 18:01:14] DEBUG[62975] devicestate.c: Changing state for PJSIP/ast150 - state 1 (Not in use) [Dec 8 18:01:14] DEBUG[63040] app_queue.c: Device 'PJSIP/ast150' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Dec 8 18:01:14] DEBUG[63044] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: PJSIP/ast150 State: NOT_INUSE [Dec 8 18:01:21] DEBUG[63001] res_pjsip_registrar.c: Woke up at 1607450481 Interval: 30 [Dec 8 18:01:21] DEBUG[63001] res_pjsip_registrar.c: Expiring 0 contacts [Dec 8 18:01:34] DEBUG[63049] threadpool.c: Worker thread idle timeout reached. Dying. [Dec 8 18:01:34] DEBUG[62963] threadpool.c: Destroying worker thread 12 [Dec 8 18:01:46] DEBUG[62991] res_pjsip_session.c: ast150: Destroying SIP session [Dec 8 18:01:51] DEBUG[63001] res_pjsip_registrar.c: Woke up at 1607450511 Interval: 30 [Dec 8 18:01:51] DEBUG[63001] res_pjsip_registrar.c: Expiring 0 contacts [Dec 8 18:01:54] VERBOSE[62990] res_pjsip_logger.c: <--- Received SIP request (909 bytes) from UDP:10.9.9.151:5060 ---> NOTIFY sip:asterisk@10.9.9.151:5061 SIP/2.0 Record-Route: Via: SIP/2.0/UDP 10.9.9.151;branch=z9hG4bKeaab.2aaa7ab811e64c701367edf7efb3a469.0 Via: SIP/2.0/UDP 10.9.9.150:5061;received=10.9.9.150;rport=5061;branch=z9hG4bKPj7994f3fb-d305-404f-a42e-fe434d9a248a From: ;tag=60d365bd-0fc2-4c29-b82f-3c63962e47b1 To: "8002" ;tag=e40f373c-93f5-45ec-bf6b-e16978266a05 Contact: Call-ID: 6e75a4f3-db8f-4b65-961f-8490edad3d7a CSeq: 18150 NOTIFY Route: Event: refer Subscription-State: terminated;reason=noresource Allow-Events: message-summary, presence, dialog, refer Max-Forwards: 69 User-Agent: Asterisk PBX 16.7.0 Content-Type: message/sipfrag;version=2.0 Content-Length: 33 SIP/2.0 503 Service Unavailable [Dec 8 18:01:54] DEBUG[62990] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f8b0805ec18 for Request msg NOTIFY/cseq=18150 (rdata0x7f8b50037ec8) [Dec 8 18:01:54] DEBUG[62990] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000022 to use for Request msg NOTIFY/cseq=18150 (rdata0x7f8b50037ec8) [Dec 8 18:01:54] DEBUG[62991] res_pjsip_endpoint_identifier_ip.c: Source address 10.9.9.151:5060 does not match identify '8002' [Dec 8 18:01:54] DEBUG[62991] res_pjsip_endpoint_identifier_ip.c: Source address 10.9.9.151:5060 does not match identify 'ast150' [Dec 8 18:01:54] DEBUG[62991] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '8000' domain '10.9.9.150' [Dec 8 18:01:54] DEBUG[62991] res_pjsip_endpoint_identifier_user.c: Endpoint not found for From username '8000' domain '10.9.9.150' [Dec 8 18:01:54] NOTICE[62991] res_pjsip/pjsip_distributor.c: Request 'NOTIFY' from '' failed for '10.9.9.151:5060' (callid: 6e75a4f3-db8f-4b65-961f-8490edad3d7a) - No matching endpoint found [Dec 8 18:01:54] VERBOSE[62991] res_pjsip_logger.c: <--- Transmitting SIP response (789 bytes) to UDP:10.9.9.151:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.9.9.151;rport=5060;received=10.9.9.151;branch=z9hG4bKeaab.2aaa7ab811e64c701367edf7efb3a469.0 Via: SIP/2.0/UDP 10.9.9.150:5061;rport=5061;received=10.9.9.150;branch=z9hG4bKPj7994f3fb-d305-404f-a42e-fe434d9a248a Record-Route: Call-ID: 6e75a4f3-db8f-4b65-961f-8490edad3d7a From: ;tag=60d365bd-0fc2-4c29-b82f-3c63962e47b1 To: "8002" ;tag=e40f373c-93f5-45ec-bf6b-e16978266a05 CSeq: 18150 NOTIFY Contact: Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER Supported: 100rel, timer, replaces, norefersub Server: Asterisk PBX 16.15.0 Content-Length: 0