Incoming calls get rejected

Status
Not open for further replies.

saito89

New Member
Oct 11, 2019
4
1
3
34
Hi to all you guys,

I have a fresh installed FusionPBX (4.5.9) on Debian 9.11. I can create extensions and I am logged in remotely to my FusionPBX domain without no problems. I can even make calls and there is no issues at all. I have a Gateway configured with no authentification. My gateways public IP was added to the access control/domain section. The problem is with the incoming calls. My FusionPBX is behind a router and the ports 5060-5090 (TCP/UDP) and 16384-32768 (UDP) are forwarded to my internal IP Address (172.16.89.227). I have a public IP Address on my router (190.xxx.xxx.xxx). Sometimes the incoming calls get in and sometimes they do not. Here is the log for the incoming call:

2019-10-12 17:32:06.217433 [DEBUG] sofia.c:10243 sofia/external/anonymous@190.xxx.xxx.xxx receiving invite from 172.16.89.1:5060 version: 1.10.1 -release-12-f9990221e6 64bit
2019-10-12 17:32:06.217433 [DEBUG] sofia.c:10337 verifying acl "domains" for ip/port 172.16.89.1:0.
2019-10-12 17:32:06.217433 [WARNING] sofia_reg.c:2930 Can't find user [anonymous@190.xxx.xxx.yyy] from 172.16.89.1
You must define a domain called '190.xxx.xxx.yyy' in your directory and add a user with the id="anonymous" attribute
and you must configure your device to use the proper domain in it's authentication credentials.
2019-10-12 17:32:06.217433 [NOTICE] sofia.c:2424 Hangup sofia/external/anonymous@190.xxx.xxx.xxx [CS_NEW] [CALL_REJECTED]
2019-10-12 17:32:06.237431 [DEBUG] sofia.c:1540 Channel is already hungup.
2019-10-12 17:32:06.237431 [DEBUG] switch_core_state_machine.c:585 (sofia/external/anonymous@190.xxx.xxx.xxx) Running State Change CS_HANGUP (Cur 1 Tot 14)
2019-10-12 17:32:06.237431 [DEBUG] switch_core_state_machine.c:848 (sofia/external/anonymous@190.xxx.xxx.xxx) Callstate Change DOWN -> HANGUP
2019-10-12 17:32:06.237431 [DEBUG] switch_core_state_machine.c:850 (sofia/external/anonymous@190.xxx.xxx.xxx) State HANGUP
2019-10-12 17:32:06.237431 [DEBUG] mod_sofia.c:460 Channel sofia/external/anonymous@190.xxx.xxx.xxx hanging up, cause: CALL_REJECTED
2019-10-12 17:32:06.237431 [DEBUG] switch_core_state_machine.c:60 sofia/external/anonymous@190.xxx.xxx.xxx Standard HANGUP, cause: CALL_REJECTED
2019-10-12 17:32:06.237431 [DEBUG] switch_core_state_machine.c:850 (sofia/external/anonymous@190.xxx.xxx.xxx) State HANGUP going to sleep
2019-10-12 17:32:06.237431 [DEBUG] switch_core_state_machine.c:620 (sofia/external/anonymous@190.xxx.xxx.xxx) State Change CS_HANGUP -> CS_REPORTING
2019-10-12 17:32:06.237431 [DEBUG] switch_core_state_machine.c:585 (sofia/external/anonymous@190.xxx.xxx.xxx) Running State Change CS_REPORTING (Cur 1 Tot 14)
2019-10-12 17:32:06.237431 [DEBUG] switch_core_state_machine.c:936 (sofia/external/anonymous@190.xxx.xxx.xxx) State REPORTING
2019-10-12 17:32:06.237431 [DEBUG] switch_core_state_machine.c:174 sofia/external/anonymous@190.xxx.xxx.xxx Standard REPORTING, cause: CALL_REJECTED
2019-10-12 17:32:06.237431 [DEBUG] switch_core_state_machine.c:936 (sofia/external/anonymous@190.xxx.xxx.xxx) State REPORTING going to sleep
2019-10-12 17:32:06.237431 [DEBUG] switch_core_state_machine.c:611 (sofia/external/anonymous@190.xxx.xxx.xxx) State Change CS_REPORTING -> CS_DESTROY
2019-10-12 17:32:06.237431 [DEBUG] switch_core_session.c:1726 Session 14 (sofia/external/anonymous@190.xxx.xxx.xxx) Locked, Waiting on external entities
2019-10-12 17:32:06.237431 [NOTICE] switch_core_session.c:1744 Session 14 (sofia/external/anonymous@190.xxx.xxx.xxx) Ended
2019-10-12 17:32:06.237431 [NOTICE] switch_core_session.c:1748 Close Channel sofia/external/anonymous@190.xxx.xxx.xxx [CS_DESTROY]
2019-10-12 17:32:06.237431 [DEBUG] switch_core_state_machine.c:739 (sofia/external/anonymous@190.xxx.xxx.xxx) Running State Change CS_DESTROY (Cur 0 Tot 14)
2019-10-12 17:32:06.237431 [DEBUG] switch_core_state_machine.c:749 (sofia/external/anonymous@190.xxx.xxx.xxx) State DESTROY
2019-10-12 17:32:06.237431 [DEBUG] mod_sofia.c:365 sofia/external/anonymous@190.xxx.xxx.xxx SOFIA DESTROY
2019-10-12 17:32:06.237431 [DEBUG] switch_core_state_machine.c:181 sofia/external/anonymous@190.xxx.xxx.xxx Standard DESTROY
2019-10-12 17:32:06.237431 [DEBUG] switch_core_state_machine.c:749 (sofia/external/anonymous@190.xxx.xxx.xxx) State DESTROY going to sleep

What I really do not understand is that sometimes it works without changing a thing. Here is the log when the incoming call works:

2019-10-12 17:17:33.357436 [NOTICE] switch_channel.c:1118 New Channel sofia/external/anonymous@190.xxx.xxx.xxx [8401b282-9c71-41a9-bf60-4c903159c079]
2019-10-12 17:17:33.357436 [DEBUG] switch_core_state_machine.c:585 (sofia/external/anonymous@190.xxx.xxx.xxx) Running State Change CS_NEW (Cur 1 Tot 6)
2019-10-12 17:17:33.357436 [DEBUG] sofia.c:10243 sofia/external/anonymous@190.xxx.xxx.xxx receiving invite from 190.xxx.xxx.xxx:5060 version: 1.10.1 -release-12-f9990221e6 64bit
2019-10-12 17:17:33.357436 [DEBUG] sofia.c:10337 verifying acl "domains" for ip/port 190.xxx.xxx.xxx:0.
2019-10-12 17:17:33.357436 [DEBUG] sofia.c:10366 IP 190.xxx.xxx.xxx Approved by acl "domains[]". Access Granted.
2019-10-12 17:17:33.357436 [DEBUG] sofia.c:7290 Channel sofia/external/anonymous@190.xxx.xxx.xxx entering state [received][100]
2019-10-12 17:17:33.357436 [DEBUG] sofia.c:7300 Remote SDP:
v=0
o=Sansay-VSXi 188 1 IN IP4 190.xxx.xxx.xxx
s=Session Controller
c=IN IP4 190.xxx.xxx.ttt
t=0 0
m=audio 28014 RTP/AVP 8 101
b=AS:82
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20

2019-10-12 17:17:33.357436 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2019-10-12 17:17:33.357436 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2019-10-12 17:17:33.357436 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2019-10-12 17:17:33.357436 [DEBUG] switch_core_media.c:5645 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2019-10-12 17:17:33.357436 [DEBUG] switch_core_media.c:5506 Set telephone-event payload to 101@8000
2019-10-12 17:17:33.357436 [DEBUG] switch_core_media.c:3834 Set Codec sofia/external/anonymous@190.xxx.xxx.xxx PCMA/8000 20 ms 160 samples 64000 bits 1 channels
2019-10-12 17:17:33.357436 [DEBUG] switch_core_codec.c:111 sofia/external/anonymous@190.xxx.xxx.xxx Original read codec set to PCMA:8
2019-10-12 17:17:33.357436 [DEBUG] switch_core_media.c:5849 Set telephone-event payload to 101@8000
2019-10-12 17:17:33.357436 [DEBUG] switch_core_media.c:5907 sofia/external/anonymous@190.xxx.xxx.xxx Set 2833 dtmf send payload to 101 recv payload to 101
2019-10-12 17:17:33.357436 [DEBUG] sofia.c:7724 (sofia/external/anonymous@190.xxx.xxx.xxx) State Change CS_NEW -> CS_INIT
2019-10-12 17:17:33.357436 [DEBUG] switch_core_state_machine.c:604 (sofia/external/anonymous@190.xxx.xxx.xxx) State NEW
2019-10-12 17:17:33.357436 [DEBUG] switch_core_state_machine.c:585 (sofia/external/anonymous@190.xxx.xxx.xxx) Running State Change CS_INIT (Cur 1 Tot 6)
2019-10-12 17:17:33.357436 [DEBUG] switch_core_state_machine.c:628 (sofia/external/anonymous@190.xxx.xxx.xxx) State INIT
2019-10-12 17:17:33.357436 [DEBUG] mod_sofia.c:93 sofia/external/anonymous@190.xxx.xxx.xxx SOFIA INIT
2019-10-12 17:17:33.357436 [DEBUG] switch_core_state_machine.c:40 sofia/external/anonymous@190.xxx.xxx.xxx Standard INIT
2019-10-12 17:17:33.357436 [DEBUG] switch_core_state_machine.c:48 (sofia/external/anonymous@190.xxx.xxx.xxx) State Change CS_INIT -> CS_ROUTING
2019-10-12 17:17:33.357436 [DEBUG] switch_core_state_machine.c:628 (sofia/external/anonymous@190.xxx.xxx.xxx) State INIT going to sleep
2019-10-12 17:17:33.357436 [DEBUG] switch_core_state_machine.c:585 (sofia/external/anonymous@190.xxx.xxx.xxx) Running State Change CS_ROUTING (Cur 1 Tot 6)
2019-10-12 17:17:33.357436 [DEBUG] switch_channel.c:2332 (sofia/external/anonymous@190.xxx.xxx.xxx) Callstate Change DOWN -> RINGING
2019-10-12 17:17:33.357436 [DEBUG] switch_core_state_machine.c:644 (sofia/external/anonymous@190.xxx.xxx.xxx) State ROUTING
2019-10-12 17:17:33.357436 [DEBUG] mod_sofia.c:154 sofia/external/anonymous@190.xxx.xxx.xxx SOFIA ROUTING
2019-10-12 17:17:33.357436 [DEBUG] switch_core_state_machine.c:236 sofia/external/anonymous@190.xxx.xxx.xxx Standard ROUTING
2019-10-12 17:17:33.357436 [INFO] mod_dialplan_xml.c:637 Processing Anonymous <anonymous>->40xxxxxx in context public
Dialplan: sofia/external/anonymous@190.xxx.xxx.xxx parsing [public->caller-details] continue=true
Dialplan: sofia/external/anonymous@190.xxx.xxx.xxx Regex (PASS) [caller-details] () =~ // break=never
Dialplan: sofia/external/anonymous@190.xxx.xxx.xxx Action export(call_direction=inbound) INLINE
EXECUTE [depth=0] sofia/external/anonymous@190.xxx.xxx.xxx export(call_direction=inbound)
2019-10-12 17:17:33.377420 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [call_direction]=[inbound]
Dialplan: sofia/external/anonymous@190.xxx.xxx.xxx Action set(caller_destination=${sip_to_user}) INLINE
EXECUTE [depth=0] sofia/external/anonymous@190.xxx.xxx.xxx set(caller_destination=40xxxxxx)
2019-10-12 17:17:33.377420 [DEBUG] mod_dptools.c:1672 SET sofia/external/anonymous@190.xxx.xxx.xxx [caller_destination]=[40xxxxxx]
Dialplan: sofia/external/anonymous@190.xxx.xxx.xxx Action set(caller_id_name=${caller_id_name}) INLINE
EXECUTE [depth=0] sofia/external/anonymous@190.xxx.xxx.xxx set(caller_id_name=Anonymous)
2019-10-12 17:17:33.377420 [DEBUG] mod_dptools.c:1672 SET sofia/external/anonymous@190.xxx.xxx.xxx [caller_id_name]=[Anonymous]


I do not understand why the system show that the invite is coming from a private IP (when is not) instead of the public IP. I changed the ext-rtp-ip and ext-sip-ip in sip profiles/external and in variables to autonat:190.xxx.xxx.xxx.

I have no experience with FusionPBX, I have being working with FreePBX for a long time but that is it.

Any help will be appreciate it.

Thanks,

Erick
 

DigitalDaz

Administrator
Staff member
Sep 29, 2016
3,044
565
113
This is the gateway problem and nothing to do with FusionPBX, the fact that the gateway is using port 0 makes it wrong for a start. I would be seeking groups that deal with this router and see if they can come up with something.

Port 0 is an invalid port.
 
Status
Not open for further replies.