New fusionobx istance, trouble when i change internet provider on extensions.

[Nedo]

Hi, i Will post a log a soon possibile, i have this trouble with the latest versions of fusionpbx i post anyway in the hope that is a know problem.

I set up a new fusionobx istance as usual, i connect my extensions to fusionpbx server. Evetything work as expected. But If i change internet provider of extensions some things not working anymore, Like internal calls to other extensions, it seems that internal call are interpreted as external, in fs_cli i can see (IP of new provider) not in ACL.
In My acl i ever set only the voip trunk ip and nothing else. I try to add this ip to acl but when i try to call from extension to another extension it say route not found.
Someone know how to solve this issue please?

 

[hfoster]

If the phones are in the external context, that tends to tell me that they are not registered and are simply sending INVITES to the PBX.

 

[Nedo]

If the phones are in the external context, that tends to tell me that they are not registered and are simply sending INVITES to the PBX.

Hi how to see If it is in external context? I can see the extensions correcly autenticated to server as usual. If i switch the extensions connection to old internet provider it start to work again. In both cases i can see extensions connected. Obliviously the source ip is different.

 

[hfoster]

sofia_profile_name in the CDR detail probably if you see one.

If you can post a log of an attempted call, that might help. Remember to find and replace any sensitive information like phone numbers and domain names.

 

[Nedo]

Hi hfoster, today i have made another attempt, i switched to new internet provider, i have rebooted the ip phones it seems autenticated to fusionpbx as usual.
This log report the attempt of calling from extension 100 to 101:

2023-03-29 13:54:11.805504 98.00% [NOTICE] switch_channel.c:1123 New Channel sofia/internal/100@XXXXXXXXX.con9.cloud [564488d9-34ca-40c8-b8d8-fef27c34b11c]
2023-03-29 13:54:11.805504 98.00% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/100@XXXXXXXXX.con9.cloud) Running State Change CS_NEW (Cur 2 Tot 1145)
2023-03-29 13:54:11.805504 98.00% [INFO] sofia.c:10468 sofia/internal/100@XXXXXXXXX.con9.cloud receiving invite from XXXXXX.119:28094 version: 1.10.8 -release 64bit call-id: 58064110842320-14088390163464@XXXXXX.119
2023-03-29 13:54:11.805504 98.00% [DEBUG] sofia.c:10562 verifying acl "providers" for ip/port XXXXXX.119:0.
2023-03-29 13:54:11.805504 98.00% [DEBUG] sofia.c:2419 detaching session 564488d9-34ca-40c8-b8d8-fef27c34b11c
2023-03-29 13:54:11.805504 98.00% [DEBUG] switch_core_state_machine.c:600 (sofia/internal/100@XXXXXXXXX.con9.cloud) State NEW
2023-03-29 13:54:21.825506 98.53% [WARNING] switch_core_state_machine.c:684 564488d9-34ca-40c8-b8d8-fef27c34b11c sofia/internal/100@XXXXXXXXX.con9.cloud Abandoned
2023-03-29 13:54:21.825506 98.53% [NOTICE] switch_core_state_machine.c:687 Hangup sofia/internal/100@XXXXXXXXX.con9.cloud [CS_NEW] [WRONG_CALL_STATE]
2023-03-29 13:54:21.825506 98.53% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/100@XXXXXXXXX.con9.cloud) Running State Change CS_HANGUP (Cur 2 Tot 1145)
2023-03-29 13:54:21.825506 98.53% [DEBUG] switch_core_state_machine.c:844 (sofia/internal/100@XXXXXXXXX.con9.cloud) Callstate Change DOWN -> HANGUP
2023-03-29 13:54:21.825506 98.53% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/100@XXXXXXXXX.con9.cloud) State HANGUP
2023-03-29 13:54:21.825506 98.53% [DEBUG] mod_sofia.c:468 Channel sofia/internal/100@XXXXXXXXX.con9.cloud hanging up, cause: WRONG_CALL_STATE
2023-03-29 13:54:21.825506 98.53% [DEBUG] switch_core_state_machine.c:59 sofia/internal/100@XXXXXXXXX.con9.cloud Standard HANGUP, cause: WRONG_CALL_STATE
2023-03-29 13:54:21.825506 98.53% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/100@XXXXXXXXX.con9.cloud) State HANGUP going to sleep
2023-03-29 13:54:21.825506 98.53% [DEBUG] switch_core_state_machine.c:616 (sofia/internal/100@XXXXXXXXX.con9.cloud) State Change CS_HANGUP -> CS_REPORTING
2023-03-29 13:54:21.825506 98.53% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/100@XXXXXXXXX.con9.cloud) Running State Change CS_REPORTING (Cur 2 Tot 1145)
2023-03-29 13:54:21.825506 98.53% [DEBUG] switch_core_state_machine.c:932 (sofia/internal/100@XXXXXXXXX.con9.cloud) State REPORTING
2023-03-29 13:54:21.825506 98.53% [DEBUG] switch_core_state_machine.c:168 sofia/internal/100@XXXXXXXXX.con9.cloud Standard REPORTING, cause: WRONG_CALL_STATE
2023-03-29 13:54:21.825506 98.53% [DEBUG] switch_core_state_machine.c:932 (sofia/internal/100@XXXXXXXXX.con9.cloud) State REPORTING going to sleep
2023-03-29 13:54:21.825506 98.53% [DEBUG] switch_core_state_machine.c:607 (sofia/internal/100@XXXXXXXXX.con9.cloud) State Change CS_REPORTING -> CS_DESTROY
2023-03-29 13:54:21.825506 98.53% [DEBUG] switch_core_session.c:1747 Session 1145 (sofia/internal/100@XXXXXXXXX.con9.cloud) Locked, Waiting on external entities
2023-03-29 13:54:21.825506 98.53% [NOTICE] switch_core_session.c:1765 Session 1145 (sofia/internal/100@XXXXXXXXX.con9.cloud) Ended
2023-03-29 13:54:21.825506 98.53% [NOTICE] switch_core_session.c:1769 Close Channel sofia/internal/100@XXXXXXXXX.con9.cloud [CS_DESTROY]
2023-03-29 13:54:21.825506 98.53% [DEBUG] switch_core_state_machine.c:735 (sofia/internal/100@XXXXXXXXX.con9.cloud) Running State Change CS_DESTROY (Cur 1 Tot 1145)
2023-03-29 13:54:21.825506 98.53% [DEBUG] switch_core_state_machine.c:745 (sofia/internal/100@XXXXXXXXX.con9.cloud) State DESTROY
2023-03-29 13:54:21.825506 98.53% [DEBUG] mod_sofia.c:379 sofia/internal/100@XXXXXXXXX.con9.cloud SOFIA DESTROY
2023-03-29 13:54:21.825506 98.53% [DEBUG] switch_core_state_machine.c:175 sofia/internal/100@XXXXXXXXX.con9.cloud Standard DESTROY
2023-03-29 13:54:21.825506 98.53% [DEBUG] switch_core_state_machine.c:745 (sofia/internal/100@XXXXXXXXX.con9.cloud) State DESTROY going to sleep

Why this happen?

Clearing existing udp and tcp connection to client router and server reboot not solve this trouble :'(

 

[Nedo]

sofia_profile_name in the CDR detail probably if you see one.

If you can post a log of an attempted call, that might help. Remember to find and replace any sensitive information like phone numbers and domain names.

Above the log.

I have made a new cloud server with debian 11 and last fusionpbx, i have the same problem on this. When i switch to new providers i obtain wrong call state, the strange thing is that if i switch from phone from udp to tcp it work without issues.

 

[hfoster]

WRONG CALL STATE usually implies that FreeSWITCH tried to authenticate on the INVITE but couldn't complete. Given the second clue about TCP working and UDP not working, that makes me think that one of the routers is blocking arbitrary UDP ports. Create a firewall rule that allows everything from your PBX address/

 

[Nedo]

Hi, i haven't any firewall drop rule, initially i have used the router from isp, but i had this problem so i set up a mikrotik, it has only a ip lan address, a dhcp server and a masquerade on pppoe interface for clients navigation.

 

[hfoster]

SIP ALG disabled?

 

[Nedo]

It was the first thing I deactivated, between the various attempts I also tried to reactivate it to see if it made any difference but unfortunately nothing.
What I still don't understand, it is true that the customer has a natted ip, i.e. he does not have a public ip because he passes under a wisp operator, but it is an identical situation to many other customers that I manage on which I have never had any problem. I also had this problem on another domain with vodafone operator which also had a public ip. It's a problem that I encounter only and exclusively on the latest versions of fusion. My old instances with customer situations like this continue to run fine.

 

[hfoster]

Really it is a crapshoot to know whether you are on the dreaded Carrier Grade NAT now all the IPv4 has gone. Time to pull out the packet captures to see what is happening to the INVITEs, or just stick to using TCP SIP only (the modern recommendation anyway).

On sngrep on the server you should see the following when making a call:



This should match on the endpoint too, in particular the 407 Proxy Authentication. If not, something, somewhere along the way is blocking it.

 

[Lorena Watkins]

Good morning!!

I came to this thread because something similar has been happening to me for about 3 months with the biggest client we have (400 extensions) and the calls are suddenly disconnected, not all at the same time, they happen sporadically but especially from 2 to 4 pm.

The client explains they can see on the phone how the registration ligth turns off suddenly (image attached), and if there is an ongoing call, of course it disconnects. This are the logs I can see at the time of the disconnections:
___________________________________________________________________________________________________________________________________
2023-03-28 14:08:02.637777 [WARNING] sofia_reg.c:1794 SIP auth challenge (INVITE) on sofia profile 'internal' for [1900@voip.xxx.dom] from ip a.a.a.a
2023-03-28 14:08:06.857775 [WARNING] sofia_reg.c:1794 SIP auth challenge (INVITE) on sofia profile 'internal' for [park+*5902@at.voip.xxx.dom] from ip
ed3921f5-0f65-4405-8abf-4fe1cbf2a420 2023-03-28 14:08:07.257851 [WARNING] switch_core_state_machine.c:688 ed3921f5-0f65-4405-8abf-4fe1cbf2a420 sofia/internal/2202@voip.xxx.dom Abandoned
2023-03-28 14:08:07.377805 [WARNING] sofia_reg.c:2930 Can't find user [102@clin.dom.xxx.net] from
You must define a domain called 'clin.dom.xxx.net' in your directory and add a user with the id="102" attribute
and you must configure your device to use the proper domain in its authentication credentials.
2023-03-28 14:08:07.377805 [WARNING] sofia_reg.c:1739 SIP auth failure (REGISTER) on sofia profile 'internal' for [102@clin.dom.xxx.net] from ip c.c.c.c
2023-03-28 14:08:08.017800 [WARNING] sofia_reg.c:1794 SIP auth challenge (INVITE) on sofia profile 'internal' for [park+*5902@at.voip.xxx.dom] from ip b.b.b.b
2023-03-28 14:08:09.417831 [WARNING] sofia_reg.c:1794 SIP auth challenge (INVITE) on sofia profile 'internal' for [7874444444@voip.xxx.dom] from ip d.d.d.d
2023-03-28 14:08:11.077773 [ERR] switch_core_sqldb.c:1347 ERR: [select * from v_call_block
where (domain_uuid = 'be8931de-92ae-4bbd-874d-9d628ed34476' or domain_uuid is null)
and call_block_enabled = 'true'
and call_block_direction = 'inbound'
and (
(
call_block_name = '1787xxxxxxx'
and (
'+' || call_block_country_code || call_block_number = '1787xxxxxxx'
or call_block_country_code || call_block_number = '1787xxxxxxx'
or call_block_number = '1787xxxxxxx'
)
)
or (
call_block_name is null
and (
'+' || call_block_country_code || call_block_number = '1787xxxxxxx'
or call_block_country_code || call_block_number = '1787xxxxxxx'
or call_block_number = '1787xxxxxxx'
)
)
or (call_block_name = '1787xxxxxxx' and call_block_number is null)
)
and extension_uuid is null]
[ERROR: column "call_block_direction" does not exist
LINE 4: and call_block_direction = 'inbound'
^
]
___________________________________________________________________________________________________________________________________
Any help is highly appreciated!!

 

[hfoster]

I don't think it's related at all. You have a big fat SQL error. What's happened to that table?

It's either that or Fail2Ban/Event Guard is blocking due to an invalid REGISTER:
2023-03-28 14:08:07.377805 [WARNING] sofia_reg.c:1739 SIP auth failure (REGISTER) on sofia profile 'internal' for [102@clin.dom.xxx.net] from ip c.c.c.c

 

[Lorena Watkins]

Thanks for your quick reply @hfoster, what makes you think I have an SQL issue, this message?

2023-03-28 14:08:11.077773 [ERR] switch_core_sqldb.c:1347 ERR: [select * from v_call_block

My logs show this message literally 26 times in every minute.

 

[hfoster]

[ERROR: column "call_block_direction" does not exist
LINE 4: and call_block_direction = 'inbound'

Your table is missing an entire column. I wonder if you missed an update schema some time ago. It might not affect functionality for this fault, but it would annoy the hell out of me. Also, your Call Block app won't work.

What's the deal with that failed registration too on extension 102? Is this intended? I.e, forgot to put in a password, etc.

2023-03-28 14:08:07.377805 [WARNING] sofia_reg.c:1739 SIP auth failure (REGISTER) on sofia profile 'internal' for [102@clin.dom.xxx.net] from ip c.c.c.c

 

[Lorena Watkins]

Thanks @hfoster that makes complete sense! I was distracted thinking about the call disconnections and didn't took care of this message. I will start from here, maybe my DB is corrupt and somehow may cause the disconnections.

BTW..does anyone know what is the best way to reestructure the v_call_block table?

 

[hfoster]

If you haven't done a lot of crazy custom stuff, there's a schema upgrade tool in the upgrade area. This checks the DB schema and updates it.

As always with server admin jobs, check your backups and ensure you can restore if anything goes wrong before doing this.

As stated, this probably won't fix the call disconnections but should at least make the logs a bit more readable. Most disconnections I have found are down to codec mismatches on endpoints, firmware versions and internet connections.