Update to 4.1.0 [1.23.0] failed

[imc67]

A Matomo app on one of my Cloudrons failed to update, it stops during backup of mysqldump that stocked at 1955MB upload, but in the GUI you don't notice because just after it stops for a moment at 1955MB the app is restarting without an error.

In the Cloudron GUI there is no error message or whatever, I noticed after logging into Matomo that it wasn't updated. Could be that this (backup error?) is already there for a longer time?

The app had 8GB memory, I thought that might be too low so I increased it to 32GB but same issue.

Here is the log (somehow in a different order?!).

Jan 04 09:51:51 box:tasks 3197: {"percent":15,"message":"Backup - Uploading mysqldump: 1955M@69MBps (analytics.DOMAIN.TLD)"}
Jan 04 09:52:34 box:shell backup-snapshot/app_1a3d1f08-a28a-45e9-a950-fc794671478d code: null, signal: SIGKILL
Jan 04 09:52:34 box:apptask analytics.DOMAIN.TLD update aborted because backup failed { BoxError: Backuptask crashed
at /home/yellowtent/box/src/backups.js:872:29
at f (/home/yellowtent/box/node_modules/once/once.js:25:25)
at ChildProcess.<anonymous> (/home/yellowtent/box/src/shell.js:69:9)
at ChildProcess.emit (events.js:198:13)
at Process.ChildProcess._handle.onexit (internal/child_process.js:248:12)
name: 'BoxError',
reason: 'Internal Error',
details: {},
message: 'Backuptask crashed',
backupError: true }
Jan 04 09:52:35 box:apptask analytics.DOMAIN.TLD updating app with values: {"installationState":"installed","error":null,"health":null}
Jan 04 09:52:35 box:taskworker Task took 165.747 seconds
Jan 04 09:52:35 box:tasks setCompleted - 3197: {"result":null,"error":{"stack":"BoxError: Backuptask crashed\n at /home/yellowtent/box/src/backups.js:872:29\n at f (/home/yellowtent/box/node_modules/once/once.js:25:25)\n at ChildProcess.<anonymous> (/home/yellowtent/box/src/shell.js:69:9)\n at ChildProcess.emit (events.js:198:13)\n at Process.ChildProcess._handle.onexit (internal/child_process.js:248:12)","name":"BoxError","reason":"Internal Error","details":{},"message":"Backuptask crashed","backupError":true}}
Jan 04 09:52:35 box:tasks 3197: {"percent":100,"result":null,"error":{"stack":"BoxError: Backuptask crashed\n at /home/yellowtent/box/src/backups.js:872:29\n at f (/home/yellowtent/box/node_modules/once/once.js:25:25)\n at ChildProcess.<anonymous> (/home/yellowtent/box/src/shell.js:69:9)\n at ChildProcess.emit (events.js:198:13)\n at Process.ChildProcess._handle.onexit (internal/child_process.js:248:12)","name":"BoxError","reason":"Internal Error","details":{},"message":"Backuptask crashed","backupError":true}}
Jan 04 09:49:27 => Perform db migration
Jan 04 09:49:27
Jan 04 09:49:27 Everything is already up to date.
Jan 04 09:49:27
Jan 04 09:49:27 => Ensure database charset
Jan 04 09:49:28 ERROR [2021-01-04 08:49:28] 252 Uncaught exception: /app/code/vendor/symfony/console/Symfony/Component/Console/Application.php(549): Command "core:convert-to-utf8mb4" is not defined.
Jan 04 09:49:28
Jan 04 09:49:28 Did you mean one of these?
Jan 04 09:49:28 core:delete-logs-data
Jan 04 09:49:28 core:fix-duplicate-log-actions
Jan 04 09:49:28 core:invalidate-report-data
Jan 04 09:49:28 core:matomo4-migrate-token-auths
Jan 04 09:49:28 core:purge-old-archive-data
Jan 04 09:49:28 core:run-scheduled-tasks
Jan 04 09:49:28 core:update
Jan 04 09:49:28 core:clear-caches
Jan 04 09:49:28 core:archive
Jan 04 09:49:28 core:test-email
Jan 04 09:49:28 Command "core:convert-to-utf8mb4" is not defined.
Jan 04 09:49:28
Jan 04 09:49:28 Did you mean one of these?
Jan 04 09:49:28 core:delete-logs-data
Jan 04 09:49:28 core:fix-duplicate-log-actions
Jan 04 09:49:28 core:invalidate-report-data
Jan 04 09:49:28 core:matomo4-migrate-token-auths
Jan 04 09:49:28 core:purge-old-archive-data
Jan 04 09:49:28 core:run-scheduled-tasks
Jan 04 09:49:28 core:update
Jan 04 09:49:28 core:clear-caches
Jan 04 09:49:28 core:archive
Jan 04 09:49:28 core:test-email
Jan 04 09:49:28
Jan 04 09:49:28
Jan 04 09:49:28
Jan 04 09:49:28 [InvalidArgumentException]
Jan 04 09:49:28 Command "core:convert-to-utf8mb4" is not defined.
Jan 04 09:49:28 Did you mean one of these?
Jan 04 09:49:28 core:delete-logs-data
Jan 04 09:49:28 core:fix-duplicate-log-actions
Jan 04 09:49:28 core:invalidate-report-data
Jan 04 09:49:28 core:matomo4-migrate-token-auths
Jan 04 09:49:28 core:purge-old-archive-data
Jan 04 09:49:28 core:run-scheduled-tasks
Jan 04 09:49:28 core:update
Jan 04 09:49:28 core:clear-caches
Jan 04 09:49:28 core:archive
Jan 04 09:49:28 core:test-email

[nebulon]

A normal app update would trigger a backup before attempting to update. If that backup fails, then the update is not even attempted, which looks to be the case for you here.

Can you first check if there are any recent backups for that app made?

Also that seems like a huge mysqldump, I wonder if we miss some matomo db housekeeping cron job or so.

[imc67]

@nebulon it looks like there are backups, see screenshot.

Can you see in the log what happens just before the backup (in the log after the backup, see timestamps) also there it seems there is an error?

The dump might be so huge because this Matomo app is analyzing 3 sites of which one is a high traffic site.

[girish]

@imc67 It could be that it's the mysql service that doesn't have enough memory. Can you bump up the memory of mysql and try the update again?

BTW, the InvalidArgumentException in the logs is a separate bug and it's already fixed in the new package.

[imc67]

@girish MYSQL has 48GB memory of which roughly 10% occupied

[girish]

@imc67 So what you can do is to keep Services -> mysql -> logs open and then try to update. Do you then see any error in the mysql logs?

[imc67]

@girish just did what you suggested.

Logs from app:

Jan 04 16:41:34 box:tasks 3200: {"percent":15,"message":"Backup - Uploading mysqldump: 1882M@88MBps (analytics.domain.tld)"}
Jan 04 16:42:04 box:shell backup-snapshot/app_1a3d1f08-a28a-45e9-a950-fc794671478d (stdout): 2021-01-04T15:42:04.903Z box:backupupload process: rss: 385785856 heapTotal: 46919680 heapUsed: 32459480 external: 3893192338
Jan 04 16:42:04 box:shell backup-snapshot/app_1a3d1f08-a28a-45e9-a950-fc794671478d (stdout): 2021-01-04T15:42:04.905Z box:backupupload v8 heap : used 32462864 total: 46919680 max: 8769069275
Jan 04 16:42:19 box:shell backup-snapshot/app_1a3d1f08-a28a-45e9-a950-fc794671478d code: null, signal: SIGKILL
Jan 04 16:42:19 box:apptask analytics.domain.tld update aborted because backup failed { BoxError: Backuptask crashed
at /home/yellowtent/box/src/backups.js:872:29
at f (/home/yellowtent/box/node_modules/once/once.js:25:25)
at ChildProcess.<anonymous> (/home/yellowtent/box/src/shell.js:69:9)
at ChildProcess.emit (events.js:198:13)
at Process.ChildProcess._handle.onexit (internal/child_process.js:248:12)
name: 'BoxError',
reason: 'Internal Error',
details: {},
message: 'Backuptask crashed',
backupError: true }
Jan 04 16:42:19 box:apptask analytics.domain.tld updating app with values: {"installationState":"installed","error":null,"health":null}
Jan 04 16:42:19 box:taskworker Task took 172.781 seconds
Jan 04 16:42:19 box:tasks setCompleted - 3200: {"result":null,"error":{"stack":"BoxError: Backuptask crashed\n at /home/yellowtent/box/src/backups.js:872:29\n at f (/home/yellowtent/box/node_modules/once/once.js:25:25)\n at ChildProcess.<anonymous> (/home/yellowtent/box/src/shell.js:69:9)\n at ChildProcess.emit (events.js:198:13)\n at Process.ChildProcess._handle.onexit (internal/child_process.js:248:12)","name":"BoxError","reason":"Internal Error","details":{},"message":"Backuptask crashed","backupError":true}}
Jan 04 16:42:19 box:tasks 3200: {"percent":100,"result":null,"error":{"stack":"BoxError: Backuptask crashed\n at /home/yellowtent/box/src/backups.js:872:29\n at f (/home/yellowtent/box/node_modules/once/once.js:25:25)\n at ChildProcess.<anonymous> (/home/yellowtent/box/src/shell.js:69:9)\n at ChildProcess.emit (events.js:198:13)\n at Process.ChildProcess._handle.onexit (internal/child_process.js:248:12)","name":"BoxError","reason":"Internal Error","details":{},"message":"Backuptask crashed","backupError":true}}

In the meanwhile an open mysql log, no single log entry during the update, though regular warnings:

Jan 04 09:18:47
Jan 04 09:23:31 [POST] /databases/d5ea7447b3f5af8d/backup
Jan 04 09:23:31 backup: database d5ea7447b3f5af8d
Jan 04 09:23:31 Stderr from db import: mysqldump: [Warning] Using a password on the command line interface can be insecure.
Jan 04 09:23:31
Jan 04 09:27:42 [GET] /healthcheck
Jan 04 09:49:21 [POST] /databases
Jan 04 09:49:49 [POST] /databases/d5ea7447b3f5af8d/backup
Jan 04 09:49:49 backup: database d5ea7447b3f5af8d
Jan 04 09:49:49 Stderr from db import: mysqldump: [Warning] Using a password on the command line interface can be insecure.
Jan 04 09:49:49
Jan 04 16:16:24 [GET] /healthcheck
Jan 04 16:38:56 [GET] /healthcheck
Jan 04 16:39:26 [POST] /databases/d5ea7447b3f5af8d/backup
Jan 04 16:39:26 backup: database d5ea7447b3f5af8d
Jan 04 16:39:26 Stderr from db import: mysqldump: [Warning] Using a password on the command line interface can be insecure.
Jan 04 16:39:26

There is something realy strange, every time I try to update the app, my Zabbix monitoring on this Cloudron gets triggered by a low Swap, but here is more than enough memory:

[imc67]

@girish did you already found something?

[imc67]

@girish and @zjuhasz this issue and this one https://forum.cloudron.io/topic/4113/backup-failing-with-unspecified-error/7 is easily reproducible:

backup via rsync can't handle files > 2GB

1. As a test I uploaded a zip-file of 3,6GB into a Surfer app via Filemanager, that went fine.
2. Then I started a app backup and that crashed around 2GB

So, it looks like somehow backup via rsync doesn't handle files bigger than 2GB, in this Matomo case it's a mysql dump of > 2GB

The really bad thing is that there is no error in the GUI so now I'm wondering how many backups of all my apps might be defect?

[girish]

@imc67 Good detective work!

So, we found that the issue is because the memory limit settings are currently not set for "app task" processes but only for backup tasks. Should have this fixed for the next release.