(worker): unexpected termination

[Guikingone]

Hi Dunglas 👋🏻

First, thanks for this new SAPI, amazing to see how PHP can be improved for future applications.

Small issue that I'm facing while using the worker mode, I followed the documentation for the Symfony application then launched it using Docker:

docker run \
    -e FRANKENPHP_CONFIG="worker ./public/index.php" \
    -v $PWD:/app \       
    -p 80:80 -p 443:443 \
    dunglas/frankenphp
WARNING: The requested image's platform (linux/amd64) does not match the detected host platform (linux/arm64/v8) and no specific platform was requested

# ...

First, it seems that the v8 version is not automatically pulled, is there any issue using an arm64 image (I'm on M1 chip)?

Second, when launched (it launched even with the warning message, it seems that it cannot be started correctly:

{"level":"info","ts":1665988244.9370515,"msg":"using provided configuration","config_file":"/etc/Caddyfile","config_adapter":""}
{"level":"warn","ts":1665988244.965832,"msg":"Caddyfile input is not formatted; run the 'caddy fmt' command to fix inconsistencies","adapter":"caddyfile","file":"/etc/Caddyfile","line":3}
{"level":"info","ts":1665988244.9821901,"logger":"admin","msg":"admin endpoint started","address":"localhost:2019","enforce_origin":false,"origins":["//localhost:2019","//[::1]:2019","//127.0.0.1:2019"]}
{"level":"info","ts":1665988244.9869301,"logger":"tls.cache.maintenance","msg":"started background certificate maintenance","cache":"0xc000518540"}
{"level":"info","ts":1665988244.9886699,"logger":"http","msg":"server is listening only on the HTTPS port but has no TLS connection policies; adding one to enable TLS","server_name":"srv0","https_port":443}
{"level":"info","ts":1665988244.989175,"logger":"http","msg":"enabling automatic HTTP->HTTPS redirects","server_name":"srv0"}
{"level":"error","ts":1665988250.9599025,"msg":"unexpected termination, restarting","worker":"/app/public/index.php"}
{"level":"error","ts":1665988250.9616716,"msg":"unexpected termination, restarting","worker":"/app/public/index.php"}
{"level":"error","ts":1665988250.9628036,"msg":"unexpected termination, restarting","worker":"/app/public/index.php"}
{"level":"error","ts":1665988250.9642198,"msg":"unexpected termination, restarting","worker":"/app/public/index.php"}
{"level":"error","ts":1665988250.9654243,"msg":"unexpected termination, restarting","worker":"/app/public/index.php"}
{"level":"error","ts":1665988250.9677563,"msg":"unexpected termination, restarting","worker":"/app/public/index.php"}

I'm not sure why it tries to restart the worker (maybe it's due to the arm64 architecture?) but the application does not respond 🙁

Thanks for the help and sorry for this issue 😄

[husimo-tilleuls]

For the second error, did you run docker run --rm -it -v $PWD:/app composer:latest install for downloading composer dependencies ? I faced the same error but it could not be related at all.

[Guikingone]

I tried to install the dependencies before launching it but the error still the same 🙁

[husimo-tilleuls]

Okay, weird.

For the first error, it seems that FrankenPHP docker image is not yet available to linux/arm64/v8 platform : https://hub.docker.com/r/dunglas/frankenphp/tags ; don't really know what's the difference with linux/arm64 platform ?! ; php for example has a image dedicated to linux/arm64/v8 but no linux/arm64

[dunglas]

The two problems are most likely unrelated.

I cross-compiled, the images, that's weird that it doesn't use the proper platform. Can you try to pull the latest version?

Regarding the 2nd error, this means that the worker script has an error. Can you try adding -e DEBUG=debug to see if we can find more details?

Also, is the app already working without the worker mode?

[Guikingone]

Sure, here's the output:

docker run \
    -e FRANKENPHP_CONFIG="worker ./public/index.php" \
    -v $PWD:/app \
    -p 80:80 -p 443:443 \
    -e DEBUG=debug \
    dunglas/frankenphp:latest

WARNING: The requested image's platform (linux/amd64) does not match the detected host platform (linux/arm64/v8) and no specific platform was requested
{"level":"info","ts":1665992417.3603036,"msg":"using provided configuration","config_file":"/etc/Caddyfile","config_adapter":""}
{"level":"warn","ts":1665992417.38682,"msg":"Caddyfile input is not formatted; run the 'caddy fmt' command to fix inconsistencies","adapter":"caddyfile","file":"/etc/Caddyfile","line":3}
{"level":"info","ts":1665992417.4028971,"logger":"admin","msg":"admin endpoint started","address":"localhost:2019","enforce_origin":false,"origins":["//localhost:2019","//[::1]:2019","//127.0.0.1:2019"]}
{"level":"info","ts":1665992417.4086516,"logger":"tls.cache.maintenance","msg":"started background certificate maintenance","cache":"0xc0006be460"}
{"level":"info","ts":1665992417.4102502,"logger":"http","msg":"server is listening only on the HTTPS port but has no TLS connection policies; adding one to enable TLS","server_name":"srv0","https_port":443}
{"level":"info","ts":1665992417.4107287,"logger":"http","msg":"enabling automatic HTTP->HTTPS redirects","server_name":"srv0"}
{"level":"debug","ts":1665992417.4526346,"msg":"starting","worker":"/app/public/index.php"}
{"level":"debug","ts":1665992417.4526458,"msg":"starting","worker":"/app/public/index.php"}
{"level":"debug","ts":1665992417.4526718,"msg":"starting","worker":"/app/public/index.php"}
{"level":"debug","ts":1665992417.4527564,"msg":"starting","worker":"/app/public/index.php"}
{"level":"debug","ts":1665992417.452575,"msg":"starting","worker":"/app/public/index.php"}
{"level":"debug","ts":1665992417.452532,"msg":"starting","worker":"/app/public/index.php"}
{"level":"error","ts":1665992420.2902257,"msg":"unexpected termination, restarting","worker":"/app/public/index.php"}
{"level":"debug","ts":1665992420.2903821,"msg":"starting","worker":"/app/public/index.php"}
{"level":"error","ts":1665992420.2909434,"msg":"unexpected termination, restarting","worker":"/app/public/index.php"}
{"level":"debug","ts":1665992420.2909799,"msg":"starting","worker":"/app/public/index.php"}

The application is working as usual, I mean, without any frontend assets but it works outside the worker mode.

[dunglas]

Do you think you could give me access to the code?

[jorismak]

I have the same thing when just trying around.

I compile php8.2 with the options specified for Linux in https://github.com/dunglas/frankenphp/blob/main/docs/compile.md. I've installed it in /usr/local/php82.

So - still locally - I add /usr/local/php82/bin as first entry to the $PATH, I check with symfony local:php:refresh and symfony local:php:list that it is listed.

I create a new local project with a simple symfony local:new franken-test. Inside it, I add .php-version to 8.2, and remove the composer.lock file and the vendor folder, and do a new symfony composer install, to make sure it really installs dependencies with 8.2.

I create a new simple DefaultController.php in src/Controller, with nothing but a 'return new Response('foobar');`.

Then, I follow the steps from https://github.com/dunglas/frankenphp/blob/main/docs/worker.md#symfony-runtime for the Symfony Runtime.

So I do symfony composer require runtime/frankenphp-symfony.

I add the line to my .env file:

APP_RUNTIME='Runtime\FrankenPhpSymfony\Runtime'

I test without worker mode:

docker run -it --rm --network mybridge -e DEBUG=debug -v $PWD:/app -p 81:80 -p 444:443 dunglas/frankenphp

I use port 81 and 444 on my host because I have another Caddy instance running for normal use. And the --network is because I have a custom docker bridge network, so I always need to add this to connect containers to my host.

But, this works. If I run this, I connect to https://localhost:444 I need to bypass the certificate warning, but then I get my 'foobar' response.

Now, I stop the container and run it again with

docker run -it --rm --network mybridge -e DEBUG=debug -e FRANKENPHP_CONFIG="worker ./public/index.php" -v $PWD:/app -p 81:80 -p 444:443 dunglas/frankenphp

But I get the same endless looping 'unexpected termination, restarting'. Here just posted 'one', but since I have 20 workers it all seems to merge a bit.

DEBUG   starting        {"worker": "/app/public/index.php"}
INFO    [info] Matched route "default".
        {"syslog_level": "notice"}
ERROR   unexpected termination, restarting      {"worker": "/app/public/index.php"}
DEBUG   starting        {"worker": "/app/public/index.php"}
INFO    [info] Matched route "default".
        {"syslog_level": "notice"}
ERROR   unexpected termination, restarting      {"worker": "/app/public/index.php"}
DEBUG   starting        {"worker": "/app/public/index.php"}

It's a bit weird that it instantly says 'matched route' while I didn't even refresh my browser or anything.

[Guikingone]

@dunglas Sure, here's the repository: https://github.com/Guikingone/Frankenphp

[dunglas]

I wonder if the runtime is used correctly. Can you try to do dump/die into https://github.com/php-runtime/runtime/blob/main/src/frankenphp-symfony/src/Runner.php ?

Also, calling error_log() will print on Caddy's stderr. can you try to wrap https://github.com/php-runtime/runtime/blob/main/src/frankenphp-symfony/src/Runner.php#L30-L42 in a try-catch and print the potential exception on stderr? (the frankenphp_handle_request should do that for you but it may be buggy).

I'll try to find some time tonight to test your code, thanks for the reproducer!!

[jorismak]

(Since my example is working without the worker mode, but the Runtime IS installed, it seems the issue is indeed the runtime not being picked up correectly?)

[jorismak]

Got it working!

The APP_RUNTIME needed to be added to my docker run command as well. It seems, setting it in just .env isn't enough (or dotEnv gets loaded too late to have an impact?)

[dunglas]

Likely! We need to update the docs then.

[Guikingone]

Hi 👋🏻

Small update, when using the following command:

docker run \
    -e FRANKENPHP_CONFIG="worker index.php" \
    -v $PWD:/app \
    -p 80:80 -p 443:443 \
    -e DEBUG=debug \
    -e APP_RUNTIME=Runtime\\FrankenPhpSymfony\\Runtime \
    dunglas/frankenphp:latest

It seems to work, I mean, the application can be launched and it works correctly (I guess that's what @jorismak was talking about), thing is, the error logs still there:

{"level":"error","ts":1666158067.2553306,"msg":"unexpected termination, restarting","worker":"/app/index.php"}
{"level":"debug","ts":1666158067.2553678,"msg":"starting","worker":"/app/index.php"}
{"level":"info","ts":1666158067.2584994,"msg":"shutting down","signal":"SIGINT"}
{"level":"warn","ts":1666158067.2586815,"msg":"exiting; byeee!! 👋","signal":"SIGINT"}
{"level":"error","ts":1666158067.2642834,"msg":"unexpected termination, restarting","worker":"/app/index.php"}
{"level":"debug","ts":1666158067.2643805,"msg":"starting","worker":"/app/index.php"}
{"level":"error","ts":1666158067.2648373,"msg":"unexpected termination, restarting","worker":"/app/index.php"}
{"level":"debug","ts":1666158067.2649267,"msg":"starting","worker":"/app/index.php"}
{"level":"error","ts":1666158067.2653258,"msg":"unexpected termination, restarting","worker":"/app/index.php"}
{"level":"debug","ts":1666158067.2653623,"msg":"starting","worker":"/app/index.php"}
{"level":"error","ts":1666158067.2658422,"msg":"unexpected termination, restarting","worker":"/app/index.php"}
{"level":"debug","ts":1666158067.2658794,"msg":"starting","worker":"/app/index.php"}
{"level":"error","ts":1666158067.2664037,"msg":"unexpected termination, restarting","worker":"/app/index.php"}
{"level":"debug","ts":1666158067.2664354,"msg":"starting","worker":"/app/index.php"}
{"level":"error","ts":1666158067.2669594,"msg":"unexpected termination, restarting","worker":"/app/index.php"}
{"level":"debug","ts":1666158067.2669938,"msg":"starting","worker":"/app/index.php"}
{"level":"warn","ts":1666158067.2672875,"msg":"force quit","signal":"SIGINT"}

I tried to try/catch/error_log the run() method but Caddy doesn't seems to display any log / error message 🤔

[dunglas]

I think that the APP_RUNTIME env var is set too late when using .env and that the FrankenPHP Runtime isn't loaded. That's probably more a bug of runtime than of FrankenPHP.

[Guikingone]

Yes, it seems that environment variables are loaded before using DotEnv: https://github.com/symfony/symfony/blob/6.2/src/Symfony/Component/Runtime/SymfonyRuntime.php#L91, the question is, is frankenphp responsability to force loading variables via DotEnv or using "default environment variables" is enough?

[Yoann-TYT]

@Guikingone I think you forgot ./public :)

Define APP_RUNTIME as docker environment variable solved this problem for me :)

docker run \
    -e FRANKENPHP_CONFIG="worker ./public/index.php" \
    -v $PWD:/app \
    -p 80:80 -p 443:443 \
    -e APP_RUNTIME=Runtime\\FrankenPhpSymfony\\Runtime \
    dunglas/frankenphp

[Guikingone]

AH, nice catch, indeed, works way better with public 😅

Same using the APP_RUNTIME, it solved the issue regarding the runtime selection.

[Yoann-TYT]

Perfect ! 😁 I created a PR for this issue https://github.com/dunglas/frankenphp/pull/40

[Guikingone]

I'm closing this issue in this case, no need to keep it alive.

[jorismak]

It seems to work, I mean, the application can be launched and it works correctly (I guess that's what @jorismak was talking about), thing is, the error logs still there:

I don't have the 'termination' errors when doing it that way. Even with debug on, output looks pretty clean (one INFO for 'handled request'), and things like 'handling started' and 'handling finished'

[Guikingone]

Might be related to the missing public directory or the M1 platform that doesn't pull the correct image? 🤔