Toggle sidebar Toggle sidebar

3CXCfgServ01.service: Failed with result 'protocol'.

Status
Not open for further replies.

jpmchia

SOHO User
Joined
Jul 22, 2022
Messages
4
Reaction score
0
Running version 18.0 Update 8 (Built 917), originally deployed as self-managed Azure instance.

Rebooted the VM today and now 3CX will not startup. Probably the first time that the VM has been restarted since deployment as a fresh install. Had to redeployed a new VM because of a similar issue with the previous instance.

Errors in /var/lib/3cxpbx/Data/Logs/CloudServiceWatcher.log:

Code: 
023/09/08 10:26:44.093|0006|Excpt(03)| Npgsql.NpgsqlException (0x80004005): Exception while connecting

 ---> System.Net.Sockets.SocketException (111): Connection refused

   at Npgsql.NpgsqlConnector.Connect(NpgsqlTimeout timeout)

   at Npgsql.NpgsqlConnector.Connect(NpgsqlTimeout timeout)

   at Npgsql.NpgsqlConnector.RawOpen(NpgsqlTimeout timeout, Boolean async, CancellationToken cancellationToken)

   at Npgsql.NpgsqlConnector.Open(NpgsqlTimeout timeout, Boolean async, CancellationToken cancellationToken)

   at Npgsql.NpgsqlConnection.<>c__DisplayClass41_0.<<Open>g__OpenAsync|0>d.MoveNext()

--- End of stack trace from previous location ---

   at Npgsql.NpgsqlConnection.Open()

   at PostInstall.DBConnection.get_Connection()

   at PostInstall.DBConnection.Execute(String sqlQuery, IDictionary`2 parameters, Action`1 readAction)

   at CloudServicesWatcher.ServiceWatcher.BuildTenants()

2023/09/08 10:28:49.106|0007|Excpt(03)| Npgsql.NpgsqlException (0x80004005): Exception while connecting

 ---> System.Net.Sockets.SocketException (111): Connection refused

   at Npgsql.NpgsqlConnector.Connect(NpgsqlTimeout timeout)

   at Npgsql.NpgsqlConnector.Connect(NpgsqlTimeout timeout)

   at Npgsql.NpgsqlConnector.RawOpen(NpgsqlTimeout timeout, Boolean async, CancellationToken cancellationToken)

   at Npgsql.NpgsqlConnector.Open(NpgsqlTimeout timeout, Boolean async, CancellationToken cancellationToken)

   at Npgsql.NpgsqlConnection.<>c__DisplayClass41_0.<<Open>g__OpenAsync|0>d.MoveNext()

--- End of stack trace from previous location ---

   at Npgsql.NpgsqlConnection.Open()

   at PostInstall.DBConnection.get_Connection()

   at PostInstall.DBConnection.Execute(String sqlQuery, IDictionary`2 parameters, Action`1 readAction)

   at CloudServicesWatcher.ServiceWatcher.BuildTenants()

2023/09/08 10:30:54.113|0004|Excpt(03)| Npgsql.NpgsqlException (0x80004005): Exception while connecting

 ---> System.Net.Sockets.SocketException (111): Connection refused

   at Npgsql.NpgsqlConnector.Connect(NpgsqlTimeout timeout)

   at Npgsql.NpgsqlConnector.Connect(NpgsqlTimeout timeout)

   at Npgsql.NpgsqlConnector.RawOpen(NpgsqlTimeout timeout, Boolean async, CancellationToken cancellationToken)

   at Npgsql.NpgsqlConnector.Open(NpgsqlTimeout timeout, Boolean async, CancellationToken cancellationToken)

   at Npgsql.NpgsqlConnection.<>c__DisplayClass41_0.<<Open>g__OpenAsync|0>d.MoveNext()

--- End of stack trace from previous location ---

   at Npgsql.NpgsqlConnection.Open()

   at PostInstall.DBConnection.get_Connection()

   at PostInstall.DBConnection.Execute(String sqlQuery, IDictionary`2 parameters, Action`1 readAction)

   at CloudServicesWatcher.ServiceWatcher.BuildTenants()

When restarting the services via: 3CXStartServices
Code: 
Job for 3CXCfgServ01.service failed because the service did not take the steps required by its unit configuration.
See "systemctl status 3CXCfgServ01.service" and "journalctl -xe" for details.
A dependency job for 3CXPhoneSystemMC01.service failed. See 'journalctl -xe' for details.
A dependency job for 3CXGatewayService.service failed. See 'journalctl -xe' for details.
A dependency job for 3CXSystemService01.service failed. See 'journalctl -xe' for details.
A dependency job for 3CXPhoneSystem01.service failed. See 'journalctl -xe' for details.
A dependency job for 3CXCallFlow01.service failed. See 'journalctl -xe' for details.
A dependency job for 3CXIVR01.service failed. See 'journalctl -xe' for details.
A dependency job for 3CXQueueManager01.service failed. See 'journalctl -xe' for details.
A dependency job for 3CXHotelModule01.service failed. See 'journalctl -xe' for details.
A dependency job for 3CXAudioProvider01.service failed. See 'journalctl -xe' for details.

Postgresql starts up without a problem, but 3CX fails on Configuration Service with "3CXCfgServ01.service: Failed with result 'protocol'.".
Code: 
Sep  8 10:38:48 vm-tnet-prod-uks-orpheus systemd[1]: postgresql.service: Succeeded.
Sep  8 10:38:48 vm-tnet-prod-uks-orpheus systemd[1]: Stopped PostgreSQL RDBMS.
Sep  8 10:38:48 vm-tnet-prod-uks-orpheus systemd[1]: Stopping PostgreSQL RDBMS...
Sep  8 10:38:48 vm-tnet-prod-uks-orpheus systemd[1]: Stopping PostgreSQL Cluster 11-main...
Sep  8 10:38:49 vm-tnet-prod-uks-orpheus systemd[1]: [email protected]: Succeeded.
Sep  8 10:38:49 vm-tnet-prod-uks-orpheus systemd[1]: Stopped PostgreSQL Cluster 11-main.
Sep  8 10:38:49 vm-tnet-prod-uks-orpheus systemd[1]: Starting PostgreSQL Cluster 11-main...
Sep  8 10:38:51 vm-tnet-prod-uks-orpheus systemd[1]: Started PostgreSQL Cluster 11-main.
Sep  8 10:38:51 vm-tnet-prod-uks-orpheus systemd[1]: Starting PostgreSQL RDBMS...
Sep  8 10:38:51 vm-tnet-prod-uks-orpheus systemd[1]: Started PostgreSQL RDBMS.
Sep  8 10:39:00 vm-tnet-prod-uks-orpheus systemd[1]: Reloading.
Sep  8 10:39:01 vm-tnet-prod-uks-orpheus systemd[1]: Starting 3CX PhoneSystem Configuration Service...
Sep  8 10:39:26 vm-tnet-prod-uks-orpheus systemd[1]: 3CXCfgServ01.service: Failed with result 'protocol'.
Sep  8 10:39:26 vm-tnet-prod-uks-orpheus systemd[1]: Failed to start 3CX PhoneSystem Configuration Service.
Sep  8 10:39:26 vm-tnet-prod-uks-orpheus systemd[1]: Dependency failed for 3CX PhoneSystem 01 Management Console.
Sep  8 10:39:26 vm-tnet-prod-uks-orpheus systemd[1]: Dependency failed for 3CX Gateway Service.
Sep  8 10:39:26 vm-tnet-prod-uks-orpheus systemd[1]: 3CXGatewayService.service: Job 3CXGatewayService.service/start failed with result 'dependency'.
Sep  8 10:39:26 vm-tnet-prod-uks-orpheus systemd[1]: 3CXPhoneSystemMC01.service: Job 3CXPhoneSystemMC01.service/start failed with result 'dependency'.
Sep  8 10:39:26 vm-tnet-prod-uks-orpheus systemd[1]: Dependency failed for 3CX PhoneSystem 01 System Server.
Sep  8 10:39:26 vm-tnet-prod-uks-orpheus systemd[1]: 3CXSystemService01.service: Job 3CXSystemService01.service/start failed with result 'dependency'.
Sep  8 10:39:26 vm-tnet-prod-uks-orpheus systemd[1]: Dependency failed for 3CX PhoneSystem 01 SIP Server.
Sep  8 10:39:26 vm-tnet-prod-uks-orpheus systemd[1]: Dependency failed for 3CX PhoneSystem 01 CallFlow Server.
Sep  8 10:39:26 vm-tnet-prod-uks-orpheus systemd[1]: 3CXCallFlow01.service: Job 3CXCallFlow01.service/start failed with result 'dependency'.
Sep  8 10:39:26 vm-tnet-prod-uks-orpheus systemd[1]: Dependency failed for 3CX PhoneSystem 01 IVR Server.
Sep  8 10:39:26 vm-tnet-prod-uks-orpheus systemd[1]: 3CXIVR01.service: Job 3CXIVR01.service/start failed with result 'dependency'.
Sep  8 10:39:26 vm-tnet-prod-uks-orpheus systemd[1]: Dependency failed for 3CX PhoneSystem 01 Queue Manager Server.
Sep  8 10:39:26 vm-tnet-prod-uks-orpheus systemd[1]: 3CXQueueManager01.service: Job 3CXQueueManager01.service/start failed with result 'dependency'.
Sep  8 10:39:26 vm-tnet-prod-uks-orpheus systemd[1]: 3CXPhoneSystem01.service: Job 3CXPhoneSystem01.service/start failed with result 'dependency'.
Sep  8 10:39:26 vm-tnet-prod-uks-orpheus systemd[1]: Dependency failed for 3CX PhoneSystem 01 Hotel Module.
Sep  8 10:39:26 vm-tnet-prod-uks-orpheus systemd[1]: 3CXHotelModule01.service: Job 3CXHotelModule01.service/start failed with result 'dependency'.
Sep  8 10:39:26 vm-tnet-prod-uks-orpheus systemd[1]: Dependency failed for 3CX PhoneSystem 01 Audio Provider Server.
Sep  8 10:39:26 vm-tnet-prod-uks-orpheus systemd[1]: 3CXAudioProvider01.service: Job 3CXAudioProvider01.service/start failed with result 'dependency'.
 
Output of journalctl -xe:
Code: 
Sep 08 10:39:00 vm-tnet-prod-uks-orpheus systemd[1]: Reloading.
Sep 08 10:39:01 vm-tnet-prod-uks-orpheus systemd[1]: Starting 3CX PhoneSystem Configuration Service...
-- Subject: A start job for unit 3CXCfgServ01.service has begun execution
-- Defined-By: systemd
-- Support: https://www.debian.org/support
--
-- A start job for unit 3CXCfgServ01.service has begun execution.
--
-- The job identifier is 8258.
Sep 08 10:39:26 vm-tnet-prod-uks-orpheus systemd[1]: 3CXCfgServ01.service: Failed with result 'protocol'.
-- Subject: Unit failed
-- Defined-By: systemd
-- Support: https://www.debian.org/support
--
-- The unit 3CXCfgServ01.service has entered the 'failed' state with result 'protocol'.
Sep 08 10:39:26 vm-tnet-prod-uks-orpheus systemd[1]: Failed to start 3CX PhoneSystem Configuration Service.
-- Subject: A start job for unit 3CXCfgServ01.service has failed
-- Defined-By: systemd
-- Support: https://www.debian.org/support
--
-- A start job for unit 3CXCfgServ01.service has finished with a failure.
--
-- The job identifier is 8258 and the job result is failed.
Sep 08 10:39:26 vm-tnet-prod-uks-orpheus systemd[1]: Dependency failed for 3CX PhoneSystem 01 Management Console.
-- Subject: A start job for unit 3CXPhoneSystemMC01.service has failed
-- Defined-By: systemd
-- Support: https://www.debian.org/support
--
-- A start job for unit 3CXPhoneSystemMC01.service has finished with a failure.
--

When running the Configuration Service directly it exits:
Code: 
root@vm-tnet-prod-uks-orpheus:/etc/systemd/system# /usr/sbin/3CXSLDBServ -n -p /var/run/phonesystem/3CXCfgServ01.pid -o /var/lib/3cxpbx/Bin/Objects.cls -c /var/lib/3cxpbx/Bin/3CXPhoneSystem.ini
Instance configuration file: /var/lib/3cxpbx/Bin/3CXPhoneSystem.ini
Starting without forking
config=/var/lib/3cxpbx/Bin/3CXPhoneSystem.ini
Objects definition file has been changed to: /var/lib/3cxpbx/Bin/Objects.cls
Configuration file has been changed to:/var/lib/3cxpbx/Bin/3CXPhoneSystem.ini
configuration file has been (re)loaded :/var/lib/3cxpbx/Bin/3CXPhoneSystem.ini

root@vm-tnet-prod-uks-orpheus:/etc/systemd/system#
 
Noticed that the appSettings for the connection string in 3CX specify port 5480 for PostgresDB but postgresqld is set to the default port 5432 in the VM.

/var/lib/3cxpbx/Bin/3CXSystemService.exe.config
/var/lib/3cxpbx//Bin/CloudServicesWatcher.exe.config

When I change the port from 5432 to 5480 and restart postgres and 3CXStartServices, I can see that it is now attempting to connect:
Code: 
2023-09-08 10:56:52.945 UTC [2870] LOG:  listening on IPv4 address "127.0.0.1", port 5480
2023-09-08 10:56:52.946 UTC [2870] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5480"
2023-09-08 10:56:52.957 UTC [2871] LOG:  database system was shut down at 2023-09-08 10:56:52 UTC
2023-09-08 10:56:52.961 UTC [2870] LOG:  database system is ready to accept connections
2023-09-08 10:56:53.537 UTC [2878] [unknown]@[unknown] LOG:  incomplete startup packet
2023-09-08 10:57:35.016 UTC [2929] phonesystem@masterprofiles FATAL:  password authentication failed for user "phonesystem"
2023-09-08 10:57:35.016 UTC [2929] phonesystem@masterprofiles DETAIL:  Password does not match for user "phonesystem".
        Connection matched pg_hba.conf line 92: "host    all             all             127.0.0.1/32            md5"
2023-09-08 10:57:35.019 UTC [2930] phonesystem@masterprofiles FATAL:  password authentication failed for user "phonesystem"
2023-09-08 10:57:35.019 UTC [2930] phonesystem@masterprofiles DETAIL:  Password does not match for user "phonesystem".
        Connection matched pg_hba.conf line 92: "host    all             all             127.0.0.1/32            md5"
2023-09-08 10:57:40.024 UTC [2932] phonesystem@masterprofiles FATAL:  password authentication failed for user "phonesystem"
2023-09-08 10:57:40.024 UTC [2932] phonesystem@masterprofiles DETAIL:  Password does not match for user "phonesystem".
        Connection matched pg_hba.conf line 92: "host    all             all             127.0.0.1/32            md5"
2023-09-08 10:57:40.027 UTC [2933] phonesystem@masterprofiles FATAL:  password authentication failed for user "phonesystem"
2023-09-08 10:57:40.027 UTC [2933] phonesystem@masterprofiles DETAIL:  Password does not match for user "phonesystem".
        Connection matched pg_hba.conf line 92: "host    all             all             127.0.0.1/32            md5"
2023-09-08 10:57:45.032 UTC [2934] phonesystem@masterprofiles FATAL:  password authentication failed for user "phonesystem"
2023-09-08 10:57:45.032 UTC [2934] phonesystem@masterprofiles DETAIL:  Password does not match for user "phonesystem".
        Connection matched pg_hba.conf line 92: "host    all             all             127.0.0.1/32            md5"
2023-09-08 10:57:45.035 UTC [2935] phonesystem@masterprofiles FATAL:  password authentication failed for user "phonesystem"
2023-09-08 10:57:45.035 UTC [2935] phonesystem@masterprofiles DETAIL:  Password does not match for user "phonesystem".
        Connection matched pg_hba.conf line 92: "host    all             all             127.0.0.1/32            md5"
2023-09-08 10:57:50.040 UTC [2937] phonesystem@masterprofiles FATAL:  password authentication failed for user "phonesystem"
2023-09-08 10:57:50.040 UTC [2937] phonesystem@masterprofiles DETAIL:  Password does not match for user "phonesystem".
        Connection matched pg_hba.conf line 92: "host    all             all             127.0.0.1/32            md5"
2023-09-08 10:57:50.043 UTC [2938] phonesystem@masterprofiles FATAL:  password authentication failed for user "phonesystem"
2023-09-08 10:57:50.043 UTC [2938] phonesystem@masterprofiles DETAIL:  Password does not match for user "phonesystem".
        Connection matched pg_hba.conf line 92: "host    all             all             127.0.0.1/32            md5"
2023-09-08 10:57:55.048 UTC [2943] phonesystem@masterprofiles FATAL:  password authentication failed for user "phonesystem"
2023-09-08 10:57:55.048 UTC [2943] phonesystem@masterprofiles DETAIL:  Password does not match for user "phonesystem".
        Connection matched pg_hba.conf line 92: "host    all             all             127.0.0.1/32            md5"
2023-09-08 10:57:55.051 UTC [2944] phonesystem@masterprofiles FATAL:  password authentication failed for user "phonesystem"
2023-09-08 10:57:55.051 UTC [2944] phonesystem@masterprofiles DETAIL:  Password does not match for user "phonesystem".
        Connection matched pg_hba.conf line 92: "host    all             all             127.0.0.1/32            md5"
 
Set the authentication method to "trust" in /etc/postgresql/11/main/pg_hba.conf:

Code: 
#
# Database administrative login by Unix domain socket
local   all             postgres                                trust

# TYPE  DATABASE        USER            ADDRESS                 METHOD

# "local" is for Unix domain socket connections only
local   all             all                                     trust
# IPv4 local connections:
host    all             all             127.0.0.1/32            trust
# IPv6 local connections:
host    all             all             ::1/128                 trust

Now receiving the more concerning error in the Postges log:
Code: 
2023-09-08 11:09:43.024 UTC [2870] LOG:  database system is shut down
2023-09-08 11:09:43.178 UTC [3149] LOG:  listening on IPv4 address "127.0.0.1", port 5480
2023-09-08 11:09:43.179 UTC [3149] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5480"
2023-09-08 11:09:43.190 UTC [3150] LOG:  database system was shut down at 2023-09-08 11:09:43 UTC
2023-09-08 11:09:43.193 UTC [3149] LOG:  database system is ready to accept connections
2023-09-08 11:09:43.770 UTC [3157] [unknown]@[unknown] LOG:  incomplete startup packet
2023-09-08 11:09:50.007 UTC [3199] phonesystem@masterprofiles FATAL:  database "masterprofiles" does not exist
2023-09-08 11:09:55.012 UTC [3200] phonesystem@masterprofiles FATAL:  database "masterprofiles" does not exist
2023-09-08 11:10:00.017 UTC [3203] phonesystem@masterprofiles FATAL:  database "masterprofiles" does not exist
2023-09-08 11:10:05.023 UTC [3204] phonesystem@masterprofiles FATAL:  database "masterprofiles" does not exist
2023-09-08 11:10:10.028 UTC [3206] phonesystem@masterprofiles FATAL:  database "masterprofiles" does not exist
2023-09-08 11:10:24.414 UTC [3211] phonesystem@masterprofiles FATAL:  database "masterprofiles" does not exist
2023-09-08 11:10:25.423 UTC [3213] phonesystem@masterprofiles FATAL:  database "masterprofiles" does not exist
2023-09-08 11:10:26.427 UTC [3214] phonesystem@masterprofiles FATAL:  database "masterprofiles" does not exist
2023-09-08 11:10:27.430 UTC [3215] phonesystem@masterprofiles FATAL:  database "masterprofiles" does not exist
2023-09-08 11:10:28.432 UTC [3218] phonesystem@masterprofiles FATAL:  database "masterprofiles" does not exist
2023-09-08 11:10:29.435 UTC [3220] phonesystem@masterprofiles FATAL:  database "masterprofiles" does not exist

And similarly, the logs in /var /lib/3cxpbx/Data/Logs:
Code: 
#Date: 2023/09/08
11:09:50.002|7f2865e699c0| Info|: New log file has started
11:09:50.002|7f2865e699c0| Info|DBServ.cpp(1085): connecting masterprofile:
        dbhost=localhost
        dbport=5480
        dbname=masterprofiles
        dbclasses=/var/lib/3cxpbx/Bin/Objects.cls
        dbuser=<default>
        dbpassword=<default>
        addPVfields=enabled

11:09:50.007|7f2865e699c0|Error|DBProvPostgress.cpp(178): Can't connect to master profile configurationreason:FATAL:  database "masterprofiles" does not exist

Try again in 5 sec...
11:09:55.013|7f2865e699c0|Error|DBProvPostgress.cpp(178): Can't connect to master profile configurationreason:FATAL:  database "masterprofiles" does not exist

Try again in 5 sec...
11:10:00.018|7f2865e699c0|Error|DBProvPostgress.cpp(178): Can't connect to master profile configurationreason:FATAL:  database "masterprofiles" does not exist

Try again in 5 sec...
11:10:05.023|7f2865e699c0|Error|DBProvPostgress.cpp(178): Can't connect to master profile configurationreason:FATAL:  database "masterprofiles" does not exist

Try again in 5 sec...
11:10:10.029|7f2865e699c0|Error|DBProvPostgress.cpp(178): Can't connect to master profile configurationreason:FATAL:  database "masterprofiles" does not exist

Try again in 5 sec...
11:10:15.029|7f2865e699c0|Error|DBProvPostgress.cpp(193): No database available. Stop
11:10:15.029|7f2865e699c0|Error|DBServ.cpp(1141): Unhandled exception causes shutdown()
11:10:15.029|7f2865e699c0| Info|DBServ.cpp(1217): StartHost ended
11:10:15.029|7f2865e699c0| Info|DBServ.cpp(1036): ~ConfigServiceHost called
 
Status
Not open for further replies.

Latest Posts

Forum statistics

Threads
111,974
Messages
590,081
Members
164,899
Latest member
mazet
3CX Logo Footer Copyright © Sitemap Privacy
Top Bottom