SIP Extension not Answering the calls

FreePBX Endpoints
, ,
1

SIP Extension when dialled not answering the call. Ringing Twice and Busy tone is played.

[2022-11-07 17:04:28] WARNING[20397] chan_sip.c: Retransmission timeout reached on transmission [email protected]:5060 for seqno 102 (Non-critical Request) -- See https://wiki.asterisk.org/wiki/display/AST/SIP+Retransmissions
Packet timed out after 6399ms with no response
[2022-11-07 17:04:28] WARNING[20397] chan_sip.c: Timeout on [email protected]:5060 on non-critical invite transaction.
[2022-11-07 17:04:29] WARNING[20397] chan_sip.c: Retransmission timeout reached on transmission [email protected]:5060 for seqno 102 (Critical Request) -- See https://wiki.asterisk.org/wiki/display/AST/SIP+Retransmissions
Packet timed out after 6399ms with no response
[2022-11-07 17:04:29] WARNING[20397] chan_sip.c: Hanging up call [email protected]:5060 - no reply to our critical packet (see https://wiki.asterisk.org/wiki/display/AST/SIP+Retransmissions).
[2022-11-07 17:04:29] VERBOSE[32206][C-00000199] app_dial.c: Everyone is busy/congested at this time (1:0/0/1)
[2022-11-07 17:04:29] VERBOSE[32206][C-00000199] pbx.c: Executing [s@macro-dial-one:56] ExecIf("SIP/3999-00000213", "0?MacroExit()") in new stack
[2022-11-07 17:04:29] VERBOSE[32206][C-00000199] pbx.c: Executing [s@macro-dial-one:57] ExecIf("SIP/3999-00000213", "0?Set(DIALSTATUS=)") in new stack
[2022-11-07 17:04:29] VERBOSE[32206][C-00000199] pbx.c: Executing [s@macro-dial-one:58] GosubIf("SIP/3999-00000213", "0?s-CHANUNAVAIL,1()") in new stack
[2022-11-07 17:04:29] VERBOSE[32206][C-00000199] pbx.c: Executing [s@macro-dial-one:59] MacroExit("SIP/3999-00000213", "") in new stack
[2022-11-07 17:04:29] VERBOSE[32206][C-00000199] pbx.c: Executing [s@macro-exten-vm:15] Set("SIP/3999-00000213", "SV_DIALSTATUS=CHANUNAVAIL") in new stack
[2022-11-07 17:04:29] VERBOSE[32206][C-00000199] pbx.c: Executing [s@macro-exten-vm:16] GosubIf("SIP/3999-00000213", "0?docfu,1()") in new stack
[2022-11-07 17:04:29] VERBOSE[32206][C-00000199] pbx.c: Executing [s@macro-exten-vm:17] GosubIf("SIP/3999-00000213", "0?docfb,1()") in new stack
[2022-11-07 17:04:29] VERBOSE[32206][C-00000199] pbx.c: Executing [s@macro-exten-vm:18] Set("SIP/3999-00000213", "DIALSTATUS=CHANUNAVAIL") in new stack
[2022-11-07 17:04:29] VERBOSE[32206][C-00000199] pbx.c: Executing [s@macro-exten-vm:19] ExecIf("SIP/3999-00000213", "1?MacroExit()") in new stack
[2022-11-07 17:04:29] VERBOSE[32206][C-00000199] pbx.c: Executing [3810@from-internal:4] Set("SIP/3999-00000213", "__PICKUPMARK=") in new stack
[2022-11-07 17:04:29] VERBOSE[32206][C-00000199] pbx.c: Executing [3810@from-internal:5] GotoIf("SIP/3999-00000213", "0?app-blackhole,busy,1") in new stack
[2022-11-07 17:04:29] VERBOSE[32206][C-00000199] pbx.c: Executing [3810@from-internal:6] GotoIf("SIP/3999-00000213", "0?app-blackhole,busy,1") in new stack
[2022-11-07 17:04:29] VERBOSE[32206][C-00000199] pbx.c: Executing [3810@from-internal:7] GotoIf("SIP/3999-00000213", "1?app-blackhole,busy,1") in new stack
[2022-11-07 17:04:29] VERBOSE[32206][C-00000199] pbx_builtins.c: Goto (app-blackhole,busy,1)
[2022-11-07 17:04:29] VERBOSE[32206][C-00000199] pbx.c: Executing [busy@app-blackhole:1] NoOp("SIP/3999-00000213", "Blackhole Dest: Busy") in new stack
[2022-11-07 17:04:29] VERBOSE[32206][C-00000199] pbx.c: Executing [busy@app-blackhole:2] Progress("SIP/3999-00000213", "") in new stack
[2022-11-07 17:04:29] VERBOSE[32206][C-00000199] chan_sip.c: Audio is at 18048
[2022-11-07 17:04:29] VERBOSE[32206][C-00000199] chan_sip.c: Adding codec ulaw to SDP
[2022-11-07 17:04:29] VERBOSE[32206][C-00000199] chan_sip.c: Adding codec alaw to SDP
[2022-11-07 17:04:29] VERBOSE[32206][C-00000199] chan_sip.c: Adding codec g722 to SDP
[2022-11-07 17:04:29] VERBOSE[32206][C-00000199] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP
[2022-11-07 17:04:29] VERBOSE[32206][C-00000199] chan_sip.c: 
<--- Transmitting (NAT) to 192.168.5.61:58337 --->
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP 192.168.5.61:58337;branch=z9hG4bKPjyk7Uxqgw78pBMfW.F4diDVbDGVajnTTo;received=192.168.5.61;rport=58337
From: "GILLP" <sip:[email protected]>;tag=ooWRjlZa4E7U8HeF8DMYB26ji5c.3H-K
To: sip:[email protected];tag=as24b13068
Call-ID: 2Y6wXdRdSaNpLNt1NRU4bGJtmqhd44nO
CSeq: 28402 INVITE
Server: FPBX-15.0.17.9(16.11.1)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Contact: <sip:[email protected]:5060>
Content-Type: application/sdp
Content-Length: 294

v=0
o=root 13579130 13579130 IN IP4 192.168.5.5
s=Asterisk PBX 16.11.1
c=IN IP4 192.168.5.5
t=0 0
m=audio 18048 RTP/AVP 0 8 9 102
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:102 telephone-event/8000
a=fmtp:102 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

<------------>
[2022-11-07 17:04:29] VERBOSE[32206][C-00000199] pbx.c: Executing [busy@app-blackhole:3] Busy("SIP/3999-00000213", "20") in new stack
[2022-11-07 17:04:29] VERBOSE[32206][C-00000199] chan_sip.c: 
<--- Reliably Transmitting (NAT) to 192.168.5.61:58337 --->
SIP/2.0 486 Busy Here
Via: SIP/2.0/UDP 192.168.5.61:58337;branch=z9hG4bKPjyk7Uxqgw78pBMfW.F4diDVbDGVajnTTo;received=192.168.5.61;rport=58337
From: "GILLP" <sip:[email protected]>;tag=ooWRjlZa4E7U8HeF8DMYB26ji5c.3H-K
To: sip:[email protected];tag=as24b13068
Call-ID: 2Y6wXdRdSaNpLNt1NRU4bGJtmqhd44nO
CSeq: 28402 INVITE
Server: FPBX-15.0.17.9(16.11.1)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
X-Asterisk-HangupCause: No user responding
X-Asterisk-HangupCauseCode: 18
Content-Length: 0


<------------>
[2022-11-07 17:04:29] WARNING[32206][C-00000199] channel.c: Prodding channel 'SIP/3999-00000213' failed
[2022-11-07 17:04:29] VERBOSE[32206][C-00000199] pbx.c: Spawn extension (app-blackhole, busy, 3) exited non-zero on 'SIP/3999-00000213'
[2022-11-07 17:04:29] VERBOSE[20397] chan_sip.c: 
<--- SIP read from UDP:192.168.5.61:58337 --->
ACK sip:[email protected] SIP/2.0
Via: SIP/2.0/UDP 192.168.5.61:58337;rport;branch=z9hG4bKPjyk7Uxqgw78pBMfW.F4diDVbDGVajnTTo
Max-Forwards: 70
From: "GILLP" <sip:[email protected]>;tag=ooWRjlZa4E7U8HeF8DMYB26ji5c.3H-K
To: sip:[email protected];tag=as24b13068
Call-ID: 2Y6wXdRdSaNpLNt1NRU4bGJtmqhd44nO
CSeq: 28402 ACK
Content-Length: 0

<------------->
[2022-11-07 17:04:29] VERBOSE[20397] chan_sip.c: --- (8 headers 0 lines) ---
[2022-11-07 17:04:29] VERBOSE[20397] chan_sip.c: Really destroying SIP dialog '2Y6wXdRdSaNpLNt1NRU4bGJtmqhd44nO' Method: ACK
[2022-11-07 17:04:30] NOTICE[20397] chan_sip.c:    -- Re-registration for  [email protected]
[2022-11-07 17:04:30] NOTICE[20397] chan_sip.c: Outbound Registration: Expiry for 192.168.6.6 is 45 sec (Scheduling reregistration in 30 s)
[2022-11-07 17:04:37] VERBOSE[20397] chan_sip.c: Reliably Transmitting (NAT) to 192.168.5.61:58337:
OPTIONS sip:[email protected]:58337;ob SIP/2.0
Via: SIP/2.0/UDP 192.168.5.5:5060;branch=z9hG4bK54a36cdf;rport
Max-Forwards: 70
From: "Unknown" <sip:[email protected]>;tag=as3cd371a8
To: <sip:[email protected]:58337;ob>
Contact: <sip:[email protected]:5060>
Call-ID: [email protected]:5060
CSeq: 102 OPTIONS
User-Agent: FPBX-15.0.17.9(16.11.1)
Date: Mon, 07 Nov 2022 11:34:37 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


---
[2022-11-07 17:04:37] VERBOSE[20397] chan_sip.c: 
<--- SIP read from UDP:192.168.5.61:58337 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.5.5:5060;rport=5060;received=192.168.5.5;branch=z9hG4bK54a36cdf
Call-ID: [email protected]:5060
From: "Unknown" <sip:[email protected]>;tag=as3cd371a8
To: <sip:[email protected];ob>;tag=z9hG4bK54a36cdf
CSeq: 102 OPTIONS
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Accept: application/sdp, application/pidf+xml, application/xpidf+xml, application/simple-message-summary, message/sipfrag;version=2.0, application/im-iscomposing+xml, text/plain
Supported: replaces, 100rel, timer, norefersub
Allow-Events: presence, message-summary, refer
User-Agent: Telephone 1.6
Content-Length: 0

<------------->
[2022-11-07 17:04:37] VERBOSE[20397] chan_sip.c: --- (12 headers 0 lines) ---
[2022-11-07 17:04:37] VERBOSE[20397] chan_sip.c: Really destroying SIP dialog '[email protected]:5060' Method: OPTIONS
[2022-11-07 17:04:37] VERBOSE[20397] chan_sip.c: 
<--- SIP read from UDP:192.168.5.61:58337 --->

<------------->
[2022-11-07 17:04:51] NOTICE[20397] chan_sip.c:    -- Re-registration for  [email protected]
[2022-11-07 17:04:51] NOTICE[20397] chan_sip.c: Outbound Registration: Expiry for 192.168.5.7 is 55 sec (Scheduling reregistration in 40 s)
[2022-11-07 17:04:52] VERBOSE[20397] chan_sip.c: 
<--- SIP read from UDP:192.168.5.61:58337 --->

<------------->
[2022-11-07 17:04:59] NOTICE[20397] chan_sip.c: Peer '3810' is now UNREACHABLE!  Last qualify: 30
[2022-11-07 17:05:00] NOTICE[20397] chan_sip.c:    -- Re-registration for  [email protected]
[2022-11-07 17:05:00] NOTICE[20397] chan_sip.c: Outbound Registration: Expiry for 192.168.6.6 is 45 sec (Scheduling reregistration in 30 s)
[2022-11-07 17:05:07] VERBOSE[20397] chan_sip.c: 
<--- SIP read from UDP:192.168.5.61:58337 --->

<------------->
[2022-11-07 17:05:22] VERBOSE[20397] chan_sip.c: 
<--- SIP read from UDP:192.168.5.61:58337 --->

<------------->
[2022-11-07 17:05:30] NOTICE[20397] chan_sip.c:    -- Re-registration for  [email protected]
[2022-11-07 17:05:30] NOTICE[20397] chan_sip.c: Outbound Registration: Expiry for 192.168.6.6 is 45 sec (Scheduling reregistration in 30 s)
[2022-11-07 17:05:31] NOTICE[20397] chan_sip.c:    -- Re-registration for  [email protected]
[2022-11-07 17:05:31] NOTICE[20397] chan_sip.c: Outbound Registration: Expiry for 192.168.5.7 is 55 sec (Scheduling reregistration in 40 s)
[2022-11-07 17:05:32] VERBOSE[20397] chan_sip.c: 
<--- SIP read from UDP:192.168.5.61:58337 --->
REGISTER sip:192.168.5.5 SIP/2.0
Via: SIP/2.0/UDP 192.168.5.61:58337;rport;branch=z9hG4bKPjSeHy97q41V-U4MfJHkYVeVdaygbs75er
Max-Forwards: 70
From: "GILLP" <sip:[email protected]>;tag=PlAnDG0aiby95c-UAs4.1kcKWWT629Rn
To: "GILLP" <sip:[email protected]>
Call-ID: 8WyFtRZ4uLgq9dJobzQ8i6G2QEr3c1eB
CSeq: 33694 REGISTER
User-Agent: Telephone 1.6
Contact: "GILLP" <sip:[email protected]:58337;ob>
Expires: 300
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Content-Length: 0

<------------->
[2022-11-07 17:05:32] VERBOSE[20397] chan_sip.c: --- (12 headers 0 lines) ---
[2022-11-07 17:05:32] VERBOSE[20397] chan_sip.c: Sending to 192.168.5.61:58337 (no NAT)
[2022-11-07 17:05:32] VERBOSE[20397] chan_sip.c: Sending to 192.168.5.61:58337 (no NAT)
[2022-11-07 17:05:32] VERBOSE[20397] chan_sip.c: 
<--- Transmitting (NAT) to 192.168.5.61:58337 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 192.168.5.61:58337;branch=z9hG4bKPjSeHy97q41V-U4MfJHkYVeVdaygbs75er;received=192.168.5.61;rport=58337
From: "GILLP" <sip:[email protected]>;tag=PlAnDG0aiby95c-UAs4.1kcKWWT629Rn
To: "GILLP" <sip:[email protected]>;tag=as149a0cfa
Call-ID: 8WyFtRZ4uLgq9dJobzQ8i6G2QEr3c1eB
CSeq: 33694 REGISTER
Server: FPBX-15.0.17.9(16.11.1)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="6e521459"
Content-Length: 0


<------------>
[2022-11-07 17:05:32] VERBOSE[20397] chan_sip.c: Scheduling destruction of SIP dialog '8WyFtRZ4uLgq9dJobzQ8i6G2QEr3c1eB' in 32000 ms (Method: REGISTER)
[2022-11-07 17:05:32] VERBOSE[20397] chan_sip.c: 
<--- SIP read from UDP:192.168.5.61:58337 --->
REGISTER sip:192.168.5.5 SIP/2.0
Via: SIP/2.0/UDP 192.168.5.61:58337;rport;branch=z9hG4bKPj.3XEVoGnxTea5B-tVzuUAvE5YALy2Wwq
Max-Forwards: 70
From: "GILLP" <sip:[email protected]>;tag=PlAnDG0aiby95c-UAs4.1kcKWWT629Rn
To: "GILLP" <sip:[email protected]>
Call-ID: 8WyFtRZ4uLgq9dJobzQ8i6G2QEr3c1eB
CSeq: 33695 REGISTER
User-Agent: Telephone 1.6
Contact: "GILLP" <sip:[email protected]:58337;ob>
Expires: 300
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Authorization: Digest username="3999", realm="asterisk", nonce="6e521459", uri="sip:192.168.5.5", response="9ee7bb70045183b1c47fd0432010914c", algorithm=MD5
Content-Length: 0

<------------->
[2022-11-07 17:05:32] VERBOSE[20397] chan_sip.c: --- (13 headers 0 lines) ---
[2022-11-07 17:05:32] VERBOSE[20397] chan_sip.c: Sending to 192.168.5.61:58337 (NAT)
[2022-11-07 17:05:32] VERBOSE[20397] chan_sip.c: Reliably Transmitting (NAT) to 192.168.5.61:58337:
OPTIONS sip:[email protected]:58337;ob SIP/2.0
Via: SIP/2.0/UDP 192.168.5.5:5060;branch=z9hG4bK235cc3e5;rport
Max-Forwards: 70
From: "Unknown" <sip:[email protected]>;tag=as35e1413f
To: <sip:[email protected]:58337;ob>
Contact: <sip:[email protected]:5060>
Call-ID: [email protected]:5060
CSeq: 102 OPTIONS
User-Agent: FPBX-15.0.17.9(16.11.1)
Date: Mon, 07 Nov 2022 11:35:32 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


---
[2022-11-07 17:05:32] VERBOSE[20397] chan_sip.c: 
<--- Transmitting (NAT) to 192.168.5.61:58337 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.5.61:58337;branch=z9hG4bKPj.3XEVoGnxTea5B-tVzuUAvE5YALy2Wwq;received=192.168.5.61;rport=58337
From: "GILLP" <sip:[email protected]>;tag=PlAnDG0aiby95c-UAs4.1kcKWWT629Rn
To: "GILLP" <sip:[email protected]>;tag=as149a0cfa
Call-ID: 8WyFtRZ4uLgq9dJobzQ8i6G2QEr3c1eB
CSeq: 33695 REGISTER
Server: FPBX-15.0.17.9(16.11.1)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Expires: 300
Contact: <sip:[email protected]:58337;ob>;expires=300
Date: Mon, 07 Nov 2022 11:35:32 GMT
Content-Length: 0


<------------>
[2022-11-07 17:05:32] VERBOSE[20397] chan_sip.c: Scheduling destruction of SIP dialog '[email protected]:5060' in 6400 ms (Method: NOTIFY)
[2022-11-07 17:05:32] VERBOSE[20397] chan_sip.c: Reliably Transmitting (NAT) to 192.168.5.61:58337:
NOTIFY sip:[email protected]:58337;ob SIP/2.0
Via: SIP/2.0/UDP 192.168.5.5:5060;branch=z9hG4bK5ff8f5e0;rport
Max-Forwards: 70
From: "Unknown" <sip:[email protected]>;tag=as5d8c4f1e
To: <sip:[email protected]:58337;ob>
Contact: <sip:[email protected]:5060>
Call-ID: [email protected]:5060
CSeq: 102 NOTIFY
User-Agent: FPBX-15.0.17.9(16.11.1)
Event: message-summary
Content-Type: application/simple-message-summary
Content-Length: 86

Messages-Waiting: no
Message-Account: sip:*[email protected]
Voice-Message: 0/0 (0/0)

---
[2022-11-07 17:05:32] VERBOSE[20397] chan_sip.c: Scheduling destruction of SIP dialog '8WyFtRZ4uLgq9dJobzQ8i6G2QEr3c1eB' in 32000 ms (Method: REGISTER)
[2022-11-07 17:05:32] VERBOSE[20397] chan_sip.c: 
<--- SIP read from UDP:192.168.5.61:58337 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.5.5:5060;rport=5060;received=192.168.5.5;branch=z9hG4bK235cc3e5
Call-ID: [email protected]:5060
From: "Unknown" <sip:[email protected]>;tag=as35e1413f
To: <sip:[email protected];ob>;tag=z9hG4bK235cc3e5
CSeq: 102 OPTIONS
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Accept: application/sdp, application/pidf+xml, application/xpidf+xml, application/simple-message-summary, message/sipfrag;version=2.0, application/im-iscomposing+xml, text/plain
Supported: replaces, 100rel, timer, norefersub
Allow-Events: presence, message-summary, refer
User-Agent: Telephone 1.6
Content-Length: 0

<------------->
[2022-11-07 17:05:32] VERBOSE[20397] chan_sip.c: --- (12 headers 0 lines) ---
[2022-11-07 17:05:32] VERBOSE[20397] chan_sip.c: 
<--- SIP read from UDP:192.168.5.61:58337 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.5.5:5060;rport=5060;received=192.168.5.5;branch=z9hG4bK5ff8f5e0
Call-ID: [email protected]:5060
From: "Unknown" <sip:[email protected]>;tag=as5d8c4f1e
To: <sip:[email protected];ob>;tag=z9hG4bK5ff8f5e0
CSeq: 102 NOTIFY
Content-Length: 0

<------------->
[2022-11-07 17:05:32] VERBOSE[20397] chan_sip.c: --- (7 headers 0 lines) ---
[2022-11-07 17:05:32] VERBOSE[20397] chan_sip.c: Really destroying SIP dialog '[email protected]:5060' Method: OPTIONS
[2022-11-07 17:05:32] VERBOSE[20397] chan_sip.c: Really destroying SIP dialog '[email protected]:5060' Method: NOTIFY
[2022-11-07 17:05:47] VERBOSE[20397] chan_sip.c: 
<--- SIP read from UDP:192.168.5.61:58337 --->

<------------->
[2022-11-07 17:06:00] NOTICE[20397] chan_sip.c:    -- Re-registration for  [email protected]
[2022-11-07 17:06:00] NOTICE[20397] chan_sip.c: Outbound Registration: Expiry for 192.168.6.6 is 45 sec (Scheduling reregistration in 30 s)
[2022-11-07 17:06:02] VERBOSE[20397] chan_sip.c: 
<--- SIP read from UDP:192.168.5.61:58337 --->

<------------->
[2022-11-07 17:06:04] VERBOSE[20397] chan_sip.c: Really destroying SIP dialog '8WyFtRZ4uLgq9dJobzQ8i6G2QEr3c1eB' Method: REGISTER
[2022-11-07 17:06:11] NOTICE[20397] chan_sip.c:    -- Re-registration for  [email protected]
[2022-11-07 17:06:11] NOTICE[20397] chan_sip.c: Outbound Registration: Expiry for 192.168.5.7 is 55 sec (Scheduling reregistration in 40 s)
[2022-11-07 17:06:17] VERBOSE[20397] chan_sip.c: 
<--- SIP read from UDP:192.168.5.61:58337 --->

<------------->
[2022-11-07 17:06:30] NOTICE[20397] chan_sip.c:    -- Re-registration for  [email protected]
[2022-11-07 17:06:30] NOTICE[20397] chan_sip.c: Outbound Registration: Expiry for 192.168.6.6 is 45 sec (Scheduling reregistration in 30 s)
[2022-11-07 17:06:32] VERBOSE[20397] chan_sip.c: Reliably Transmitting (NAT) to 192.168.5.61:58337:
OPTIONS sip:[email protected]:58337;ob SIP/2.0
Via: SIP/2.0/UDP 192.168.5.5:5060;branch=z9hG4bK07412229;rport
Max-Forwards: 70
From: "Unknown" <sip:[email protected]>;tag=as3028a407
To: <sip:[email protected]:58337;ob>
Contact: <sip:[email protected]:5060>
Call-ID: [email protected]:5060
CSeq: 102 OPTIONS
User-Agent: FPBX-15.0.17.9(16.11.1)
Date: Mon, 07 Nov 2022 11:36:32 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


---
[2022-11-07 17:06:32] VERBOSE[20397] chan_sip.c: 
<--- SIP read from UDP:192.168.5.61:58337 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.5.5:5060;rport=5060;received=192.168.5.5;branch=z9hG4bK07412229
Call-ID: [email protected]:5060
From: "Unknown" <sip:[email protected]>;tag=as3028a407
To: <sip:[email protected];ob>;tag=z9hG4bK07412229
CSeq: 102 OPTIONS
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Accept: application/sdp, application/pidf+xml, application/xpidf+xml, application/simple-message-summary, message/sipfrag;version=2.0, application/im-iscomposing+xml, text/plain
Supported: replaces, 100rel, timer, norefersub
Allow-Events: presence, message-summary, refer
User-Agent: Telephone 1.6
Content-Length: 0

<------------->
[2022-11-07 17:06:32] VERBOSE[20397] chan_sip.c: --- (12 headers 0 lines) ---
[2022-11-07 17:06:32] VERBOSE[20397] chan_sip.c: 
<--- SIP read from UDP:192.168.5.61:58337 --->

<------------->
[2022-11-07 17:06:32] VERBOSE[20397] chan_sip.c: Really destroying SIP dialog '[email protected]:5060' Method: OPTIONS
[2022-11-07 17:06:47] VERBOSE[20397] chan_sip.c: 
<--- SIP read from UDP:192.168.5.61:58337 --->

<------------->
[2022-11-07 17:06:51] NOTICE[20397] chan_sip.c:    -- Re-registration for  [email protected]
[2022-11-07 17:06:51] NOTICE[20397] chan_sip.c: Outbound Registration: Expiry for 192.168.5.7 is 55 sec (Scheduling reregistration in 40 s)
[2022-11-07 17:07:00] NOTICE[20397] chan_sip.c:    -- Re-registration for  [email protected]
[2022-11-07 17:07:00] NOTICE[20397] chan_sip.c: Outbound Registration: Expiry for 192.168.6.6 is 45 sec (Scheduling reregistration in 30 s)
[2022-11-07 17:07:02] VERBOSE[20397] chan_sip.c: 
<--- SIP read from UDP:192.168.5.61:58337 --->

<------------->
[2022-11-07 17:07:17] VERBOSE[20397] chan_sip.c: 
<--- SIP read from UDP:192.168.5.61:58337 --->

<------------->
[2022-11-07 17:07:30] NOTICE[20397] chan_sip.c:    -- Re-registration for  [email protected]
[2022-11-07 17:07:30] NOTICE[20397] chan_sip.c: Outbound Registration: Expiry for 192.168.6.6 is 45 sec (Scheduling reregistration in 30 s)
[2022-11-07 17:07:31] NOTICE[20397] chan_sip.c:    -- Re-registration for  [email protected]
[2022-11-07 17:07:31] NOTICE[20397] chan_sip.c: Outbound Registration: Expiry for 192.168.5.7 is 55 sec (Scheduling reregistration in 40 s)
[2022-11-07 17:07:32] VERBOSE[20397] chan_sip.c: Reliably Transmitting (NAT) to 192.168.5.61:58337:
OPTIONS sip:[email protected]:58337;ob SIP/2.0
Via: SIP/2.0/UDP 192.168.5.5:5060;branch=z9hG4bK66f35663;rport
Max-Forwards: 70
From: "Unknown" <sip:[email protected]>;tag=as5302a98d
To: <sip:[email protected]:58337;ob>
Contact: <sip:[email protected]:5060>
Call-ID: [email protected]:5060
CSeq: 102 OPTIONS
User-Agent: FPBX-15.0.17.9(16.11.1)
Date: Mon, 07 Nov 2022 11:37:32 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


---
[2022-11-07 17:07:32] VERBOSE[20397] chan_sip.c: 
<--- SIP read from UDP:192.168.5.61:58337 --->

<------------->
[2022-11-07 17:07:32] VERBOSE[20397] chan_sip.c: 
<--- SIP read from UDP:192.168.5.61:58337 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.5.5:5060;rport=5060;received=192.168.5.5;branch=z9hG4bK66f35663
Call-ID: [email protected]:5060
From: "Unknown" <sip:[email protected]>;tag=as5302a98d
To: <sip:[email protected];ob>;tag=z9hG4bK66f35663
CSeq: 102 OPTIONS
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Accept: application/sdp, application/pidf+xml, application/xpidf+xml, application/simple-message-summary, message/sipfrag;version=2.0, application/im-iscomposing+xml, text/plain
Supported: replaces, 100rel, timer, norefersub
Allow-Events: presence, message-summary, refer
User-Agent: Telephone 1.6
Content-Length: 0

<------------->
[2022-11-07 17:07:32] VERBOSE[20397] chan_sip.c: --- (12 headers 0 lines) ---
[2022-11-07 17:07:32] VERBOSE[20397] chan_sip.c: Really destroying SIP dialog '[email protected]:5060' Method: OPTIONS
[2022-11-07 17:07:47] VERBOSE[20397] chan_sip.c: 
<--- SIP read from UDP:192.168.5.61:58337 --->

<------------->
[2022-11-07 17:08:00] NOTICE[20397] chan_sip.c:    -- Re-registration for  [email protected]
[2022-11-07 17:08:00] NOTICE[20397] chan_sip.c: Outbound Registration: Expiry for 192.168.6.6 is 45 sec (Scheduling reregistration in 30 s)
[2022-11-07 17:08:02] VERBOSE[20397] chan_sip.c: 
<--- SIP read from UDP:192.168.5.61:58337 --->

<------------->
[2022-11-07 17:08:11] NOTICE[20397] chan_sip.c:    -- Re-registration for  [email protected]
[2022-11-07 17:08:11] NOTICE[20397] chan_sip.c: Outbound Registration: Expiry for 192.168.5.7 is 55 sec (Scheduling reregistration in 40 s)
[2022-11-07 17:08:17] VERBOSE[20397] chan_sip.c: 
<--- SIP read from UDP:192.168.5.61:58337 --->

<------------->
[2022-11-07 17:08:30] NOTICE[20397] chan_sip.c:    -- Re-registration for  [email protected]
[2022-11-07 17:08:30] NOTICE[20397] chan_sip.c: Outbound Registration: Expiry for 192.168.6.6 is 45 sec (Scheduling reregistration in 30 s)
[2022-11-07 17:08:32] VERBOSE[20397] chan_sip.c: Reliably Transmitting (NAT) to 192.168.5.61:58337:
OPTIONS sip:[email protected]:58337;ob SIP/2.0
Via: SIP/2.0/UDP 192.168.5.5:5060;branch=z9hG4bK13fcb6a7;rport
Max-Forwards: 70
From: "Unknown" <sip:[email protected]>;tag=as06f06eb7
To: <sip:[email protected]:58337;ob>
Contact: <sip:[email protected]:5060>
Call-ID: [email protected]:5060
CSeq: 102 OPTIONS
User-Agent: FPBX-15.0.17.9(16.11.1)
Date: Mon, 07 Nov 2022 11:38:32 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


---
[2022-11-07 17:08:32] VERBOSE[20397] chan_sip.c: 
<--- SIP read from UDP:192.168.5.61:58337 --->

<------------->
[2022-11-07 17:08:32] VERBOSE[20397] chan_sip.c: 
<--- SIP read from UDP:192.168.5.61:58337 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.5.5:5060;rport=5060;received=192.168.5.5;branch=z9hG4bK13fcb6a7
Call-ID: [email protected]:5060
From: "Unknown" <sip:[email protected]>;tag=as06f06eb7
To: <sip:[email protected];ob>;tag=z9hG4bK13fcb6a7
CSeq: 102 OPTIONS
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Accept: application/sdp, application/pidf+xml, application/xpidf+xml, application/simple-message-summary, message/sipfrag;version=2.0, application/im-iscomposing+xml, text/plain
Supported: replaces, 100rel, timer, norefersub
Allow-Events: presence, message-summary, refer
User-Agent: Telephone 1.6
Content-Length: 0

<------------->
[2022-11-07 17:08:32] VERBOSE[20397] chan_sip.c: --- (12 headers 0 lines) ---
[2022-11-07 17:08:32] VERBOSE[20397] chan_sip.c: Really destroying SIP dialog '[email protected]:5060' Method: OPTIONS
[2022-11-07 17:08:47] VERBOSE[20397] chan_sip.c: 
<--- SIP read from UDP:192.168.5.61:58337 --->

<------------->
[2022-11-07 17:08:51] NOTICE[20397] chan_sip.c:    -- Re-registration for  [email protected]
[2022-11-07 17:08:51] NOTICE[20397] chan_sip.c: Outbound Registration: Expiry for 192.168.5.7 is 55 sec (Scheduling reregistration in 40 s)
[2022-11-07 17:09:00] NOTICE[20397] chan_sip.c:    -- Re-registration for  [email protected]
[2022-11-07 17:09:02] VERBOSE[20397] chan_sip.c: 
<--- SIP read from UDP:192.168.5.61:58337 --->

<------------->
[2022-11-07 17:09:17] VERBOSE[20397] chan_sip.c: 
<--- SIP read from UDP:192.168.5.61:58337 --->

<------------->
[2022-11-07 17:09:20] NOTICE[20397] chan_sip.c: Outbound Registration: Expiry for 192.168.6.6 is 45 sec (Scheduling reregistration in 30 s)
[2022-11-07 17:09:31] NOTICE[20397] chan_sip.c:    -- Re-registration for  [email protected]
[2022-11-07 17:09:31] NOTICE[20397] chan_sip.c: Outbound Registration: Expiry for 192.168.5.7 is 55 sec (Scheduling reregistration in 40 s)
[2022-11-07 17:09:32] VERBOSE[20397] chan_sip.c: 
<--- SIP read from UDP:192.168.5.61:58337 --->

<------------->
[2022-11-07 17:09:32] VERBOSE[20397] chan_sip.c: Reliably Transmitting (NAT) to 192.168.5.61:58337:
OPTIONS sip:[email protected]:58337;ob SIP/2.0
Via: SIP/2.0/UDP 192.168.5.5:5060;branch=z9hG4bK2ff44c67;rport
Max-Forwards: 70
From: "Unknown" <sip:[email protected]>;tag=as5f276528
To: <sip:[email protected]:58337;ob>
Contact: <sip:[email protected]:5060>
Call-ID: [email protected]:5060
CSeq: 102 OPTIONS
User-Agent: FPBX-15.0.17.9(16.11.1)
Date: Mon, 07 Nov 2022 11:39:32 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


---
[2022-11-07 17:09:32] VERBOSE[20397] chan_sip.c: 
<--- SIP read from UDP:192.168.5.61:58337 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.5.5:5060;rport=5060;received=192.168.5.5;branch=z9hG4bK2ff44c67
Call-ID: [email protected]:5060
From: "Unknown" <sip:[email protected]>;tag=as5f276528
To: <sip:[email protected];ob>;tag=z9hG4bK2ff44c67
CSeq: 102 OPTIONS
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Accept: application/sdp, application/pidf+xml, application/xpidf+xml, application/simple-message-summary, message/sipfrag;version=2.0, application/im-iscomposing+xml, text/plain
Supported: replaces, 100rel, timer, norefersub
Allow-Events: presence, message-summary, refer
User-Agent: Telephone 1.6
Content-Length: 0

<------------->
[2022-11-07 17:09:32] VERBOSE[20397] chan_sip.c: --- (12 headers 0 lines) ---
[2022-11-07 17:09:32] VERBOSE[20397] chan_sip.c: Really destroying SIP dialog '[email protected]:5060' Method: OPTIONS
[2022-11-07 17:09:47] VERBOSE[20397] chan_sip.c: 
<--- SIP read from UDP:192.168.5.61:58337 --->

<------------->
[2022-11-07 17:09:50] NOTICE[20397] chan_sip.c:    -- Re-registration for  [email protected]
[2022-11-07 17:09:50] NOTICE[20397] chan_sip.c: Outbound Registration: Expiry for 192.168.6.6 is 45 sec (Scheduling reregistration in 30 s)
^C
root@GCPLGoogleeServer:~# asterisk -rvvvv
Asterisk 16.11.1, Copyright (C) 1999 - 2018, Digium, Inc. and others.
Created by Mark Spencer <[email protected]>
Asterisk comes with ABSOLUTELY NO WARRANTY; type 'core show warranty' for details.
This is free software, with components licensed under the GNU General Public
License version 2 and other licenses; you are welcome to redistribute it under
certain conditions. Type 'core show license' for details.
=========================================================================
Connected to Asterisk 16.11.1 currently running on GCPLGoogleeServer (pid = 1086)
[2022-11-07 17:10:11] NOTICE[20397]: chan_sip.c:15893 sip_reregister:    -- Re-registration for  [email protected]
[2022-11-07 17:10:11] NOTICE[20397]: chan_sip.c:24960 handle_response_register: Outbound Registration: Expiry for 192.168.5.7 is 55 sec (Scheduling reregistration in 40 s)

<--- SIP read from UDP:192.168.5.61:58337 --->

<------------->
[2022-11-07 17:10:20] NOTICE[20397]: chan_sip.c:15893 sip_reregister:    -- Re-registration for  [email protected]
[2022-11-07 17:10:20] NOTICE[20397]: chan_sip.c:24960 handle_response_register: Outbound Registration: Expiry for 192.168.6.6 is 45 sec (Scheduling reregistration in 30 s)
GCPLGoogleeServer*CLI> sip noset debug ip 192.168.5.61
No such command 'sip noset debug ip 192.168.5.61' (type 'core show help sip noset debug' for other possible commands)

<--- SIP read from UDP:192.168.5.61:58337 --->
REGISTER sip:192.168.5.5 SIP/2.0
Via: SIP/2.0/UDP 192.168.5.61:58337;rport;branch=z9hG4bKPjibSk63c6YMeCX-tEInPx0MupKO6xamj.
Max-Forwards: 70
From: "GILLP" <sip:[email protected]>;tag=bR7sS6kHkCbMKRvrOcm92nqpzuEyL.tz
To: "GILLP" <sip:[email protected]>
Call-ID: 8WyFtRZ4uLgq9dJobzQ8i6G2QEr3c1eB
CSeq: 33696 REGISTER
User-Agent: Telephone 1.6
Contact: "GILLP" <sip:[email protected]:58337;ob>
Expires: 300
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Content-Length: 0

<------------->
--- (12 headers 0 lines) ---
Sending to 192.168.5.61:58337 (no NAT)
Sending to 192.168.5.61:58337 (no NAT)

<--- Transmitting (NAT) to 192.168.5.61:58337 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 192.168.5.61:58337;branch=z9hG4bKPjibSk63c6YMeCX-tEInPx0MupKO6xamj.;received=192.168.5.61;rport=58337
From: "GILLP" <sip:[email protected]>;tag=bR7sS6kHkCbMKRvrOcm92nqpzuEyL.tz
To: "GILLP" <sip:[email protected]>;tag=as4a1743d5
Call-ID: 8WyFtRZ4uLgq9dJobzQ8i6G2QEr3c1eB
CSeq: 33696 REGISTER
Server: FPBX-15.0.17.9(16.11.1)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="5da9f1b1"
Content-Length: 0


<------------>
Scheduling destruction of SIP dialog '8WyFtRZ4uLgq9dJobzQ8i6G2QEr3c1eB' in 32000 ms (Method: REGISTER)

<--- SIP read from UDP:192.168.5.61:58337 --->
REGISTER sip:192.168.5.5 SIP/2.0
Via: SIP/2.0/UDP 192.168.5.61:58337;rport;branch=z9hG4bKPj7KpJ7ZtPe.fX5Zj1FDs5-zl1pk79cWOg
Max-Forwards: 70
From: "GILLP" <sip:[email protected]>;tag=bR7sS6kHkCbMKRvrOcm92nqpzuEyL.tz
To: "GILLP" <sip:[email protected]>
Call-ID: 8WyFtRZ4uLgq9dJobzQ8i6G2QEr3c1eB
CSeq: 33697 REGISTER
User-Agent: Telephone 1.6
Contact: "GILLP" <sip:[email protected]:58337;ob>
Expires: 300
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Authorization: Digest username="3999", realm="asterisk", nonce="5da9f1b1", uri="sip:192.168.5.5", response="4359d3f533206417eb372d236382b82a", algorithm=MD5
Content-Length: 0

Please suggest

2

You haven’t included the failed INVITE requests in your log above. I’d suggest looking at those and making sure that they are sent to the right place, and have the correct address, in the Via header, for replying from that place. If so, you will have to look further out in the network.

Is the phone ringing? If not the request is probably getting lost on its way out.

3 
<------------>
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [3810@from-internal:1] Set("SIP/3999-000000c8", "__RINGTIMER=15") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [3810@from-internal:2] ExecIf("SIP/3999-000000c8", "0?Set(__CWIGNORE=)") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [3810@from-internal:3] Macro("SIP/3999-000000c8", "exten-vm,novm,3810,1,1,1") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-exten-vm:1] Macro("SIP/3999-000000c8", "user-callerid,") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:1] Set("SIP/3999-000000c8", "TOUCH_MONITOR=1667900041.434") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:2] Set("SIP/3999-000000c8", "AMPUSER=3999") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:3] Set("SIP/3999-000000c8", "HOTDESCKCHAN=3999-000000c8") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:4] Set("SIP/3999-000000c8", "HOTDESKEXTEN=3999") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:5] Set("SIP/3999-000000c8", "HOTDESKCALL=0") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:6] ExecIf("SIP/3999-000000c8", "0?Set(HOTDESKCALL=1)") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:7] ExecIf("SIP/3999-000000c8", "0?Set(CALLERID(name)=)") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:8] GotoIf("SIP/3999-000000c8", "0?report") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:9] ExecIf("SIP/3999-000000c8", "1?Set(REALCALLERIDNUM=3999)") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:10] Set("SIP/3999-000000c8", "AMPUSER=3999") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:11] GotoIf("SIP/3999-000000c8", "0?limit") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:12] Set("SIP/3999-000000c8", "AMPUSERCIDNAME=GCPL") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:13] ExecIf("SIP/3999-000000c8", "0?Set(__CIDMASQUERADING=TRUE)") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:14] GotoIf("SIP/3999-000000c8", "0?report") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:15] Set("SIP/3999-000000c8", "AMPUSERCID=3999") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:16] Set("SIP/3999-000000c8", "__DIAL_OPTIONS=HhTtr") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:17] Set("SIP/3999-000000c8", "CALLERID(all)="GCPL" <3999>") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:18] ExecIf("SIP/3999-000000c8", "0?Set(CUSDIAL=3810)") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:19] ExecIf("SIP/3999-000000c8", "0?Set(CALLERID(all)="GCPL" <3999>)") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:20] GotoIf("SIP/3999-000000c8", "0?limit") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:21] ExecIf("SIP/3999-000000c8", "0?Set(GROUP(concurrency_limit)=3999)") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:22] NoOp("SIP/3999-000000c8", "Macro Depth is 2") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:23] GotoIf("SIP/3999-000000c8", "1?report2:macroerror") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx_builtins.c: Goto (macro-user-callerid,s,24)
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:24] GotoIf("SIP/3999-000000c8", "0?continue") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:25] Set("SIP/3999-000000c8", "__TTL=64") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:26] GotoIf("SIP/3999-000000c8", "1?continue") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx_builtins.c: Goto (macro-user-callerid,s,42)
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:42] Set("SIP/3999-000000c8", "CALLERID(number)=3999") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:43] Set("SIP/3999-000000c8", "CALLERID(name)=GCPL") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:44] GotoIf("SIP/3999-000000c8", "0?cnum") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:45] Set("SIP/3999-000000c8", "CDR(cnam)=GCPL") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:46] Set("SIP/3999-000000c8", "CDR(cnum)=3999") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:47] Set("SIP/3999-000000c8", "CHANNEL(language)=en") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-exten-vm:2] Set("SIP/3999-000000c8", "RingGroupMethod=none") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-exten-vm:3] Set("SIP/3999-000000c8", "__EXTTOCALL=3810") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-exten-vm:4] Set("SIP/3999-000000c8", "__PICKUPMARK=3810") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-exten-vm:5] Set("SIP/3999-000000c8", "RT=15") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-exten-vm:6] Gosub("SIP/3999-000000c8", "sub-record-check,s,1(exten,3810,dontcare)") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@sub-record-check:1] GotoIf("SIP/3999-000000c8", "0?initialized") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@sub-record-check:2] Set("SIP/3999-000000c8", "__REC_STATUS=INITIALIZED") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@sub-record-check:3] Set("SIP/3999-000000c8", "NOW=1667900041") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@sub-record-check:4] Set("SIP/3999-000000c8", "__DAY=08") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@sub-record-check:5] Set("SIP/3999-000000c8", "__MONTH=11") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@sub-record-check:6] Set("SIP/3999-000000c8", "__YEAR=2022") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@sub-record-check:7] Set("SIP/3999-000000c8", "__TIMESTR=20221108-150401") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@sub-record-check:8] Set("SIP/3999-000000c8", "__FROMEXTEN=3999") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@sub-record-check:9] Set("SIP/3999-000000c8", "__MON_FMT=wav") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@sub-record-check:10] NoOp("SIP/3999-000000c8", "Recordings initialized") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@sub-record-check:11] ExecIf("SIP/3999-000000c8", "0?Set(ARG3=dontcare)") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@sub-record-check:12] Set("SIP/3999-000000c8", "REC_POLICY_MODE_SAVE=") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@sub-record-check:13] ExecIf("SIP/3999-000000c8", "0?Set(REC_STATUS=NO)") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@sub-record-check:14] GotoIf("SIP/3999-000000c8", "5?checkaction") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx_builtins.c: Goto (sub-record-check,s,17)
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@sub-record-check:17] GotoIf("SIP/3999-000000c8", "1?sub-record-check,exten,1") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx_builtins.c: Goto (sub-record-check,exten,1)
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [exten@sub-record-check:1] NoOp("SIP/3999-000000c8", "Exten Recording Check between 3999 and 3810") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [exten@sub-record-check:2] Set("SIP/3999-000000c8", "CALLTYPE=internal") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [exten@sub-record-check:3] ExecIf("SIP/3999-000000c8", "0?Set(CALLTYPE=)") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [exten@sub-record-check:4] Set("SIP/3999-000000c8", "CALLEE=never") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [exten@sub-record-check:5] ExecIf("SIP/3999-000000c8", "0?Set(CALLEE=dontcare)") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [exten@sub-record-check:6] GotoIf("SIP/3999-000000c8", "0?callee") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [exten@sub-record-check:7] GotoIf("SIP/3999-000000c8", "0?caller") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [exten@sub-record-check:8] ExecIf("SIP/3999-000000c8", "2?Set(CALLER_PRI=10):Set(CALLER_PRI=0)") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [exten@sub-record-check:9] ExecIf("SIP/3999-000000c8", "2?Set(CALLEE_PRI=10):Set(CALLEE_PRI=0)") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [exten@sub-record-check:10] GotoIf("SIP/3999-000000c8", "1?caller:callee") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx_builtins.c: Goto (sub-record-check,exten,13)
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [exten@sub-record-check:13] Set("SIP/3999-000000c8", "RECMODE=never") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [exten@sub-record-check:14] ExecIf("SIP/3999-000000c8", "0?Set(RECMODE=dontcare)") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [exten@sub-record-check:15] ExecIf("SIP/3999-000000c8", "0?Set(RECMODE=never)") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [exten@sub-record-check:16] Gosub("SIP/3999-000000c8", "recordcheck,1(never,internal,3810)") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("SIP/3999-000000c8", "Starting recording check against never") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("SIP/3999-000000c8", "never") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx_builtins.c: Goto (sub-record-check,recordcheck,14)
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [recordcheck@sub-record-check:14] Set("SIP/3999-000000c8", "__REC_POLICY_MODE=NEVER") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [recordcheck@sub-record-check:15] Goto("SIP/3999-000000c8", "stoprec") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx_builtins.c: Goto (sub-record-check,recordcheck,24)
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [recordcheck@sub-record-check:24] NoOp("SIP/3999-000000c8", "Stopping recording: internal, 3810") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [recordcheck@sub-record-check:25] Set("SIP/3999-000000c8", "__REC_STATUS=STOPPED") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [recordcheck@sub-record-check:26] System("SIP/3999-000000c8", "/var/lib/asterisk/bin/stoprecording.php "SIP/3999-000000c8"") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [recordcheck@sub-record-check:27] Return("SIP/3999-000000c8", "") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [exten@sub-record-check:17] Return("SIP/3999-000000c8", "") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-exten-vm:7] GotoIf("SIP/3999-000000c8", "0?macrodial") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-exten-vm:8] Set("SIP/3999-000000c8", "INTERCOM_EXT_DOPTIONS=HhTtr") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-exten-vm:9] Set("SIP/3999-000000c8", "INTERCOM_RETURN=TRUE") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-exten-vm:10] Gosub("SIP/3999-000000c8", "ext-intercom,*803810,1()") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [*803810@ext-intercom:1] Macro("SIP/3999-000000c8", "user-callerid,") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:1] Set("SIP/3999-000000c8", "TOUCH_MONITOR=1667900041.434") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:2] Set("SIP/3999-000000c8", "AMPUSER=3999") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:3] Set("SIP/3999-000000c8", "HOTDESCKCHAN=3999-000000c8") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:4] Set("SIP/3999-000000c8", "HOTDESKEXTEN=3999") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:5] Set("SIP/3999-000000c8", "HOTDESKCALL=0") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:6] ExecIf("SIP/3999-000000c8", "0?Set(HOTDESKCALL=1)") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:7] ExecIf("SIP/3999-000000c8", "0?Set(CALLERID(name)=)") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:8] GotoIf("SIP/3999-000000c8", "4?report") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx_builtins.c: Goto (macro-user-callerid,s,22)
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:22] NoOp("SIP/3999-000000c8", "Macro Depth is 2") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:23] GotoIf("SIP/3999-000000c8", "1?report2:macroerror") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx_builtins.c: Goto (macro-user-callerid,s,24)
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:24] GotoIf("SIP/3999-000000c8", "0?continue") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:25] Set("SIP/3999-000000c8", "__TTL=63") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:26] GotoIf("SIP/3999-000000c8", "1?continue") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx_builtins.c: Goto (macro-user-callerid,s,42)
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:42] Set("SIP/3999-000000c8", "CALLERID(number)=3999") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:43] Set("SIP/3999-000000c8", "CALLERID(name)=GCPL") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:44] GotoIf("SIP/3999-000000c8", "0?cnum") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:45] Set("SIP/3999-000000c8", "CDR(cnam)=GCPL") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:46] Set("SIP/3999-000000c8", "CDR(cnum)=3999") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-user-callerid:47] Set("SIP/3999-000000c8", "CHANNEL(language)=en") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [*803810@ext-intercom:2] Set("SIP/3999-000000c8", "dialnumber=3810") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [*803810@ext-intercom:3] Set("SIP/3999-000000c8", "INTERCOM_CALL=TRUE") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [*803810@ext-intercom:4] Gosub("SIP/3999-000000c8", "sub-record-check,s,1(exten,3810)") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@sub-record-check:1] GotoIf("SIP/3999-000000c8", "4?initialized") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx_builtins.c: Goto (sub-record-check,s,10)
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@sub-record-check:10] NoOp("SIP/3999-000000c8", "Recordings initialized") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@sub-record-check:11] ExecIf("SIP/3999-000000c8", "0?Set(ARG3=dontcare)") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@sub-record-check:12] Set("SIP/3999-000000c8", "REC_POLICY_MODE_SAVE=NEVER") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@sub-record-check:13] ExecIf("SIP/3999-000000c8", "0?Set(REC_STATUS=NO)") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@sub-record-check:14] GotoIf("SIP/3999-000000c8", "5?checkaction") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx_builtins.c: Goto (sub-record-check,s,17)
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@sub-record-check:17] GotoIf("SIP/3999-000000c8", "1?sub-record-check,exten,1") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx_builtins.c: Goto (sub-record-check,exten,1)
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [exten@sub-record-check:1] NoOp("SIP/3999-000000c8", "Exten Recording Check between 3999 and 3810") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [exten@sub-record-check:2] Set("SIP/3999-000000c8", "CALLTYPE=internal") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [exten@sub-record-check:3] ExecIf("SIP/3999-000000c8", "0?Set(CALLTYPE=)") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [exten@sub-record-check:4] Set("SIP/3999-000000c8", "CALLEE=never") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [exten@sub-record-check:5] ExecIf("SIP/3999-000000c8", "0?Set(CALLEE=dontcare)") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [exten@sub-record-check:6] GotoIf("SIP/3999-000000c8", "0?callee") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [exten@sub-record-check:7] GotoIf("SIP/3999-000000c8", "0?caller") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [exten@sub-record-check:8] ExecIf("SIP/3999-000000c8", "2?Set(CALLER_PRI=10):Set(CALLER_PRI=0)") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [exten@sub-record-check:9] ExecIf("SIP/3999-000000c8", "2?Set(CALLEE_PRI=10):Set(CALLEE_PRI=0)") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [exten@sub-record-check:10] GotoIf("SIP/3999-000000c8", "1?caller:callee") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx_builtins.c: Goto (sub-record-check,exten,13)
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [exten@sub-record-check:13] Set("SIP/3999-000000c8", "RECMODE=never") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [exten@sub-record-check:14] ExecIf("SIP/3999-000000c8", "0?Set(RECMODE=dontcare)") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [exten@sub-record-check:15] ExecIf("SIP/3999-000000c8", "0?Set(RECMODE=never)") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [exten@sub-record-check:16] Gosub("SIP/3999-000000c8", "recordcheck,1(never,internal,3810)") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("SIP/3999-000000c8", "Starting recording check against never") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("SIP/3999-000000c8", "never") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx_builtins.c: Goto (sub-record-check,recordcheck,14)
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [recordcheck@sub-record-check:14] Set("SIP/3999-000000c8", "__REC_POLICY_MODE=NEVER") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [recordcheck@sub-record-check:15] Goto("SIP/3999-000000c8", "stoprec") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx_builtins.c: Goto (sub-record-check,recordcheck,24)
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [recordcheck@sub-record-check:24] NoOp("SIP/3999-000000c8", "Stopping recording: internal, 3810") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [recordcheck@sub-record-check:25] Set("SIP/3999-000000c8", "__REC_STATUS=STOPPED") in new stack
[2022-11-08 15:04:01] VERBOSE[26801][C-000000a4] pbx.c: Executing [recordcheck@sub-record-check:26] System("SIP/3999-000000c8", "/var/lib/asterisk/bin/stoprecording.php "SIP/3999-000000c8"") in new stack
[2022-11-08 15:04:02] VERBOSE[317] chan_sip.c: 
<--- SIP read from UDP:192.168.13.62:5060 --->
jaK
<------------->
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [recordcheck@sub-record-check:27] Return("SIP/3999-000000c8", "") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [exten@sub-record-check:17] Return("SIP/3999-000000c8", "") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [*803810@ext-intercom:5] GotoIf("SIP/3999-000000c8", "0?end") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [*803810@ext-intercom:6] GotoIf("SIP/3999-000000c8", "0?end") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [*803810@ext-intercom:7] GotoIf("SIP/3999-000000c8", "0?allow") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [*803810@ext-intercom:8] GotoIf("SIP/3999-000000c8", "0?nointercom") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [*803810@ext-intercom:9] GotoIf("SIP/3999-000000c8", "0?nointercom") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [*803810@ext-intercom:10] Set("SIP/3999-000000c8", "DEVICES=3810") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [*803810@ext-intercom:11] GotoIf("SIP/3999-000000c8", "0?end") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [*803810@ext-intercom:12] Set("SIP/3999-000000c8", "OVERRIDE=reject") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [*803810@ext-intercom:13] Set("SIP/3999-000000c8", "LOOPCNT=1") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [*803810@ext-intercom:14] Set("SIP/3999-000000c8", "_SIPURI=") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [*803810@ext-intercom:15] Set("SIP/3999-000000c8", "_ALERTINFO=Ring Answer") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [*803810@ext-intercom:16] Set("SIP/3999-000000c8", "_CALLINFO=<uri>;answer-after=0") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [*803810@ext-intercom:17] Set("SIP/3999-000000c8", "_SIPURI=intercom=true") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [*803810@ext-intercom:18] Set("SIP/3999-000000c8", "_DTIME=5") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [*803810@ext-intercom:19] Set("SIP/3999-000000c8", "_ANSWERMACRO=") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [*803810@ext-intercom:20] GotoIf("SIP/3999-000000c8", "0?pagemode") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [*803810@ext-intercom:21] Macro("SIP/3999-000000c8", "autoanswer,3810") in new stack
4

Continuing

[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-autoanswer:1] GotoIf("SIP/3999-000000c8", "0?knowndial") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-autoanswer:2] Set("SIP/3999-000000c8", "DEVICE=SIP/3810") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-autoanswer:3] GotoIf("SIP/3999-000000c8", "0?dopjsip") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-autoanswer:4] Set("SIP/3999-000000c8", "KNOWNDIAL=SIP/3810") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-autoanswer:5] Goto("SIP/3999-000000c8", "knowndial") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx_builtins.c: Goto (macro-autoanswer,s,19)
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-autoanswer:19] Set("SIP/3999-000000c8", "DIAL=SIP/3810") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-autoanswer:20] GotoIf("SIP/3999-000000c8", "0?macro") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-autoanswer:21] GotoIf("SIP/3999-000000c8", "0?pjsipua") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-autoanswer:22] Set("SIP/3999-000000c8", "USERAGENT=Linphonec/3.12.0 (belle-sip/1.6.3)") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-autoanswer:23] Goto("SIP/3999-000000c8", "uafin") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx_builtins.c: Goto (macro-autoanswer,s,27)
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-autoanswer:27] ExecIf("SIP/3999-000000c8", "0?Set(USERAGENT=)") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-autoanswer:28] ExecIf("SIP/3999-000000c8", "0?Set(PAGE_VOL=;volume=)") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-autoanswer:29] ExecIf("SIP/3999-000000c8", "0?Set(ALERTINFO=ring-answer)") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-autoanswer:30] ExecIf("SIP/3999-000000c8", "0?Set(CALLINFO=<sip:broadworks.net>;answer-after=0)") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-autoanswer:31] ExecIf("SIP/3999-000000c8", "0?Set(ALERTINFO=<http://example.com>;info=alert-autoanswer)") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-autoanswer:32] ExecIf("SIP/3999-000000c8", "0?Set(ALERTINFO=Intercom)") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-autoanswer:33] ExecIf("SIP/3999-000000c8", "0?Set(ALERTINFO=info=Auto Answer)") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-autoanswer:34] ExecIf("SIP/3999-000000c8", "0?Set(ALERTINFO=<http://www.sangoma.com>;info=external)") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@macro-autoanswer:35] ExecIf("SIP/3999-000000c8", "1?Set(__SIP_URI_OPTIONS=intercom=true)") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [*803810@ext-intercom:22] Set("SIP/3999-000000c8", "_DOPTIONS=A(beep)b(autoanswer^s^1(Ring Answer,<uri>;answer-after=0))") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [*803810@ext-intercom:23] ChanIsAvail("SIP/3999-000000c8", "SIP/3810,s") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] netsock2.c: Using SIP RTP TOS bits 184
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] netsock2.c: Using SIP RTP CoS mark 5
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] chan_sip.c: Scheduling destruction of SIP dialog '[email protected]:5060' in 6400 ms (Method: INVITE)
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [*803810@ext-intercom:24] ExecIf("SIP/3999-000000c8", "0?Set(AVAILORIGCHAN=SIP/3810)") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [*803810@ext-intercom:25] GotoIf("SIP/3999-000000c8", "1?continue") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx_builtins.c: Goto (ext-intercom,*803810,30)
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [*803810@ext-intercom:30] NoOp("SIP/3999-000000c8", "Continuing with page") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [*803810@ext-intercom:31] GotoIf("SIP/3999-000000c8", "0?godial") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [*803810@ext-intercom:32] Set("SIP/3999-000000c8", "CONNECTEDLINE(name,i)=Test Extension") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [*803810@ext-intercom:33] Set("SIP/3999-000000c8", "CONNECTEDLINE(num)=3810") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [*803810@ext-intercom:34] Dial("SIP/3999-000000c8", "SIP/3810,5,IA(beep)b(autoanswer^s^1(Ring Answer,<uri>;answer-after=0))HhTtr") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] netsock2.c: Using SIP RTP TOS bits 184
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] netsock2.c: Using SIP RTP CoS mark 5
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] app_stack.c: SIP/3810-000000ca Internal Gosub(autoanswer,s,1(Ring Answer,<uri>;answer-after=0)) start
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@autoanswer:1] GosubIf("SIP/3810-000000ca", "1?func-set-sipheader,s,1(Alert-Info,Ring Answer)") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@func-set-sipheader:1] NoOp("SIP/3810-000000ca", "Sip Add Header function called. Adding Alert-Info = Ring Answer") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@func-set-sipheader:2] Set("SIP/3810-000000ca", "HASH(__SIPHEADERS,Alert-Info)=Ring Answer") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@func-set-sipheader:3] Return("SIP/3810-000000ca", "") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@autoanswer:2] GosubIf("SIP/3810-000000ca", "1?func-set-sipheader,s,1(Call-Info,<uri>;answer-after=0)") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@func-set-sipheader:1] NoOp("SIP/3810-000000ca", "Sip Add Header function called. Adding Call-Info = <uri>;answer-after=0") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@func-set-sipheader:2] Set("SIP/3810-000000ca", "HASH(__SIPHEADERS,Call-Info)=<uri>;answer-after=0") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@func-set-sipheader:3] Return("SIP/3810-000000ca", "") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@autoanswer:3] Gosub("SIP/3810-000000ca", "func-apply-sipheaders,s,1()") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@func-apply-sipheaders:1] NoOp("SIP/3810-000000ca", "Applying SIP Headers to channel SIP/3810-000000ca") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@func-apply-sipheaders:2] Set("SIP/3810-000000ca", "TECH=SIP") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@func-apply-sipheaders:3] Set("SIP/3810-000000ca", "SIPHEADERKEYS=Call-Info,Alert-Info") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@func-apply-sipheaders:4] While("SIP/3810-000000ca", "1") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@func-apply-sipheaders:5] Set("SIP/3810-000000ca", "sipheader=<uri>;answer-after=0") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@func-apply-sipheaders:6] ExecIf("SIP/3810-000000ca", "0?SIPRemoveHeader(Call-Info:)") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@func-apply-sipheaders:7] ExecIf("SIP/3810-000000ca", "0?Set(PJSIP_HEADER(remove,Call-Info)=)") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@func-apply-sipheaders:8] ExecIf("SIP/3810-000000ca", "0?Set(sipheader=<http://127.0.0.1>;info=<uri>;answer-after=0)") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@func-apply-sipheaders:9] ExecIf("SIP/3810-000000ca", "0?Set(sipheader=<http://127.0.0.1><uri>;answer-after=0)") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@func-apply-sipheaders:10] ExecIf("SIP/3810-000000ca", "1?SIPAddHeader(Call-Info:<uri>;answer-after=0)") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@func-apply-sipheaders:11] ExecIf("SIP/3810-000000ca", "0?Set(PJSIP_HEADER(add,Call-Info)=<uri>;answer-after=0)") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@func-apply-sipheaders:12] EndWhile("SIP/3810-000000ca", "") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@func-apply-sipheaders:4] While("SIP/3810-000000ca", "1") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@func-apply-sipheaders:5] Set("SIP/3810-000000ca", "sipheader=Ring Answer") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@func-apply-sipheaders:6] ExecIf("SIP/3810-000000ca", "0?SIPRemoveHeader(Alert-Info:)") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@func-apply-sipheaders:7] ExecIf("SIP/3810-000000ca", "0?Set(PJSIP_HEADER(remove,Alert-Info)=)") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@func-apply-sipheaders:8] ExecIf("SIP/3810-000000ca", "1?Set(sipheader=<http://127.0.0.1>;info=Ring Answer)") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@func-apply-sipheaders:9] ExecIf("SIP/3810-000000ca", "0?Set(sipheader=<http://127.0.0.1><http://127.0.0.1>;info=Ring Answer)") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@func-apply-sipheaders:10] ExecIf("SIP/3810-000000ca", "1?SIPAddHeader(Alert-Info:<http://127.0.0.1>;info=Ring Answer)") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@func-apply-sipheaders:11] ExecIf("SIP/3810-000000ca", "0?Set(PJSIP_HEADER(add,Alert-Info)=<http://127.0.0.1>;info=Ring Answer)") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@func-apply-sipheaders:12] EndWhile("SIP/3810-000000ca", "") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@func-apply-sipheaders:4] While("SIP/3810-000000ca", "0") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@func-apply-sipheaders:13] Return("SIP/3810-000000ca", "") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] pbx.c: Executing [s@autoanswer:4] Return("SIP/3810-000000ca", "") in new stack
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] app_stack.c: Spawn extension (from-internal, 3810, 1) exited non-zero on 'SIP/3810-000000ca'
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] app_stack.c: SIP/3810-000000ca Internal Gosub(autoanswer,s,1(Ring Answer,<uri>;answer-after=0)) complete GOSUB_RETVAL=
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] chan_sip.c: Audio is at 14208
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] chan_sip.c: Adding codec ulaw to SDP
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] chan_sip.c: Adding codec alaw to SDP
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] chan_sip.c: Adding codec gsm to SDP
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] chan_sip.c: Adding codec g726 to SDP
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] chan_sip.c: Adding codec g722 to SDP
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] chan_sip.c: Reliably Transmitting (NAT) to 192.168.5.177:5060:
INVITE sip:[email protected];transport=udp;intercom=true SIP/2.0
Via: SIP/2.0/UDP 192.168.5.5:5060;branch=z9hG4bK7f0b92df;rport
Max-Forwards: 70
From: "GCPL" <sip:[email protected]>;tag=as18c62dd7
To: <sip:[email protected];transport=udp;intercom=true>
Contact: <sip:[email protected]:5060>
Call-ID: [email protected]:5060
CSeq: 102 INVITE
User-Agent: FPBX-15.0.17.9(16.11.1)
Date: Tue, 08 Nov 2022 09:34:02 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Alert-Info: <http://127.0.0.1>;info=Ring Answer
Call-Info: <uri>;answer-after=0
P-Asserted-Identity: "GCPL" <sip:[email protected]>
Content-Type: application/sdp
Content-Length: 350

v=0
o=root 451713732 451713732 IN IP4 192.168.5.5
s=Asterisk PBX 16.11.1
c=IN IP4 192.168.5.5
t=0 0
m=audio 14208 RTP/AVP 0 8 3 111 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:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

---
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] app_dial.c: Called SIP/3810
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] chan_sip.c: 
<--- Transmitting (NAT) to 192.168.5.174:54766 --->
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 192.168.5.174:54766;branch=z9hG4bKPjk7hhcCcjHCYdw5q6NKz4CA17161l5iK-;received=192.168.5.174;rport=54766
From: "Dhj PA Client" <sip:[email protected]>;tag=JvwrcZDpdaUcHDOEG-kWIeSwOHQZoBSJ
To: sip:[email protected];tag=as4c81e854
Call-ID: mLP0gUKb5nU--4.0f0aBJOkg3PkwxUaq
CSeq: 18659 INVITE
Server: FPBX-15.0.17.9(16.11.1)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Contact: <sip:[email protected]:5060>
P-Asserted-Identity: "Test Extension" <sip:[email protected]>
Content-Length: 0


<------------>
[2022-11-08 15:04:02] VERBOSE[26801][C-000000a4] app_dial.c: Connected line update to SIP/3999-000000c8 prevented.
[2022-11-08 15:04:03] VERBOSE[317] chan_sip.c: Retransmitting #1 (NAT) to 192.168.5.177:5060:
INVITE sip:[email protected];transport=udp;intercom=true SIP/2.0
Via: SIP/2.0/UDP 192.168.5.5:5060;branch=z9hG4bK7f0b92df;rport
Max-Forwards: 70
From: "GCPL" <sip:[email protected]>;tag=as18c62dd7
To: <sip:[email protected];transport=udp;intercom=true>
Contact: <sip:[email protected]:5060>
Call-ID: [email protected]:5060
CSeq: 102 INVITE
User-Agent: FPBX-15.0.17.9(16.11.1)
Date: Tue, 08 Nov 2022 09:34:02 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Alert-Info: <http://127.0.0.1>;info=Ring Answer
Call-Info: <uri>;answer-after=0
P-Asserted-Identity: "GCPL" <sip:[email protected]>
Content-Type: application/sdp
Content-Length: 350

v=0
o=root 451713732 451713732 IN IP4 192.168.5.5
s=Asterisk PBX 16.11.1
c=IN IP4 192.168.5.5
t=0 0
m=audio 14208 RTP/AVP 0 8 3 111 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:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

---
[2022-11-08 15:04:03] VERBOSE[317] chan_sip.c: Retransmitting #2 (NAT) to 192.168.5.177:5060:
INVITE sip:[email protected];transport=udp;intercom=true SIP/2.0
Via: SIP/2.0/UDP 192.168.5.5:5060;branch=z9hG4bK7f0b92df;rport
Max-Forwards: 70
From: "GCPL" <sip:[email protected]>;tag=as18c62dd7
To: <sip:[email protected];transport=udp;intercom=true>
Contact: <sip:[email protected]:5060>
Call-ID: [email protected]:5060
CSeq: 102 INVITE
User-Agent: FPBX-15.0.17.9(16.11.1)
Date: Tue, 08 Nov 2022 09:34:02 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Alert-Info: <http://127.0.0.1>;info=Ring Answer
Call-Info: <uri>;answer-after=0
P-Asserted-Identity: "GCPL" <sip:[email protected]>
Content-Type: application/sdp
Content-Length: 350

v=0
o=root 451713732 451713732 IN IP4 192.168.5.5
s=Asterisk PBX 16.11.1
c=IN IP4 192.168.5.5
t=0 0
m=audio 14208 RTP/AVP 0 8 3 111 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:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

---
[2022-11-08 15:04:03] VERBOSE[317] chan_sip.c: 
<--- SIP read from UDP:192.168.5.107:5060 --->
jaK
<------------->
[2022-11-08 15:04:03] VERBOSE[317] chan_sip.c: Retransmitting #3 (NAT) to 192.168.5.177:5060:
INVITE sip:[email protected];transport=udp;intercom=true SIP/2.0
Via: SIP/2.0/UDP 192.168.5.5:5060;branch=z9hG4bK7f0b92df;rport
Max-Forwards: 70
From: "GCPL" <sip:[email protected]>;tag=as18c62dd7
To: <sip:[email protected];transport=udp;intercom=true>
Contact: <sip:[email protected]:5060>
Call-ID: [email protected]:5060
CSeq: 102 INVITE
User-Agent: FPBX-15.0.17.9(16.11.1)
Date: Tue, 08 Nov 2022 09:34:02 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Alert-Info: <http://127.0.0.1>;info=Ring Answer
Call-Info: <uri>;answer-after=0
P-Asserted-Identity: "GCPL" <sip:[email protected]>
Content-Type: application/sdp
Content-Length: 350

v=0
o=root 451713732 451713732 IN IP4 192.168.5.5
s=Asterisk PBX 16.11.1
c=IN IP4 192.168.5.5
t=0 0
m=audio 14208 RTP/AVP 0 8 3 111 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:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

---
5

There is incoming gibberish, but no outgoing INVITE, in the log.

I do notice you are adding a header to try to force the phone to auto answer. If the subject is really saying not auto-answering, you should note that autoanswer is a security risk (self inflicted infinity bug), so sensible phones will need to have that security check disabled before autoanswer will work.

(Not enabling autoanswer on the phone should not, however, result in the error you got, which means there wasn’t even a Trying response.)

6

Yes we need to enable auto answer for this extension 3810. I have very limited knowledge of FreePBX and wondering how to fix the on issue issue.

It rings twice and busy tone plays then after if we try to redial the ext its not available.

7

There isn’t enough information to understand why its response isn’t reaching Asterisk. We definitely need to see the INVITE.

You should also check if a firewall is blocking the responses.

Note I read “it rings twice” as meaning the phone actually rang, so must have received the INVITE but you could refer to the ring back tone heard by the caller.

8

As mentioned, when we dial the Extension 3810, the caller can hear ringing tone twice and then the busy tone comes and call gets disconnected.
Moreover I have checked firewall and its not blocking anything.

9

If it is the caller that is hearing things, that doesn’t add anything to what the log shows, namely that there are no responses from the callee.

You still haven’t provided the INVITE to the callee.

10

I am trying to upload logs however due to size limit unable to. Is there any way by which I can share the logs with you.

11

Paste the log at pastebin.freepbx.org and post the link here.

12

https://pastebin.freepbx.org/view/d8b8c811

Please check

13

The INVITEs to 192.168.5.177 look good, but you are getting no responses. You need to trace it through the network to see where the INVITE or response is getting lost.

14

The device isn’t responding to the INVITE being sent by FreePBX. The correct headers are there but there are 3 retransmissions of the INVITE to the device with no response. That is 4 attempts to send the INVITE and get a reply.

15

Actually 7:

1213. [2022-11-08 15:03:54] VERBOSE[317] chan_sip.c: Retransmitting #6 (NAT) to 192.168.5.177:5060:

16

So I need to check the network connectivity right.

17 
[2022-11-10 11:38:33] VERBOSE[25264][C-00000089] pbx.c: Executing [3810@from-internal:4] Set("SIP/3999-00000098", "__PICKUPMARK=") in new stack
[2022-11-10 11:38:33] VERBOSE[25264][C-00000089] pbx.c: Executing [3810@from-internal:5] GotoIf("SIP/3999-00000098", "0?app-blackhole,busy,1") in new stack
[2022-11-10 11:38:33] VERBOSE[25264][C-00000089] pbx.c: Executing [3810@from-internal:6] GotoIf("SIP/3999-00000098", "0?app-blackhole,busy,1") in new stack
[2022-11-10 11:38:33] VERBOSE[25264][C-00000089] pbx.c: Executing [3810@from-internal:7] GotoIf("SIP/3999-00000098", "1?app-blackhole,busy,1") in new stack
[2022-11-10 11:38:33] VERBOSE[25264][C-00000089] pbx_builtins.c: Goto (app-blackhole,busy,1)
[2022-11-10 11:38:33] VERBOSE[25264][C-00000089] pbx.c: Executing [busy@app-blackhole:1] NoOp("SIP/3999-00000098", "Blackhole Dest: Busy") in new stack
[2022-11-10 11:38:33] VERBOSE[25264][C-00000089] pbx.c: Executing [busy@app-blackhole:2] Progress("SIP/3999-00000098", "") in new stack
[2022-11-10 11:38:33] VERBOSE[25264][C-00000089] pbx.c: Executing [busy@app-blackhole:3] Busy("SIP/3999-00000098", "20") in new stack
[2022-11-10 11:38:33] WARNING[25264][C-00000089] channel.c: Prodding channel 'SIP/3999-00000098' failed
[2022-11-10 11:38:33] VERBOSE[25264][C-00000089] pbx.c: Spawn extension (app-blackhole, busy, 3) exited non-zero on 'SIP/3999-00000098'
18

After testing Ext 3810 went unreachable. Why?
There are no packet drops between Ext 3999 and Ext 3810.
Changed N/W cable, tried connecting to different Switch port as well as with different VLAn as well.
Still the results are same.

19 
chan_sip.c: Timeout on [email protected]:5060 on non-critical invite transaction.

what does it mean?

I have connected Sip Extension and Servers to a same Switch then to above error is occurring.

What should I check next.

20

You failed to get a response to a re-INVITE, but that re-INVITE was for something not essential to the session’s continuing, for example, I think updating the connected line information.

Are you using a device with broken support for Re-INVITE?