"Starting services, this can take a while" on v7.3.4 update

[austin]

Ran:

/home/yellowtent/box/setup/start.sh

And I get this:

2022-12-08T17:53:50 ==> start: Cloudron Start
media:x:500:
2022-12-08T17:53:50 ==> start: Configuring docker
Synchronizing state of apparmor.service with SysV service script with /lib/systemd/systemd-sysv-install.
Executing: /lib/systemd/systemd-sysv-install enable apparmor
2022-12-08T17:53:57 ==> start: Ensuring directories
2022-12-08T17:53:57 ==> start: Configuring journald
2022-12-08T17:53:59 ==> start: Setting up unbound
2022-12-08T17:53:59 ==> start: Adding systemd services
Synchronizing state of unbound.service with SysV service script with /lib/systemd/systemd-sysv-install.
Executing: /lib/systemd/systemd-sysv-install enable unbound
Synchronizing state of cron.service with SysV service script with /lib/systemd/systemd-sysv-install.
Executing: /lib/systemd/systemd-sysv-install enable cron
2022-12-08T17:54:18 ==> start: Configuring sudoers
2022-12-08T17:54:18 ==> start: Configuring collectd
2022-12-08T17:54:19 ==> start: Configuring sysctl
2022-12-08T17:54:19 ==> start: Configuring logrotate
2022-12-08T17:54:19 ==> start: Adding motd message for admins
2022-12-08T17:54:19 ==> start: Configuring nginx
2022-12-08T17:54:21 ==> start: Starting mysql
mysqladmin: [Warning] Using a password on the command line interface can be insecure.
Warning: Since password will be sent to server in plain text, use ssl connection to ensure password safety.
mysql: [Warning] Using a password on the command line interface can be insecure.
mysql: [Warning] Using a password on the command line interface can be insecure.
2022-12-08T17:54:21 ==> start: Migrating data
Ignoring invalid configuration option passed to Connection: driver. This is currently a warning, but in future versions of MySQL2, an error will be thrown if you pass an invalid configuration option to a Connection
[INFO] No migrations to run
[INFO] Done
2022-12-08T17:54:24 ==> start: Changing ownership
2022-12-08T17:54:24 ==> start: Starting Cloudron
2022-12-08T17:54:26 ==> start: Almost done

[girish]

@austin Can you check /home/yellowtent/platformdata/logs/box.log for any errors ?

[austin]

@girish This is the log content

  GNU nano 4.8                                                                        /home/yellowtent/platformdata/logs/box.log                                                                                   2022-12-01T00:00:09.664Z box:janitor cleanupTmpVolume ["/623d8050-f1fb-4b9b-a941-854eb58b53e8"]
2022-12-01T00:00:11.202Z box:janitor cleanupTmpVolume ["/107b7039-13cf-47b6-b522-1a0b1f01f458"]
2022-12-01T00:00:12.954Z box:apphealthmonitor app health: 7 alive / 0 dead.
2022-12-01T00:00:13.441Z box:janitor cleanupTmpVolume ["/redis-623d8050-f1fb-4b9b-a941-854eb58b53e8"]
2022-12-01T00:00:14.216Z box:janitor cleanupTmpVolume ["/redis-107b7039-13cf-47b6-b522-1a0b1f01f458"]
2022-12-01T00:00:15.217Z box:janitor cleanupTmpVolume ["/sftp"]
2022-12-01T00:00:16.114Z box:janitor cleanupTmpVolume ["/redis-94b48f7d-f8f8-4f9a-8210-adadc921da1d"]
2022-12-01T00:00:17.036Z box:janitor cleanupTmpVolume ["/mongodb"]
2022-12-01T00:00:18.504Z box:janitor cleanupTmpVolume ["/postgresql"]
2022-12-01T00:00:19.466Z box:janitor cleanupTmpVolume ["/graphite"]
2022-12-01T00:00:20.606Z box:janitor cleanupTmpVolume ["/mysql"]
2022-12-01T00:00:21.116Z box:apphealthmonitor app health: 7 alive / 0 dead.
2022-12-01T00:00:21.925Z box:janitor cleanupTmpVolume ["/turn"]
2022-12-01T00:00:23.741Z box:shell startTask (stdout): Finished with result: success
Main processes terminated with: code=exited/status=0
Service runtime: 21.574s

2022-12-01T00:00:23.747Z box:shell startTask (stdout): Service box-task-4484 finished with exit code 0

2022-12-01T00:00:23.758Z box:tasks startTask: 4484 completed with code 0 and signal 0
2022-12-01T00:00:23.766Z box:tasks startTask: 4484 done. error: null
2022-12-01T00:00:30.630Z box:apphealthmonitor app health: 7 alive / 0 dead.
2022-12-01T00:00:40.429Z box:apphealthmonitor app health: 7 alive / 0 dead.
2022-12-01T00:00:50.345Z box:apphealthmonitor app health: 7 alive / 0 dead.
2022-12-01T00:01:00.498Z box:apphealthmonitor app health: 7 alive / 0 dead.
2022-12-01T00:01:10.622Z box:apphealthmonitor app health: 7 alive / 0 dead.
2022-12-01T00:01:20.506Z box:apphealthmonitor app health: 7 alive / 0 dead.
2022-12-01T00:01:30.628Z box:apphealthmonitor app health: 7 alive / 0 dead.
2022-12-01T00:01:40.363Z box:apphealthmonitor app health: 7 alive / 0 dead.
2022-12-01T00:01:50.510Z box:apphealthmonitor app health: 7 alive / 0 dead.
2022-12-01T00:02:00.565Z box:apphealthmonitor app health: 7 alive / 0 dead.
2022-12-01T00:02:10.540Z box:apphealthmonitor app health: 7 alive / 0 dead.
2022-12-01T00:02:20.508Z box:apphealthmonitor app health: 7 alive / 0 dead.
2022-12-01T00:02:30.702Z box:apphealthmonitor app health: 7 alive / 0 dead.
2022-12-01T00:02:40.474Z box:apphealthmonitor app health: 7 alive / 0 dead.
2022-12-01T00:02:50.317Z box:apphealthmonitor app health: 7 alive / 0 dead.
2022-12-01T00:03:00.581Z box:apphealthmonitor app health: 7 alive / 0 dead.
2022-12-01T00:03:10.714Z box:apphealthmonitor app health: 7 alive / 0 dead.
2022-12-01T00:03:20.335Z box:apphealthmonitor app health: 7 alive / 0 dead.
2022-12-01T00:03:30.499Z box:apphealthmonitor app health: 7 alive / 0 dead.
2022-12-01T00:03:40.402Z box:apphealthmonitor app health: 7 alive / 0 dead.
2022-12-01T00:03:50.350Z box:apphealthmonitor app health: 7 alive / 0 dead.
2022-12-01T00:04:00.716Z box:apphealthmonitor app health: 7 alive / 0 dead.
2022-12-01T00:04:10.817Z box:apphealthmonitor app health: 7 alive / 0 dead.
2022-12-01T00:04:20.341Z box:apphealthmonitor app health: 7 alive / 0 dead.
2022-12-01T00:04:30.336Z box:apphealthmonitor app health: 7 alive / 0 dead.

[girish]

@austin These are old logs (from Dec 1), you have to go to the end of the file. You can write to support@cloudron.io , if you are not comfortable with linux .

[austin]

@girish Sorry, I've just copied the log today to this text file. Will delete it once you confirm that you have it downloaded.

https://drive.google.com/file/d/1lg6xGiDgTENp_iE8W_htz_ENWBYq5mui/view?usp=sharing

[girish]

@austin thanks, it seems mysql service is not starting properly. Can you try the steps in https://docs.cloudron.io/troubleshooting/#mysql-addon ?

2022-12-08T17:38:51.836Z box:shell startMysql (stderr): null
2022-12-08T17:38:51.837Z box:services Waiting for mysql
2022-12-08T17:38:52.003Z box:services Attempt 1 failed. Will retry: Network error waiting for mysql: connect ECONNREFUSED 172.18.0.3:3000
2022-12-08T17:39:07.372Z box:services Attempt 2 failed. Will retry: Network error waiting for mysql: connect ECONNREFUSED 172.18.0.3:3000
2022-12-08T17:39:22.402Z box:services Attempt 3 failed. Will retry: Network error waiting for mysql: connect ECONNREFUSED 172.18.0.3:3000
2022-12-08T17:39:37.415Z box:services Attempt 4 failed. Will retry: Network error waiting for mysql: connect ECONNREFUSED 172.18.0.3:3000
2022-12-08T17:39:52.517Z box:services Attempt 5 failed. Will retry: Network error waiting for mysql: connect ECONNREFUSED 172.18.0.3:3000
2022-12-08T17:40:07.532Z box:services Attempt 6 failed. Will retry: Network error waiting for mysql: connect ECONNREFUSED 172.18.0.3:3000
2022-12-08T17:40:22.545Z box:services Attempt 7 failed. Will retry: Network error waiting for mysql: connect ECONNREFUSED 172.18.0.3:3000
2022-12-08T17:40:37.562Z box:services Attempt 8 failed. Will retry: Network error waiting for mysql: connect ECONNREFUSED 172.18.0.3:3000
2022-12-08T17:40:52.579Z box:services Attempt 9 failed. Will retry: Network error waiting for mysql: connect ECONNREFUSED 172.18.0.3:3000
2022-12-08T17:41:07.594Z box:platform Failed to start services. retry=false (attempt 0): Network error waiting for mysql: connect ECONNREFUSED 172.18.0.3:3000
2022-12-08T17:41:07.595Z box:cloudron Startup task at index 2 failed: Network error waiting for mysql: connect ECONNREFUSED 172.18.0.3:3000 BoxError: Network error waiting for mysql: connect ECONNREFUSED 172.18.0.3:3000
    at /home/yellowtent/box/src/services.js:588:33
    at processTicksAndRejections (node:internal/process/task_queues:96:5)
    at async promiseRetry (/home/yellowtent/box/src/promise-retry.js:17:20)
    at async waitForContainer (/home/yellowtent/box/src/services.js:583:5)
    at async startMysql (/home/yellowtent/box/src/services.js:1150:9)
    at async Object.startServices (/home/yellowtent/box/src/services.js:806:9)
    at async Object.start (/home/yellowtent/box/src/platform.js:67:13)
    at async onActivated (/home/yellowtent/box/src/cloudron.js:79:5)
    at async Array.<anonymous> (/home/yellowtent/box/src/cloudron.js:130:9)
2022-12-08T17:43:12.795Z box:locker Lock unreleased platform_start

[austin]

@girish

This is the result

root@ssdnodes-60a8b3bcc2ffd:~# docker ps | grep mysql
4b762803fa94   cloudron/mysql:3.2.2   "/app/code/start.sh"   About an hour ago   Up 37 minutes                                                                                                                                                                                                                                                             mysql
root@ssdnodes-60a8b3bcc2ffd:~# docker exec -ti mysql /bin/bash
root@mysql:/# tail -f /tmp/mysqld.err
2022-12-08T18:30:36.602186Z 0 [Warning] [MY-010918] [Server] 'default_authentication_plugin' is deprecated and will be removed in a future release. Please use authentication_policy instead.
2022-12-08T18:30:36.602236Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.0.30-0ubuntu0.20.04.2) starting as process 12
2022-12-08T18:30:36.618876Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2022-12-08T18:30:38.859424Z 1 [ERROR] [MY-012526] [InnoDB] Upgrade is not supported after a crash or shutdown with innodb_fast_shutdown = 2. This redo log was created with MySQL 8.0.28, and it appears logically non empty. Please follow the instructions at http://dev.mysql.com/doc/refman/8.0/en/upgrading.html
2022-12-08T18:30:38.859512Z 1 [ERROR] [MY-012930] [InnoDB] Plugin initialization aborted with error Generic error.
2022-12-08T18:30:39.257841Z 1 [ERROR] [MY-010334] [Server] Failed to initialize DD Storage Engine
2022-12-08T18:30:39.258356Z 0 [ERROR] [MY-010020] [Server] Data Dictionary initialization failed.
2022-12-08T18:30:39.258404Z 0 [ERROR] [MY-010119] [Server] Aborting
2022-12-08T18:30:39.259625Z 0 [System] [MY-010910] [Server] /usr/sbin/mysqld: Shutdown complete (mysqld 8.0.30-0ubuntu0.20.04.2)  (Ubuntu).

^C

[girish]

@austin Can you try this:

First:

docker exec -ti mysql /bin/bash

Then (make sure you are in the container):

cd /var/lib/mysql
mv ib_logfile* /tmp
mkdir '#innodb_redo'
chown mysql:mysql #innodb_redo

Then, exit the shell (ctrl+D). Then,

docker restart mysql
docker logs -f mysql # check if it's saying running

If that worked, systemctl restart box and you should be back in sometime.

[austin]

@girish I restarted box 5 mins ago but still see this:

Also this is the code when I run it. Thank you.

root@ssdnodes-60a8b3bcc2ffd:~# docker exec -ti mysql /bin/bash
root@mysql:/# cd /var/lib/mysql
root@mysql:/var/lib/mysql# mv ib_logfile* /tmp
root@mysql:/var/lib/mysql# mkdir '#innodb_redo'
root@mysql:/var/lib/mysql# chown mysql:mysql #innodb_redo
chown: missing operand after 'mysql:mysql'
Try 'chown --help' for more information.
root@mysql:/var/lib/mysql# chown mysql:mysql '#innodb_redo'
root@mysql:/var/lib/mysql# exit
root@ssdnodes-60a8b3bcc2ffd:~# docker restart mysql
mysql
root@ssdnodes-60a8b3bcc2ffd:~# docker logs -f mysql
Detected existing installation
Resetting root password to 9d1cde56cab9fafc04f8822373d5a06c1ae4d040b198b4af8ddb67bab9225b74370c3676756b0e25a37501280f6b40cad5286020513df39748f1032ae87f31755145589167c75b9800a69922d208fcffbf8bf393bf8a5c1ba4581bbfce405e7efc751037078530abfcba966a65a85508b060fe5c505559ea0268cf1b128fec6f
Waiting with password
Waiting for MySQL to come up
Waiting for MySQL to come up
.......................
.......................
.......................
Waiting for MySQL to come up
Waiting for MySQL to come up
mysqladmin: [Warning] Using a password on the command line interface can be insecure.
Starting supervisor
2022-12-08 19:34:43,643 CRIT Supervisor is running as root.  Privileges were not dropped because no user is specified in the config file.  If you intend to run as root, you can set user=root in the config file to avoid this message.
2022-12-08 19:34:43,643 INFO Included extra file "/etc/supervisor/conf.d/mysql-service.conf" during parsing
2022-12-08 19:34:43,644 INFO Included extra file "/etc/supervisor/conf.d/mysql.conf" during parsing
2022-12-08 19:34:43,680 INFO RPC interface 'supervisor' initialized
2022-12-08 19:34:43,680 CRIT Server 'inet_http_server' running without any HTTP authentication checking
2022-12-08 19:34:43,680 INFO RPC interface 'supervisor' initialized
2022-12-08 19:34:43,681 CRIT Server 'unix_http_server' running without any HTTP authentication checking
2022-12-08 19:34:43,681 INFO supervisord started with pid 1
2022-12-08 19:34:44,686 INFO spawned: 'mysql' with pid 405
2022-12-08 19:34:44,690 INFO spawned: 'mysql-service' with pid 406
2022-12-08 19:34:45,919 INFO success: mysql entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2022-12-08 19:34:45,920 INFO success: mysql-service entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
MySQL service endpoint listening on http://:::3000
^C
root@ssdnodes-60a8b3bcc2ffd:~# systemctl restart box
root@ssdnodes-60a8b3bcc2ffd:~#

[austin]

You rock! They are configuring & starting now!

[privsec]

I got this one on of my cloudron installs and I just rebooted the server and that solved it.

Seems like something just needed to get "unstuck", but the issue was that the services were not starting properly.