[bug]: UCP unable to connect to the node server (xhr poll error) #576

va7wv · 2024-12-03T17:16:24Z

FreePBX Version

FreePBX 17

Issue Description

This is a new install using the official bash script on Debian. Have tried disabling firewall, restarting mysqld, nothing seems to change condition. Error popup on UCP login page indicates "xhr poll error". Mariadb is running but service shows error. How do I begin to troubleshoot this? Everything else works fine, but I would like to have a working UCP.

Operating Environment

Relevant log output

2024-12-02 15:20 -08:00: There was an error with MySQL Connection
2024-12-02 15:21 -08:00: SqlError: (conn:39, no: 45009, SQLState: 08S01) socket has unexpectedly been closed
2024-12-02 15:21 -08:00:     at module.exports.createFatalError (/var/www/html/admin/modules/ucp/node/node_modules/mariadb/lib/misc/errors.js:90:10)
2024-12-02 15:21 -08:00:     at Connection.socketErrorHandler (/var/www/html/admin/modules/ucp/node/node_modules/mariadb/lib/connection.js:1193:20)
2024-12-02 15:21 -08:00:     at Socket.emit (node:events:529:35)
2024-12-02 15:21 -08:00:     at endReadableNT (node:internal/streams/readable:1400:12)
2024-12-02 15:21 -08:00:     at process.processTicksAndRejections (node:internal/process/task_queues:82:21) {
2024-12-02 15:21 -08:00:   sqlMessage: 'socket has unexpectedly been closed',
2024-12-02 15:21 -08:00:   sql: null,
2024-12-02 15:21 -08:00:   fatal: true,
2024-12-02 15:21 -08:00:   errno: 45009,
2024-12-02 15:21 -08:00:   sqlState: '08S01',
2024-12-02 15:21 -08:00:   code: 'ER_SOCKET_UNEXPECTED_CLOSE'
2024-12-02 15:21 -08:00: }
2024-12-02 15:21 -08:00: Error: connect ECONNREFUSED 127.0.0.1:3306
2024-12-02 15:21 -08:00:     at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1549:16)
2024-12-02 15:21 -08:00:  From event:
2024-12-02 15:21 -08:00:     at /var/www/html/admin/modules/ucp/node/node_modules/mariadb/lib/connection.js:142:13
2024-12-02 15:21 -08:00:     at new Promise (<anonymous>)
2024-12-02 15:21 -08:00:     at Connection.connect (/var/www/html/admin/modules/ucp/node/node_modules/mariadb/lib/connection.js:131:12)
2024-12-02 15:21 -08:00:     at Object.createConnection (/var/www/html/admin/modules/ucp/node/node_modules/mariadb/promise.js:37:17)
2024-12-02 15:21 -08:00:     at connect2database (/var/www/html/admin/modules/ucp/node/lib/freepbx.js:74:25)
2024-12-02 15:21 -08:00:     at /var/www/html/admin/modules/ucp/node/lib/freepbx.js:35:4
2024-12-02 15:21 -08:00:     at ChildProcess.exithandler (node:child_process:414:7)
2024-12-02 15:21 -08:00:     at ChildProcess.emit (node:events:517:28)
2024-12-02 15:21 -08:00:     at maybeClose (node:internal/child_process:1098:16)
2024-12-02 15:21 -08:00:     at ChildProcess._handle.onexit (node:internal/child_process:303:5) {
2024-12-02 15:21 -08:00:   errno: -111,
2024-12-02 15:21 -08:00:   code: 'ECONNREFUSED',
2024-12-02 15:21 -08:00:   syscall: 'connect',
2024-12-02 15:21 -08:00:   address: '127.0.0.1',
2024-12-02 15:21 -08:00:   port: 3306,
2024-12-02 15:21 -08:00:   fatal: true,
2024-12-02 15:21 -08:00:   sqlState: 'HY000'
2024-12-02 15:21 -08:00: }
2024-12-02 15:21 -08:00: There was an error with MySQL Connection

● mariadb.service - MariaDB 10.11.6 database server
     Loaded: loaded (/lib/systemd/system/mariadb.service; enabled; preset: enabled)
     Active: active (running) since Mon 2024-12-02 15:21:35 PST; 17h ago
       Docs: man:mariadbd(8)
             https://mariadb.com/kb/en/library/systemd/
    Process: 245858 ExecStartPre=/usr/bin/install -m 755 -o mysql -g root -d /var/run/mysqld (code=exited, status=0/SUCCESS)
    Process: 245860 ExecStartPre=/bin/sh -c systemctl unset-environment _WSREP_START_POSITION (code=exited, status=0/SUCCESS)
    Process: 245862 ExecStartPre=/bin/sh -c [ ! -e /usr/bin/galera_recovery ] && VAR= ||   VAR=`cd /usr/bin/..; /usr/bin/galera_recovery`; [ $? -eq 0 ]   && systemctl set-environment _WSREP_START_P>
    Process: 245932 ExecStartPost=/bin/sh -c systemctl unset-environment _WSREP_START_POSITION (code=exited, status=0/SUCCESS)
    Process: 245936 ExecStartPost=/etc/mysql/debian-start (code=exited, status=0/SUCCESS)
   Main PID: 245921 (mariadbd)
     Status: "Taking your SQL requests now..."
      Tasks: 23 (limit: 4644)
     Memory: 256.8M
        CPU: 3min 26.170s
     CGroup: /system.slice/mariadb.service
             └─245921 /usr/sbin/mariadbd

Dec 02 15:21:35 freepbx mariadbd[245921]: 2024-12-02 15:21:35 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
Dec 02 15:21:35 freepbx mariadbd[245921]: 2024-12-02 15:21:35 0 [Note] /usr/sbin/mariadbd: ready for connections.
Dec 02 15:21:35 freepbx mariadbd[245921]: Version: '10.11.6-MariaDB-0+deb12u1'  socket: '/run/mysqld/mysqld.sock'  port: 3306  Debian 12
Dec 02 15:21:35 freepbx systemd[1]: Started mariadb.service - MariaDB 10.11.6 database server.
Dec 02 15:21:35 freepbx /etc/mysql/debian-start[245938]: Upgrading MySQL tables if necessary.
Dec 02 15:21:35 freepbx mariadbd[245921]: 2024-12-02 15:21:35 0 [Note] InnoDB: Buffer pool(s) load completed at 241202 15:21:35
Dec 02 15:21:35 freepbx /etc/mysql/debian-start[245949]: Checking for insecure root accounts.
Dec 02 15:21:35 freepbx /etc/mysql/debian-start[245953]: Triggering myisam-recover for all MyISAM tables and aria-recover for all Aria tables
Dec 03 09:06:42 freepbx mariadbd[245921]: 2024-12-03  9:06:42 255 [Warning] Aborted connection 255 to db: 'asterisk' user: 'freepbxuser' host: 'localhost' (Got an error reading communication packet>
Dec 03 09:06:42 freepbx mariadbd[245921]: 2024-12-03  9:06:42 248 [Warning] Aborted connection 248 to db: 'asterisk' user: 'freepbxuser' host: 'localhost' (Got an error reading communication packet>

kguptasangoma · 2024-12-03T17:21:41Z

hi @va7wv first of all confirm your mariadb service is running properly ?

then check why [127.0.0.1:3306](http://127.0.0.1:3306/) getting connection refused to this IP and port? Please note If you have ipv6 enabled then ensure localhost is resolving to 127.0.0.1.

va7wv · 2024-12-03T17:34:13Z

● mariadb.service - MariaDB 10.11.6 database server
Loaded: loaded (/lib/systemd/system/mariadb.service; enabled; preset: enabled)
Active: active (running) since Tue 2024-12-03 09:26:49 PST; 6min ago
Docs: man:mariadbd(8)
https://mariadb.com/kb/en/library/systemd/
Main PID: 725 (mariadbd)
Status: "Taking your SQL requests now..."
Tasks: 30 (limit: 4644)
Memory: 283.0M
CPU: 2.663s
CGroup: /system.slice/mariadb.service
└─725 /usr/sbin/mariadbd

Dec 03 09:26:49 freepbx mariadbd[725]: 2024-12-03 9:26:49 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
Dec 03 09:26:49 freepbx mariadbd[725]: 2024-12-03 9:26:49 0 [Warning] You need to use --log-bin to make --expire-logs-days or --binlog-expire-logs-seconds work.
Dec 03 09:26:49 freepbx mariadbd[725]: 2024-12-03 9:26:49 0 [Note] Server socket created on IP: '127.0.0.1'.
Dec 03 09:26:49 freepbx mariadbd[725]: 2024-12-03 9:26:49 0 [Note] InnoDB: Buffer pool(s) load completed at 241203 9:26:49
Dec 03 09:26:49 freepbx mariadbd[725]: 2024-12-03 9:26:49 0 [Note] /usr/sbin/mariadbd: ready for connections.
Dec 03 09:26:49 freepbx mariadbd[725]: Version: '10.11.6-MariaDB-0+deb12u1' socket: '/run/mysqld/mysqld.sock' port: 3306 Debian 12
Dec 03 09:26:49 freepbx systemd[1]: Started mariadb.service - MariaDB 10.11.6 database server.
Dec 03 09:26:49 freepbx /etc/mysql/debian-start[961]: Upgrading MySQL tables if necessary.
Dec 03 09:26:49 freepbx /etc/mysql/debian-start[992]: Checking for insecure root accounts.
Dec 03 09:26:49 freepbx /etc/mysql/debian-start[1006]: Triggering myisam-recover for all MyISAM tables and aria-recover for all Aria tables

va7wv · 2024-12-03T17:41:51Z

IPV6 disabled and not used.

kguptasangoma · 2024-12-03T17:44:32Z

May be please try fwconsole restart to ensure all the services starting properly.

just thinking about below error

SqlError: (conn:39, no: 45009, SQLState: 08S01) socket has unexpectedly been closed
2024-12-02 15:21 -08:00:     at module.exports.createFatalError (/var/www/html/admin/modules/ucp/node/node_modules/mariadb/lib/misc/errors.js:90:10)
2024-12-02 15:21 -08:00:     at Connection.socketErrorHandler (/var/www/html/admin/modules/ucp/node/node_modules/mariadb/lib/connection.js:1193:20)
2024-12-02 15:21 -08:00:     at Socket.emit (node:events:529:35)
2024-12-02 15:21 -08:00:     at endReadableNT (node:internal/streams/readable:1400:12)
2024-12-02 15:21 -08:00:     at process.processTicksAndRejections (node:internal/process/task_queues:82:21) {
2024-12-02 15:21 -08:00:   sqlMessage: 'socket has unexpectedly been closed',
2024-12-02 15:21 -08:00:   sql: null,
2024-12-02 15:21 -08:00:   fatal: true,
2024-12-02 15:21 -08:00:   errno: 45009,
2024-12-02 15:21 -08:00:   sqlState: '08S01',
2024-12-02 15:21 -08:00:   code: 'ER_SOCKET_UNEXPECTED_CLOSE'
2024-12-02 15:21 -08:00: }
2024-12-02 15:21 -08:00: Error: connect ECONNREFUSED 127.0.0.1:3306

va7wv · 2024-12-03T18:47:20Z

No go, unfortunately. I have attempted to restart the system several times as well. Appreciate the suggestion. I am not against spinning up another fresh Debian 12 VM and transferring the settings. Literally all I did was run the official script and setup the IVR though.

va7wv · 2024-12-04T16:22:13Z

Started a new VM with the newest official bash script, transferred the configuration using Backup/restore and same problem.

kguptasangoma · 2024-12-04T16:25:11Z

are you seeing any node socket error again on the new system ?

How about just fresh system without backup / restore, does that work fine for you ? just thinking if its due to your system environment/VM issue Vs config issue ?

va7wv · 2024-12-04T16:29:17Z

I will try another install in a fresh VM without the backup/restore and report back.

kguptasangoma · 2024-12-04T16:31:55Z

yes and if you face any issue on fresh system without your configuration then can you please send me access details to [email protected] (if possible) so i can try to ssh to your system to check what is going on.

thanks

va7wv · 2024-12-04T23:27:31Z

Confirmed. Fresh VM, new install. Added one extension, changed the user password. Go to UCP and immediately fails with same xhr error. No other settings changed at all.

kguptasangoma · 2024-12-05T04:21:54Z

Hi @va7wv is it possible for you to give me ssh access , so i can see what is going on? Send me credentials to [email protected]. Thanks

va7wv added bug Something isn't working triage Triage labels Dec 3, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[bug]: UCP unable to connect to the node server (xhr poll error) #576

[bug]: UCP unable to connect to the node server (xhr poll error) #576

va7wv commented Dec 3, 2024

kguptasangoma commented Dec 3, 2024

va7wv commented Dec 3, 2024

va7wv commented Dec 3, 2024

kguptasangoma commented Dec 3, 2024

va7wv commented Dec 3, 2024

va7wv commented Dec 4, 2024

kguptasangoma commented Dec 4, 2024

va7wv commented Dec 4, 2024

kguptasangoma commented Dec 4, 2024

va7wv commented Dec 4, 2024 •

edited

Loading

kguptasangoma commented Dec 5, 2024

[bug]: UCP unable to connect to the node server (xhr poll error) #576

[bug]: UCP unable to connect to the node server (xhr poll error) #576

Comments

va7wv commented Dec 3, 2024

FreePBX Version

Issue Description

Operating Environment

Relevant log output

kguptasangoma commented Dec 3, 2024

va7wv commented Dec 3, 2024

va7wv commented Dec 3, 2024

kguptasangoma commented Dec 3, 2024

va7wv commented Dec 3, 2024

va7wv commented Dec 4, 2024

kguptasangoma commented Dec 4, 2024

va7wv commented Dec 4, 2024

kguptasangoma commented Dec 4, 2024

va7wv commented Dec 4, 2024 • edited Loading

kguptasangoma commented Dec 5, 2024

va7wv commented Dec 4, 2024 •

edited

Loading