Wekan fails to install with `error code 1 and signal null`

[ctrl]

Here we go:

Oct 28 16:13:57 box:apps downloading manifest from https://api.cloudron.io/api/v1/apps/io.wekan.cloudronapp/versions/4.5.3
Oct 28 16:13:57 box:apps Will install app with id : 188bcd35-b9f5-48c6-8e69-fbf51b61a422
Oct 28 16:13:58 box:locker Acquired : apptask
Oct 28 16:13:58 box:tasks startTask - starting task 4772. logs at /home/yellowtent/platformdata/logs/188bcd35-b9f5-48c6-8e69-fbf51b61a422/apptask.log
Oct 28 16:13:58 box:shell startTask spawn: /usr/bin/sudo -S -E /home/yellowtent/box/src/scripts/starttask.sh 4772 /home/yellowtent/platformdata/logs/188bcd35-b9f5-48c6-8e69-fbf51b61a422/apptask.log 15 400
Oct 28 16:13:58 box:shell startTask (stdout): Running as unit box-task-4772.service.
Oct 28 16:14:00 box:apphealthmonitor app health: 8 alive / 1 dead.
GET /api/v1/tasks/4772 403 Forbidden role 'admin' is required but user has only 'user' 3.308 ms - 93
Oct 28 16:14:01 box:shell startTask (stdout): Waiting for service box-task-4772 to finish
Oct 28 16:14:04 box:shell startTask (stdout): Waiting for service box-task-4772 to finish
GET /api/v1/tasks/4772 403 Forbidden role 'admin' is required but user has only 'user' 6.076 ms - 93
Oct 28 16:14:07 box:shell startTask (stdout): Waiting for service box-task-4772 to finish
Oct 28 16:14:10 box:shell startTask (stdout): Waiting for service box-task-4772 to finish
Oct 28 16:14:10 box:apphealthmonitor app health: 8 alive / 1 dead.
GET /api/v1/tasks/4772 403 Forbidden role 'admin' is required but user has only 'user' 2.435 ms - 93
Oct 28 16:14:13 box:shell startTask (stdout): Waiting for service box-task-4772 to finish
GET /api/v1/tasks/4772 403 Forbidden role 'admin' is required but user has only 'user' 2.482 ms - 93
Oct 28 16:14:16 box:shell startTask (stdout): Waiting for service box-task-4772 to finish
Oct 28 16:14:19 box:shell startTask (stdout): Waiting for service box-task-4772 to finish
GET /api/v1/tasks/4772 403 Forbidden role 'admin' is required but user has only 'user' 5.728 ms - 93
Oct 28 16:14:21 box:apphealthmonitor app health: 8 alive / 1 dead.
Oct 28 16:14:22 box:shell startTask (stdout): Waiting for service box-task-4772 to finish
Oct 28 16:14:25 box:shell startTask (stdout): Waiting for service box-task-4772 to finish
GET /api/v1/tasks/4772 403 Forbidden role 'admin' is required but user has only 'user' 2.457 ms - 93
Oct 28 16:14:28 box:shell startTask (stdout): Waiting for service box-task-4772 to finish
Oct 28 16:14:30 box:apphealthmonitor app health: 8 alive / 1 dead.
GET /api/v1/tasks/4772 403 Forbidden role 'admin' is required but user has only 'user' 6.272 ms - 93
Oct 28 16:14:31 box:shell startTask (stdout): Waiting for service box-task-4772 to finish
Oct 28 16:14:34 box:shell startTask (stdout): Service box-task-4772 finished with exit code 1
Oct 28 16:14:34 box:shell startTask code: 1, signal: null
Oct 28 16:14:34 box:tasks startTask: 4772 completed with code 1 and signal null
Oct 28 16:14:34 box:tasks setCompleted - 4772: {"error":{"message":"Task 4772 crashed with code 1 and signal null","code":"crashed"}}
Oct 28 16:14:34 box:tasks 4772: {"percent":100,"error":{"message":"Task 4772 crashed with code 1 and signal null","code":"crashed"}}
Oct 28 16:14:34 box:apps scheduleTask: task 4772 of 188bcd35-b9f5-48c6-8e69-fbf51b61a422 completed
Oct 28 16:14:34 box:apps Apptask crashed/stopped: Task 4772 crashed with code 1 and signal null
Oct 28 16:14:34 box:locker Released : apptask
Oct 28 16:14:34 box:sftp rebuilding container
Oct 28 16:14:34 box:tasks startTask: 4772 done
Oct 28 16:14:34 box:sftp Ignoring volume for 188bcd35-b9f5-48c6-8e69-fbf51b61a422 since it does not exist
Oct 28 16:14:34 box:shell inspectSftp exec: docker inspect --format="{{json .Mounts }}" sftp
Oct 28 16:14:35 box:shell inspectSftp (stdout): [{"Type":"volume","Name":"dae45d5a3c3276751d66e0049375c71e45e80a5af05fb6884ac3b53c9511632f","Source":"/var/lib/docker/volumes/dae45d5a3c3276751d66e0049375c71e45e80a5af05fb6884ac3b53c9511632f/_data","Destination":"/run","Driver":"local","Mode":"","RW":true,"Propagation":""},{"Type":"volume","Name":"3f03d0438ec00bd7124eb37444aae893cde7058389e7bc457da7e3a51b9d3365","Source":"/var/lib/docker/volumes/3f03d0438ec00bd7124eb37444aae893cde7058389e7bc457da7e3a51b9d3365/_data","Destination":"/tmp","Driver":"local","Mode":"","RW":true,"Propagation":""},{"Type":"bind","Source":"/etc/ssh","Destination":"/etc/ssh","Mode":"ro","RW":false,"Propagation":"rprivate"},{"Type":"bind","Source":"/home/yellowtent/appsdata/5d397a2e-3fb2-43b3-b2b8-d50a862c5425/data","Destination":"/app/data/5d397a2e-3fb2-43b3-b2b8-d50a862c5425","Mode":"","RW":true,"Propagation":"rprivate"},{"Type":"bind","Source":"/mnt/data/app.kimai","Destination":"/app/data/d959db68-da8d-458c-abbb-c5f2ac3a04e9","Mode":"","RW":true,"Propagation":"rprivate"},{"Type":"bind","Source":"/mnt/data/app.nextcloud","Destination":"/app/data/47927a8f-015f-4acb-9b0a-010d2fd7826b","Mode":"","RW":true,"Propagation":"rprivate"},{"Type":"bind","Source":"/mnt/data/app.nodebb","Destination":"/app/data/9fcde755-6cbe-476b-897a-8bd359a7f369","Mode":"","RW":true,"Propagation":"rprivate"},{"Type":"bind","Source":"/mnt/data/app.syncthing","Destination":"/app/data/52bb70d6-028a-41c5-998d-8f22e1da070b","Mode":"","RW":true,"Propagation":"rprivate"},{"Type":"bind","Source":"/mnt/data/app.wiki-js","Destination":"/app/data/6f421917-b4a0-468b-9144-4a712bfbaacd","Mode":"","RW":true,"Propagation":"rprivate"},{"Type":"bind","Source":"/mnt/data/app.mattermost","Destination":"/app/data/4b895931-6502-4d14-a60d-57855c113bfc","Mode":"","RW":true,"Propagation":"rprivate"},{"Type":"bind","Source":"/mnt/data/app.gitea","Destination":"/app/data/85aa8413-01e6-4f7a-97a0-747e4947bb1a","Mode":"","RW":true,"Propagation":"rprivate"}]
Oct 28 16:14:35 box:shell inspectSftp (stderr):
Oct 28 16:14:35 box:sftp Skipping rebuild, no changes
Oct 28 16:14:40 box:apphealthmonitor app health: 8 alive / 1 dead.

This one looks quite suspicious:

 GET /api/v1/tasks/4772 403 Forbidden role 'admin' is required but user has only 'user' 3.308 ms - 93

[nebulon]

Ok so the app task did indeed crash. Now hopefully we can find that crash in journalctl --system somewhere

Sorry that since some Cloudron releases the crash logs are a bit all over the place until the next.

The other issue is interesting, but I don't think related. Is is possible that some non admin user has the dashboard open? Maybe there is a bug where it tries to show progress?

[ctrl]

@nebulon said in Wekan fails to install with `error code 1 and signal null`:

Ok so the app task did indeed crash. Now hopefully we can find that crash in journalctl --system somewhere

Do you have any keyword in mind? ^^ box-task-4772 maybe?

The other issue is interesting, but I don't think related. Is is possible that some non admin user has the dashboard open? Maybe there is a bug where it tries to show progress?

No, we just double checked. I'm the only user being logged in currently.

Edit:

Oct 28 16:18:48 example.tld systemd[1]: Started /home/yellowtent/box/src/scripts/../taskworker.js 4773 /home/yellowtent/platformdata/logs/188bcd35-b9f5-48c6-8e69-fbf51b6
Oct 28 16:18:50 example.tld sudo[15881]: pam_unix(sudo:session): session opened for user root by (uid=0)
Oct 28 16:18:50 example.tld sudo[15881]: pam_unix(sudo:session): session closed for user root
Oct 28 16:18:50 example.tld sudo[15885]: pam_unix(sudo:session): session opened for user root by (uid=0)
Oct 28 16:18:50 example.tld systemd[1]: Stopping Statistics collection and monitoring daemon...
Oct 28 16:18:50 example.tld systemd[1]: Stopped Statistics collection and monitoring daemon.
Oct 28 16:18:50 example.tld systemd[1]: Starting Statistics collection and monitoring daemon...
Oct 28 16:18:50 example.tld systemd[1]: Started Statistics collection and monitoring daemon.
Oct 28 16:18:50 example.tld sudo[15885]: pam_unix(sudo:session): session closed for user root
Oct 28 16:18:50 example.tld sudo[15900]: pam_unix(sudo:session): session opened for user root by (uid=0)
Oct 28 16:18:50 example.tld sudo[15900]: pam_unix(sudo:session): session closed for user root
Oct 28 16:18:51 example.tld collectd[15894]: du: cannot access '/mnt/data/47927a8f-015f-4acb-9b0a-010d2fd7826b': No such file or directory
Oct 28 16:18:51 example.tld collectd[15894]: du: cannot access '/home/yellowtent/appsdata/4b895931-6502-4d14-a60d-57855c113bfc/data': No such file or directory
Oct 28 16:18:51 example.tld collectd[15894]: du: cannot access '/home/yellowtent/appsdata/52bb70d6-028a-41c5-998d-8f22e1da070b/data': No such file or directory
Oct 28 16:18:51 example.tld collectd[15894]: du: cannot access '/home/yellowtent/appsdata/6f421917-b4a0-468b-9144-4a712bfbaacd/data': No such file or directory
Oct 28 16:18:51 example.tld collectd[15894]: du: cannot access '/home/yellowtent/appsdata/85aa8413-01e6-4f7a-97a0-747e4947bb1a/data': No such file or directory
Oct 28 16:18:51 example.tld collectd[15894]: du: cannot access '/home/yellowtent/appsdata/9fcde755-6cbe-476b-897a-8bd359a7f369/data': No such file or directory
Oct 28 16:18:54 example.tld systemd[1]: Stopped /home/yellowtent/box/src/scripts/../taskworker.js 4773 /home/yellowtent/platformdata/logs/188bcd35-b9f5-48c6-8e69-fbf51b6

These entries correspond to the time of the last installation process.

[nebulon]

The task id might not be there, maybe try to match the timestamps or run journalctl -f --system as root while retrying the installation.

[nebulon]

Hm ok, this does not reveal much. Maybe it is the issue of running low on disk space. Docker images tend to be quite large and wekan is meteor which pulls in a lot of stuff. Can you see anything in the journalctl -u docker logs?

[ctrl]

@nebulon
I just let the installation run again while watching the live journal.

root@my ~ # journalctl -f --system
-- Logs begin at Tue 2020-10-27 13:39:17 CET. --
Oct 28 16:39:38 example.tld sudo[17170]: pam_unix(sudo:session): session opened for user root by (uid=0)
Oct 28 16:39:38 example.tld systemd[1]: Started /home/yellowtent/box/src/scripts/../taskworker.js 4774 /home/yellowtent/platformdata/logs/c57bf1ee-74f7-4de9-a407-c2159030a94a/apptask.log.
Oct 28 16:39:39 example.tld sudo[17194]: pam_unix(sudo:session): session opened for user root by (uid=0)
Oct 28 16:39:39 example.tld sudo[17194]: pam_unix(sudo:session): session closed for user root
Oct 28 16:39:39 example.tld sudo[17197]: pam_unix(sudo:session): session opened for user root by (uid=0)
Oct 28 16:39:39 example.tld systemd[1]: Stopping Statistics collection and monitoring daemon...
Oct 28 16:39:39 example.tld systemd[1]: Stopped Statistics collection and monitoring daemon.
Oct 28 16:39:39 example.tld systemd[1]: Starting Statistics collection and monitoring daemon...
Oct 28 16:39:39 example.tld systemd[1]: Started Statistics collection and monitoring daemon.
Oct 28 16:39:39 example.tld sudo[17197]: pam_unix(sudo:session): session closed for user root
Oct 28 16:39:39 example.tld sudo[17211]: pam_unix(sudo:session): session opened for user root by (uid=0)
Oct 28 16:39:39 example.tld sudo[17211]: pam_unix(sudo:session): session closed for user root
Oct 28 16:39:40 example.tld collectd[17206]: du: cannot access '/mnt/data/47927a8f-015f-4acb-9b0a-010d2fd7826b': No such file or directory
Oct 28 16:39:40 example.tld collectd[17206]: du: cannot access '/home/yellowtent/appsdata/4b895931-6502-4d14-a60d-57855c113bfc/data': No such file or directory
Oct 28 16:39:40 example.tld collectd[17206]: du: cannot access '/home/yellowtent/appsdata/52bb70d6-028a-41c5-998d-8f22e1da070b/data': No such file or directory
Oct 28 16:39:40 example.tld collectd[17206]: du: cannot access '/home/yellowtent/appsdata/6f421917-b4a0-468b-9144-4a712bfbaacd/data': No such file or directory
Oct 28 16:39:40 example.tld collectd[17206]: du: cannot access '/home/yellowtent/appsdata/85aa8413-01e6-4f7a-97a0-747e4947bb1a/data': No such file or directory
Oct 28 16:39:40 example.tld collectd[17206]: du: cannot access '/home/yellowtent/appsdata/9fcde755-6cbe-476b-897a-8bd359a7f369/data': No such file or directory
Oct 28 16:39:43 example.tld collectd[17206]: du: cannot access '/home/yellowtent/appsdata/d959db68-da8d-458c-abbb-c5f2ac3a04e9/data': No such file or directory
Oct 28 16:40:20 example.tld systemd[1]: box-task-4774.service: Main process exited, code=exited, status=1/FAILURE
Oct 28 16:40:20 example.tld systemd[1]: Stopped /home/yellowtent/box/src/scripts/../taskworker.js 4774 /home/yellowtent/platformdata/logs/c57bf1ee-74f7-4de9-a407-c2159030a94a/apptask.log.
Oct 28 16:40:20 example.tld systemd[1]: box-task-4774.service: Unit entered failed state.
Oct 28 16:40:20 example.tld systemd[1]: box-task-4774.service: Failed with result 'exit-code'.
Oct 28 16:40:20 example.tld sudo[17170]: pam_unix(sudo:session): session closed for user root
Oct 28 16:40:20 example.tld dockerd[1559]: time="2020-10-28T16:40:20.853986218+01:00" level=error msg="Not continuing with pull after error: context canceled"

[ctrl]

@nebulon said in Wekan fails to install with `error code 1 and signal null`:

Hm ok, this does not reveal much. Maybe it is the issue of running low on disk space. Docker images tend to be quite large and wekan is meteor which pulls in a lot of stuff. Can you see anything in the journalctl -u docker logs?

This seems to be the only error:

Oct 28 16:40:20 example.tld dockerd[1559]: time="2020-10-28T16:40:20.853986218+01:00" level=error msg="Not continuing with pull after error: context canceled"

EDIT:
For testing purposes I could move the docker images onto an external volume tomorrow and report back afterwards.
Could you please confirm if this guide is still valid?

[nebulon]

Yes those docs are still valid and is a good idea here for testing.

[girish]

Out of curiosity, does this happen with other apps as well or just Wekan? The "Not continuing with pull after..." implies some docker error. Does docker pull cloudron/io.wekan.cloudronapp:20201021-004852-015f556b1 work on the server ?

[ctrl]

@girish
There were no issues installing other apps inbetween.
I just did a manual pull on the shell as you proposed:

docker pull cloudron/io.wekan.cloudronapp:20201021-004852-015f556b1
20201021-004852-015f556b1: Pulling from cloudron/io.wekan.cloudronapp
5bed26d33875: Already exists
f11b29a9c730: Already exists
930bda195c84: Already exists
78bf9a5ad49e: Already exists
5fb75e41baf0: Already exists
a6f85a52927e: Already exists
20e214459d60: Already exists
d461f640523d: Already exists
98b7bf60a788: Already exists
36a830325af0: Already exists
3d36b087c419: Already exists
52bb0e0c6e5f: Already exists
fb9616b4c1c8: Already exists
7db4c0654238: Pull complete
5a35c3fdb427: Pull complete
d3a7ee1355ea: Pull complete
382c963fb47c: Pull complete
211ee9d4324e: Pull complete
8912dece76ee: Extracting [==================================================>]  123.6MB/123.6MB
09a34c31c952: Download complete
52acd38c73b9: Download complete
8f94e8eda951: Download complete
e4ab3fb5c557: Download complete
failed to register layer: Error processing tar file(exit status 1): write /home/cloudron/.meteor/package-metadata/v2.0.1/packages.data.db: no space left on device
root@my ~ # df -h /
Filesystem      Size  Used Avail Use% Mounted on
/dev/sda1        19G   17G  1.3G  93% /

Looks like the available space is not sufficient. But as I said earlier, not even ~2.8G seem to be enough. Do you have an estimate how much it requires approx.?

[nebulon]

I think wekan is really some outlier here, we may have to improve the package for it to consume less space, but I am just preparing a new wekan release and saw that there were at least two layers one 1Gb and another close to 3Gb for that image!

[ctrl]

@nebulon
Ok I see. Thank you very much for the clarification! ^^
I'm going to move the image location to an external volume for the time being.

It looks like the last docker pull command of the previous test ate some space. Could you guys please tell me how I would clean up the remaining cruft?

EDIT:
Reporting back that it was installed successfully after changing the image location to an external volume offering enough disk space.