Extensions not able to receive calls (but are able to call out to external numbers)

I am using FreePBX 15.0.17.64 in combination with Asterisk 16.22 on a CentOS 7 VPS
It all seems to work well with my current configuration which contains 2 IVR’s 1 general VM and 2 ringroups with mobile phone numbers in them.

But now i want to add VOIP phones (soft and hard) and i have followed a few instructions on the internet but it will not work very well.

At this moment i got 3 Fanvil X3C phones on the latest firmware version and wilt there own extension on line (sip) 1. I am able to call out and reach any external phone. But i am not able to reach any internal extensions with exception for ringroups, those are reachable. So i now have 500, 501 and 502 and when i want to call from 500 to 501 it just goes straight to the voicemail of 501.

Also, when i want to listen to a message on my general VM (which is on 300, calling from 500, 501 or 502), i get the lady voice telling me that there is a message and then the call drops.

What i have tried:
→ Delete extentions and reset phones and quick create the extentions with no other settings tuned.
→ change some time-out settings
→ Reboot the VPS
→ Disabeld the VPS firewall (i don’t have the firewall module of FreePBX installed)

Also a note: Since i am running my PBX on a VPS, the phone are not in the same network as the PBX. the phones are now with me at home behind a simpel ISP-modem/router

Does anyone maybe know what could be wrong?

Have the phones actually registered with the server? An unregistered phone can usually dial out, because it makes a request to dial and is then asked for its credentials, but an unregistered phone won’t recieve calls.
Check the asterisk info menu and see if the extensions show as available.

Hi Johnoneszeros, thank you for responding.
This is the info i found:

    -= Registered Asterisk Dial Plan Hints =-
_*45*[email protected]  : ${DB(AMPUSER/${EXTEN  State:Unavailable     Presence:                Watchers  0
_*46*[email protected]  : ${DB(AMPUSER/${EXTEN  State:Unavailable     Presence:                Watchers  0
*[email protected]: Custom:TC1            State:Idle            Presence:not_set         Watchers  0
_*45XXX*[email protected]: Custom:QUEUE${EXTEN:  State:Unavailable     Presence:                Watchers  0
[email protected]       : ,CustomPresence:500   State:Unavailable     Presence:not_set         Watchers  0
[email protected]       : ,CustomPresence:501   State:Unavailable     Presence:not_set         Watchers  0
[email protected]       : ,CustomPresence:502   State:Unavailable     Presence:not_set         Watchers  0
_*[email protected] : Custom:DEVCF${EXTEN:  State:Unavailable     Presence:                Watchers  0
_*[email protected]    : ${DB(AMPUSER/${EXTEN  State:Unavailable     Presence:                Watchers  0
[email protected]       : ,CustomPresence:300   State:Unavailable     Presence:not_set         Watchers  0
_*[email protected]   : MWI:${EXTEN:3}@${DB(  State:Unavailable     Presence:                Watchers  0
----------------
- 11 hints registered

The have indeed the state “Unavailable”.

And when i use “sip show peers”, i get the following:

server04*CLI> sip show peers
Name/username             Host                                    		Dyn Forcerport Comedia    ACL Port     Status      Description
500/500                   <My home IP>                            		D  Yes        Yes         A  5511     OK (44 ms)
501/501                   <My home IP>                            		D  Yes        Yes         A  5623     OK (23 ms)
502/502                   <My home IP>                            		D  Yes        Yes         A  5060     OK (24 ms)
I_cmFive                  <IP_of_SIPtrunk>                                 Yes        No             5060     OK (17 ms)
I_cmFour                  <IP_of_SIPtrunk>                                 Yes        No             5060     OK (21 ms)
I_cmOne                   <IP_of_SIPtrunk>                                 Yes        No             5060     OK (13 ms)
I_cmSeven                 <IP_of_SIPtrunk>                                 Yes        No             5060     OK (20 ms)
I_cmSix                   <IP_of_SIPtrunk>                                 Yes        No             5060     OK (21 ms)
I_cmThree                 <IP_of_SIPtrunk>                                 Yes        No             5060     OK (12 ms)
I_cmTwo                   <IP_of_SIPtrunk>                                 Yes        No             5060     OK (16 ms)
O_cmFive/HammerTEp6b      <IP_of_SIPtrunk>                                 Yes        No             5060     OK (8 ms)
O_cmFour/HammerTEp6b      <IP_of_SIPtrunk>                                 Yes        No             5060     OK (11 ms)
O_cmOne/HammerTEp6b       <IP_of_SIPtrunk>                                 Yes        Yes            5060     OK (8 ms)
O_cmSeven/HammerTEp6b     <IP_of_SIPtrunk>                                 Yes        No             5060     OK (8 ms)
O_cmSix/HammerTEp6b       <IP_of_SIPtrunk>                                 Yes        No             5060     OK (9 ms)
O_cmThree/HammerTEp6b     <IP_of_SIPtrunk>                                 Yes        No             5060     OK (11 ms)
cmTwo/HammerTEp6b         <IP_of_SIPtrunk>                                 Yes        No             5060     OK (11 ms)
17 sip peers [Monitored: 17 online, 0 offline Unmonitored: 0 online, 0 offline]

I had a similar problem yesterday but with sip trunks. I think if the qualify messages are going back and forth the phone will show as status OK.
However it doesn’t mean it is registered.
I suggest you turn on sip logging and see if registration requests arrive at the PBX from the phone.
You should see a register request, a rejection (because the request was sent without credentials) , another request and a 200 OK back from the PBX.

If you are using PJSIP. PJSIP set logger on / off can be used when in asterisk cli.

I do get a 200 OK back, this is the log i got when calling from 500 to 502:

[2022-01-13 18:25:40] VERBOSE[4314][C-00000085] chan_sip.c: Looking for 502 in from-internal (domain <My VPS domain>)
[2022-01-13 18:25:40] VERBOSE[4314][C-00000085] sip/route.c: sip_route_dump: route/path hop: <sip:[email protected]<My home IP>:5397>
[2022-01-13 18:25:40] VERBOSE[4314][C-00000085] chan_sip.c: 
<--- Transmitting (NAT) to <My home IP>:5397 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP <Internal IP phone ext 502>:5397;branch=z9hG4bK359940801533523955;received=<My home IP>;rport=5397
From: <My name> <sip:[email protected]<My VPS domain>:5060>;tag=311238012
To: "502" <sip:[email protected]<My VPS domain>;user=phone>
Call-ID: [email protected]<My home IP>
CSeq: 2 INVITE
Server: FPBX-15.0.17.64(16.22.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Contact: <sip:[email protected]<My VPS IP>:5060>
Content-Length: 0


<------------>
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:1] Set("SIP/500-00000084", "__RINGTIMER=15") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:2] ExecIf("SIP/500-00000084", "0?Set(__CWIGNORE=)") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:3] Macro("SIP/500-00000084", "exten-vm,502,502,0,0,0") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:1] Macro("SIP/500-00000084", "user-callerid,") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:1] Set("SIP/500-00000084", "TOUCH_MONITOR=1642094740.132") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:2] Set("SIP/500-00000084", "CHANCONTEXT=") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:3] Set("SIP/500-00000084", "CHANCONTEXT=") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:4] Set("SIP/500-00000084", "CHANEXTENCONTEXT=500-00000084") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:5] Set("SIP/500-00000084", "CHANEXTEN=500-00000084") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:6] Set("SIP/500-00000084", "CALLERID(number)=500") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:7] Set("SIP/500-00000084", "AMPUSER=500") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:8] Set("SIP/500-00000084", "HOTDESCKCHAN=500-00000084") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:9] Set("SIP/500-00000084", "HOTDESKEXTEN=500") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:10] Set("SIP/500-00000084", "HOTDESKCALL=0") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:11] ExecIf("SIP/500-00000084", "0?Set(HOTDESKCALL=1)") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:12] ExecIf("SIP/500-00000084", "0?Set(CALLERID(name)=)") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:13] GotoIf("SIP/500-00000084", "0?report") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:14] ExecIf("SIP/500-00000084", "1?Set(REALCALLERIDNUM=500)") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:15] Set("SIP/500-00000084", "AMPUSER=") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:16] GotoIf("SIP/500-00000084", "0?limit") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:17] Set("SIP/500-00000084", "AMPUSERCIDNAME=") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:18] ExecIf("SIP/500-00000084", "0?Set(__CIDMASQUERADING=TRUE)") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:19] GotoIf("SIP/500-00000084", "1?report") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx_builtins.c: Goto (macro-user-callerid,s,27)
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:27] NoOp("SIP/500-00000084", "Macro Depth is 2") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:28] GotoIf("SIP/500-00000084", "1?report2:macroerror") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx_builtins.c: Goto (macro-user-callerid,s,29)
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:29] GotoIf("SIP/500-00000084", "0?continue") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:30] Set("SIP/500-00000084", "__TTL=64") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:31] GotoIf("SIP/500-00000084", "1?continue") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx_builtins.c: Goto (macro-user-callerid,s,47)
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:47] Set("SIP/500-00000084", "CALLERID(number)=500") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:48] Set("SIP/500-00000084", "CALLERID(name)=<My name>") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:49] GotoIf("SIP/500-00000084", "0?cnum") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:50] Set("SIP/500-00000084", "CDR(cnam)=<My name>") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:51] Set("SIP/500-00000084", "CDR(cnum)=500") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:52] Set("SIP/500-00000084", "CHANNEL(language)=nl") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:2] Set("SIP/500-00000084", "RingGroupMethod=none") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:3] Set("SIP/500-00000084", "__EXTTOCALL=502") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:4] Set("SIP/500-00000084", "__PICKUPMARK=502") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:5] Set("SIP/500-00000084", "RT=15") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:6] Gosub("SIP/500-00000084", "sub-record-check,s,1(exten,502,dontcare)") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:1] GotoIf("SIP/500-00000084", "0?initialized") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:2] Set("SIP/500-00000084", "__REC_STATUS=INITIALIZED") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:3] Set("SIP/500-00000084", "NOW=1642094740") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:4] Set("SIP/500-00000084", "__DAY=13") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:5] Set("SIP/500-00000084", "__MONTH=01") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:6] Set("SIP/500-00000084", "__YEAR=2022") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:7] Set("SIP/500-00000084", "__TIMESTR=20220113-182540") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:8] Set("SIP/500-00000084", "__FROMEXTEN=500") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:9] Set("SIP/500-00000084", "__MON_FMT=wav") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:10] NoOp("SIP/500-00000084", "Recordings initialized") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:11] ExecIf("SIP/500-00000084", "0?Set(ARG3=dontcare)") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:12] Set("SIP/500-00000084", "REC_POLICY_MODE_SAVE=") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:13] ExecIf("SIP/500-00000084", "0?Set(REC_STATUS=NO)") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:14] GotoIf("SIP/500-00000084", "5?checkaction") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx_builtins.c: Goto (sub-record-check,s,17)
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:17] GotoIf("SIP/500-00000084", "1?sub-record-check,exten,1") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx_builtins.c: Goto (sub-record-check,exten,1)
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:1] NoOp("SIP/500-00000084", "Exten Recording Check between 500 and 502") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:2] Set("SIP/500-00000084", "CALLTYPE=internal") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:3] ExecIf("SIP/500-00000084", "0?Set(CALLTYPE=)") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:4] Set("SIP/500-00000084", "CALLEE=") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:5] ExecIf("SIP/500-00000084", "1?Set(CALLEE=dontcare)") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:6] GotoIf("SIP/500-00000084", "0?callee") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:7] GotoIf("SIP/500-00000084", "1?caller") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx_builtins.c: Goto (sub-record-check,exten,13)
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:13] Set("SIP/500-00000084", "RECMODE=") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:14] Set("SIP/500-00000084", "CALLERRECMODE=") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:15] Set("SIP/500-00000084", "CALEERECMODE=") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:16] GotoIf("SIP/500-00000084", "1?processnormal") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx_builtins.c: Goto (sub-record-check,exten,21)
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:21] ExecIf("SIP/500-00000084", "1?Set(RECMODE=dontcare)") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:22] ExecIf("SIP/500-00000084", "1?Set(RECMODE=dontcare)") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:23] Gosub("SIP/500-00000084", "recordcheck,1(dontcare,internal,502)") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:1] NoOp("SIP/500-00000084", "Starting recording check against dontcare") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:2] Goto("SIP/500-00000084", "dontcare") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:3] Return("SIP/500-00000084", "") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:24] Return("SIP/500-00000084", "") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:7] GotoIf("SIP/500-00000084", "1?macrodial") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx_builtins.c: Goto (macro-exten-vm,s,13)
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:13] GosubIf("SIP/500-00000084", "0?clrheader,1()") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:14] Macro("SIP/500-00000084", "dial-one,15,HhTtr,502") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:1] Set("SIP/500-00000084", "DEXTEN=502") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:2] ExecIf("SIP/500-00000084", "0?Set(__EXTTOCALL=502)") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:3] Set("SIP/500-00000084", "DIALSTATUS_CW=") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:4] GosubIf("SIP/500-00000084", "0?screen,1()") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:5] GosubIf("SIP/500-00000084", "0?cf,1()") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:6] GotoIf("SIP/500-00000084", "1?skip1") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx_builtins.c: Goto (macro-dial-one,s,9)
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:9] GotoIf("SIP/500-00000084", "0?nodial") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:10] GotoIf("SIP/500-00000084", "0?continue") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:11] Set("SIP/500-00000084", "EXTHASCW=") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:12] GotoIf("SIP/500-00000084", "1?next1:cwinusebusy") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx_builtins.c: Goto (macro-dial-one,s,13)
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:13] GotoIf("SIP/500-00000084", "0?docfu:skip3") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx_builtins.c: Goto (macro-dial-one,s,17)
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:17] GotoIf("SIP/500-00000084", "1?next2:continue") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx_builtins.c: Goto (macro-dial-one,s,18)
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:18] GotoIf("SIP/500-00000084", "1?continue") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx_builtins.c: Goto (macro-dial-one,s,26)
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:26] GotoIf("SIP/500-00000084", "0?nodial") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:27] GosubIf("SIP/500-00000084", "1?dstring,1():dlocal,1()") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:1] Set("SIP/500-00000084", "DSTRING=") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:2] Set("SIP/500-00000084", "DEVICES=") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:3] ExecIf("SIP/500-00000084", "1?Return()") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:28] GotoIf("SIP/500-00000084", "1?nodial") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx_builtins.c: Goto (macro-dial-one,s,60)
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:60] NoOp("SIP/500-00000084", "") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:61] ExecIf("SIP/500-00000084", "1?Set(DIALSTATUS=NOANSWER)") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:62] NoOp("SIP/500-00000084", "Returned from dial-one with nothing to call and DIALSTATUS: NOANSWER") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:63] MacroExit("SIP/500-00000084", "") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:15] Set("SIP/500-00000084", "SV_DIALSTATUS=NOANSWER") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:16] GosubIf("SIP/500-00000084", "0?docfu,1()") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:17] GosubIf("SIP/500-00000084", "0?docfb,1()") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:18] Set("SIP/500-00000084", "DIALSTATUS=NOANSWER") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:19] ExecIf("SIP/500-00000084", "0?MacroExit()") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:20] GotoIf("SIP/500-00000084", "0?s-NOANSWER,1") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:21] Macro("SIP/500-00000084", "vm,502,NOANSWER,") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:1] Macro("SIP/500-00000084", "user-callerid,SKIPTTL") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:1] Set("SIP/500-00000084", "TOUCH_MONITOR=1642094740.132") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:2] Set("SIP/500-00000084", "CHANCONTEXT=") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:3] Set("SIP/500-00000084", "CHANCONTEXT=") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:4] Set("SIP/500-00000084", "CHANEXTENCONTEXT=500-00000084") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:5] Set("SIP/500-00000084", "CHANEXTEN=500-00000084") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:6] Set("SIP/500-00000084", "CALLERID(number)=500") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:7] Set("SIP/500-00000084", "AMPUSER=500") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:8] Set("SIP/500-00000084", "HOTDESCKCHAN=500-00000084") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:9] Set("SIP/500-00000084", "HOTDESKEXTEN=500") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:10] Set("SIP/500-00000084", "HOTDESKCALL=0") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:11] ExecIf("SIP/500-00000084", "0?Set(HOTDESKCALL=1)") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:12] ExecIf("SIP/500-00000084", "0?Set(CALLERID(name)=)") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:13] GotoIf("SIP/500-00000084", "0?report") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:14] ExecIf("SIP/500-00000084", "0?Set(REALCALLERIDNUM=500)") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:15] Set("SIP/500-00000084", "AMPUSER=") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:16] GotoIf("SIP/500-00000084", "0?limit") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:17] Set("SIP/500-00000084", "AMPUSERCIDNAME=") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:18] ExecIf("SIP/500-00000084", "0?Set(__CIDMASQUERADING=TRUE)") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:19] GotoIf("SIP/500-00000084", "1?report") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx_builtins.c: Goto (macro-user-callerid,s,27)
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:27] NoOp("SIP/500-00000084", "Macro Depth is 3") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:28] GotoIf("SIP/500-00000084", "1?report2:macroerror") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx_builtins.c: Goto (macro-user-callerid,s,29)
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:29] GotoIf("SIP/500-00000084", "1?continue") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx_builtins.c: Goto (macro-user-callerid,s,47)
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:47] Set("SIP/500-00000084", "CALLERID(number)=500") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:48] Set("SIP/500-00000084", "CALLERID(name)=<My name>") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:49] GotoIf("SIP/500-00000084", "0?cnum") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:50] Set("SIP/500-00000084", "CDR(cnam)=<My name>") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:51] Set("SIP/500-00000084", "CDR(cnum)=500") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:52] Set("SIP/500-00000084", "CHANNEL(language)=nl") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:2] Set("SIP/500-00000084", "VMGAIN=") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:3] Macro("SIP/500-00000084", "blkvm-check,") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:1] Set("SIP/500-00000084", "GOSUB_RETVAL=") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:2] ExecIf("SIP/500-00000084", "0?Set(GOSUB_RETVAL=TRUE)") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:3] MacroExit("SIP/500-00000084", "") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:4] GotoIf("SIP/500-00000084", "1?vmx,1") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx_builtins.c: Goto (macro-vm,vmx,1)
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:1] Set("SIP/500-00000084", "MEXTEN=502") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:2] Set("SIP/500-00000084", "MMODE=NOANSWER") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:3] Set("SIP/500-00000084", "RETVM=") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:4] Set("SIP/500-00000084", "MODE=unavail") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:5] Macro("SIP/500-00000084", "get-vmcontext,502") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:1] Set("SIP/500-00000084", "VMCONTEXT=") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:2] GotoIf("SIP/500-00000084", "1?200:300") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx_builtins.c: Goto (macro-get-vmcontext,s,200)
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:200] Set("SIP/500-00000084", "VMCONTEXT=default") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:6] Set("SIP/500-00000084", "MODE=unavail") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:7] NoOp("SIP/500-00000084", "MODE IS: unavail") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:8] GotoIf("SIP/500-00000084", "1?chknomsg") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx_builtins.c: Goto (macro-vm,vmx,10)
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:10] GotoIf("SIP/500-00000084", "0?s-NOANSWER,1") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:11] GotoIf("SIP/500-00000084", "1?notdirect") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx_builtins.c: Goto (macro-vm,vmx,13)
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:13] NoOp("SIP/500-00000084", "Checking if ext 502 is enabled: ") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:14] GotoIf("SIP/500-00000084", "1?s-NOANSWER,1") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx_builtins.c: Goto (macro-vm,s-NOANSWER,1)
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:1] Macro("SIP/500-00000084", "get-vmcontext,502") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:1] Set("SIP/500-00000084", "VMCONTEXT=") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:2] GotoIf("SIP/500-00000084", "1?200:300") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx_builtins.c: Goto (macro-get-vmcontext,s,200)
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:200] Set("SIP/500-00000084", "VMCONTEXT=default") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [[email protected]:2] VoiceMail("SIP/500-00000084", "[email protected],u") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] chan_sip.c: Audio is at 16040
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] chan_sip.c: Adding codec ulaw to SDP
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] chan_sip.c: Adding codec alaw to SDP
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] chan_sip.c: Adding codec g726 to SDP
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] chan_sip.c: Adding codec g722 to SDP
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] chan_sip.c: 
<--- Reliably Transmitting (NAT) to <My home IP>:5397 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP <Internal IP phone ext 502>:5397;branch=z9hG4bK359940801533523955;received=<My home IP>;rport=5397
From: <My name> <sip:[email protected]<My VPS domain>:5060>;tag=311238012
To: "502" <sip:[email protected]<My VPS domain>;user=phone>;tag=as6c95e1e1
Call-ID: [email protected]<My home IP>
CSeq: 2 INVITE
Server: FPBX-15.0.17.64(16.22.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Contact: <sip:[email protected]<My VPS IP>:5060>
Content-Type: application/sdp
Content-Length: 331

There is very little of the SIP signalling that’s been generated around this call in your trace, so its difficult to tell what’s happening.

It’s also not a registration attempt.

Hi, welcome to the forum.

Your 502 phone is not registered; this is the problem to figure out.

You are getting 200 OK back from the PBX because it redirects your call to the voicemail system.

Thanks! I do need to point out i am a beginner so i am not sure how i could show the right log for extension registration

If you are a newbie, you should be using chan_pjsip, not chan_sip. chan_sip is unsupported and scheduled for removal next year.

For logging, the following is some pointers I recently provided elsewhere:

See Collecting Debug Information - Asterisk Project - Asterisk Project Wiki

And given you are running FreePBX, see Providing Great Debug - Support Services - Documentation

Thanks for the info on debugging! Also i want to point out that i got the problem solved by enabeling “Call Waiting” for my extensions.