[2021-05-20 08:38:29.401] VERBOSE[3710] chan_sip.c: <--- SIP read from UDP:yy.yy.yy.yy:5060 ---> INVITE sip:160@xx.xx.xx.xx:5060 SIP/2.0 Via: SIP/2.0/UDP yy.yy.yy.yy:5060;branch=z9hG4bK24975546 Max-Forwards: 70 From: ;tag=as3aa1aae5 To: Contact: Call-ID: 5b44dd57162fc3e72a7c5ef204c538b6@yy.yy.yy.yy:5060 CSeq: 102 INVITE User-Agent: Asterisk PBX 13.7.2 Date: Thu, 20 May 2021 06:34:38 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Content-Type: application/sdp Content-Length: 233 v=0 o=root 127431866 127431866 IN IP4 yy.yy.yy.yy s=Asterisk PBX 13.7.2 c=IN IP4 yy.yy.yy.yy t=0 0 m=audio 11404 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=maxptime:150 a=sendrecv <-------------> [2021-05-20 08:38:29.401] DEBUG[3710] chan_sip.c: Header 0 [ 40]: INVITE sip:160@xx.xx.xx.xx:5060 SIP/2.0 [2021-05-20 08:38:29.401] DEBUG[3710] chan_sip.c: Header 1 [ 55]: Via: SIP/2.0/UDP yy.yy.yy.yy:5060;branch=z9hG4bK24975546 [2021-05-20 08:38:29.401] DEBUG[3710] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [2021-05-20 08:38:29.401] DEBUG[3710] chan_sip.c: Header 3 [ 41]: From: ;tag=as3aa1aae5 [2021-05-20 08:38:29.401] DEBUG[3710] chan_sip.c: Header 4 [ 31]: To: [2021-05-20 08:38:29.401] DEBUG[3710] chan_sip.c: Header 5 [ 34]: Contact: [2021-05-20 08:38:29.401] DEBUG[3710] chan_sip.c: Header 6 [ 57]: Call-ID: 5b44dd57162fc3e72a7c5ef204c538b6@yy.yy.yy.yy:5060 [2021-05-20 08:38:29.401] DEBUG[3710] chan_sip.c: Header 7 [ 16]: CSeq: 102 INVITE [2021-05-20 08:38:29.401] DEBUG[3710] chan_sip.c: Header 8 [ 31]: User-Agent: Asterisk PBX 13.7.2 [2021-05-20 08:38:29.401] DEBUG[3710] chan_sip.c: Header 9 [ 35]: Date: Thu, 20 May 2021 06:34:38 GMT [2021-05-20 08:38:29.401] DEBUG[3710] chan_sip.c: Header 10 [ 90]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE [2021-05-20 08:38:29.401] DEBUG[3710] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [2021-05-20 08:38:29.401] DEBUG[3710] chan_sip.c: Header 12 [ 29]: Content-Type: application/sdp [2021-05-20 08:38:29.401] DEBUG[3710] chan_sip.c: Header 13 [ 19]: Content-Length: 233 [2021-05-20 08:38:29.401] DEBUG[3710] chan_sip.c: Header 14 [ 0]: [2021-05-20 08:38:29.401] DEBUG[3710] chan_sip.c: Body 0 [ 3]: v=0 [2021-05-20 08:38:29.401] DEBUG[3710] chan_sip.c: Body 1 [ 44]: o=root 127431866 127431866 IN IP4 yy.yy.yy.yy [2021-05-20 08:38:29.401] DEBUG[3710] chan_sip.c: Body 2 [ 21]: s=Asterisk PBX 13.7.2 [2021-05-20 08:38:29.401] DEBUG[3710] chan_sip.c: Body 3 [ 19]: c=IN IP4 yy.yy.yy.yy [2021-05-20 08:38:29.401] DEBUG[3710] chan_sip.c: Body 4 [ 5]: t=0 0 [2021-05-20 08:38:29.401] DEBUG[3710] chan_sip.c: Body 5 [ 27]: m=audio 11404 RTP/AVP 8 101 [2021-05-20 08:38:29.401] DEBUG[3710] chan_sip.c: Body 6 [ 20]: a=rtpmap:8 PCMA/8000 [2021-05-20 08:38:29.401] DEBUG[3710] chan_sip.c: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [2021-05-20 08:38:29.401] DEBUG[3710] chan_sip.c: Body 8 [ 15]: a=fmtp:101 0-16 [2021-05-20 08:38:29.401] DEBUG[3710] chan_sip.c: Body 9 [ 14]: a=maxptime:150 [2021-05-20 08:38:29.401] DEBUG[3710] chan_sip.c: Body 10 [ 10]: a=sendrecv [2021-05-20 08:38:29.401] VERBOSE[3710] chan_sip.c: --- (14 headers 11 lines) --- [2021-05-20 08:38:29.401] DEBUG[3710] chan_sip.c: = Looking for Call ID: 5b44dd57162fc3e72a7c5ef204c538b6@yy.yy.yy.yy:5060 (Checking From) --From tag as3aa1aae5 --To-tag [2021-05-20 08:38:29.401] DEBUG[3710] acl.c: For destination 'yy.yy.yy.yy', our source address is 'xx.xx.xx.xx'. [2021-05-20 08:38:29.401] DEBUG[3710] chan_sip.c: Setting AST_TRANSPORT_UDP with address xx.xx.xx.xx:5060 [2021-05-20 08:38:29.401] DEBUG[3710] netsock2.c: Splitting 'yy.yy.yy.yy:5060' into... [2021-05-20 08:38:29.401] DEBUG[3710] netsock2.c: ...host 'yy.yy.yy.yy' and port '5060'. [2021-05-20 08:38:29.401] VERBOSE[3710] chan_sip.c: Sending to yy.yy.yy.yy:5060 (no NAT) [2021-05-20 08:38:29.401] DEBUG[3710] chan_sip.c: Allocating new SIP dialog for 5b44dd57162fc3e72a7c5ef204c538b6@yy.yy.yy.yy:5060 - INVITE (No RTP) [2021-05-20 08:38:29.401] DEBUG[3710][C-0000008f] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [2021-05-20 08:38:29.401] DEBUG[3710][C-0000008f] sip/reqresp_parser.c: Begin: parsing SIP "Supported: replaces, timer" [2021-05-20 08:38:29.401] DEBUG[3710][C-0000008f] sip/reqresp_parser.c: Found SIP option: -replaces- [2021-05-20 08:38:29.401] DEBUG[3710][C-0000008f] sip/reqresp_parser.c: Matched SIP option: replaces [2021-05-20 08:38:29.401] DEBUG[3710][C-0000008f] sip/reqresp_parser.c: Found SIP option: -timer- [2021-05-20 08:38:29.401] DEBUG[3710][C-0000008f] sip/reqresp_parser.c: Matched SIP option: timer [2021-05-20 08:38:29.401] DEBUG[3710][C-0000008f] netsock2.c: Splitting 'yy.yy.yy.yy:5060' into... [2021-05-20 08:38:29.401] DEBUG[3710][C-0000008f] netsock2.c: ...host 'yy.yy.yy.yy' and port '5060'. [2021-05-20 08:38:29.401] VERBOSE[3710][C-0000008f] chan_sip.c: Sending to yy.yy.yy.yy:5060 (no NAT) [2021-05-20 08:38:29.401] DEBUG[3710][C-0000008f] chan_sip.c: Initializing initreq for method INVITE - callid 5b44dd57162fc3e72a7c5ef204c538b6@yy.yy.yy.yy:5060 [2021-05-20 08:38:29.401] VERBOSE[3710][C-0000008f] chan_sip.c: Using INVITE request as basis request - 5b44dd57162fc3e72a7c5ef204c538b6@yy.yy.yy.yy:5060 [2021-05-20 08:38:29.401] DEBUG[3710][C-0000008f] netsock2.c: Splitting 'yy.yy.yy.yy' into... [2021-05-20 08:38:29.401] DEBUG[3710][C-0000008f] netsock2.c: ...host 'yy.yy.yy.yy' and port ''. [2021-05-20 08:38:29.401] VERBOSE[3710][C-0000008f] chan_sip.c: Found peer 'criticall' for '502' from yy.yy.yy.yy:5060 [2021-05-20 08:38:29.401] DEBUG[3710][C-0000008f] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f5e18211c00' [2021-05-20 08:38:29.402] DEBUG[3710][C-0000008f] res_rtp_asterisk.c: (0x7f5e18211c00) RTP allocated port 36290 [2021-05-20 08:38:29.402] DEBUG[3710][C-0000008f] res_rtp_asterisk.c: (0x7f5e18211c00) ICE creating session 0.0.0.0:36290 (36290) [2021-05-20 08:38:29.402] DEBUG[3710][C-0000008f] res_rtp_asterisk.c: (0x7f5e18211c00) ICE create [2021-05-20 08:38:29.405] DEBUG[3710][C-0000008f] res_rtp_asterisk.c: (0x7f5e18211c00) ICE add system candidates [2021-05-20 08:38:29.405] DEBUG[3710][C-0000008f] netsock2.c: Splitting 'zz.zz.zz.zz' into... [2021-05-20 08:38:29.405] DEBUG[3710][C-0000008f] netsock2.c: ...host 'zz.zz.zz.zz' and port ''. [2021-05-20 08:38:29.405] DEBUG[3710][C-0000008f] res_rtp_asterisk.c: (0x7f5e18211c00) ICE add candidate: zz.zz.zz.zz:36290, 2130706431 [2021-05-20 08:38:29.405] DEBUG[3710][C-0000008f] netsock2.c: Splitting 'xx.xx.xx.xx' into... [2021-05-20 08:38:29.405] DEBUG[3710][C-0000008f] netsock2.c: ...host 'xx.xx.xx.xx' and port ''. [2021-05-20 08:38:29.405] DEBUG[3710][C-0000008f] res_rtp_asterisk.c: (0x7f5e18211c00) ICE add candidate: xx.xx.xx.xx:36290, 2130706431 [2021-05-20 08:38:29.405] DEBUG[3710][C-0000008f] netsock2.c: Splitting 'aa.aa.aa.aa' into... [2021-05-20 08:38:29.405] DEBUG[3710][C-0000008f] netsock2.c: ...host 'aa.aa.aa.aa' and port ''. [2021-05-20 08:38:29.405] DEBUG[3710][C-0000008f] res_rtp_asterisk.c: (0x7f5e18211c00) ICE add candidate: aa.aa.aa.aa:36290, 2130706431 [2021-05-20 08:38:29.405] DEBUG[3710][C-0000008f] rtp_engine.c: RTP instance '0x7f5e18211c00' is setup and ready to go [2021-05-20 08:38:29.405] DEBUG[3710][C-0000008f] res_rtp_asterisk.c: (0x7f5e18211c00) ICE stopped [2021-05-20 08:38:29.405] DEBUG[3710][C-0000008f] netsock2.c: Splitting 'criticall02' into... [2021-05-20 08:38:29.405] DEBUG[3710][C-0000008f] netsock2.c: ...host 'criticall02' and port ''. [2021-05-20 08:38:29.405] DEBUG[3710][C-0000008f] res_rtp_asterisk.c: (0x7f5e18211c00) RTCP setup on RTP instance [2021-05-20 08:38:29.405] VERBOSE[3710][C-0000008f] netsock2.c: Using SIP RTP TOS bits 48 [2021-05-20 08:38:29.405] VERBOSE[3710][C-0000008f] netsock2.c: Using SIP RTP CoS mark 5 [2021-05-20 08:38:29.405] DEBUG[3710][C-0000008f] chan_sip.c: Setting NAT on RTP to Off [2021-05-20 08:38:29.405] DEBUG[3710][C-0000008f] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [2021-05-20 08:38:29.405] VERBOSE[3710][C-0000008f] chan_sip.c: Got SDP version 127431866 and unique parts [root 127431866 IN IP4 yy.yy.yy.yy] [2021-05-20 08:38:29.405] DEBUG[3710][C-0000008f] chan_sip.c: Processing session-level SDP o=root 127431866 127431866 IN IP4 yy.yy.yy.yy... OK. [2021-05-20 08:38:29.405] DEBUG[3710][C-0000008f] chan_sip.c: Processing session-level SDP s=Asterisk PBX 13.7.2... UNSUPPORTED OR FAILED. [2021-05-20 08:38:29.405] DEBUG[3710][C-0000008f] netsock2.c: Splitting 'yy.yy.yy.yy' into... [2021-05-20 08:38:29.405] DEBUG[3710][C-0000008f] netsock2.c: ...host 'yy.yy.yy.yy' and port ''. [2021-05-20 08:38:29.405] DEBUG[3710][C-0000008f] chan_sip.c: Processing session-level SDP c=IN IP4 yy.yy.yy.yy... OK. [2021-05-20 08:38:29.405] DEBUG[3710][C-0000008f] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [2021-05-20 08:38:29.405] VERBOSE[3710][C-0000008f] chan_sip.c: Found RTP audio format 8 [2021-05-20 08:38:29.405] DEBUG[3710][C-0000008f] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7f5dbdda21a0 [2021-05-20 08:38:29.405] VERBOSE[3710][C-0000008f] chan_sip.c: Found RTP audio format 101 [2021-05-20 08:38:29.405] VERBOSE[3710][C-0000008f] chan_sip.c: Found audio description format PCMA for ID 8 [2021-05-20 08:38:29.405] DEBUG[3710][C-0000008f] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [2021-05-20 08:38:29.405] VERBOSE[3710][C-0000008f] chan_sip.c: Found audio description format telephone-event for ID 101 [2021-05-20 08:38:29.405] DEBUG[3710][C-0000008f] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [2021-05-20 08:38:29.405] DEBUG[3710][C-0000008f] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED OR FAILED. [2021-05-20 08:38:29.405] DEBUG[3710][C-0000008f] chan_sip.c: Processing media-level (audio) SDP a=maxptime:150... UNSUPPORTED OR FAILED. [2021-05-20 08:38:29.405] DEBUG[3710][C-0000008f] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [2021-05-20 08:38:29.405] DEBUG[3710][C-0000008f] rtp_engine.c: Crossover copying tx to rx payload mapping 8 (0x7f5e181a90c8) from 0x7f5dbdda21a0 to 0x7f5dbdda21a0 [2021-05-20 08:38:29.405] DEBUG[3710][C-0000008f] rtp_engine.c: Crossover copying tx to rx payload mapping 101 (0x7f5e18061028) from 0x7f5dbdda21a0 to 0x7f5dbdda21a0 [2021-05-20 08:38:29.405] VERBOSE[3710][C-0000008f] chan_sip.c: Capabilities: us - (alaw), peer - audio=(alaw)/video=(nothing)/text=(nothing), combined - (alaw) [2021-05-20 08:38:29.405] VERBOSE[3710][C-0000008f] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [2021-05-20 08:38:29.405] DEBUG[3710][C-0000008f] acl.c: For destination 'yy.yy.yy.yy', our source address is 'xx.xx.xx.xx'. [2021-05-20 08:38:29.406] DEBUG[3710][C-0000008f] res_rtp_asterisk.c: (0x7f5e18211c00) RTCP setting address on RTP instance [2021-05-20 08:38:29.406] VERBOSE[3710][C-0000008f] res_rtp_asterisk.c: 0x7f5e18257200 -- Strict RTP learning after remote address set to: yy.yy.yy.yy:11404 [2021-05-20 08:38:29.406] VERBOSE[3710][C-0000008f] chan_sip.c: Peer audio RTP is at port yy.yy.yy.yy:11404 [2021-05-20 08:38:29.406] DEBUG[3710][C-0000008f] rtp_engine.c: Copying rx payload mapping 8 (0x7f5e181a90c8) from 0x7f5dbdda21a0 to 0x7f5e18211dd8 [2021-05-20 08:38:29.406] DEBUG[3710][C-0000008f] rtp_engine.c: Copying rx payload mapping 101 (0x7f5e18061028) from 0x7f5dbdda21a0 to 0x7f5e18211dd8 [2021-05-20 08:38:29.406] DEBUG[3710][C-0000008f] rtp_engine.c: Copying tx payload mapping 8 (0x7f5e181a90c8) from 0x7f5dbdda21a0 to 0x7f5e18211dd8 [2021-05-20 08:38:29.406] DEBUG[3710][C-0000008f] rtp_engine.c: Copying tx payload mapping 101 (0x7f5e18061028) from 0x7f5dbdda21a0 to 0x7f5e18211dd8 [2021-05-20 08:38:29.406] DEBUG[3710][C-0000008f] res_rtp_asterisk.c: (0x7f5e18211c00) RTCP ignoring duplicate property [2021-05-20 08:38:29.406] DEBUG[3710][C-0000008f] chan_sip.c: We're settling with these formats: (alaw) [2021-05-20 08:38:29.406] DEBUG[3710][C-0000008f] chan_sip.c: Checking SIP call limits for device criticall [2021-05-20 08:38:29.406] DEBUG[3710][C-0000008f] chan_sip.c: Updating call counter for incoming call [2021-05-20 08:38:29.406] DEBUG[3710][C-0000008f] netsock2.c: Splitting 'xx.xx.xx.xx:5060' into... [2021-05-20 08:38:29.406] DEBUG[3710][C-0000008f] netsock2.c: ...host 'xx.xx.xx.xx' and port ''. [2021-05-20 08:38:29.406] DEBUG[3710][C-0000008f] netsock2.c: Splitting 'yy.yy.yy.yy' into... [2021-05-20 08:38:29.406] DEBUG[3710][C-0000008f] netsock2.c: ...host 'yy.yy.yy.yy' and port ''. [2021-05-20 08:38:29.406] VERBOSE[3710][C-0000008f] chan_sip.c: Looking for 160 in incoming_call (domain xx.xx.xx.xx) [2021-05-20 08:38:29.406] DEBUG[3710][C-0000008f] chan_sip.c: Incoming INVITE with 'timer' option supported [2021-05-20 08:38:29.406] DEBUG[3710][C-0000008f] stasis.c: Creating topic. name: channel:1621492709.539, detail: [2021-05-20 08:38:29.406] DEBUG[3710][C-0000008f] stasis.c: Topic 'channel:1621492709.539': 0x7f5e18097140 created [2021-05-20 08:38:29.406] DEBUG[3710][C-0000008f] stasis.c: Creating topic. name: cache:634/channel:1621492709.539, detail: [2021-05-20 08:38:29.406] DEBUG[3710][C-0000008f] stasis.c: Topic 'cache:634/channel:1621492709.539': 0x7f5e182139b0 created [2021-05-20 08:38:29.406] DEBUG[3710][C-0000008f] channel.c: Channel 0x7f5e1818b980 'SIP/criticall-00000189' allocated [2021-05-20 08:38:29.406] DEBUG[3710][C-0000008f] chan_sip.c: *** Our native formats are (alaw) [2021-05-20 08:38:29.406] DEBUG[3710][C-0000008f] chan_sip.c: *** Joint capabilities are (alaw) [2021-05-20 08:38:29.406] DEBUG[3710][C-0000008f] chan_sip.c: *** Our capabilities are (alaw) [2021-05-20 08:38:29.406] DEBUG[3710][C-0000008f] chan_sip.c: *** AST_CODEC_CHOOSE formats are alaw [2021-05-20 08:38:29.406] DEBUG[3710][C-0000008f] chan_sip.c: This channel will not be able to handle video. [2021-05-20 08:38:29.406] DEBUG[3807] res_http_websocket.c: Writing websocket string of length 233 [2021-05-20 08:38:29.406] DEBUG[3807] res_http_websocket.c: Writing websocket text frame, length 233 [2021-05-20 08:38:29.406] DEBUG[3739] manager.c: Examining AMI event: Event: Newchannel Privilege: call,all Channel: SIP/criticall-00000189 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: incoming_call Exten: 160 Priority: 1 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 [2021-05-20 08:38:29.406] DEBUG[4938] manager.c: Examining AMI event: Event: Newchannel Privilege: call,all Channel: SIP/criticall-00000189 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: incoming_call Exten: 160 Priority: 1 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 [2021-05-20 08:38:29.406] VERBOSE[3710][C-0000008f] sip/route.c: sip_route_dump: route/path hop: [2021-05-20 08:38:29.406] DEBUG[3710][C-0000008f] chan_sip.c: SIP/criticall-00000189: New call is still down.... Trying... [2021-05-20 08:38:29.406] VERBOSE[3710][C-0000008f] chan_sip.c: <--- Transmitting (no NAT) to yy.yy.yy.yy:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP yy.yy.yy.yy:5060;branch=z9hG4bK24975546;received=yy.yy.yy.yy From: ;tag=as3aa1aae5 To: Call-ID: 5b44dd57162fc3e72a7c5ef204c538b6@yy.yy.yy.yy:5060 CSeq: 102 INVITE Server: L12893-16.16.0;Ast-PBX;L12917-1.0.46.0;Ast-Cfg criticall02 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Session-Expires: 120;refresher=uas Contact: Content-Length: 0 <------------> [2021-05-20 08:38:29.406] DEBUG[3710][C-0000008f] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for yy.yy.yy.yy:5060 [2021-05-20 08:38:29.406] DEBUG[4938] manager.c: Examining AMI event: Event: Newstate Privilege: call,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: incoming_call Exten: 160 Priority: 1 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 [2021-05-20 08:38:29.406] DEBUG[3739] manager.c: Examining AMI event: Event: Newstate Privilege: call,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: incoming_call Exten: 160 Priority: 1 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 [2021-05-20 08:38:29.406] DEBUG[3671] devicestate.c: No provider found, checking channel drivers for SIP - criticall [2021-05-20 08:38:29.406] DEBUG[3671] chan_sip.c: Checking device state for peer criticall [2021-05-20 08:38:29.406] DEBUG[3671] devicestate.c: Changing state for SIP/criticall - state 1 (Not in use) [2021-05-20 08:38:29.406] DEBUG[16181][C-0000008f] pbx.c: Launching 'Gosub' [2021-05-20 08:38:29.406] VERBOSE[16181][C-0000008f] pbx.c: Executing [160@incoming_call:1] Gosub("SIP/criticall-00000189", "fix-main-backup,s,1") in new stack [2021-05-20 08:38:29.407] DEBUG[3739] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: incoming_call Exten: 160 Priority: 1 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 Extension: 160 Application: Gosub AppData: fix-main-backup,s,1 [2021-05-20 08:38:29.407] DEBUG[4938] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: incoming_call Exten: 160 Priority: 1 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 Extension: 160 Application: Gosub AppData: fix-main-backup,s,1 [2021-05-20 08:38:29.407] DEBUG[16181][C-0000008f] app_stack.c: Channel SIP/criticall-00000189 has no datastore, so we're allocating one. [2021-05-20 08:38:29.407] DEBUG[16181][C-0000008f] pbx_variables.c: Function CHANNEL(peername) result is 'criticall' [2021-05-20 08:38:29.407] DEBUG[3807] res_http_websocket.c: Writing websocket string of length 686 [2021-05-20 08:38:29.407] DEBUG[16181][C-0000008f] pbx.c: Launching 'Set' [2021-05-20 08:38:29.407] DEBUG[3807] res_http_websocket.c: Writing websocket text frame, length 686 [2021-05-20 08:38:29.407] VERBOSE[16181][C-0000008f] pbx.c: Executing [s@fix-main-backup:1] Set("SIP/criticall-00000189", "SRC_TRUNK=criticall") in new stack [2021-05-20 08:38:29.407] DEBUG[3739] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: fix-main-backup Exten: s Priority: 1 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 Extension: s Application: Set AppData: SRC_TRUNK=criticall [2021-05-20 08:38:29.407] DEBUG[4938] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: fix-main-backup Exten: s Priority: 1 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 Extension: s Application: Set AppData: SRC_TRUNK=criticall [2021-05-20 08:38:29.407] DEBUG[16181][C-0000008f] pbx_variables.c: Result of 'SRC_TRUNK' is 'criticall' [2021-05-20 08:38:29.407] DEBUG[16181][C-0000008f] pbx_variables.c: Result of 'TRUNK_criticall' is 'criticall' [2021-05-20 08:38:29.407] DEBUG[16181][C-0000008f] pbx_variables.c: Expression result is '0' [2021-05-20 08:38:29.407] DEBUG[16181][C-0000008f] pbx.c: Launching 'GotoIf' [2021-05-20 08:38:29.407] VERBOSE[16181][C-0000008f] pbx.c: Executing [s@fix-main-backup:2] GotoIf("SIP/criticall-00000189", "0?handleBackup,1:handleMain,1") in new stack [2021-05-20 08:38:29.407] DEBUG[3739] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: fix-main-backup Exten: s Priority: 2 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 Extension: s Application: GotoIf AppData: 0?handleBackup,1:handleMain,1 [2021-05-20 08:38:29.407] DEBUG[4938] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: fix-main-backup Exten: s Priority: 2 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 Extension: s Application: GotoIf AppData: 0?handleBackup,1:handleMain,1 [2021-05-20 08:38:29.407] VERBOSE[16181][C-0000008f] pbx_builtins.c: Goto (fix-main-backup,handleMain,1) [2021-05-20 08:38:29.407] DEBUG[16181][C-0000008f] pbx_variables.c: Result of 'SRC_TRUNK' is 'criticall' [2021-05-20 08:38:29.407] DEBUG[16181][C-0000008f] pbx_variables.c: Result of 'SRC_TRUNK' is 'criticall' [2021-05-20 08:38:29.407] DEBUG[16181][C-0000008f] pbx.c: Launching 'Set' [2021-05-20 08:38:29.407] VERBOSE[16181][C-0000008f] pbx.c: Executing [handleMain@fix-main-backup:1] Set("SIP/criticall-00000189", "GLOBAL(TRUNK_criticall)=criticall") in new stack [2021-05-20 08:38:29.407] DEBUG[3739] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: fix-main-backup Exten: handleMain Priority: 1 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 Extension: handleMain Application: Set AppData: GLOBAL(TRUNK_criticall)=criticall [2021-05-20 08:38:29.407] DEBUG[4938] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: fix-main-backup Exten: handleMain Priority: 1 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 Extension: handleMain Application: Set AppData: GLOBAL(TRUNK_criticall)=criticall [2021-05-20 08:38:29.407] VERBOSE[16181][C-0000008f] pbx_variables.c: Setting global variable 'TRUNK_criticall' to 'criticall' [2021-05-20 08:38:29.407] DEBUG[16181][C-0000008f] pbx.c: Launching 'Return' [2021-05-20 08:38:29.407] VERBOSE[16181][C-0000008f] pbx.c: Executing [handleMain@fix-main-backup:2] Return("SIP/criticall-00000189", "") in new stack [2021-05-20 08:38:29.407] DEBUG[3739] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: fix-main-backup Exten: handleMain Priority: 2 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 Extension: handleMain Application: Return AppData: [2021-05-20 08:38:29.407] DEBUG[4938] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: fix-main-backup Exten: handleMain Priority: 2 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 Extension: handleMain Application: Return AppData: [2021-05-20 08:38:29.407] DEBUG[16181][C-0000008f] pbx.c: Launching 'Set' [2021-05-20 08:38:29.407] VERBOSE[16181][C-0000008f] pbx.c: Executing [160@incoming_call:2] Set("SIP/criticall-00000189", "PREFIX_OPTION=oxe") in new stack [2021-05-20 08:38:29.407] DEBUG[3739] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: incoming_call Exten: 160 Priority: 2 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 Extension: 160 Application: Set AppData: PREFIX_OPTION=oxe [2021-05-20 08:38:29.407] DEBUG[4938] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: incoming_call Exten: 160 Priority: 2 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 Extension: 160 Application: Set AppData: PREFIX_OPTION=oxe [2021-05-20 08:38:29.407] DEBUG[16181][C-0000008f] pbx.c: Launching 'Gosub' [2021-05-20 08:38:29.407] VERBOSE[16181][C-0000008f] pbx.c: Executing [160@incoming_call:3] Gosub("SIP/criticall-00000189", "numoption-empty,s,1") in new stack [2021-05-20 08:38:29.407] DEBUG[3739] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: incoming_call Exten: 160 Priority: 3 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 Extension: 160 Application: Gosub AppData: numoption-empty,s,1 [2021-05-20 08:38:29.407] DEBUG[4938] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: incoming_call Exten: 160 Priority: 3 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 Extension: 160 Application: Gosub AppData: numoption-empty,s,1 [2021-05-20 08:38:29.407] DEBUG[16181][C-0000008f] pbx.c: Launching 'Return' [2021-05-20 08:38:29.407] VERBOSE[16181][C-0000008f] pbx.c: Executing [s@numoption-empty:1] Return("SIP/criticall-00000189", "") in new stack [2021-05-20 08:38:29.407] DEBUG[3739] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: numoption-empty Exten: s Priority: 1 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 Extension: s Application: Return AppData: [2021-05-20 08:38:29.407] DEBUG[4938] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: numoption-empty Exten: s Priority: 1 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 Extension: s Application: Return AppData: [2021-05-20 08:38:29.407] DEBUG[16181][C-0000008f] pbx_variables.c: Function CALLERID(num) result is '502' [2021-05-20 08:38:29.407] DEBUG[16181][C-0000008f] pbx_variables.c: Result of 'TRUNK_OFFSET' is '0' [2021-05-20 08:38:29.407] DEBUG[16181][C-0000008f] pbx.c: Launching 'AGI' [2021-05-20 08:38:29.407] VERBOSE[16181][C-0000008f] pbx.c: Executing [160@incoming_call:4] AGI("SIP/criticall-00000189", "removeOffset.php,502,0") in new stack [2021-05-20 08:38:29.407] DEBUG[3739] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: incoming_call Exten: 160 Priority: 4 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 Extension: 160 Application: AGI AppData: removeOffset.php,502,0 [2021-05-20 08:38:29.407] DEBUG[4938] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: incoming_call Exten: 160 Priority: 4 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 Extension: 160 Application: AGI AppData: removeOffset.php,502,0 [2021-05-20 08:38:29.410] VERBOSE[16181][C-0000008f] res_agi.c: Launched AGI Script /opt/prescom/var/lib/asterisk/agi-bin/removeOffset.php [2021-05-20 08:38:29.441] VERBOSE[16181][C-0000008f] res_agi.c: AGI Script removeOffset.php completed, returning 0 [2021-05-20 08:38:29.444] DEBUG[16181][C-0000008f] pbx_variables.c: Result of 'OFFSET_NUM' is '502' [2021-05-20 08:38:29.444] DEBUG[16181][C-0000008f] pbx.c: Launching 'Set' [2021-05-20 08:38:29.444] VERBOSE[16181][C-0000008f] pbx.c: Executing [160@incoming_call:5] Set("SIP/criticall-00000189", "CALLERID(num)=502") in new stack [2021-05-20 08:38:29.444] DEBUG[16181][C-0000008f] pbx.c: Launching 'Wait' [2021-05-20 08:38:29.444] VERBOSE[16181][C-0000008f] pbx.c: Executing [160@incoming_call:6] Wait("SIP/criticall-00000189", "2") in new stack [2021-05-20 08:38:29.444] DEBUG[4938] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: incoming_call Exten: 160 Priority: 5 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 Extension: 160 Application: Set AppData: CALLERID(num)=502 [2021-05-20 08:38:29.444] DEBUG[4938] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: incoming_call Exten: 160 Priority: 6 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 Extension: 160 Application: Wait AppData: 2 [2021-05-20 08:38:29.444] DEBUG[3739] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: incoming_call Exten: 160 Priority: 5 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 Extension: 160 Application: Set AppData: CALLERID(num)=502 [2021-05-20 08:38:29.444] DEBUG[3739] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: incoming_call Exten: 160 Priority: 6 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 Extension: 160 Application: Wait AppData: 2 [2021-05-20 08:38:30.080] DEBUG[3710] chan_sip.c: Auto destroying SIP dialog '3e33b81e0f5375f638a88073549a6aad@yy.yy.yy.yy:5060' [2021-05-20 08:38:30.081] DEBUG[3710] chan_sip.c: Destroying SIP dialog 3e33b81e0f5375f638a88073549a6aad@yy.yy.yy.yy:5060 [2021-05-20 08:38:30.081] VERBOSE[3710] chan_sip.c: Really destroying SIP dialog '3e33b81e0f5375f638a88073549a6aad@yy.yy.yy.yy:5060' Method: BYE [2021-05-20 08:38:30.081] DEBUG[3710] res_rtp_asterisk.c: (0x7f5e181de070) DTLS stop [2021-05-20 08:38:30.081] DEBUG[3710] res_rtp_asterisk.c: (0x7f5e181de070) DTLS srtp - stopped timeout timer' [2021-05-20 08:38:30.081] DEBUG[3710] res_rtp_asterisk.c: (0x7f5e181de070) DTLS srtp - stopped timeout timer' [2021-05-20 08:38:30.081] DEBUG[3710] res_rtp_asterisk.c: (0x7f5e181de070) ICE RTP transport deallocating [2021-05-20 08:38:30.081] DEBUG[3710] rtp_engine.c: Destroyed RTP instance '0x7f5e181de070' [2021-05-20 08:38:30.089] DEBUG[3710] chan_sip.c: Re-scheduled destruction of SIP call 64ea33d30803448d73a0bf7451f8e78c@xx.xx.xx.xx:5060 [2021-05-20 08:38:30.089] DEBUG[3710] chan_sip.c: Re-scheduled destruction of SIP call 153271c62b4d68df357495a579066bb4@xx.xx.xx.xx:5060 [2021-05-20 08:38:30.090] DEBUG[3710] chan_sip.c: Re-scheduled destruction of SIP call 6366ed7008ab1ecd61e4334d48e0ce9b@xx.xx.xx.xx:5060 [2021-05-20 08:38:30.091] DEBUG[3710] chan_sip.c: Re-scheduled destruction of SIP call 53ce3b56404af7277d20580b7f07eb3f@xx.xx.xx.xx:5060 [2021-05-20 08:38:30.091] DEBUG[3710] chan_sip.c: Re-scheduled destruction of SIP call 199f16fb20c0bb5b2b6802395a12b282@xx.xx.xx.xx:5060 [2021-05-20 08:38:30.969] DEBUG[3710] chan_sip.c: Stopping retransmission on '7adc68823723b19e14f53ea10d6df493@xx.xx.xx.xx:5060' of Request 102: Match Found [2021-05-20 08:38:30.970] DEBUG[3710] chan_sip.c: Auto destroying SIP dialog '7adc68823723b19e14f53ea10d6df493@xx.xx.xx.xx:5060' [2021-05-20 08:38:30.970] DEBUG[3710] chan_sip.c: Destroying SIP dialog 7adc68823723b19e14f53ea10d6df493@xx.xx.xx.xx:5060 [2021-05-20 08:38:30.970] DEBUG[3710] res_rtp_asterisk.c: (0x7f5ddc0393c0) DTLS stop [2021-05-20 08:38:30.970] DEBUG[3710] res_rtp_asterisk.c: (0x7f5ddc0393c0) DTLS srtp - stopped timeout timer' [2021-05-20 08:38:30.970] DEBUG[3710] res_rtp_asterisk.c: (0x7f5ddc0393c0) DTLS srtp - stopped timeout timer' [2021-05-20 08:38:30.970] DEBUG[3710] res_rtp_asterisk.c: (0x7f5ddc0393c0) ICE RTP transport deallocating [2021-05-20 08:38:30.970] DEBUG[3710] rtp_engine.c: Destroyed RTP instance '0x7f5ddc0393c0' [2021-05-20 08:38:30.971] DEBUG[3710] chan_sip.c: Stopping retransmission on '49c2682d77cc8c8865ac3e8973b6ec61@xx.xx.xx.xx:5060' of Request 102: Match Found [2021-05-20 08:38:30.971] DEBUG[3710] chan_sip.c: Auto destroying SIP dialog '49c2682d77cc8c8865ac3e8973b6ec61@xx.xx.xx.xx:5060' [2021-05-20 08:38:30.971] DEBUG[3710] chan_sip.c: Destroying SIP dialog 49c2682d77cc8c8865ac3e8973b6ec61@xx.xx.xx.xx:5060 [2021-05-20 08:38:30.971] DEBUG[3710] res_rtp_asterisk.c: (0x7f5e40013c70) DTLS stop [2021-05-20 08:38:30.971] DEBUG[3710] res_rtp_asterisk.c: (0x7f5e40013c70) DTLS srtp - stopped timeout timer' [2021-05-20 08:38:30.971] DEBUG[3710] res_rtp_asterisk.c: (0x7f5e40013c70) DTLS srtp - stopped timeout timer' [2021-05-20 08:38:30.971] DEBUG[3710] res_rtp_asterisk.c: (0x7f5e40013c70) ICE RTP transport deallocating [2021-05-20 08:38:30.971] DEBUG[3710] rtp_engine.c: Destroyed RTP instance '0x7f5e40013c70' [2021-05-20 08:38:30.972] DEBUG[3710] chan_sip.c: Stopping retransmission on '3e369eb90d09815a3059a9293d580faf@xx.xx.xx.xx:5060' of Request 102: Match Found [2021-05-20 08:38:30.972] DEBUG[3710] chan_sip.c: Auto destroying SIP dialog '3e369eb90d09815a3059a9293d580faf@xx.xx.xx.xx:5060' [2021-05-20 08:38:30.972] DEBUG[3710] chan_sip.c: Destroying SIP dialog 3e369eb90d09815a3059a9293d580faf@xx.xx.xx.xx:5060 [2021-05-20 08:38:30.972] DEBUG[3710] res_rtp_asterisk.c: (0x7f5e1809e4c0) DTLS stop [2021-05-20 08:38:30.972] DEBUG[3710] res_rtp_asterisk.c: (0x7f5e1809e4c0) DTLS srtp - stopped timeout timer' [2021-05-20 08:38:30.972] DEBUG[3710] res_rtp_asterisk.c: (0x7f5e1809e4c0) DTLS srtp - stopped timeout timer' [2021-05-20 08:38:30.972] DEBUG[3710] res_rtp_asterisk.c: (0x7f5e1809e4c0) ICE RTP transport deallocating [2021-05-20 08:38:30.972] DEBUG[3710] rtp_engine.c: Destroyed RTP instance '0x7f5e1809e4c0' [2021-05-20 08:38:30.973] DEBUG[3710] chan_sip.c: Stopping retransmission on '44089cc5567d63ef1cdd2d3c609dd242@xx.xx.xx.xx:5060' of Request 102: Match Found [2021-05-20 08:38:30.973] DEBUG[3710] chan_sip.c: Auto destroying SIP dialog '44089cc5567d63ef1cdd2d3c609dd242@xx.xx.xx.xx:5060' [2021-05-20 08:38:30.973] DEBUG[3710] chan_sip.c: Destroying SIP dialog 44089cc5567d63ef1cdd2d3c609dd242@xx.xx.xx.xx:5060 [2021-05-20 08:38:30.973] DEBUG[3710] res_rtp_asterisk.c: (0x7f5e4c082970) DTLS stop [2021-05-20 08:38:30.973] DEBUG[3710] res_rtp_asterisk.c: (0x7f5e4c082970) DTLS srtp - stopped timeout timer' [2021-05-20 08:38:30.973] DEBUG[3710] res_rtp_asterisk.c: (0x7f5e4c082970) DTLS srtp - stopped timeout timer' [2021-05-20 08:38:30.973] DEBUG[3710] res_rtp_asterisk.c: (0x7f5e4c082970) ICE RTP transport deallocating [2021-05-20 08:38:30.973] DEBUG[3710] rtp_engine.c: Destroyed RTP instance '0x7f5e4c082970' [2021-05-20 08:38:30.973] DEBUG[3710] chan_sip.c: Stopping retransmission on '0d6fdab73f1a2264437289015343a387@xx.xx.xx.xx:5060' of Request 102: Match Found [2021-05-20 08:38:30.973] DEBUG[3710] chan_sip.c: Auto destroying SIP dialog '0d6fdab73f1a2264437289015343a387@xx.xx.xx.xx:5060' [2021-05-20 08:38:30.973] DEBUG[3710] chan_sip.c: Destroying SIP dialog 0d6fdab73f1a2264437289015343a387@xx.xx.xx.xx:5060 [2021-05-20 08:38:30.973] DEBUG[3710] res_rtp_asterisk.c: (0x7f5dd414d830) DTLS stop [2021-05-20 08:38:30.973] DEBUG[3710] res_rtp_asterisk.c: (0x7f5dd414d830) DTLS srtp - stopped timeout timer' [2021-05-20 08:38:30.973] DEBUG[3710] res_rtp_asterisk.c: (0x7f5dd414d830) DTLS srtp - stopped timeout timer' [2021-05-20 08:38:30.973] DEBUG[3710] res_rtp_asterisk.c: (0x7f5dd414d830) ICE RTP transport deallocating [2021-05-20 08:38:30.973] DEBUG[3710] rtp_engine.c: Destroyed RTP instance '0x7f5dd414d830' [2021-05-20 08:38:31.446] DEBUG[16181][C-0000008f] pbx_variables.c: Result of 'EXTEN' is '160' [2021-05-20 08:38:31.446] DEBUG[16181][C-0000008f] pbx.c: Launching 'Goto' [2021-05-20 08:38:31.446] VERBOSE[16181][C-0000008f] pbx.c: Executing [160@incoming_call:7] Goto("SIP/criticall-00000189", "default,160,1") in new stack [2021-05-20 08:38:31.446] VERBOSE[16181][C-0000008f] pbx_builtins.c: Goto (default,160,1) [2021-05-20 08:38:31.446] DEBUG[16181][C-0000008f] pbx.c: Launching 'Ringing' [2021-05-20 08:38:31.446] VERBOSE[16181][C-0000008f] pbx.c: Executing [160@default:1] Ringing("SIP/criticall-00000189", "") in new stack [2021-05-20 08:38:31.446] VERBOSE[16181][C-0000008f] chan_sip.c: <--- Transmitting (no NAT) to yy.yy.yy.yy:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP yy.yy.yy.yy:5060;branch=z9hG4bK24975546;received=yy.yy.yy.yy From: ;tag=as3aa1aae5 To: ;tag=as28e65bf9 Call-ID: 5b44dd57162fc3e72a7c5ef204c538b6@yy.yy.yy.yy:5060 CSeq: 102 INVITE Server: L12893-16.16.0;Ast-PBX;L12917-1.0.46.0;Ast-Cfg criticall02 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Session-Expires: 120;refresher=uas Contact: Content-Length: 0 <------------> [2021-05-20 08:38:31.446] DEBUG[16181][C-0000008f] chan_sip.c: Trying to put 'SIP/2.0 180' onto UDP socket destined for yy.yy.yy.yy:5060 [2021-05-20 08:38:31.446] DEBUG[16181][C-0000008f] pbx.c: Launching 'Set' [2021-05-20 08:38:31.446] DEBUG[3739] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: incoming_call Exten: 160 Priority: 7 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 Extension: 160 Application: Goto AppData: default,160,1 [2021-05-20 08:38:31.446] VERBOSE[16181][C-0000008f] pbx.c: Executing [160@default:2] Set("SIP/criticall-00000189", "PRIORITY_VALUE=2") in new stack [2021-05-20 08:38:31.446] DEBUG[3739] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: default Exten: 160 Priority: 1 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 Extension: 160 Application: Ringing AppData: [2021-05-20 08:38:31.446] DEBUG[16181][C-0000008f] pbx.c: Launching 'Set' [2021-05-20 08:38:31.446] VERBOSE[16181][C-0000008f] pbx.c: Executing [160@default:3] Set("SIP/criticall-00000189", "SERVICE_ID=1") in new stack [2021-05-20 08:38:31.446] DEBUG[16181][C-0000008f] pbx_variables.c: Function CALLERID(num) result is '502' [2021-05-20 08:38:31.446] DEBUG[16181][C-0000008f] pbx_variables.c: Function DIALPLAN_EXISTS(priority_numbers,502,1) result is '1' [2021-05-20 08:38:31.446] DEBUG[16181][C-0000008f] pbx_variables.c: Function CALLERID(num) result is '502' [2021-05-20 08:38:31.446] DEBUG[16181][C-0000008f] pbx.c: Launching 'GosubIf' [2021-05-20 08:38:31.446] VERBOSE[16181][C-0000008f] pbx.c: Executing [160@default:4] GosubIf("SIP/criticall-00000189", "1?priority_numbers,502,1:priority_numbers,unknown__,1") in new stack [2021-05-20 08:38:31.446] DEBUG[16181][C-0000008f] pbx.c: Launching 'Set' [2021-05-20 08:38:31.446] VERBOSE[16181][C-0000008f] pbx.c: Executing [502@priority_numbers:1] Set("SIP/criticall-00000189", "PRIORITY_VALUE=4") in new stack [2021-05-20 08:38:31.446] DEBUG[16181][C-0000008f] pbx.c: Launching 'Return' [2021-05-20 08:38:31.446] VERBOSE[16181][C-0000008f] pbx.c: Executing [502@priority_numbers:2] Return("SIP/criticall-00000189", "") in new stack [2021-05-20 08:38:31.446] DEBUG[16181][C-0000008f] pbx_variables.c: Function GCM(category) result is 'dynamic' [2021-05-20 08:38:31.446] DEBUG[16181][C-0000008f] pbx_variables.c: Expression result is '0' [2021-05-20 08:38:31.446] DEBUG[16181][C-0000008f] pbx.c: Launching 'GotoIf' [2021-05-20 08:38:31.446] VERBOSE[16181][C-0000008f] pbx.c: Executing [160@default:5] GotoIf("SIP/criticall-00000189", "0?:bridgedial") in new stack [2021-05-20 08:38:31.446] VERBOSE[16181][C-0000008f] pbx_builtins.c: Goto (default,160,7) [2021-05-20 08:38:31.446] DEBUG[16181][C-0000008f] pbx_variables.c: Result of 'PREFIX_OPTION' is 'oxe' [2021-05-20 08:38:31.446] DEBUG[16181][C-0000008f] pbx.c: Launching 'Stasis' [2021-05-20 08:38:31.446] VERBOSE[16181][C-0000008f] pbx.c: Executing [160@default:7] Stasis("SIP/criticall-00000189", "bridge-dial,incall,oxe") in new stack [2021-05-20 08:38:31.446] DEBUG[16181][C-0000008f] stasis/app.c: Channel '1621492709.539' is 1 interested in bridge-dial [2021-05-20 08:38:31.447] DEBUG[4938] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: incoming_call Exten: 160 Priority: 7 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 Extension: 160 Application: Goto AppData: default,160,1 [2021-05-20 08:38:31.447] DEBUG[4938] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: default Exten: 160 Priority: 1 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 Extension: 160 Application: Ringing AppData: [2021-05-20 08:38:31.447] DEBUG[3811] res_http_websocket.c: Writing websocket string of length 732 [2021-05-20 08:38:31.447] DEBUG[3811] res_http_websocket.c: Writing websocket text frame, length 732 [2021-05-20 08:38:31.447] DEBUG[3739] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: default Exten: 160 Priority: 2 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 Extension: 160 Application: Set AppData: PRIORITY_VALUE=2 [2021-05-20 08:38:31.447] DEBUG[3739] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: default Exten: 160 Priority: 3 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 Extension: 160 Application: Set AppData: SERVICE_ID=1 [2021-05-20 08:38:31.447] DEBUG[3739] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: default Exten: 160 Priority: 4 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 Extension: 160 Application: GosubIf AppData: 1?priority_numbers,502,1:priority_numbers,unknown__,1 [2021-05-20 08:38:31.447] DEBUG[3739] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: priority_numbers Exten: 502 Priority: 1 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 Extension: 502 Application: Set AppData: PRIORITY_VALUE=4 [2021-05-20 08:38:31.447] DEBUG[3739] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: priority_numbers Exten: 502 Priority: 2 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 Extension: 502 Application: Return AppData: [2021-05-20 08:38:31.447] DEBUG[3739] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: default Exten: 160 Priority: 5 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 Extension: 160 Application: GotoIf AppData: 0?:bridgedial [2021-05-20 08:38:31.447] DEBUG[3739] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: default Exten: 160 Priority: 7 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 Extension: 160 Application: Stasis AppData: bridge-dial,incall,oxe [2021-05-20 08:38:31.449] DEBUG[4938] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: default Exten: 160 Priority: 2 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 Extension: 160 Application: Set AppData: PRIORITY_VALUE=2 [2021-05-20 08:38:31.449] DEBUG[4938] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: default Exten: 160 Priority: 3 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 Extension: 160 Application: Set AppData: SERVICE_ID=1 [2021-05-20 08:38:31.449] DEBUG[4938] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: default Exten: 160 Priority: 4 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 Extension: 160 Application: GosubIf AppData: 1?priority_numbers,502,1:priority_numbers,unknown__,1 [2021-05-20 08:38:31.449] DEBUG[4938] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: priority_numbers Exten: 502 Priority: 1 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 Extension: 502 Application: Set AppData: PRIORITY_VALUE=4 [2021-05-20 08:38:31.449] DEBUG[4938] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: priority_numbers Exten: 502 Priority: 2 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 Extension: 502 Application: Return AppData: [2021-05-20 08:38:31.449] DEBUG[4938] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: default Exten: 160 Priority: 5 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 Extension: 160 Application: GotoIf AppData: 0?:bridgedial [2021-05-20 08:38:31.449] DEBUG[4938] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: default Exten: 160 Priority: 7 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 Extension: 160 Application: Stasis AppData: bridge-dial,incall,oxe [2021-05-20 08:38:31.451] DEBUG[16303] http.c: HTTP opening session. Top level [2021-05-20 08:38:31.451] DEBUG[16303] http.c: HTTP Request URI is /ari/channels/1621492709.539/variable?variable=PRIORITY_VALUE [2021-05-20 08:38:31.451] DEBUG[16303] http.c: match request [ari/channels/1621492709.539/variable] with handler [httpstatus] len 10 [2021-05-20 08:38:31.451] DEBUG[16303] http.c: match request [ari/channels/1621492709.539/variable] with handler [ari] len 3 [2021-05-20 08:38:31.451] DEBUG[16303] http.c: Match made with [ari] [2021-05-20 08:38:31.451] DEBUG[16301] http.c: HTTP opening session. Top level [2021-05-20 08:38:31.451] DEBUG[16301] http.c: HTTP Request URI is /ari/channels/1621492709.539/variable?variable=PLAY_ANNOUNCE [2021-05-20 08:38:31.451] DEBUG[16301] http.c: match request [ari/channels/1621492709.539/variable] with handler [httpstatus] len 10 [2021-05-20 08:38:31.451] DEBUG[16301] http.c: match request [ari/channels/1621492709.539/variable] with handler [ari] len 3 [2021-05-20 08:38:31.451] DEBUG[16301] http.c: Match made with [ari] [2021-05-20 08:38:31.451] DEBUG[16301] res_ari.c: Finding handler for channels/1621492709.539/variable [2021-05-20 08:38:31.451] DEBUG[16301] res_ari.c: Finding handler for channels [2021-05-20 08:38:31.451] DEBUG[16301] res_ari.c: Checking ari events: Didn't match channels [2021-05-20 08:38:31.451] DEBUG[16301] res_ari.c: Checking ari playbacks: Didn't match channels [2021-05-20 08:38:31.451] DEBUG[16301] res_ari.c: Checking ari sounds: Didn't match channels [2021-05-20 08:38:31.451] DEBUG[16301] res_ari.c: Checking ari endpoints: Didn't match channels [2021-05-20 08:38:31.451] DEBUG[16301] res_ari.c: Checking ari applications: Didn't match channels [2021-05-20 08:38:31.451] DEBUG[16301] res_ari.c: Checking ari deviceStates: Didn't match channels [2021-05-20 08:38:31.451] DEBUG[16301] res_ari.c: Checking ari asterisk: Didn't match channels [2021-05-20 08:38:31.451] DEBUG[16301] res_ari.c: Checking ari bridges: Didn't match channels [2021-05-20 08:38:31.451] DEBUG[16301] res_ari.c: Checking ari channels: Explicit match with channels [2021-05-20 08:38:31.451] DEBUG[16301] res_ari.c: Finding handler for 1621492709.539 [2021-05-20 08:38:31.451] DEBUG[16301] res_ari.c: Checking channels create: Didn't match 1621492709.539 [2021-05-20 08:38:31.451] DEBUG[16301] res_ari.c: Checking channels channelId: Matched wildcard. [2021-05-20 08:38:31.451] DEBUG[16301] res_ari.c: Checking channels externalMedia: Didn't match 1621492709.539 [2021-05-20 08:38:31.451] DEBUG[16301] res_ari.c: No explicit handler found for 1621492709.539. Using wildcard channelId. [2021-05-20 08:38:31.451] DEBUG[16301] res_ari.c: Finding handler for variable [2021-05-20 08:38:31.451] DEBUG[16301] res_ari.c: Checking channelId continue: Didn't match variable [2021-05-20 08:38:31.451] DEBUG[16301] res_ari.c: Checking channelId move: Didn't match variable [2021-05-20 08:38:31.451] DEBUG[16301] res_ari.c: Checking channelId redirect: Didn't match variable [2021-05-20 08:38:31.451] DEBUG[16301] res_ari.c: Checking channelId answer: Didn't match variable [2021-05-20 08:38:31.451] DEBUG[16301] res_ari.c: Checking channelId ring: Didn't match variable [2021-05-20 08:38:31.451] DEBUG[16301] res_ari.c: Checking channelId dtmf: Didn't match variable [2021-05-20 08:38:31.451] DEBUG[16301] res_ari.c: Checking channelId mute: Didn't match variable [2021-05-20 08:38:31.451] DEBUG[16301] res_ari.c: Checking channelId hold: Didn't match variable [2021-05-20 08:38:31.451] DEBUG[16301] res_ari.c: Checking channelId queue_ptt: Didn't match variable [2021-05-20 08:38:31.451] DEBUG[16301] res_ari.c: Checking channelId send_ptt: Didn't match variable [2021-05-20 08:38:31.451] DEBUG[16301] res_ari.c: Checking channelId moh: Didn't match variable [2021-05-20 08:38:31.451] DEBUG[16301] res_ari.c: Checking channelId silence: Didn't match variable [2021-05-20 08:38:31.451] DEBUG[16301] res_ari.c: Checking channelId play: Didn't match variable [2021-05-20 08:38:31.451] DEBUG[16301] res_ari.c: Checking channelId record: Didn't match variable [2021-05-20 08:38:31.451] DEBUG[16301] res_ari.c: Checking channelId variable: Explicit match with variable [2021-05-20 08:38:31.451] DEBUG[16301] pbx_variables.c: Result of 'PLAY_ANNOUNCE' is NULL [2021-05-20 08:38:31.451] DEBUG[16304] http.c: HTTP opening session. Top level [2021-05-20 08:38:31.451] DEBUG[16304] http.c: HTTP Request URI is /ari/channels/1621492709.539/variable?variable=CALLERID(dnid) [2021-05-20 08:38:31.451] DEBUG[16304] http.c: match request [ari/channels/1621492709.539/variable] with handler [httpstatus] len 10 [2021-05-20 08:38:31.451] DEBUG[16304] http.c: match request [ari/channels/1621492709.539/variable] with handler [ari] len 3 [2021-05-20 08:38:31.451] DEBUG[16304] http.c: Match made with [ari] [2021-05-20 08:38:31.451] DEBUG[16304] res_ari.c: Finding handler for channels/1621492709.539/variable [2021-05-20 08:38:31.451] DEBUG[16304] res_ari.c: Finding handler for channels [2021-05-20 08:38:31.451] DEBUG[16304] res_ari.c: Checking ari events: Didn't match channels [2021-05-20 08:38:31.451] DEBUG[16304] res_ari.c: Checking ari playbacks: Didn't match channels [2021-05-20 08:38:31.452] DEBUG[16304] res_ari.c: Checking ari sounds: Didn't match channels [2021-05-20 08:38:31.452] DEBUG[16304] res_ari.c: Checking ari endpoints: Didn't match channels [2021-05-20 08:38:31.452] DEBUG[16304] res_ari.c: Checking ari applications: Didn't match channels [2021-05-20 08:38:31.452] DEBUG[16304] res_ari.c: Checking ari deviceStates: Didn't match channels [2021-05-20 08:38:31.452] DEBUG[16304] res_ari.c: Checking ari asterisk: Didn't match channels [2021-05-20 08:38:31.452] DEBUG[16304] res_ari.c: Checking ari bridges: Didn't match channels [2021-05-20 08:38:31.452] DEBUG[16304] res_ari.c: Checking ari channels: Explicit match with channels [2021-05-20 08:38:31.452] DEBUG[16304] res_ari.c: Finding handler for 1621492709.539 [2021-05-20 08:38:31.452] DEBUG[16304] res_ari.c: Checking channels create: Didn't match 1621492709.539 [2021-05-20 08:38:31.452] DEBUG[16304] res_ari.c: Checking channels channelId: Matched wildcard. [2021-05-20 08:38:31.452] DEBUG[16303] res_ari.c: Finding handler for channels/1621492709.539/variable [2021-05-20 08:38:31.452] DEBUG[16303] res_ari.c: Finding handler for channels [2021-05-20 08:38:31.452] DEBUG[16303] res_ari.c: Checking ari events: Didn't match channels [2021-05-20 08:38:31.452] DEBUG[16303] res_ari.c: Checking ari playbacks: Didn't match channels [2021-05-20 08:38:31.452] DEBUG[16303] res_ari.c: Checking ari sounds: Didn't match channels [2021-05-20 08:38:31.452] DEBUG[16303] res_ari.c: Checking ari endpoints: Didn't match channels [2021-05-20 08:38:31.452] DEBUG[16303] res_ari.c: Checking ari applications: Didn't match channels [2021-05-20 08:38:31.452] DEBUG[16303] res_ari.c: Checking ari deviceStates: Didn't match channels [2021-05-20 08:38:31.452] DEBUG[16303] res_ari.c: Checking ari asterisk: Didn't match channels [2021-05-20 08:38:31.452] DEBUG[16303] res_ari.c: Checking ari bridges: Didn't match channels [2021-05-20 08:38:31.452] DEBUG[16303] res_ari.c: Checking ari channels: Explicit match with channels [2021-05-20 08:38:31.452] DEBUG[16303] res_ari.c: Finding handler for 1621492709.539 [2021-05-20 08:38:31.452] DEBUG[16303] res_ari.c: Checking channels create: Didn't match 1621492709.539 [2021-05-20 08:38:31.452] DEBUG[16303] res_ari.c: Checking channels channelId: Matched wildcard. [2021-05-20 08:38:31.452] DEBUG[16303] res_ari.c: Checking channels externalMedia: Didn't match 1621492709.539 [2021-05-20 08:38:31.452] DEBUG[16303] res_ari.c: No explicit handler found for 1621492709.539. Using wildcard channelId. [2021-05-20 08:38:31.452] DEBUG[16303] res_ari.c: Finding handler for variable [2021-05-20 08:38:31.452] DEBUG[16303] res_ari.c: Checking channelId continue: Didn't match variable [2021-05-20 08:38:31.452] DEBUG[16303] res_ari.c: Checking channelId move: Didn't match variable [2021-05-20 08:38:31.452] DEBUG[16303] res_ari.c: Checking channelId redirect: Didn't match variable [2021-05-20 08:38:31.452] DEBUG[16303] res_ari.c: Checking channelId answer: Didn't match variable [2021-05-20 08:38:31.452] DEBUG[16303] res_ari.c: Checking channelId ring: Didn't match variable [2021-05-20 08:38:31.452] DEBUG[16303] res_ari.c: Checking channelId dtmf: Didn't match variable [2021-05-20 08:38:31.452] DEBUG[16303] res_ari.c: Checking channelId mute: Didn't match variable [2021-05-20 08:38:31.452] DEBUG[16304] res_ari.c: Checking channels externalMedia: Didn't match 1621492709.539 [2021-05-20 08:38:31.452] DEBUG[16303] res_ari.c: Checking channelId hold: Didn't match variable [2021-05-20 08:38:31.452] DEBUG[16303] res_ari.c: Checking channelId queue_ptt: Didn't match variable [2021-05-20 08:38:31.452] DEBUG[16303] res_ari.c: Checking channelId send_ptt: Didn't match variable [2021-05-20 08:38:31.452] DEBUG[16303] res_ari.c: Checking channelId moh: Didn't match variable [2021-05-20 08:38:31.452] DEBUG[16303] res_ari.c: Checking channelId silence: Didn't match variable [2021-05-20 08:38:31.452] DEBUG[16303] res_ari.c: Checking channelId play: Didn't match variable [2021-05-20 08:38:31.452] DEBUG[16303] res_ari.c: Checking channelId record: Didn't match variable [2021-05-20 08:38:31.452] DEBUG[16303] res_ari.c: Checking channelId variable: Explicit match with variable [2021-05-20 08:38:31.452] DEBUG[16303] pbx_variables.c: Result of 'PRIORITY_VALUE' is '4' [2021-05-20 08:38:31.452] DEBUG[16304] res_ari.c: No explicit handler found for 1621492709.539. Using wildcard channelId. [2021-05-20 08:38:31.452] DEBUG[16304] res_ari.c: Finding handler for variable [2021-05-20 08:38:31.452] DEBUG[16304] res_ari.c: Checking channelId continue: Didn't match variable [2021-05-20 08:38:31.452] DEBUG[16304] res_ari.c: Checking channelId move: Didn't match variable [2021-05-20 08:38:31.452] DEBUG[16304] res_ari.c: Checking channelId redirect: Didn't match variable [2021-05-20 08:38:31.452] DEBUG[16304] res_ari.c: Checking channelId answer: Didn't match variable [2021-05-20 08:38:31.452] DEBUG[16304] res_ari.c: Checking channelId ring: Didn't match variable [2021-05-20 08:38:31.452] DEBUG[16304] res_ari.c: Checking channelId dtmf: Didn't match variable [2021-05-20 08:38:31.452] DEBUG[16304] res_ari.c: Checking channelId mute: Didn't match variable [2021-05-20 08:38:31.452] DEBUG[16304] res_ari.c: Checking channelId hold: Didn't match variable [2021-05-20 08:38:31.452] DEBUG[16304] res_ari.c: Checking channelId queue_ptt: Didn't match variable [2021-05-20 08:38:31.452] DEBUG[16304] res_ari.c: Checking channelId send_ptt: Didn't match variable [2021-05-20 08:38:31.452] DEBUG[16304] res_ari.c: Checking channelId moh: Didn't match variable [2021-05-20 08:38:31.452] DEBUG[16304] res_ari.c: Checking channelId silence: Didn't match variable [2021-05-20 08:38:31.452] DEBUG[16304] res_ari.c: Checking channelId play: Didn't match variable [2021-05-20 08:38:31.452] DEBUG[16303] http.c: HTTP keeping session open. status_code:200 [2021-05-20 08:38:31.452] DEBUG[16304] res_ari.c: Checking channelId record: Didn't match variable [2021-05-20 08:38:31.452] DEBUG[16301] http.c: HTTP keeping session open. status_code:404 [2021-05-20 08:38:31.452] DEBUG[16301] http.c: HTTP closing session. Top level [2021-05-20 08:38:31.452] DEBUG[16304] res_ari.c: Checking channelId variable: Explicit match with variable [2021-05-20 08:38:31.452] DEBUG[16303] http.c: HTTP closing session. Top level [2021-05-20 08:38:31.453] DEBUG[16304] http.c: HTTP keeping session open. status_code:200 [2021-05-20 08:38:31.453] DEBUG[16304] http.c: HTTP closing session. Top level [2021-05-20 08:38:31.453] DEBUG[16302] http.c: HTTP opening session. Top level [2021-05-20 08:38:31.453] DEBUG[16300] http.c: HTTP opening session. Top level [2021-05-20 08:38:31.453] DEBUG[16302] http.c: HTTP Request URI is /ari/channels/1621492709.539/variable?variable=SERVICE_ID [2021-05-20 08:38:31.453] DEBUG[16302] http.c: match request [ari/channels/1621492709.539/variable] with handler [httpstatus] len 10 [2021-05-20 08:38:31.453] DEBUG[16302] http.c: match request [ari/channels/1621492709.539/variable] with handler [ari] len 3 [2021-05-20 08:38:31.453] DEBUG[16302] http.c: Match made with [ari] [2021-05-20 08:38:31.453] DEBUG[16300] http.c: HTTP Request URI is /ari/applications/noOp/subscription?eventSource=channel%3A1621492709.539 [2021-05-20 08:38:31.453] DEBUG[16300] http.c: match request [ari/applications/noOp/subscription] with handler [httpstatus] len 10 [2021-05-20 08:38:31.453] DEBUG[16300] http.c: match request [ari/applications/noOp/subscription] with handler [ari] len 3 [2021-05-20 08:38:31.453] DEBUG[16302] res_ari.c: Finding handler for channels/1621492709.539/variable [2021-05-20 08:38:31.453] DEBUG[16300] http.c: Match made with [ari] [2021-05-20 08:38:31.453] DEBUG[16302] res_ari.c: Finding handler for channels [2021-05-20 08:38:31.453] DEBUG[16302] res_ari.c: Checking ari events: Didn't match channels [2021-05-20 08:38:31.453] DEBUG[16300] res_ari.c: Finding handler for applications/noOp/subscription [2021-05-20 08:38:31.453] DEBUG[16302] res_ari.c: Checking ari playbacks: Didn't match channels [2021-05-20 08:38:31.453] DEBUG[16300] res_ari.c: Finding handler for applications [2021-05-20 08:38:31.453] DEBUG[16300] res_ari.c: Checking ari events: Didn't match applications [2021-05-20 08:38:31.453] DEBUG[16302] res_ari.c: Checking ari sounds: Didn't match channels [2021-05-20 08:38:31.453] DEBUG[16300] res_ari.c: Checking ari playbacks: Didn't match applications [2021-05-20 08:38:31.453] DEBUG[16300] res_ari.c: Checking ari sounds: Didn't match applications [2021-05-20 08:38:31.453] DEBUG[16300] res_ari.c: Checking ari endpoints: Didn't match applications [2021-05-20 08:38:31.453] DEBUG[16302] res_ari.c: Checking ari endpoints: Didn't match channels [2021-05-20 08:38:31.453] DEBUG[16300] res_ari.c: Checking ari applications: Explicit match with applications [2021-05-20 08:38:31.453] DEBUG[16300] res_ari.c: Finding handler for noOp [2021-05-20 08:38:31.453] DEBUG[16302] res_ari.c: Checking ari applications: Didn't match channels [2021-05-20 08:38:31.453] DEBUG[16300] res_ari.c: Checking applications applicationName: Matched wildcard. [2021-05-20 08:38:31.453] DEBUG[16302] res_ari.c: Checking ari deviceStates: Didn't match channels [2021-05-20 08:38:31.453] DEBUG[16300] res_ari.c: No explicit handler found for noOp. Using wildcard applicationName. [2021-05-20 08:38:31.453] DEBUG[16300] res_ari.c: Finding handler for subscription [2021-05-20 08:38:31.453] DEBUG[16302] res_ari.c: Checking ari asterisk: Didn't match channels [2021-05-20 08:38:31.453] DEBUG[16300] res_ari.c: Checking applicationName subscription: Explicit match with subscription [2021-05-20 08:38:31.453] DEBUG[16302] res_ari.c: Checking ari bridges: Didn't match channels [2021-05-20 08:38:31.453] DEBUG[16302] res_ari.c: Checking ari channels: Explicit match with channels [2021-05-20 08:38:31.453] DEBUG[16302] res_ari.c: Finding handler for 1621492709.539 [2021-05-20 08:38:31.453] DEBUG[16300] res_stasis.c: noOp: Checking channel:1621492709.539 [2021-05-20 08:38:31.453] DEBUG[16302] res_ari.c: Checking channels create: Didn't match 1621492709.539 [2021-05-20 08:38:31.453] DEBUG[16300] res_stasis.c: noOp: Subscribing to channel:1621492709.539 [2021-05-20 08:38:31.453] DEBUG[16302] res_ari.c: Checking channels channelId: Matched wildcard. [2021-05-20 08:38:31.453] DEBUG[16302] res_ari.c: Checking channels externalMedia: Didn't match 1621492709.539 [2021-05-20 08:38:31.453] DEBUG[16302] res_ari.c: No explicit handler found for 1621492709.539. Using wildcard channelId. [2021-05-20 08:38:31.453] DEBUG[16300] stasis/app.c: Channel '1621492709.539' is 1 interested in noOp [2021-05-20 08:38:31.453] DEBUG[16300] res_stasis.c: noOp: Successful; setting results [2021-05-20 08:38:31.454] DEBUG[16300] http.c: HTTP keeping session open. status_code:200 [2021-05-20 08:38:31.454] DEBUG[16300] http.c: HTTP closing session. Top level [2021-05-20 08:38:31.453] DEBUG[16302] res_ari.c: Finding handler for variable [2021-05-20 08:38:31.454] DEBUG[16302] res_ari.c: Checking channelId continue: Didn't match variable [2021-05-20 08:38:31.454] DEBUG[16302] res_ari.c: Checking channelId move: Didn't match variable [2021-05-20 08:38:31.454] DEBUG[16302] res_ari.c: Checking channelId redirect: Didn't match variable [2021-05-20 08:38:31.454] DEBUG[16302] res_ari.c: Checking channelId answer: Didn't match variable [2021-05-20 08:38:31.454] DEBUG[16302] res_ari.c: Checking channelId ring: Didn't match variable [2021-05-20 08:38:31.454] DEBUG[16302] res_ari.c: Checking channelId dtmf: Didn't match variable [2021-05-20 08:38:31.454] DEBUG[16302] res_ari.c: Checking channelId mute: Didn't match variable [2021-05-20 08:38:31.454] DEBUG[16302] res_ari.c: Checking channelId hold: Didn't match variable [2021-05-20 08:38:31.454] DEBUG[16302] res_ari.c: Checking channelId queue_ptt: Didn't match variable [2021-05-20 08:38:31.454] DEBUG[16302] res_ari.c: Checking channelId send_ptt: Didn't match variable [2021-05-20 08:38:31.454] DEBUG[16302] res_ari.c: Checking channelId moh: Didn't match variable [2021-05-20 08:38:31.454] DEBUG[16302] res_ari.c: Checking channelId silence: Didn't match variable [2021-05-20 08:38:31.454] DEBUG[16302] res_ari.c: Checking channelId play: Didn't match variable [2021-05-20 08:38:31.454] DEBUG[16302] res_ari.c: Checking channelId record: Didn't match variable [2021-05-20 08:38:31.454] DEBUG[16302] res_ari.c: Checking channelId variable: Explicit match with variable [2021-05-20 08:38:31.454] DEBUG[16302] pbx_variables.c: Result of 'SERVICE_ID' is '1' [2021-05-20 08:38:31.455] DEBUG[16302] http.c: HTTP keeping session open. status_code:200 [2021-05-20 08:38:31.455] DEBUG[16302] http.c: HTTP closing session. Top level [2021-05-20 08:38:31.457] DEBUG[16305] http.c: HTTP opening session. Top level [2021-05-20 08:38:31.457] DEBUG[16305] http.c: HTTP Request URI is /ari/channels/1621492709.539/ring [2021-05-20 08:38:31.457] DEBUG[16305] http.c: match request [ari/channels/1621492709.539/ring] with handler [httpstatus] len 10 [2021-05-20 08:38:31.457] DEBUG[16305] http.c: match request [ari/channels/1621492709.539/ring] with handler [ari] len 3 [2021-05-20 08:38:31.457] DEBUG[16305] http.c: Match made with [ari] [2021-05-20 08:38:31.457] DEBUG[16305] res_ari.c: Finding handler for channels/1621492709.539/ring [2021-05-20 08:38:31.457] DEBUG[16305] res_ari.c: Finding handler for channels [2021-05-20 08:38:31.457] DEBUG[16305] res_ari.c: Checking ari events: Didn't match channels [2021-05-20 08:38:31.457] DEBUG[16305] res_ari.c: Checking ari playbacks: Didn't match channels [2021-05-20 08:38:31.457] DEBUG[16305] res_ari.c: Checking ari sounds: Didn't match channels [2021-05-20 08:38:31.457] DEBUG[16305] res_ari.c: Checking ari endpoints: Didn't match channels [2021-05-20 08:38:31.457] DEBUG[16305] res_ari.c: Checking ari applications: Didn't match channels [2021-05-20 08:38:31.457] DEBUG[16305] res_ari.c: Checking ari deviceStates: Didn't match channels [2021-05-20 08:38:31.457] DEBUG[16305] res_ari.c: Checking ari asterisk: Didn't match channels [2021-05-20 08:38:31.457] DEBUG[16305] res_ari.c: Checking ari bridges: Didn't match channels [2021-05-20 08:38:31.457] DEBUG[16305] res_ari.c: Checking ari channels: Explicit match with channels [2021-05-20 08:38:31.457] DEBUG[16305] res_ari.c: Finding handler for 1621492709.539 [2021-05-20 08:38:31.457] DEBUG[16305] res_ari.c: Checking channels create: Didn't match 1621492709.539 [2021-05-20 08:38:31.457] DEBUG[16305] res_ari.c: Checking channels channelId: Matched wildcard. [2021-05-20 08:38:31.457] DEBUG[16305] res_ari.c: Checking channels externalMedia: Didn't match 1621492709.539 [2021-05-20 08:38:31.457] DEBUG[16305] res_ari.c: No explicit handler found for 1621492709.539. Using wildcard channelId. [2021-05-20 08:38:31.457] DEBUG[16305] res_ari.c: Finding handler for ring [2021-05-20 08:38:31.457] DEBUG[16305] res_ari.c: Checking channelId continue: Didn't match ring [2021-05-20 08:38:31.457] DEBUG[16305] res_ari.c: Checking channelId move: Didn't match ring [2021-05-20 08:38:31.457] DEBUG[16305] res_ari.c: Checking channelId redirect: Didn't match ring [2021-05-20 08:38:31.457] DEBUG[16305] res_ari.c: Checking channelId answer: Didn't match ring [2021-05-20 08:38:31.457] DEBUG[16305] res_ari.c: Checking channelId ring: Explicit match with ring [2021-05-20 08:38:31.457] DEBUG[16305] http.c: HTTP keeping session open. status_code:204 [2021-05-20 08:38:31.458] DEBUG[16305] http.c: HTTP closing session. Top level [2021-05-20 08:38:31.647] VERBOSE[16181][C-0000008f] chan_sip.c: <--- Transmitting (no NAT) to yy.yy.yy.yy:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP yy.yy.yy.yy:5060;branch=z9hG4bK24975546;received=yy.yy.yy.yy From: ;tag=as3aa1aae5 To: ;tag=as28e65bf9 Call-ID: 5b44dd57162fc3e72a7c5ef204c538b6@yy.yy.yy.yy:5060 CSeq: 102 INVITE Server: L12893-16.16.0;Ast-PBX;L12917-1.0.46.0;Ast-Cfg criticall02 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Session-Expires: 120;refresher=uas Contact: Content-Length: 0 <------------> [2021-05-20 08:38:31.647] DEBUG[16181][C-0000008f] chan_sip.c: Trying to put 'SIP/2.0 180' onto UDP socket destined for yy.yy.yy.yy:5060 [2021-05-20 08:38:31.760] DEBUG[16309] http.c: HTTP opening session. Top level [2021-05-20 08:38:31.760] DEBUG[16309] http.c: HTTP Request URI is /ari/channels/1621492699.525/continue?context=pos&extension=501&priority=1 [2021-05-20 08:38:31.760] DEBUG[16309] http.c: match request [ari/channels/1621492699.525/continue] with handler [httpstatus] len 10 [2021-05-20 08:38:31.760] DEBUG[16309] http.c: match request [ari/channels/1621492699.525/continue] with handler [ari] len 3 [2021-05-20 08:38:31.760] DEBUG[16309] http.c: Match made with [ari] [2021-05-20 08:38:31.760] DEBUG[16309] res_ari.c: Finding handler for channels/1621492699.525/continue [2021-05-20 08:38:31.760] DEBUG[16309] res_ari.c: Finding handler for channels [2021-05-20 08:38:31.760] DEBUG[16309] res_ari.c: Checking ari events: Didn't match channels [2021-05-20 08:38:31.760] DEBUG[16309] res_ari.c: Checking ari playbacks: Didn't match channels [2021-05-20 08:38:31.760] DEBUG[16309] res_ari.c: Checking ari sounds: Didn't match channels [2021-05-20 08:38:31.760] DEBUG[16309] res_ari.c: Checking ari endpoints: Didn't match channels [2021-05-20 08:38:31.760] DEBUG[16309] res_ari.c: Checking ari applications: Didn't match channels [2021-05-20 08:38:31.760] DEBUG[16309] res_ari.c: Checking ari deviceStates: Didn't match channels [2021-05-20 08:38:31.760] DEBUG[16309] res_ari.c: Checking ari asterisk: Didn't match channels [2021-05-20 08:38:31.760] DEBUG[16309] res_ari.c: Checking ari bridges: Didn't match channels [2021-05-20 08:38:31.760] DEBUG[16309] res_ari.c: Checking ari channels: Explicit match with channels [2021-05-20 08:38:31.760] DEBUG[16309] res_ari.c: Finding handler for 1621492699.525 [2021-05-20 08:38:31.760] DEBUG[16309] res_ari.c: Checking channels create: Didn't match 1621492699.525 [2021-05-20 08:38:31.760] DEBUG[16309] res_ari.c: Checking channels channelId: Matched wildcard. [2021-05-20 08:38:31.760] DEBUG[16309] res_ari.c: Checking channels externalMedia: Didn't match 1621492699.525 [2021-05-20 08:38:31.760] DEBUG[16309] res_ari.c: No explicit handler found for 1621492699.525. Using wildcard channelId. [2021-05-20 08:38:31.760] DEBUG[16309] res_ari.c: Finding handler for continue [2021-05-20 08:38:31.760] DEBUG[16309] res_ari.c: Checking channelId continue: Explicit match with continue [2021-05-20 08:38:31.761] DEBUG[16309] http.c: HTTP keeping session open. status_code:404 [2021-05-20 08:38:31.761] DEBUG[16309] http.c: HTTP closing session. Top level [2021-05-20 08:38:31.840] VERBOSE[3710] chan_sip.c: <--- SIP read from UDP:yy.yy.yy.yy:5060 ---> CANCEL sip:160@xx.xx.xx.xx:5060 SIP/2.0 Via: SIP/2.0/UDP yy.yy.yy.yy:5060;branch=z9hG4bK24975546 Max-Forwards: 70 From: ;tag=as3aa1aae5 To: Call-ID: 5b44dd57162fc3e72a7c5ef204c538b6@yy.yy.yy.yy:5060 CSeq: 102 CANCEL User-Agent: Asterisk PBX 13.7.2 Content-Length: 0 <-------------> [2021-05-20 08:38:31.840] DEBUG[3710] chan_sip.c: Header 0 [ 40]: CANCEL sip:160@xx.xx.xx.xx:5060 SIP/2.0 [2021-05-20 08:38:31.840] DEBUG[3710] chan_sip.c: Header 1 [ 55]: Via: SIP/2.0/UDP yy.yy.yy.yy:5060;branch=z9hG4bK24975546 [2021-05-20 08:38:31.840] DEBUG[3710] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [2021-05-20 08:38:31.840] DEBUG[3710] chan_sip.c: Header 3 [ 41]: From: ;tag=as3aa1aae5 [2021-05-20 08:38:31.840] DEBUG[3710] chan_sip.c: Header 4 [ 31]: To: [2021-05-20 08:38:31.840] DEBUG[3710] chan_sip.c: Header 5 [ 57]: Call-ID: 5b44dd57162fc3e72a7c5ef204c538b6@yy.yy.yy.yy:5060 [2021-05-20 08:38:31.840] DEBUG[3710] chan_sip.c: Header 6 [ 16]: CSeq: 102 CANCEL [2021-05-20 08:38:31.840] DEBUG[3710] chan_sip.c: Header 7 [ 31]: User-Agent: Asterisk PBX 13.7.2 [2021-05-20 08:38:31.840] DEBUG[3710] chan_sip.c: Header 8 [ 17]: Content-Length: 0 [2021-05-20 08:38:31.840] VERBOSE[3710] chan_sip.c: --- (9 headers 0 lines) --- [2021-05-20 08:38:31.840] DEBUG[3710] chan_sip.c: = Looking for Call ID: 5b44dd57162fc3e72a7c5ef204c538b6@yy.yy.yy.yy:5060 (Checking From) --From tag as3aa1aae5 --To-tag [2021-05-20 08:38:31.840] DEBUG[3710][C-0000008f] chan_sip.c: **** Received CANCEL (14) - Command in SIP CANCEL [2021-05-20 08:38:31.840] DEBUG[3710][C-0000008f] netsock2.c: Splitting 'yy.yy.yy.yy:5060' into... [2021-05-20 08:38:31.840] DEBUG[3710][C-0000008f] netsock2.c: ...host 'yy.yy.yy.yy' and port '5060'. [2021-05-20 08:38:31.840] VERBOSE[3710][C-0000008f] chan_sip.c: Sending to yy.yy.yy.yy:5060 (no NAT) [2021-05-20 08:38:31.840] DEBUG[3710][C-0000008f] chan_sip.c: Setting SIP_ALREADYGONE on dialog 5b44dd57162fc3e72a7c5ef204c538b6@yy.yy.yy.yy:5060 [2021-05-20 08:38:31.840] DEBUG[3710][C-0000008f] res_rtp_asterisk.c: (0x7f5e18211c00) DTLS srtp - stopped timeout timer' [2021-05-20 08:38:31.840] DEBUG[3710][C-0000008f] res_rtp_asterisk.c: (0x7f5e18211c00) DTLS srtp - stopped timeout timer' [2021-05-20 08:38:31.840] VERBOSE[3710][C-0000008f] chan_sip.c: <--- Reliably Transmitting (no NAT) to yy.yy.yy.yy:5060 ---> SIP/2.0 487 Request Terminated Via: SIP/2.0/UDP yy.yy.yy.yy:5060;branch=z9hG4bK24975546;received=yy.yy.yy.yy From: ;tag=as3aa1aae5 To: ;tag=as28e65bf9 Call-ID: 5b44dd57162fc3e72a7c5ef204c538b6@yy.yy.yy.yy:5060 CSeq: 102 INVITE Server: L12893-16.16.0;Ast-PBX;L12917-1.0.46.0;Ast-Cfg criticall02 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Content-Length: 0 <------------> [2021-05-20 08:38:31.840] DEBUG[3710][C-0000008f] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #63 [2021-05-20 08:38:31.840] DEBUG[3710][C-0000008f] chan_sip.c: Trying to put 'SIP/2.0 487' onto UDP socket destined for yy.yy.yy.yy:5060 [2021-05-20 08:38:31.840] DEBUG[3739] manager.c: Examining AMI event: Event: HangupRequest Privilege: call,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: default Exten: 160 Priority: 7 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 [2021-05-20 08:38:31.841] VERBOSE[3710][C-0000008f] chan_sip.c: <--- Transmitting (no NAT) to yy.yy.yy.yy:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP yy.yy.yy.yy:5060;branch=z9hG4bK24975546;received=yy.yy.yy.yy From: ;tag=as3aa1aae5 To: ;tag=as28e65bf9 Call-ID: 5b44dd57162fc3e72a7c5ef204c538b6@yy.yy.yy.yy:5060 CSeq: 102 CANCEL Server: L12893-16.16.0;Ast-PBX;L12917-1.0.46.0;Ast-Cfg criticall02 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Content-Length: 0 <------------> [2021-05-20 08:38:31.841] DEBUG[3710][C-0000008f] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for yy.yy.yy.yy:5060 [2021-05-20 08:38:31.841] DEBUG[4938] manager.c: Examining AMI event: Event: HangupRequest Privilege: call,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: default Exten: 160 Priority: 7 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 [2021-05-20 08:38:31.841] DEBUG[16181][C-0000008f] res_stasis.c: 1621492709.539: Hangup (no more frames) [2021-05-20 08:38:31.841] DEBUG[16181][C-0000008f] stasis/app.c: channel '1621492709.539': is 0 interested in bridge-dial [2021-05-20 08:38:31.841] DEBUG[16181][C-0000008f] stasis/app.c: channel '1621492709.539' unsubscribed from bridge-dial [2021-05-20 08:38:31.841] DEBUG[16181][C-0000008f] pbx.c: Extension 160, priority 7 returned normally even though call was hung up [2021-05-20 08:38:31.841] DEBUG[16181][C-0000008f] channel.c: Soft-Hanging (0x10) up channel 'SIP/criticall-00000189' [2021-05-20 08:38:31.841] DEBUG[16181][C-0000008f] channel.c: Channel 0x7f5e1818b980 'SIP/criticall-00000189' hanging up. Refs: 2 [2021-05-20 08:38:31.841] DEBUG[16181][C-0000008f] chan_sip.c: Hangup call SIP/criticall-00000189, SIP callid 5b44dd57162fc3e72a7c5ef204c538b6@yy.yy.yy.yy:5060 [2021-05-20 08:38:31.841] DEBUG[16181][C-0000008f] res_rtp_asterisk.c: (0x7f5e18211c00) DTLS srtp - stopped timeout timer' [2021-05-20 08:38:31.841] DEBUG[16181][C-0000008f] res_rtp_asterisk.c: (0x7f5e18211c00) DTLS srtp - stopped timeout timer' [2021-05-20 08:38:31.841] DEBUG[16181][C-0000008f] channel.c: Channel 0x7f5e1818b980 'SIP/criticall-00000189' destroying [2021-05-20 08:38:31.841] DEBUG[3807] res_http_websocket.c: Writing websocket string of length 710 [2021-05-20 08:38:31.841] DEBUG[3807] res_http_websocket.c: Writing websocket text frame, length 710 [2021-05-20 08:38:31.841] DEBUG[3807] stasis/app.c: channel '1621492709.539': is 0 interested in noOp [2021-05-20 08:38:31.841] DEBUG[3807] stasis/app.c: channel '1621492709.539' unsubscribed from noOp [2021-05-20 08:38:31.841] DEBUG[3807] stasis.c: Destroying topic. name: cache:634/channel:1621492709.539, detail: [2021-05-20 08:38:31.841] DEBUG[3807] stasis.c: Topic 'cache:634/channel:1621492709.539': 0x7f5e182139b0 destroyed [2021-05-20 08:38:31.841] DEBUG[3807] res_http_websocket.c: Writing websocket string of length 710 [2021-05-20 08:38:31.841] DEBUG[3807] res_http_websocket.c: Writing websocket text frame, length 710 [2021-05-20 08:38:31.841] DEBUG[3807] stasis/app.c: App 'noOp' not subscribed to channel '1621492709.539' [2021-05-20 08:38:31.841] DEBUG[3807] stasis.c: Destroying topic. name: channel:1621492709.539, detail: [2021-05-20 08:38:31.841] DEBUG[3807] stasis.c: Topic 'channel:1621492709.539': 0x7f5e18097140 destroyed [2021-05-20 08:38:31.841] VERBOSE[3710] chan_sip.c: <--- SIP read from UDP:yy.yy.yy.yy:5060 ---> ACK sip:160@xx.xx.xx.xx:5060 SIP/2.0 Via: SIP/2.0/UDP yy.yy.yy.yy:5060;branch=z9hG4bK24975546 Max-Forwards: 70 From: ;tag=as3aa1aae5 To: ;tag=as28e65bf9 Contact: Call-ID: 5b44dd57162fc3e72a7c5ef204c538b6@yy.yy.yy.yy:5060 CSeq: 102 ACK User-Agent: Asterisk PBX 13.7.2 Content-Length: 0 <-------------> [2021-05-20 08:38:31.841] DEBUG[3710] chan_sip.c: Header 0 [ 37]: ACK sip:160@xx.xx.xx.xx:5060 SIP/2.0 [2021-05-20 08:38:31.841] DEBUG[3710] chan_sip.c: Header 1 [ 55]: Via: SIP/2.0/UDP yy.yy.yy.yy:5060;branch=z9hG4bK24975546 [2021-05-20 08:38:31.841] DEBUG[3710] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [2021-05-20 08:38:31.841] DEBUG[3710] chan_sip.c: Header 3 [ 41]: From: ;tag=as3aa1aae5 [2021-05-20 08:38:31.841] DEBUG[3710] chan_sip.c: Header 4 [ 46]: To: ;tag=as28e65bf9 [2021-05-20 08:38:31.841] DEBUG[3710] chan_sip.c: Header 5 [ 34]: Contact: [2021-05-20 08:38:31.841] DEBUG[3710] chan_sip.c: Header 6 [ 57]: Call-ID: 5b44dd57162fc3e72a7c5ef204c538b6@yy.yy.yy.yy:5060 [2021-05-20 08:38:31.841] DEBUG[3710] chan_sip.c: Header 7 [ 13]: CSeq: 102 ACK [2021-05-20 08:38:31.841] DEBUG[3710] chan_sip.c: Header 8 [ 31]: User-Agent: Asterisk PBX 13.7.2 [2021-05-20 08:38:31.841] DEBUG[3710] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [2021-05-20 08:38:31.841] VERBOSE[3710] chan_sip.c: --- (10 headers 0 lines) --- [2021-05-20 08:38:31.841] DEBUG[3710] chan_sip.c: = Looking for Call ID: 5b44dd57162fc3e72a7c5ef204c538b6@yy.yy.yy.yy:5060 (Checking From) --From tag as3aa1aae5 --To-tag as28e65bf9 [2021-05-20 08:38:31.841] DEBUG[3710][C-0000008f] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [2021-05-20 08:38:31.841] DEBUG[3710][C-0000008f] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #63 [2021-05-20 08:38:31.841] DEBUG[3807] res_http_websocket.c: Writing websocket string of length 217 [2021-05-20 08:38:31.841] DEBUG[3710][C-0000008f] chan_sip.c: Stopping retransmission on '5b44dd57162fc3e72a7c5ef204c538b6@yy.yy.yy.yy:5060' of Response 102: Match Found [2021-05-20 08:38:31.841] DEBUG[3807] res_http_websocket.c: Writing websocket text frame, length 217 [2021-05-20 08:38:31.841] DEBUG[3710] chan_sip.c: Destroying SIP dialog 5b44dd57162fc3e72a7c5ef204c538b6@yy.yy.yy.yy:5060 [2021-05-20 08:38:31.841] VERBOSE[3710] chan_sip.c: Really destroying SIP dialog '5b44dd57162fc3e72a7c5ef204c538b6@yy.yy.yy.yy:5060' Method: ACK [2021-05-20 08:38:31.841] DEBUG[3710] res_rtp_asterisk.c: (0x7f5e18211c00) DTLS stop [2021-05-20 08:38:31.841] DEBUG[3710] res_rtp_asterisk.c: (0x7f5e18211c00) DTLS srtp - stopped timeout timer' [2021-05-20 08:38:31.841] DEBUG[3710] res_rtp_asterisk.c: (0x7f5e18211c00) DTLS srtp - stopped timeout timer' [2021-05-20 08:38:31.841] DEBUG[3710] res_rtp_asterisk.c: (0x7f5e18211c00) ICE RTP transport deallocating [2021-05-20 08:38:31.841] DEBUG[3710] rtp_engine.c: Destroyed RTP instance '0x7f5e18211c00' [2021-05-20 08:38:31.841] DEBUG[3684] cdr.c: Finalized CDR for SIP/criticall-00000189 - start 1621492709.406325 answer 0.000000 end 1621492711.841238 dur 2.434 bill 1621492711.841 dispo FAILED [2021-05-20 08:38:31.841] DEBUG[3684] cdr.c: Skipping CDR for SIP/criticall-00000189 since we weren't answered [2021-05-20 08:38:31.841] DEBUG[3671] devicestate.c: No provider found, checking channel drivers for SIP - criticall [2021-05-20 08:38:31.841] DEBUG[3671] chan_sip.c: Checking device state for peer criticall [2021-05-20 08:38:31.841] DEBUG[3671] devicestate.c: Changing state for SIP/criticall - state 1 (Not in use) [2021-05-20 08:38:31.842] DEBUG[3811] res_http_websocket.c: Writing websocket string of length 717 [2021-05-20 08:38:31.842] DEBUG[3811] res_http_websocket.c: Writing websocket text frame, length 717 [2021-05-20 08:38:31.842] DEBUG[3811] res_http_websocket.c: Writing websocket string of length 706 [2021-05-20 08:38:31.842] DEBUG[3811] res_http_websocket.c: Writing websocket text frame, length 706 [2021-05-20 08:38:31.842] DEBUG[4938] manager.c: Examining AMI event: Event: SoftHangupRequest Privilege: call,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: default Exten: 160 Priority: 7 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 Cause: 16 [2021-05-20 08:38:31.842] DEBUG[4938] manager.c: Examining AMI event: Event: Hangup Privilege: call,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: default Exten: 160 Priority: 7 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 Cause: 0 Cause-txt: Unknown [2021-05-20 08:38:31.842] DEBUG[3739] manager.c: Examining AMI event: Event: SoftHangupRequest Privilege: call,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: default Exten: 160 Priority: 7 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 Cause: 16 [2021-05-20 08:38:31.842] DEBUG[3739] manager.c: Examining AMI event: Event: Hangup Privilege: call,all Channel: SIP/criticall-00000189 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 502 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: fr AccountCode: Context: default Exten: 160 Priority: 7 Uniqueid: 1621492709.539 Linkedid: 1621492709.539 Cause: 0 Cause-txt: Unknown