Container fails to start - openbox/novnc exiting with errors

[realies]

Container fails to start - openbox/novnc exiting with errors

[realies]

@dillonbck, @TheMrRandomDude, @jamesblonde007, can you please test the latest build?

[themana]

I was also having an issue with NoVNC crashing and after reading @TheMrRandomDude I added the security_opt unconfined to my configuration and it seemed to fix my problem.

For anyone using docker-compose or portainer add the section below to set the security_opt to unconfined

security_opt:
  - seccomp:unconfined

[TheMrRandomDude]

Same exact issue here.

[realies]

Thanks for the issue report, I assume there's incompatibility with the latest docker base image or there is still some caching happening. Will investigate further when I find some time soon.

[jamesblonde007]

When I try the install via the Synology UI, I add all the settings then at the final step I get a "Docker API failed" message. Might be the same issue?

[TheMrRandomDude]

Thanks for the issue report, I assume there's incompatibility with the latest docker base image or there is still some caching happening. Will investigate further when I find some time soon.

@realies No problem, thank you. I'm running unraid by the way, I saw on forums that running the container in privileged mode would fix it, but i'm worried if a security flaw is found in soulseek, then the container itself it wouldn't isolate the system properly if privilege is on, thus posing a huge security risk.

[TheMrRandomDude]

@dillonbck, @TheMrRandomDude, @jamesblonde007, can you please test the latest build?

Hi @realies Thank you for the build. Sadly, still same issue it seems:

2022-10-21 19:03:54,772 INFO Set uid to user 0 succeeded
2022-10-21 19:03:54,775 INFO supervisord started with pid 1
2022-10-21 19:03:55,779 INFO spawned: 'tigervnc' with pid 13
2022-10-21 19:03:55,782 INFO spawned: 'openbox' with pid 14
2022-10-21 19:03:55,785 INFO spawned: 'novnc' with pid 15
2022-10-21 19:03:55,787 INFO spawned: 'soulseek' with pid 16
2022-10-21 19:03:55,815 INFO exited: novnc (exit status 1; not expected)
2022-10-21 19:03:56,056 INFO exited: openbox (terminated by SIGABRT; not expected)
2022-10-21 19:03:57,057 INFO success: tigervnc entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2022-10-21 19:03:57,059 INFO spawned: 'openbox' with pid 26
2022-10-21 19:03:57,061 INFO spawned: 'novnc' with pid 27
2022-10-21 19:03:57,062 INFO success: soulseek entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2022-10-21 19:03:57,080 INFO exited: novnc (exit status 1; not expected)
2022-10-21 19:03:57,102 INFO exited: openbox (terminated by SIGABRT; not expected)
2022-10-21 19:03:59,107 INFO spawned: 'openbox' with pid 35
2022-10-21 19:03:59,110 INFO spawned: 'novnc' with pid 36
2022-10-21 19:03:59,130 INFO exited: novnc (exit status 1; not expected)
2022-10-21 19:03:59,151 INFO exited: openbox (terminated by SIGABRT; not expected)
2022-10-21 19:04:02,156 INFO spawned: 'openbox' with pid 44
2022-10-21 19:04:02,159 INFO spawned: 'novnc' with pid 45
2022-10-21 19:04:02,180 INFO exited: novnc (exit status 1; not expected)
2022-10-21 19:04:02,181 INFO gave up: novnc entered FATAL state, too many start retries too quickly
2022-10-21 19:04:02,202 INFO exited: openbox (terminated by SIGABRT; not expected)
2022-10-21 19:04:03,203 INFO gave up: openbox entered FATAL state, too many start retries too quickly

[realies]

@TheMrRandomDude, can you please try and report the output of the following commands:

docker exec -it soulseek bash
/usr/share/novnc/utils/novnc_proxy --listen 8080

[dillonbck]

Here is what I get back after running those commands:

user@server:~$ docker exec -it soulseek bash
root@fb4078f2c1a8:/# /usr/share/novnc/utils/novnc_proxy --listen 8080
Warning: could not find self.pem
The path /usr/share/novnc/utils/websockify exists, but /usr/share/novnc/utils/websockify/run either does not exist or is not executable.
If you intended to use an installed websockify package, please remove /usr/share/novnc/utils/websockify.

[TheMrRandomDude]

@TheMrRandomDude, can you please try and report the output of the following commands:

@realies I get same output as @dillonbck

./novnc_proxy --listen 8080
Warning: could not find self.pem
The path /usr/share/novnc/utils/websockify exists, but /usr/share/novnc/utils/websockify/run either does not exist or is not executable.
If you intended to use an installed websockify package, please remove /usr/share/novnc/utils/websockify.

I tested if /usr/share/novnc/utils/websockify/run exists and is executable, it is.

./run
/usr/share/novnc/utils/websockify/websockify/websocket.py:31: UserWarning: no 'numpy' module, HyBi protocol will be slower
warnings.warn("no 'numpy' module, HyBi protocol will be slower")
Usage:
main.py [options] [source_addr:]source_port [target_addr:target_port]
main.py [options] --token-plugin=CLASS [source_addr:]source_port
main.py [options] --unix-target=FILE [source_addr:]source_port
main.py [options] [source_addr:]source_port -- WRAP_COMMAND_LINE

main.py: error: Too few arguments

Is self.pem missing an issue? Since it's just a warning.

[realies]

@TheMrRandomDude, don't think it's the missing self.pem file. Over here, the output using the latest image on unRAID without privileged mode looks like this:

# docker exec -it soulseek bash
root@11b93d0a8a55:/# /usr/share/novnc/utils/novnc_proxy --listen 8080
Warning: could not find self.pem
Using local websockify at /usr/share/novnc/utils/websockify/run
Starting webserver and WebSockets proxy on port 8080
/usr/share/novnc/utils/websockify/websockify/websocket.py:31: UserWarning: no 'numpy' module, HyBi protocol will be slower
  warnings.warn("no 'numpy' module, HyBi protocol will be slower")
WebSocket server settings:
  - Listen on :8080
  - Web server. Web root: /usr/share/novnc
  - No SSL/TLS support (no cert file)
  - proxying from :8080 to localhost:5900


Navigate to this URL:

    http://11b93d0a8a55:8080/vnc.html?host=11b93d0a8a55&port=8080

Press Ctrl-C to exit

[TheMrRandomDude]

@TheMrRandomDude, don't think it's the missing self.pem file. Over here, the output using the latest image on unRAID without privileged mode looks like this:

# docker exec -it soulseek bash
root@11b93d0a8a55:/# /usr/share/novnc/utils/novnc_proxy --listen 8080
Warning: could not find self.pem
Using local websockify at /usr/share/novnc/utils/websockify/run
Starting webserver and WebSockets proxy on port 8080
/usr/share/novnc/utils/websockify/websockify/websocket.py:31: UserWarning: no 'numpy' module, HyBi protocol will be slower
  warnings.warn("no 'numpy' module, HyBi protocol will be slower")
WebSocket server settings:
  - Listen on :8080
  - Web server. Web root: /usr/share/novnc
  - No SSL/TLS support (no cert file)
  - proxying from :8080 to localhost:5900


Navigate to this URL:

    http://11b93d0a8a55:8080/vnc.html?host=11b93d0a8a55&port=8080

Press Ctrl-C to exit

Hi. @realies I'm happy to see it works for you. I fixed the novnc_proxy by modifying the novnc_proxy script to execute from absolute path rather than relative one. Now I have the same output as you above. Howeer, the container is sitll having issues it seems. Now the following thing happens:

2022-10-22 14:57:37,824 INFO Set uid to user 0 succeeded
2022-10-22 14:57:37,827 INFO supervisord started with pid 1
2022-10-22 14:57:38,831 INFO spawned: 'tigervnc' with pid 13
2022-10-22 14:57:38,834 INFO spawned: 'openbox' with pid 14
2022-10-22 14:57:38,836 INFO spawned: 'novnc' with pid 15
2022-10-22 14:57:38,838 INFO spawned: 'soulseek' with pid 16
2022-10-22 14:57:38,931 INFO exited: novnc (exit status 1; not expected)
2022-10-22 14:57:39,211 INFO exited: openbox (terminated by SIGABRT; not expected)
2022-10-22 14:57:40,212 INFO success: tigervnc entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2022-10-22 14:57:40,214 INFO spawned: 'openbox' with pid 26
2022-10-22 14:57:40,217 INFO spawned: 'novnc' with pid 27
2022-10-22 14:57:40,218 INFO success: soulseek entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2022-10-22 14:57:40,237 INFO exited: novnc (exit status 1; not expected)
2022-10-22 14:57:40,258 INFO exited: openbox (terminated by SIGABRT; not expected)
2022-10-22 14:57:42,262 INFO spawned: 'openbox' with pid 35
2022-10-22 14:57:42,265 INFO spawned: 'novnc' with pid 36
2022-10-22 14:57:42,283 INFO exited: novnc (exit status 1; not expected)
2022-10-22 14:57:42,304 INFO exited: openbox (terminated by SIGABRT; not expected)
2022-10-22 14:57:45,310 INFO spawned: 'openbox' with pid 44
2022-10-22 14:57:45,312 INFO spawned: 'novnc' with pid 45
2022-10-22 14:57:45,331 INFO exited: novnc (exit status 1; not expected)
2022-10-22 14:57:45,332 INFO gave up: novnc entered FATAL state, too many start retries too quickly
2022-10-22 14:57:45,352 INFO exited: openbox (terminated by SIGABRT; not expected)
2022-10-22 14:57:46,354 INFO gave up: openbox entered FATAL state, too many start retries too quickly
2022-10-22 17:31:44,956 INFO reaped unknown pid 1314 (exit status 0)
2022-10-22 17:31:59,975 INFO reaped unknown pid 1328 (exit status 0)
2022-10-22 17:32:45,028 INFO reaped unknown pid 1361 (exit status 0)
2022-10-22 17:38:37,453 INFO reaped unknown pid 1387 (exit status 0)
2022-10-22 17:39:04,486 WARN received SIGTERM indicating exit request
2022-10-22 17:39:04,487 INFO waiting for tigervnc, soulseek to die
2022-10-22 17:39:04,490 INFO stopped: soulseek (terminated by SIGTERM)
2022-10-22 17:39:06,503 INFO stopped: tigervnc (exit status 0)
2022-10-22 17:39:17,892 INFO Set uid to user 0 succeeded
2022-10-22 17:39:17,896 INFO supervisord started with pid 1
2022-10-22 17:39:18,900 INFO spawned: 'tigervnc' with pid 10
2022-10-22 17:39:18,902 INFO spawned: 'openbox' with pid 11
2022-10-22 17:39:18,904 INFO spawned: 'novnc' with pid 12
2022-10-22 17:39:18,907 INFO spawned: 'soulseek' with pid 13
2022-10-22 17:39:18,913 INFO exited: novnc (exit status 127; not expected)
2022-10-22 17:39:19,010 INFO exited: openbox (terminated by SIGABRT; not expected)
2022-10-22 17:39:20,011 INFO success: tigervnc entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2022-10-22 17:39:20,013 INFO spawned: 'openbox' with pid 16
2022-10-22 17:39:20,014 INFO spawned: 'novnc' with pid 17
2022-10-22 17:39:20,015 INFO success: soulseek entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2022-10-22 17:39:20,021 INFO exited: novnc (exit status 127; not expected)
2022-10-22 17:39:20,061 INFO exited: openbox (terminated by SIGABRT; not expected)
2022-10-22 17:39:22,066 INFO spawned: 'openbox' with pid 18
2022-10-22 17:39:22,069 INFO spawned: 'novnc' with pid 19
2022-10-22 17:39:22,079 INFO exited: novnc (exit status 127; not expected)
2022-10-22 17:39:22,108 INFO exited: openbox (terminated by SIGABRT; not expected)
2022-10-22 17:39:25,112 INFO spawned: 'openbox' with pid 20
2022-10-22 17:39:25,114 INFO spawned: 'novnc' with pid 21
2022-10-22 17:39:25,120 INFO exited: novnc (exit status 127; not expected)
2022-10-22 17:39:25,153 INFO gave up: novnc entered FATAL state, too many start retries too quickly
2022-10-22 17:39:25,154 INFO exited: openbox (terminated by SIGABRT; not expected)
2022-10-22 17:39:26,156 INFO gave up: openbox entered FATAL state, too many start retries too quickly
2022-10-22 17:40:28,229 INFO reaped unknown pid 39 (exit status 0)
2022-10-22 17:41:50,322 INFO reaped unknown pid 53 (exit status 0)
2022-10-22 17:47:49,728 INFO reaped unknown pid 89 (exit status 0)
2022-10-22 17:47:55,735 WARN received SIGTERM indicating exit request
2022-10-22 17:47:55,735 INFO waiting for tigervnc, soulseek to die
2022-10-22 17:47:55,738 INFO stopped: soulseek (terminated by SIGTERM)
2022-10-22 17:47:57,751 INFO stopped: tigervnc (exit status 0)
2022-10-22 17:48:02,577 INFO Set uid to user 0 succeeded
2022-10-22 17:48:02,579 INFO supervisord started with pid 1
2022-10-22 17:48:03,584 INFO spawned: 'tigervnc' with pid 10
2022-10-22 17:48:03,587 INFO spawned: 'openbox' with pid 11
2022-10-22 17:48:03,590 INFO spawned: 'novnc' with pid 12
2022-10-22 17:48:03,592 INFO spawned: 'soulseek' with pid 13
2022-10-22 17:48:03,677 INFO exited: openbox (terminated by SIGABRT; not expected)
2022-10-22 17:48:04,612 INFO success: tigervnc entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2022-10-22 17:48:04,613 INFO success: novnc entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2022-10-22 17:48:04,613 INFO success: soulseek entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2022-10-22 17:48:05,620 INFO spawned: 'openbox' with pid 29
2022-10-22 17:48:05,665 INFO exited: openbox (terminated by SIGABRT; not expected)
2022-10-22 17:48:07,670 INFO spawned: 'openbox' with pid 30
2022-10-22 17:48:07,711 INFO exited: openbox (terminated by SIGABRT; not expected)
2022-10-22 17:48:10,716 INFO spawned: 'openbox' with pid 31
2022-10-22 17:48:10,752 INFO exited: openbox (terminated by SIGABRT; not expected)
2022-10-22 17:48:11,754 INFO gave up: openbox entered FATAL state, too many start retries too quickly

So I have a question, where does the container start initializing everything? Spawning the openbox etc. I tried to look at dmesg - dmesg disabled (no permission). I tried looking for cron file or crontab, not there either, I also looked at systemctl, it's also unavalible. What spawns openbox and when, and is there anything before it?

Edit no.1 09.35UTC: Just realized the docker inspect is a thing, found the entrypoint at /init.sh; going to see if I can access dmesg or logs anywhere to see why is the "2022-10-22 14:57:38,931 INFO exited: novnc (exit status 1; not expected)" happening
Edit no.2 09:39UTC: Okay, found the stderr and stdout logs in /tmp/, going to check them out now and see what I can figure out.
Edit no.3 09:49 UTC: Okay, the issue seems to be this:

cat openbox-stderr---supervisor-x78hrmxc.log

(openbox:11): GLib-ERROR **: 17:48:03.676: file ../../../glib/gthread-posix.c: line 1339 (g_system_thread_new): error 'Operation not permitted' during 'pthread_create'
How are you gentlemen? All your base are belong to us. (Openbox received signal 5)

I tried looking for the glthread-posix.c file via find / 2>/dev/null | grep gthread, but I can't find it.. Huh? Now I'm stuck.

Edit no.4. 10:03 UTC: Duplicate of moby/moby#42680 (pay attention to mentions).
SOLUTION: Preferably upgrade Docker, or change the seccomp policy, or I guess disable seccomp for these containers, as mentioned in the issue.
CAUSE: Newer versions of the OS move to newer SYSCALLS, which older versions of Docker do not allow.

I'm running Unraid 6.7.2 on this server, seems like it's finally due for upgrades, from kernel to everything. In the meantime, since I can't upgrade it today, I'll run Soulseek with seccomp disabled. (Will try --security-opt seccomp=unconfined first)

Edit no.5. 10:14 UTC: Just ran the container with additional parameters mentioned above in edit no 4., log outpot looks ok so far, will confirm that it runs properly in a few minutes.

2022-10-23 12:13:41,928 INFO Set uid to user 0 succeeded
2022-10-23 12:13:41,931 INFO supervisord started with pid 1
2022-10-23 12:13:42,934 INFO spawned: 'tigervnc' with pid 13
2022-10-23 12:13:42,937 INFO spawned: 'openbox' with pid 14
2022-10-23 12:13:42,941 INFO spawned: 'novnc' with pid 15
2022-10-23 12:13:42,943 INFO spawned: 'soulseek' with pid 16
2022-10-23 12:13:44,057 INFO success: tigervnc entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2022-10-23 12:13:44,057 INFO success: openbox entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2022-10-23 12:13:44,057 INFO success: novnc entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2022-10-23 12:13:44,058 INFO success: soulseek entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)

Edit no 6. @realies I confirm that it works properly now. Only three things needed fixing, a permission issue in run script that happened for some reason, a novnc_proxy change from relative to absolute path and running the container with seccomp uncofined. I'd like to add additional code that will check the syscalls handlng via versoin checking of the kernel + additional error handling for novnc_proxy and run, and absolute path fix and I'd like to add this as a push request. The ultimate fix is upgrading the docker & kernel that's running the container to latest versions, but as not all people will do this, I think it would be a good idea to add this pull request. I will add in the script if the old version is detected to have stdout scream at the user that they're running on outdated build and that we highly reccomend upgrading to latest. Does this sound good?

Thanks realises. Much appreciate the help

[deadrubberboy]

I'm getting "script error" once NOVNC starts. Is this related?

Is the security_opt an "environment variable"?

[VinneyUK]

Ive got the same issue - nothing ive attempted works ...

2023-04-14 15:02:11,598 INFO Set uid to user 1000 succeeded 2023-04-14 15:02:11,600 INFO supervisord started with pid 1 2023-04-14 15:02:12,604 INFO spawned: 'tigervnc' with pid 22 2023-04-14 15:02:12,607 INFO spawned: 'openbox' with pid 23 2023-04-14 15:02:12,611 INFO spawned: 'novnc' with pid 24 2023-04-14 15:02:12,615 INFO spawned: 'soulseek' with pid 25 2023-04-14 15:02:12,623 INFO exited: tigervnc (exit status 1; not expected) 2023-04-14 15:02:12,655 INFO exited: openbox (exit status 0; not expected) 2023-04-14 15:02:13,641 INFO spawned: 'tigervnc' with pid 46 2023-04-14 15:02:13,642 INFO success: novnc entered RUNNING state, process has stayed up for > than 1 seconds (startsecs) 2023-04-14 15:02:13,642 INFO success: soulseek entered RUNNING state, process has stayed up for > than 1 seconds (startsecs) 2023-04-14 15:02:13,662 INFO spawned: 'openbox' with pid 48 2023-04-14 15:02:13,662 INFO exited: tigervnc (exit status 1; not expected) 2023-04-14 15:02:13,714 INFO exited: openbox (exit status 0; not expected) 2023-04-14 15:02:15,719 INFO spawned: 'tigervnc' with pid 50 2023-04-14 15:02:15,722 INFO spawned: 'openbox' with pid 51 2023-04-14 15:02:15,729 INFO exited: tigervnc (exit status 1; not expected) 2023-04-14 15:02:15,754 INFO exited: openbox (exit status 0; not expected) 2023-04-14 15:02:18,759 INFO spawned: 'tigervnc' with pid 53 2023-04-14 15:02:18,760 INFO spawned: 'openbox' with pid 54 2023-04-14 15:02:18,769 INFO exited: tigervnc (exit status 1; not expected) 2023-04-14 15:02:18,774 INFO gave up: tigervnc entered FATAL state, too many start retries too quickly 2023-04-14 15:02:18,794 INFO exited: openbox (exit status 0; not expected) 2023-04-14 15:02:19,795 INFO gave up: openbox entered FATAL state, too many start retries too quickly

[realies]

@VinneyUK, Docker and host versions?

[oldsweatyman]

I have identical logs as above, running unRAID 6.11.4 with Docker version 20.10.21. I noticed that the errors specifically occur when I run the container with --net=container:qbittorrentvpn and network type set to none, but it runs just fine when network is set to bridge without the extra parameter. Any workarounds? I'd like to continue running the container through a VPN.

[realies]

I have identical logs as above, running unRAID 6.11.4 with Docker version 20.10.21. I noticed that the errors specifically occur when I run the container with --net=container:qbittorrentvpn and network type set to none, but it runs just fine when network is set to bridge without the extra parameter. Any workarounds? I'd like to continue running the container through a VPN.

Not sure why using a container network would cause this. You could configure VPN for the whole Unraid server as a workaround.