Fusion PBX 5.3 New install On Debian 12

R

Rasreby

New Member
Jun 12, 2024
8
0
1
61
Extension to extension call works fine, inbound also works fine but fast busy on all outbound calls.

See logs below.
a1316f56-7bda-48f9-b689-b4f45351f609 2024-12-17 18:58:27.182495 99.77% [DEBUG] switch_core_state_machine.c:281 (sofia/internal/401@192.168.2.241) State Change CS_ROUTING -> CS_EXECUTE
a1316f56-7bda-48f9-b689-b4f45351f609 2024-12-17 18:58:27.182495 99.77% [DEBUG] switch_core_state_machine.c:640 (sofia/internal/401@192.168.2.241) State ROUTING going to sleep
a1316f56-7bda-48f9-b689-b4f45351f609 2024-12-17 18:58:27.182495 99.77% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/401@192.168.2.241) Running State Change CS_EXECUTE (Cur 1 Tot 44)
a1316f56-7bda-48f9-b689-b4f45351f609 2024-12-17 18:58:27.182495 99.77% [DEBUG] switch_core_state_machine.c:647 (sofia/internal/401@192.168.2.241) State EXECUTE
a1316f56-7bda-48f9-b689-b4f45351f609 2024-12-17 18:58:27.182495 99.77% [DEBUG] mod_sofia.c:213 sofia/internal/401@192.168.2.241 SOFIA EXECUTE
a1316f56-7bda-48f9-b689-b4f45351f609 2024-12-17 18:58:27.182495 99.77% [DEBUG] switch_core_state_machine.c:323 sofia/internal/401@192.168.2.241 Standard EXECUTE
a1316f56-7bda-48f9-b689-b4f45351f609 EXECUTE [depth=0] sofia/internal/401@192.168.2.241 set(caller_id_number=401)
a1316f56-7bda-48f9-b689-b4f45351f609 2024-12-17 18:58:27.182495 99.77% [DEBUG] mod_dptools.c:1671 SET sofia/internal/401@192.168.2.241 [caller_id_number]=[401]
a1316f56-7bda-48f9-b689-b4f45351f609 EXECUTE [depth=0] sofia/internal/401@192.168.2.241 set(RFC2822_DATE=Tue, 17 Dec 2024 18:58:27 -0500)
a1316f56-7bda-48f9-b689-b4f45351f609 2024-12-17 18:58:27.182495 99.77% [DEBUG] mod_dptools.c:1671 SET sofia/internal/401@192.168.2.241 [RFC2822_DATE]=[Tue, 17 Dec 2024 18:58:27 -0500]
a1316f56-7bda-48f9-b689-b4f45351f609 EXECUTE [depth=0] sofia/internal/401@192.168.2.241 export(origination_callee_id_name=14163075555)
a1316f56-7bda-48f9-b689-b4f45351f609 2024-12-17 18:58:27.182495 99.77% [DEBUG] switch_channel.c:1334 EXPORT (export_vars) [origination_callee_id_name]=[14163075555]
a1316f56-7bda-48f9-b689-b4f45351f609 EXECUTE [depth=0] sofia/internal/401@192.168.2.241 hash(insert/192.168.2.241-last_dial/401/14163075555)
a1316f56-7bda-48f9-b689-b4f45351f609 EXECUTE [depth=0] sofia/internal/401@192.168.2.241 eval(not_secure)
a1316f56-7bda-48f9-b689-b4f45351f609 2024-12-17 18:58:27.182495 99.77% [NOTICE] switch_core_state_machine.c:382 sofia/internal/401@192.168.2.241 has executed the last dialplan instruction, hanging up.
a1316f56-7bda-48f9-b689-b4f45351f609 2024-12-17 18:58:27.182495 99.77% [NOTICE] switch_core_state_machine.c:384 Hangup sofia/internal/401@192.168.2.241 [CS_EXECUTE] [NORMAL_CLEARING]
a1316f56-7bda-48f9-b689-b4f45351f609 2024-12-17 18:58:27.182495 99.77% [DEBUG] switch_core_state_machine.c:647 (sofia/internal/401@192.168.2.241) State EXECUTE going to sleep
a1316f56-7bda-48f9-b689-b4f45351f609 2024-12-17 18:58:27.182495 99.77% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/401@192.168.2.241) Running State Change CS_HANGUP (Cur 1 Tot 44)
a1316f56-7bda-48f9-b689-b4f45351f609 2024-12-17 18:58:27.182495 99.77% [DEBUG] switch_core_state_machine.c:844 (sofia/internal/401@192.168.2.241) Callstate Change RINGING -> HANGUP
a1316f56-7bda-48f9-b689-b4f45351f609 2024-12-17 18:58:27.182495 99.77% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/401@192.168.2.241) State HANGUP
a1316f56-7bda-48f9-b689-b4f45351f609 2024-12-17 18:58:27.182495 99.77% [DEBUG] mod_sofia.c:469 Channel sofia/internal/401@192.168.2.241 hanging up, cause: NORMAL_CLEARING
a1316f56-7bda-48f9-b689-b4f45351f609 2024-12-17 18:58:27.182495 99.77% [DEBUG] mod_sofia.c:614 Responding to INVITE with: 480
a1316f56-7bda-48f9-b689-b4f45351f609 2024-12-17 18:58:27.182495 99.77% [DEBUG] switch_core_state_machine.c:59 sofia/internal/401@192.168.2.241 Standard HANGUP, cause: NORMAL_CLEARING
a1316f56-7bda-48f9-b689-b4f45351f609 2024-12-17 18:58:27.182495 99.77% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/401@192.168.2.241) State HANGUP going to sleep
a1316f56-7bda-48f9-b689-b4f45351f609 2024-12-17 18:58:27.182495 99.77% [DEBUG] switch_core_state_machine.c:616 (sofia/internal/401@192.168.2.241) State Change CS_HANGUP -> CS_REPORTING
a1316f56-7bda-48f9-b689-b4f45351f609 2024-12-17 18:58:27.182495 99.77% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/401@192.168.2.241) Running State Change CS_REPORTING (Cur 1 Tot 44)
a1316f56-7bda-48f9-b689-b4f45351f609 2024-12-17 18:58:27.182495 99.77% [DEBUG] switch_core_state_machine.c:932 (sofia/internal/401@192.168.2.241) State REPORTING
a1316f56-7bda-48f9-b689-b4f45351f609 2024-12-17 18:58:27.182495 99.77% [DEBUG] switch_core_state_machine.c:168 sofia/internal/401@192.168.2.241 Standard REPORTING, cause: NORMAL_CLEARING
a1316f56-7bda-48f9-b689-b4f45351f609 2024-12-17 18:58:27.182495 99.77% [DEBUG] switch_core_state_machine.c:932 (sofia/internal/401@192.168.2.241) State REPORTING going to sleep
a1316f56-7bda-48f9-b689-b4f45351f609 2024-12-17 18:58:27.182495 99.77% [DEBUG] switch_core_state_machine.c:607 (sofia/internal/401@192.168.2.241) State Change CS_REPORTING -> CS_DESTRO
 
R

Rasreby

New Member
Jun 12, 2024
8
0
1
61
Yes, outbound route is created. Order is 100 and limits was first blank. I put it to 10 and it seem to for a while but it stopped working all together now.
 
J

Jonathan Black

Member
Jan 9, 2018
158
16
18
54
Is carrier receiving the request? (If not, then it isn't making it out of your server. If it is, then the carrier might be rejecting it.) Try using sngrep to see SIP activity.

I'm not seeing that it's executing a bridge statement, which is normally at the end of the outbound route. For example, normally the last statement in the outbound route looks something like this, depending on your carrier:

1734625564597.png

Which could mean it's not matching your outbound route. Set the route order to 90 and try again. And then watch your logs for a "PASS" on that outbound route. You do not want the order set too low or too high. In my experience, beyond 100 it doesn't seem to like it, and if you set it to low, it supercedes some other necessary dialplans.

Check your outbound caller ID number--make sure it it set in the extension. It looks like it may be trying to use the ext number, instead of a valid phone number as the caller ID number. Most carriers now will reject the call if it's not a valid number. (If it is not executing the outbound route, this may be a red herring)
 
R

Rasreby

New Member
Jun 12, 2024
8
0
1
61
Still no success with the changes recommended. On the CDR, Destination says limit_exceeded and on Hang Up Cause it says Exchange routing error. Also I just notice inbound calls are not coming in. This must have been broken while playing around with the configs.
 
M

markjcrane

Active Member
Staff member
Jul 22, 2018
509
180
43
50
Basic steps for an outbound call
- Create a gateway or a bridge statement
- Add an outbound caller ID number to your extension that matches a number at your VoIP provider.
- Make an outbound route to use to route calls to your Gateway.
- When you create your outbound route make sure you are sending the right number of digits to the provider
 
R

Rasreby

New Member
Jun 12, 2024
8
0
1
61
Gateway is properly setup and registered.
Sending 10 digits CLID
Outbound route is set with Dialplan expression set for North America.
I think my issues are around limit which is set at 120 and order which is set for 100.
 
R

Rasreby

New Member
Jun 12, 2024
8
0
1
61
Order is now set to 90. See logs below.

8dc97725-2f15-4165-a4c5-be1b60813615 2024-12-21 06:27:41.231989 99.50% [DEBUG] switch_core_state_machine.c:281 (sofia/internal/401@192.168.2.245:5090) State Change CS_ROUTING -> CS_EXECUTE
8dc97725-2f15-4165-a4c5-be1b60813615 2024-12-21 06:27:41.231989 99.50% [DEBUG] switch_core_state_machine.c:640 (sofia/internal/401@192.168.2.245:5090) State ROUTING going to sleep
8dc97725-2f15-4165-a4c5-be1b60813615 2024-12-21 06:27:41.231989 99.50% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/401@192.168.2.245:5090) Running State Change CS_EXECUTE (Cur 1 Tot 6)
8dc97725-2f15-4165-a4c5-be1b60813615 2024-12-21 06:27:41.231989 99.50% [DEBUG] switch_core_state_machine.c:647 (sofia/internal/401@192.168.2.245:5090) State EXECUTE
8dc97725-2f15-4165-a4c5-be1b60813615 2024-12-21 06:27:41.231989 99.50% [DEBUG] mod_sofia.c:213 sofia/internal/401@192.168.2.245:5090 SOFIA EXECUTE
8dc97725-2f15-4165-a4c5-be1b60813615 2024-12-21 06:27:41.231989 99.50% [DEBUG] switch_core_state_machine.c:323 sofia/internal/401@192.168.2.245:5090 Standard EXECUTE
8dc97725-2f15-4165-a4c5-be1b60813615 EXECUTE [depth=0] sofia/internal/401@192.168.2.245:5090 set(caller_id_number=401)
8dc97725-2f15-4165-a4c5-be1b60813615 2024-12-21 06:27:41.231989 99.50% [DEBUG] mod_dptools.c:1671 SET sofia/internal/401@192.168.2.245:5090 [caller_id_number]=[401]
8dc97725-2f15-4165-a4c5-be1b60813615 EXECUTE [depth=0] sofia/internal/401@192.168.2.245:5090 set(RFC2822_DATE=Sat, 21 Dec 2024 06:27:41 -0500)
8dc97725-2f15-4165-a4c5-be1b60813615 2024-12-21 06:27:41.231989 99.50% [DEBUG] mod_dptools.c:1671 SET sofia/internal/401@192.168.2.245:5090 [RFC2822_DATE]=[Sat, 21 Dec 2024 06:27:41 -0500]
8dc97725-2f15-4165-a4c5-be1b60813615 EXECUTE [depth=0] sofia/internal/401@192.168.2.245:5090 export(origination_callee_id_name=4163075555)
8dc97725-2f15-4165-a4c5-be1b60813615 2024-12-21 06:27:41.231989 99.50% [DEBUG] switch_channel.c:1334 EXPORT (export_vars) [origination_callee_id_name]=[4163075555]
8dc97725-2f15-4165-a4c5-be1b60813615 EXECUTE [depth=0] sofia/internal/401@192.168.2.245:5090 hash(insert/192.168.2.245-last_dial/401/4163075555)
8dc97725-2f15-4165-a4c5-be1b60813615 EXECUTE [depth=0] sofia/internal/401@192.168.2.245:5090 eval(not_secure)
8dc97725-2f15-4165-a4c5-be1b60813615 2024-12-21 06:27:41.231989 99.50% [NOTICE] switch_core_state_machine.c:382 sofia/internal/401@192.168.2.245:5090 has executed the last dialplan instruction, hanging up.
8dc97725-2f15-4165-a4c5-be1b60813615 2024-12-21 06:27:41.231989 99.50% [NOTICE] switch_core_state_machine.c:384 Hangup sofia/internal/401@192.168.2.245:5090 [CS_EXECUTE] [NORMAL_CLEARING]
8dc97725-2f15-4165-a4c5-be1b60813615 2024-12-21 06:27:41.231989 99.50% [DEBUG] switch_core_state_machine.c:647 (sofia/internal/401@192.168.2.245:5090) State EXECUTE going to sleep
8dc97725-2f15-4165-a4c5-be1b60813615 2024-12-21 06:27:41.231989 99.50% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/401@192.168.2.245:5090) Running State Change CS_HANGUP (Cur 1 Tot 6)
8dc97725-2f15-4165-a4c5-be1b60813615 2024-12-21 06:27:41.231989 99.50% [DEBUG] switch_core_state_machine.c:844 (sofia/internal/401@192.168.2.245:5090) Callstate Change RINGING -> HANGUP
8dc97725-2f15-4165-a4c5-be1b60813615 2024-12-21 06:27:41.231989 99.50% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/401@192.168.2.245:5090) State HANGUP
8dc97725-2f15-4165-a4c5-be1b60813615 2024-12-21 06:27:41.231989 99.50% [DEBUG] mod_sofia.c:469 Channel sofia/internal/401@192.168.2.245:5090 hanging up, cause: NORMAL_CLEARING
8dc97725-2f15-4165-a4c5-be1b60813615 2024-12-21 06:27:41.231989 99.50% [DEBUG] mod_sofia.c:614 Responding to INVITE with: 480
8dc97725-2f15-4165-a4c5-be1b60813615 2024-12-21 06:27:41.231989 99.50% [DEBUG] switch_core_state_machine.c:59 sofia/internal/401@192.168.2.245:5090 Standard HANGUP, cause: NORMAL_CLEARING
8dc97725-2f15-4165-a4c5-be1b60813615 2024-12-21 06:27:41.231989 99.50% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/401@192.168.2.245:5090) State HANGUP going to sleep
8dc97725-2f15-4165-a4c5-be1b60813615 2024-12-21 06:27:41.231989 99.50% [DEBUG] switch_core_state_machine.c:616 (sofia/internal/401@192.168.2.245:5090) State Change CS_HANGUP -> CS_REPORTING
8dc97725-2f15-4165-a4c5-be1b60813615 2024-12-21 06:27:41.231989 99.50% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/401@192.168.2.245:5090) Running State Change CS_REPORTING (Cur 1 Tot 6)
8dc97725-2f15-4165-a4c5-be1b60813615 2024-12-21 06:27:41.231989 99.50% [DEBUG] switch_core_state_machine.c:932 (sofia/internal/401@192.168.2.245:5090) State REPORTING
8dc97725-2f15-4165-a4c5-be1b60813615 2024-12-21 06:27:41.231989 99.50% [DEBUG] switch_core_state_machine.c:168 sofia/internal/401@192.168.2.245:5090 Standard REPORTING, cause: NORMAL_CLEARING
8dc97725-2f15-4165-a4c5-be1b60813615 2024-12-21 06:27:41.231989 99.50% [DEBUG] switch_core_state_machine.c:932 (sofia/internal/401@192.168.2.245:5090) State REPORTING going to sleep
8dc97725-2f15-4165-a4c5-be1b60813615 2024-12-21 06:27:41.231989 99.50% [DEBUG] switch_core_state_machine.c:607 (sofia/internal/401@192.168.2.245:5090) State Change CS_REPORTING -> CS_DESTROY
8dc97725-2f15-4165-a4c5-be1b60813615 2024-12-21 06:27:41.231989 99.50% [DEBUG] switch_core_session.c:1748 Session 6 (sofia/internal/401@192.168.2.245:5090) Locked, Waiting on external entities
8dc97725-2f15-4165-a4c5-be1b60813615 2024-12-21 06:27:41.231989 99.50% [NOTICE] switch_core_session.c:1766 Session 6 (sofia/internal/401@192.168.2.245:5090) Ended
8dc97725-2f15-4165-a4c5-be1b60813615 2024-12-21 06:27:41.231989 99.50% [NOTICE] switch_core_session.c:1770 Close Channel sofia/internal/401@192.168.2.245:5090 [CS_DESTROY]
8dc97725-2f15-4165-a4c5-be1b60813615 2024-12-21 06:27:41.251987 99.50% [DEBUG] switch_core_state_machine.c:735 (sofia/internal/401@192.168.2.245:5090) Running State Change CS_DESTROY (Cur 0 Tot 6)
8dc97725-2f15-4165-a4c5-be1b60813615 2024-12-21 06:27:41.251987 99.50% [DEBUG] switch_core_state_machine.c:745 (sofia/internal/401@192.168.2.245:5090) State DESTROY
8dc97725-2f15-4165-a4c5-be1b60813615 2024-12-21 06:27:41.251987 99.50% [DEBUG] mod_sofia.c:380 sofia/internal/401@192.168.2.245:5090 SOFIA DESTROY
8dc97725-2f15-4165-a4c5-be1b60813615 2024-12-21 06:27:41.251987 99.50% [DEBUG] switch_core_state_machine.c:175 sofia/internal/401@192.168.2.245:5090 Standard DESTROY
8dc97725-2f15-4165-a4c5-be1b60813615 2024-12-21 06:27:41.251987 99.50% [DEBUG] switch_core_state_machine.c:745 (sofia/internal/401@192.168.2.245:5090) State DESTROY going to sleep

See SIP trace below

xINVITE sip:4163075555@192.168.2.245:5090;user=phone SIP/2.0
192.168.2.87:5060 192.168.2.245:5090xVia: SIP/2.0/UDP 192.168.2.87;branch=z9hG4bK7565341cCBECD5F9
qqqqqqqqqqwqqqqqqqqq qqqqqqqqqqwqqqqqqqqqxFrom: "Reby" <sip:401@192.168.2.245:5090>;tag=6199DE00-2DF9F63D
06:31:25.198946 x INVITE (SDP) x xTo: <sip:4163075555@192.168.2.245;user=phone>
+0.002016 x qqqqqqqqqqqqqqqqqqqqqqqqqq> x xCSeq: 1 INVITE
06:31:25.200962 x 407 Proxy Authentication R x xCall-ID: 658f8b27f7ed169d10ac0dcbd9d0769f
+0.017288 x <qqqqqqqqqqqqqqqqqqqqqqqqqq x xContact: <sip:401@192.168.2.87>
06:31:25.218250 x ACK x xAllow: INVITE,ACK,BYE,CANCEL,OPTIONS,INFO,MESSAGE,SUBSCRIBE,NOTIFY,PRACK,UPDAT
+0.002050 x qqqqqqqqqqqqqqqqqqqqqqqqqq> x xE,REFER
06:31:25.220300 x INVITE (SDP) x xUser-Agent: PolycomVVX-VVX_410-UA/5.9.8.5760
+0.007447 x qqqqqqqqqqqqqqqqqqqqqqqqqq> x xAccept-Language: en
06:31:25.227747 x 100 Trying x xSupported: replaces,100rel
+0.027653 x <qqqqqqqqqqqqqqqqqqqqqqqqqq x xAllow-Events: conference,talk,hold
06:31:25.255400 x 480 Temporarily Unavailabl x xMax-Forwards: 70
+0.025108 x <qqqqqqqqqqqqqqqqqqqqqqqqqq x xContent-Type: application/sdp
06:31:25.280508 x ACK x xContent-Length: 350
x qqqqqqqqqqqqqqqqqqqqqqqqqq> x x
x x xv=0
x x xo=- 1734780684 1734780684 IN IP4 192.168.2.87
x x xs=Polycom IP Phone
x x xc=IN IP4 192.168.2.87
x x xt=0 0
x x xa=sendrecv
x x xm=audio 2250 RTP/AVP 9 102 0 8 18 127
x x xa=rtpmap:9 G722/8000
x x xa=rtpmap:102 G7221/16000
x x xa=fmtp:102 bitrate=32000
x x xa=rtpmap:0 PCMU/8000
x x xa=rtpmap:8 PCMA/8000
x x xa=rtpmap:18 G729/8000
x x xa=fmtp:18 annexb=no
x x xa=rtpmap:127 telephone-event/8000
x x x
x
 
You must log in or register to reply here.
Top Bottom