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

EHammer98 · January 12, 2022, 7:24pm

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?

johnoneszeros · January 13, 2022, 8:55am

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.

EHammer98 · January 13, 2022, 10:51am

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

    -= Registered Asterisk Dial Plan Hints =-
_*45*X.@ext-queues  : ${DB(AMPUSER/${EXTEN  State:Unavailable     Presence:                Watchers  0
_*46*X.@ext-queues  : ${DB(AMPUSER/${EXTEN  State:Unavailable     Presence:                Watchers  0
*271@timeconditions-: Custom:TC1            State:Idle            Presence:not_set         Watchers  0
_*45XXX*XXX@ext-queu: Custom:QUEUE${EXTEN:  State:Unavailable     Presence:                Watchers  0
500@ext-local       : ,CustomPresence:500   State:Unavailable     Presence:not_set         Watchers  0
501@ext-local       : ,CustomPresence:501   State:Unavailable     Presence:not_set         Watchers  0
502@ext-local       : ,CustomPresence:502   State:Unavailable     Presence:not_set         Watchers  0
_*96X.@ext-cf-hints : Custom:DEVCF${EXTEN:  State:Unavailable     Presence:                Watchers  0
_*80X.@ext-local    : ${DB(AMPUSER/${EXTEN  State:Unavailable     Presence:                Watchers  0
300@ext-local       : ,CustomPresence:300   State:Unavailable     Presence:not_set         Watchers  0
_*98X.@app-dialvm   : 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]

johnoneszeros · January 13, 2022, 12:17pm

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.

EHammer98 · January 13, 2022, 5:32pm

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:500@<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:500@<My VPS domain>:5060>;tag=311238012
To: "502" <sip:502@<My VPS domain>;user=phone>
Call-ID: 1123216619741-6769649223191@<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:502@<My VPS IP>:5060>
Content-Length: 0


<------------>
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [502@from-internal:1] Set("SIP/500-00000084", "__RINGTIMER=15") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [502@from-internal:2] ExecIf("SIP/500-00000084", "0?Set(__CWIGNORE=)") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [502@from-internal: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 [s@macro-exten-vm:1] Macro("SIP/500-00000084", "user-callerid,") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-user-callerid: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 [s@macro-user-callerid:2] Set("SIP/500-00000084", "CHANCONTEXT=") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-user-callerid:3] Set("SIP/500-00000084", "CHANCONTEXT=") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-user-callerid:4] Set("SIP/500-00000084", "CHANEXTENCONTEXT=500-00000084") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-user-callerid:5] Set("SIP/500-00000084", "CHANEXTEN=500-00000084") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-user-callerid:6] Set("SIP/500-00000084", "CALLERID(number)=500") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-user-callerid:7] Set("SIP/500-00000084", "AMPUSER=500") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-user-callerid:8] Set("SIP/500-00000084", "HOTDESCKCHAN=500-00000084") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-user-callerid:9] Set("SIP/500-00000084", "HOTDESKEXTEN=500") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-user-callerid:10] Set("SIP/500-00000084", "HOTDESKCALL=0") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid:13] GotoIf("SIP/500-00000084", "0?report") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-user-callerid: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 [s@macro-user-callerid:15] Set("SIP/500-00000084", "AMPUSER=") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-user-callerid:16] GotoIf("SIP/500-00000084", "0?limit") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-user-callerid:17] Set("SIP/500-00000084", "AMPUSERCIDNAME=") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid:29] GotoIf("SIP/500-00000084", "0?continue") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-user-callerid:30] Set("SIP/500-00000084", "__TTL=64") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-user-callerid: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 [s@macro-user-callerid:47] Set("SIP/500-00000084", "CALLERID(number)=500") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-user-callerid: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 [s@macro-user-callerid:49] GotoIf("SIP/500-00000084", "0?cnum") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-user-callerid: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 [s@macro-user-callerid:51] Set("SIP/500-00000084", "CDR(cnum)=500") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-user-callerid:52] Set("SIP/500-00000084", "CHANNEL(language)=nl") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-exten-vm:2] Set("SIP/500-00000084", "RingGroupMethod=none") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-exten-vm:3] Set("SIP/500-00000084", "__EXTTOCALL=502") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-exten-vm:4] Set("SIP/500-00000084", "__PICKUPMARK=502") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-exten-vm:5] Set("SIP/500-00000084", "RT=15") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-exten-vm: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 [s@sub-record-check:1] GotoIf("SIP/500-00000084", "0?initialized") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@sub-record-check:2] Set("SIP/500-00000084", "__REC_STATUS=INITIALIZED") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@sub-record-check:3] Set("SIP/500-00000084", "NOW=1642094740") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@sub-record-check:4] Set("SIP/500-00000084", "__DAY=13") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@sub-record-check:5] Set("SIP/500-00000084", "__MONTH=01") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@sub-record-check:6] Set("SIP/500-00000084", "__YEAR=2022") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@sub-record-check:7] Set("SIP/500-00000084", "__TIMESTR=20220113-182540") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@sub-record-check:8] Set("SIP/500-00000084", "__FROMEXTEN=500") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@sub-record-check:9] Set("SIP/500-00000084", "__MON_FMT=wav") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@sub-record-check:10] NoOp("SIP/500-00000084", "Recordings initialized") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [exten@sub-record-check: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 [exten@sub-record-check:2] Set("SIP/500-00000084", "CALLTYPE=internal") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [exten@sub-record-check:3] ExecIf("SIP/500-00000084", "0?Set(CALLTYPE=)") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [exten@sub-record-check:4] Set("SIP/500-00000084", "CALLEE=") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [exten@sub-record-check: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 [exten@sub-record-check:6] GotoIf("SIP/500-00000084", "0?callee") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [exten@sub-record-check: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 [exten@sub-record-check:13] Set("SIP/500-00000084", "RECMODE=") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [exten@sub-record-check:14] Set("SIP/500-00000084", "CALLERRECMODE=") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [exten@sub-record-check:15] Set("SIP/500-00000084", "CALEERECMODE=") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [exten@sub-record-check: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 [exten@sub-record-check: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 [exten@sub-record-check: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 [exten@sub-record-check: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 [recordcheck@sub-record-check: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 [recordcheck@sub-record-check: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 [recordcheck@sub-record-check:3] Return("SIP/500-00000084", "") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [exten@sub-record-check:24] Return("SIP/500-00000084", "") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-exten-vm: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 [s@macro-exten-vm:13] GosubIf("SIP/500-00000084", "0?clrheader,1()") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-exten-vm: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 [s@macro-dial-one:1] Set("SIP/500-00000084", "DEXTEN=502") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-dial-one: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 [s@macro-dial-one:3] Set("SIP/500-00000084", "DIALSTATUS_CW=") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-dial-one:4] GosubIf("SIP/500-00000084", "0?screen,1()") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-dial-one:5] GosubIf("SIP/500-00000084", "0?cf,1()") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-dial-one: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 [s@macro-dial-one:9] GotoIf("SIP/500-00000084", "0?nodial") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-dial-one:10] GotoIf("SIP/500-00000084", "0?continue") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-dial-one:11] Set("SIP/500-00000084", "EXTHASCW=") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one:26] GotoIf("SIP/500-00000084", "0?nodial") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-dial-one: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 [dstring@macro-dial-one:1] Set("SIP/500-00000084", "DSTRING=") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [dstring@macro-dial-one:2] Set("SIP/500-00000084", "DEVICES=") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [dstring@macro-dial-one:3] ExecIf("SIP/500-00000084", "1?Return()") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-dial-one: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 [s@macro-dial-one:60] NoOp("SIP/500-00000084", "") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one:63] MacroExit("SIP/500-00000084", "") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-exten-vm:15] Set("SIP/500-00000084", "SV_DIALSTATUS=NOANSWER") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-exten-vm:16] GosubIf("SIP/500-00000084", "0?docfu,1()") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-exten-vm:17] GosubIf("SIP/500-00000084", "0?docfb,1()") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-exten-vm:18] Set("SIP/500-00000084", "DIALSTATUS=NOANSWER") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-exten-vm:19] ExecIf("SIP/500-00000084", "0?MacroExit()") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-exten-vm: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 [s@macro-exten-vm:21] Macro("SIP/500-00000084", "vm,502,NOANSWER,") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-vm:1] Macro("SIP/500-00000084", "user-callerid,SKIPTTL") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-user-callerid: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 [s@macro-user-callerid:2] Set("SIP/500-00000084", "CHANCONTEXT=") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-user-callerid:3] Set("SIP/500-00000084", "CHANCONTEXT=") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-user-callerid:4] Set("SIP/500-00000084", "CHANEXTENCONTEXT=500-00000084") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-user-callerid:5] Set("SIP/500-00000084", "CHANEXTEN=500-00000084") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-user-callerid:6] Set("SIP/500-00000084", "CALLERID(number)=500") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-user-callerid:7] Set("SIP/500-00000084", "AMPUSER=500") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-user-callerid:8] Set("SIP/500-00000084", "HOTDESCKCHAN=500-00000084") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-user-callerid:9] Set("SIP/500-00000084", "HOTDESKEXTEN=500") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-user-callerid:10] Set("SIP/500-00000084", "HOTDESKCALL=0") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid:13] GotoIf("SIP/500-00000084", "0?report") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-user-callerid: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 [s@macro-user-callerid:15] Set("SIP/500-00000084", "AMPUSER=") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-user-callerid:16] GotoIf("SIP/500-00000084", "0?limit") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-user-callerid:17] Set("SIP/500-00000084", "AMPUSERCIDNAME=") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid:47] Set("SIP/500-00000084", "CALLERID(number)=500") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-user-callerid: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 [s@macro-user-callerid:49] GotoIf("SIP/500-00000084", "0?cnum") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-user-callerid: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 [s@macro-user-callerid:51] Set("SIP/500-00000084", "CDR(cnum)=500") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-user-callerid:52] Set("SIP/500-00000084", "CHANNEL(language)=nl") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-vm:2] Set("SIP/500-00000084", "VMGAIN=") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-vm:3] Macro("SIP/500-00000084", "blkvm-check,") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-blkvm-check:1] Set("SIP/500-00000084", "GOSUB_RETVAL=") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-blkvm-check: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 [s@macro-blkvm-check:3] MacroExit("SIP/500-00000084", "") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-vm: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 [vmx@macro-vm:1] Set("SIP/500-00000084", "MEXTEN=502") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [vmx@macro-vm:2] Set("SIP/500-00000084", "MMODE=NOANSWER") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [vmx@macro-vm:3] Set("SIP/500-00000084", "RETVM=") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [vmx@macro-vm:4] Set("SIP/500-00000084", "MODE=unavail") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [vmx@macro-vm:5] Macro("SIP/500-00000084", "get-vmcontext,502") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-get-vmcontext:1] Set("SIP/500-00000084", "VMCONTEXT=") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-get-vmcontext: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 [s@macro-get-vmcontext:200] Set("SIP/500-00000084", "VMCONTEXT=default") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [vmx@macro-vm:6] Set("SIP/500-00000084", "MODE=unavail") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [vmx@macro-vm:7] NoOp("SIP/500-00000084", "MODE IS: unavail") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [vmx@macro-vm: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 [vmx@macro-vm: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 [vmx@macro-vm: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 [vmx@macro-vm: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 [vmx@macro-vm: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 [s-NOANSWER@macro-vm:1] Macro("SIP/500-00000084", "get-vmcontext,502") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-get-vmcontext:1] Set("SIP/500-00000084", "VMCONTEXT=") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s@macro-get-vmcontext: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 [s@macro-get-vmcontext:200] Set("SIP/500-00000084", "VMCONTEXT=default") in new stack
[2022-01-13 18:25:40] VERBOSE[7389][C-00000085] pbx.c: Executing [s-NOANSWER@macro-vm:2] VoiceMail("SIP/500-00000084", "502@default,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:500@<My VPS domain>:5060>;tag=311238012
To: "502" <sip:502@<My VPS domain>;user=phone>;tag=as6c95e1e1
Call-ID: 1123216619741-6769649223191@<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:502@<My VPS IP>:5060>
Content-Type: application/sdp
Content-Length: 331

johnoneszeros · January 15, 2022, 1:48pm

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.

david55 · January 15, 2022, 1:58pm

It’s also not a registration attempt.

billsimon · January 15, 2022, 3:49pm

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.

EHammer98 · January 20, 2022, 11:31am

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

david55 · January 20, 2022, 12:17pm

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

EHammer98 · January 20, 2022, 4:28pm

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.

system · January 27, 2022, 4:28pm

This topic was automatically closed 7 days after the last reply. New replies are no longer allowed.