Intermittent `Waiting for control socket to be removed...` after unit reconfiguration

[cgearing]

Hi,

I've noticed since moving from threaded to multiprocess nginx-unit with python 3.9 I frequently get a loop of Waiting for control socket to be removed after the container starts up.

The nginx-unit config:

{
    "listeners": {
        "*:8099": {
            "pass": "applications/fastapi"
        }
    },
    "access_log": "/dev/stdout",
    "applications": {
        "fastapi": {
            "processes": 4,
            "limits": {
                "requests": 200
            },
            "type": "python 3.9",
            "path": "/app",
            "module": "main",
            "home": "/usr/local",
            "callable": "app",
            "protocol": "asgi",
        }
    }
}

Logs from the container:

prod_web_1          | /usr/local/bin/docker-entrypoint.sh: /docker-entrypoint.d/ is not empty, launching Unit daemon to perform initial configuration...
prod_web_1          | 2021/11/30 11:07:58 [info] 14#14 unit started
prod_web_1          | 2021/11/30 11:07:58 [info] 17#17 discovery started
Notice: d_web_1          | 2021/11/30 11:07:58 [notice] 17#17 module: python 3.9.9 "/usr/lib/unit/modules/python3.unit.so"
prod_web_1          | 2021/11/30 11:07:58 [info] 15#15 controller started
prod_web_1          | 2021/11/30 11:07:58 [info] 19#19 router started
Notice: d_web_1          | 2021/11/30 11:07:58 [notice] 15#15 process 17 exited with code 0
prod_web_1          | 2021/11/30 11:07:58 [info] 19#19 OpenSSL 1.1.1k  25 Mar 2021, 101010bf
prod_web_1          | {
prod_web_1          | 	"certificates": {},
prod_web_1          | 	"config": {
prod_web_1          | 		"listeners": {},
prod_web_1          | 		"applications": {}
prod_web_1          | 	}
prod_web_1          | }
prod_web_1          | /usr/local/bin/docker-entrypoint.sh: Looking for certificate bundles in /docker-entrypoint.d/...
prod_web_1          | /usr/local/bin/docker-entrypoint.sh: Looking for configuration snippets in /docker-entrypoint.d/...
prod_web_1          | /usr/local/bin/docker-entrypoint.sh: Applying configuration /docker-entrypoint.d/config.json
prod_web_1          | 2021/11/30 11:07:58 [info] 23#23 "fastapi" prototype started
prod_web_1          | 2021/11/30 11:07:58 [info] 24#24 "fastapi" application started
prod_web_1          | 2021/11/30 11:07:59 [info] 29#29 "fastapi" application started
prod_web_1          | 2021/11/30 11:08:00 [info] 34#34 "fastapi" application started
prod_web_1          | 2021/11/30 11:08:00 [info] 39#39 "fastapi" application started
prod_web_1          | /usr/local/bin/docker-entrypoint.sh: OK: HTTP response status code is '200'
prod_web_1          | {
prod_web_1          | 	"success": "Reconfiguration done."
prod_web_1          | }
prod_web_1          | 
prod_web_1          | /usr/local/bin/docker-entrypoint.sh: Looking for shell scripts in /docker-entrypoint.d/...
prod_web_1          | /usr/local/bin/docker-entrypoint.sh: Stopping Unit daemon after initial configuration...
prod_web_1          | /usr/local/bin/docker-entrypoint.sh: Waiting for control socket to be removed...
Notice: d_web_1          | 2021/11/30 11:08:01 [notice] 15#15 process 18 exited with code 0
prod_web_1          | /usr/local/bin/docker-entrypoint.sh: Waiting for control socket to be removed...
Notice: d_web_1          | 2021/11/30 11:08:01 [notice] 23#23 app process (isolated 34) exited with code 0
prod_web_1          | 2021/11/30 11:08:01 [alert] 23#23 sendmsg(13, -1, -1, 2) failed (32: Broken pipe)
Notice: d_web_1          | 2021/11/30 11:08:01 [notice] 23#23 app process (isolated 24) exited with code 0
prod_web_1          | 2021/11/30 11:08:01 [alert] 23#23 sendmsg(13, -1, -1, 2) failed (32: Broken pipe)
prod_web_1          | /usr/local/bin/docker-entrypoint.sh: Waiting for control socket to be removed...
Notice: d_web_1          | 2021/11/30 11:08:01 [notice] 23#23 app process (isolated 29) exited with code 0
prod_web_1          | 2021/11/30 11:08:01 [alert] 23#23 sendmsg(13, -1, -1, 2) failed (32: Broken pipe)
Notice: d_web_1          | 2021/11/30 11:08:01 [notice] 23#23 app process (isolated 39) exited with code 0
prod_web_1          | 2021/11/30 11:08:01 [alert] 23#23 sendmsg(13, -1, -1, 2) failed (32: Broken pipe)
Notice: d_web_1          | 2021/11/30 11:08:01 [notice] 15#15 process 19 exited with code 0
prod_web_1          | /usr/local/bin/docker-entrypoint.sh: Waiting for control socket to be removed...
prod_web_1          | /usr/local/bin/docker-entrypoint.sh: Waiting for control socket to be removed...

[VBart]

It looks like a duplicate of this issue: #600.
Are you using Unit 1.26.0?

[cgearing]

Yes, this is using 1.26.0 - I ran unit with debug and couldn't see any obvious extra information:

prod_web_1          | /usr/local/bin/docker-entrypoint.sh: /docker-entrypoint.d/ is not empty, launching Unit daemon to perform initial configuration...
prod_web_1          | 2021/11/30 11:32:35 [info] 13#13 unit started
prod_web_1          | 2021/11/30 11:32:35 [info] 16#16 discovery started
prod_web_1          | 2021/11/30 11:32:35 [notice] 16#16 module: python 3.9.9 "/usr/lib/unit/modules/python3.unit.so"
prod_web_1          | 2021/11/30 11:32:35 [info] 14#14 controller started
prod_web_1          | 2021/11/30 11:32:35 [info] 18#18 router started
prod_web_1          | 2021/11/30 11:32:35 [notice] 14#14 process 16 exited with code 0
prod_web_1          | 2021/11/30 11:32:35 [info] 18#18 OpenSSL 1.1.1k  25 Mar 2021, 101010bf
prod_web_1          | {
prod_web_1          | 	"certificates": {},
prod_web_1          | 	"config": {
prod_web_1          | 		"listeners": {},
prod_web_1          | 		"applications": {}
prod_web_1          | 	}
prod_web_1          | }
prod_web_1          | /usr/local/bin/docker-entrypoint.sh: Looking for certificate bundles in /docker-entrypoint.d/...
prod_web_1          | /usr/local/bin/docker-entrypoint.sh: Looking for configuration snippets in /docker-entrypoint.d/...
prod_web_1          | /usr/local/bin/docker-entrypoint.sh: Applying configuration /docker-entrypoint.d/config.json
prod_web_1          | 2021/11/30 11:32:35 [info] 22#22 "fastapi" prototype started
prod_web_1          | 2021/11/30 11:32:35 [info] 23#23 "fastapi" application started
prod_web_1          | 2021/11/30 11:32:40 [info] 28#28 "fastapi" application started
prod_web_1          | 2021/11/30 11:32:41 [info] 33#33 "fastapi" application started
prod_web_1          | 2021/11/30 11:32:42 [info] 38#38 "fastapi" application started
prod_web_1          | /usr/local/bin/docker-entrypoint.sh: OK: HTTP response status code is '200'
prod_web_1          | {
prod_web_1          | 	"success": "Reconfiguration done."
prod_web_1          | }
prod_web_1          |
prod_web_1          | /usr/local/bin/docker-entrypoint.sh: Looking for shell scripts in /docker-entrypoint.d/...
prod_web_1          | /usr/local/bin/docker-entrypoint.sh: Stopping Unit daemon after initial configuration...
prod_web_1          | /usr/local/bin/docker-entrypoint.sh: Waiting for control socket to be removed...
prod_web_1          | 2021/11/30 11:32:43 [notice] 14#14 process 17 exited with code 0
prod_web_1          | /usr/local/bin/docker-entrypoint.sh: Waiting for control socket to be removed...
prod_web_1          | /usr/local/bin/docker-entrypoint.sh: Waiting for control socket to be removed...
prod_web_1          | 2021/11/30 11:32:44 [notice] 22#22 app process (isolated 28) exited with code 0
prod_web_1          | 2021/11/30 11:32:44 [alert] 22#22 sendmsg(13, -1, -1, 2) failed (32: Broken pipe)
prod_web_1          | /usr/local/bin/docker-entrypoint.sh: Waiting for control socket to be removed...
prod_web_1          | 2021/11/30 11:32:44 [notice] 22#22 app process (isolated 33) exited with code 0
prod_web_1          | 2021/11/30 11:32:44 [alert] 22#22 sendmsg(13, -1, -1, 2) failed (32: Broken pipe)
prod_web_1          | 2021/11/30 11:32:44 [notice] 22#22 app process (isolated 23) exited with code 0
prod_web_1          | 2021/11/30 11:32:44 [alert] 22#22 sendmsg(13, -1, -1, 2) failed (32: Broken pipe)
prod_web_1          | 2021/11/30 11:32:44 [notice] 22#22 app process (isolated 38) exited with code 0
prod_web_1          | 2021/11/30 11:32:44 [alert] 22#22 sendmsg(13, -1, -1, 2) failed (32: Broken pipe)
prod_web_1          | 2021/11/30 11:32:44 [notice] 14#14 process 18 exited with code 0
prod_web_1          | /usr/local/bin/docker-entrypoint.sh: Waiting for control socket to be removed...
prod_web_1          | /usr/local/bin/docker-entrypoint.sh: Waiting for control socket to be removed...
prod_web_1          | /usr/local/bin/docker-entrypoint.sh: Waiting for control socket to be removed...
prod_web_1          | /usr/local/bin/docker-entrypoint.sh: Waiting for control socket to be removed...
prod_web_1          | /usr/local/bin/docker-entrypoint.sh: Waiting for control socket to be removed...
prod_web_1          | /usr/local/bin/docker-entrypoint.sh: Waiting for control socket to be removed...

[VBart]

It doesn't look like Unit with debug. When debug is enabled, there will be lots of [debug] lines in output. How do you run it? Note, that you have to change the docker-entrypoint.sh script, since it runs Unit in your case.

[cgearing]

I added a layer to my docker image as per the docs - does that not pass the arguments to the entrypoint script?
Running it with a specific command through docer
It doesn't seem to hit the debug messages until the processes restart successfully:

❯ docker-compose build prod_web && docker-compose run --rm prod_web unitd-debug --no-daemon --control unix:/var/run/control.unit.sock
Building prod_web
[+] Building 0.8s (11/11) FINISHED
 => [internal] load build definition from Dockerfile                                                                                                                   0.0s
 => => transferring dockerfile: 37B                                                                                                                                    0.0s
 => [internal] load .dockerignore                                                                                                                                      0.0s
 => => transferring context: 34B                                                                                                                                       0.0s
 => [internal] load metadata for docker.io/nginx/unit:1.26.0-python3.9                                                                                                 0.5s
 => [internal] load build context                                                                                                                                      0.0s
 => => transferring context: 3.62kB                                                                                                                                    0.0s
 => [1/6] FROM docker.io/nginx/unit:1.26.0-python3.9@sha256:5011c53db087b6b08934ddf1eb16a0963a2f7ebfaf1b4f6fbdd70e6d9025c2c7                                           0.0s
 => CACHED [2/6] COPY . .                                                                                                                                              0.0s
 => CACHED [3/6] RUN chown -R unit:unit app scripts                                                                                                                    0.0s
 => CACHED [4/6] COPY config/config.json /docker-entrypoint.d/config.json                                                                                              0.0s
 => CACHED [5/6] RUN echo ./requirements.txt                                                                                                                           0.0s
 => CACHED [6/6] RUN apt update && apt install -y python3-pip                                     && pip3 install -r ./requirements.txt                                0.0s
 => exporting to image                                                                                                                                                 0.0s
 => => exporting layers                                                                                                                                                0.0s
 => => writing image sha256:20352bce353cc6b26827cc54fe76b804561d8493cd800204d371625e2066c43d                                                                           0.0s
 => => naming to docker.io/library/cost-planning-service_prod_web                                                                                                      0.0s

Use 'docker scan' to run Snyk tests against images to find vulnerabilities and learn how to fix them
Creating cost-planning-service_prod_web_run ... done
/usr/local/bin/docker-entrypoint.sh: /docker-entrypoint.d/ is not empty, launching Unit daemon to perform initial configuration...
2021/11/30 13:30:59 [info] 11#11 unit started
2021/11/30 13:30:59 [info] 13#13 discovery started
2021/11/30 13:30:59 [notice] 13#13 module: python 3.9.9 "/usr/lib/unit/modules/python3.unit.so"
2021/11/30 13:30:59 [info] 12#12 controller started
2021/11/30 13:30:59 [notice] 12#12 process 13 exited with code 0
2021/11/30 13:30:59 [info] 16#16 router started
2021/11/30 13:30:59 [info] 16#16 OpenSSL 1.1.1k  25 Mar 2021, 101010bf
{
	"certificates": {},
	"config": {
		"listeners": {},
		"applications": {}
	}
}
/usr/local/bin/docker-entrypoint.sh: Looking for certificate bundles in /docker-entrypoint.d/...
/usr/local/bin/docker-entrypoint.sh: Looking for configuration snippets in /docker-entrypoint.d/...
/usr/local/bin/docker-entrypoint.sh: Applying configuration /docker-entrypoint.d/config.json
2021/11/30 13:30:59 [info] 20#20 "fastapi" prototype started
2021/11/30 13:30:59 [info] 21#21 "fastapi" application started
2021/11/30 13:31:00 [info] 26#26 "fastapi" application started
2021/11/30 13:31:01 [info] 31#31 "fastapi" application started
2021/11/30 13:31:02 [info] 36#36 "fastapi" application started
/usr/local/bin/docker-entrypoint.sh: OK: HTTP response status code is '200'
{
	"success": "Reconfiguration done."
}

/usr/local/bin/docker-entrypoint.sh: Looking for shell scripts in /docker-entrypoint.d/...
/usr/local/bin/docker-entrypoint.sh: Stopping Unit daemon after initial configuration...
/usr/local/bin/docker-entrypoint.sh: Waiting for control socket to be removed...
2021/11/30 13:31:04 [notice] 12#12 process 15 exited with code 0
/usr/local/bin/docker-entrypoint.sh: Waiting for control socket to be removed...
/usr/local/bin/docker-entrypoint.sh: Waiting for control socket to be removed...
2021/11/30 13:31:04 [notice] 20#20 app process (isolated 31) exited with code 0
2021/11/30 13:31:04 [alert] 20#20 sendmsg(13, -1, -1, 2) failed (32: Broken pipe)
2021/11/30 13:31:04 [notice] 20#20 app process (isolated 21) exited with code 0
2021/11/30 13:31:04 [alert] 20#20 sendmsg(13, -1, -1, 2) failed (32: Broken pipe)
2021/11/30 13:31:04 [notice] 20#20 app process (isolated 26) exited with code 0
2021/11/30 13:31:04 [alert] 20#20 sendmsg(13, -1, -1, 2) failed (32: Broken pipe)
/usr/local/bin/docker-entrypoint.sh: Waiting for control socket to be removed...
2021/11/30 13:31:04 [notice] 20#20 app process (isolated 36) exited with code 0
2021/11/30 13:31:04 [alert] 20#20 sendmsg(13, -1, -1, 2) failed (32: Broken pipe)
2021/11/30 13:31:04 [notice] 12#12 process 16 exited with code 0
/usr/local/bin/docker-entrypoint.sh: Waiting for control socket to be removed...
/usr/local/bin/docker-entrypoint.sh: Waiting for control socket to be removed...
/usr/local/bin/docker-entrypoint.sh: Waiting for control socket to be removed...

That is the unsuccessful run - the last message just repeats forever.

A successful run in debug mode:

❯ docker-compose build prod_web && docker-compose run --rm prod_web unitd-debug --no-daemon --control unix:/var/run/control.unit.sock
Building prod_web
[+] Building 0.7s (11/11) FINISHED
 => [internal] load build definition from Dockerfile                                                                                                                   0.0s
 => => transferring dockerfile: 37B                                                                                                                                    0.0s
 => [internal] load .dockerignore                                                                                                                                      0.0s
 => => transferring context: 34B                                                                                                                                       0.0s
 => [internal] load metadata for docker.io/nginx/unit:1.26.0-python3.9                                                                                                 0.4s
 => [internal] load build context                                                                                                                                      0.0s
 => => transferring context: 3.62kB                                                                                                                                    0.0s
 => [1/6] FROM docker.io/nginx/unit:1.26.0-python3.9@sha256:5011c53db087b6b08934ddf1eb16a0963a2f7ebfaf1b4f6fbdd70e6d9025c2c7                                           0.0s
 => CACHED [2/6] COPY . .                                                                                                                                              0.0s
 => CACHED [3/6] RUN chown -R unit:unit app scripts                                                                                                                    0.0s
 => CACHED [4/6] COPY config/config.json /docker-entrypoint.d/config.json                                                                                              0.0s
 => CACHED [5/6] RUN echo ./requirements.txt                                                                                                                           0.0s
 => CACHED [6/6] RUN apt update && apt install -y python3-pip                                     && pip3 install -r ./requirements.txt                                0.0s
 => exporting to image                                                                                                                                                 0.0s
 => => exporting layers                                                                                                                                                0.0s
 => => writing image sha256:20352bce353cc6b26827cc54fe76b804561d8493cd800204d371625e2066c43d                                                                           0.0s
 => => naming to docker.io/library/cost-planning-service_prod_web                                                                                                      0.0s

Use 'docker scan' to run Snyk tests against images to find vulnerabilities and learn how to fix them
Creating cost-planning-service_prod_web_run ... done
/usr/local/bin/docker-entrypoint.sh: /docker-entrypoint.d/ is not empty, launching Unit daemon to perform initial configuration...
2021/11/30 13:31:25 [info] 11#11 unit started
2021/11/30 13:31:25 [info] 13#13 discovery started
2021/11/30 13:31:25 [notice] 13#13 module: python 3.9.9 "/usr/lib/unit/modules/python3.unit.so"
2021/11/30 13:31:25 [info] 12#12 controller started
2021/11/30 13:31:25 [notice] 12#12 process 13 exited with code 0
2021/11/30 13:31:25 [info] 16#16 router started
2021/11/30 13:31:25 [info] 16#16 OpenSSL 1.1.1k  25 Mar 2021, 101010bf
{
	"certificates": {},
	"config": {
		"listeners": {},
		"applications": {}
	}
}
/usr/local/bin/docker-entrypoint.sh: Looking for certificate bundles in /docker-entrypoint.d/...
/usr/local/bin/docker-entrypoint.sh: Looking for configuration snippets in /docker-entrypoint.d/...
/usr/local/bin/docker-entrypoint.sh: Applying configuration /docker-entrypoint.d/config.json
2021/11/30 13:31:25 [info] 20#20 "fastapi" prototype started
2021/11/30 13:31:25 [info] 21#21 "fastapi" application started
2021/11/30 13:31:26 [info] 26#26 "fastapi" application started
2021/11/30 13:31:27 [info] 31#31 "fastapi" application started
2021/11/30 13:31:28 [info] 36#36 "fastapi" application started
/usr/local/bin/docker-entrypoint.sh: OK: HTTP response status code is '200'
{
	"success": "Reconfiguration done."
}

/usr/local/bin/docker-entrypoint.sh: Looking for shell scripts in /docker-entrypoint.d/...
/usr/local/bin/docker-entrypoint.sh: Stopping Unit daemon after initial configuration...
/usr/local/bin/docker-entrypoint.sh: Waiting for control socket to be removed...
2021/11/30 13:31:29 [notice] 12#12 process 15 exited with code 0
2021/11/30 13:31:29 [notice] 12#12 process 16 exited with code 0
/usr/local/bin/docker-entrypoint.sh: Waiting for control socket to be removed...
/usr/local/bin/docker-entrypoint.sh: Waiting for control socket to be removed...
/usr/local/bin/docker-entrypoint.sh: Waiting for control socket to be removed...
2021/11/30 13:31:29 [notice] 20#20 app process (isolated 31) exited with code 0
2021/11/30 13:31:29 [alert] 20#20 sendmsg(13, -1, -1, 2) failed (32: Broken pipe)
2021/11/30 13:31:29 [notice] 20#20 app process (isolated 36) exited with code 0
2021/11/30 13:31:29 [alert] 20#20 sendmsg(13, -1, -1, 2) failed (32: Broken pipe)
/usr/local/bin/docker-entrypoint.sh: Waiting for control socket to be removed...
2021/11/30 13:31:29 [notice] 20#20 app process (isolated 21) exited with code 0
2021/11/30 13:31:29 [alert] 20#20 sendmsg(13, -1, -1, 2) failed (32: Broken pipe)
2021/11/30 13:31:29 [notice] 20#20 app process (isolated 26) exited with code 0
2021/11/30 13:31:29 [alert] 20#20 sendmsg(13, -1, -1, 2) failed (32: Broken pipe)
2021/11/30 13:31:29 [notice] 12#12 process 20 exited with code 0

/usr/local/bin/docker-entrypoint.sh: Unit initial configuration complete; ready for start up...

unit: [debug] sys_nerr: 132
unit: [debug] malloc(6820): 56513508E6B0
unit: [debug] stderr flags: 0x8402
unit: [debug] ncpu: 4
unit: [debug] pagesize: 4096
unit: [debug] malloc(40): 565135090160
unit: [debug] malloc(770): 565135090190
unit: [debug] malloc(184): 5651350904A0
2021/11/30 13:31:29.998 [debug] 1#1 realloc(0, 32): 565135090610

etc etc - this then responds to requests.

[VBart]

@cgearing Your parameters don't affect the command for starting Unit in docker-entrypoint.sh. You can look at the script, it's pretty simple: https://github.com/nginx/unit/blob/master/pkg/docker/docker-entrypoint.sh#L27

Probably it needs to be fixed for respecting unit-debug (cc: @thresheek )

[VBart]

But, anyway, the issue with stopping Unit 1.26 is reported in #600 and fixed with 2bc9599, which will be released soon.

[cgearing]

Sorry @VBart my brain has finally caught up with what you're saying.

Here's a gist for the logs https://gist.github.com/cgearing/d1bbe789181c4400f5381301c9550be3 (I thought it would be too much for this thread).

[mar0x]

Thanks for debug log. I've inspected it and confirm the issue caused by the bug in SIGCHLD handler which was fixed in #600 .

In the log I was unable to find the last records from PID 16 (controller), notable exit: 0, however the process terminated according to waitpid(): 16 record.

[cgearing]

I've just tried 1.26.1 and I'm fairly sure that it has fixed the issue - thank you for creating a brilliant tool - it's made developing/deploying small applications very easy!