frankenphp worker is not restarting when using xdebug on symfony project

What happened?

I am new to Frankenphp. I was setting up a new symfony 6.4 project with FrankenPHP and faced issue with xdebug when xdebug.mode=debug. I also check #563 but it seems not to be the same issue.

Environment: image: dunglas/frankenphp:1.1.5-php8.3 (also tried dunglas/frankenphp:1.1.5-php8.2) xdebug: v3.3.2 symfony: 6.4.* runtime/frankenphp-symfony: 0.2.0

For development environment I set num of workers to 1 and FRANKENPHP_LOOP_MAX=1.

What happens is, the first request is served without issue, the second request loading goes into endless loading. I compared container logs with xdebug.mode=off (working one) and xdebug.debug=debug. The difference is that as you can see from the screenshot, there is no restarting log on the left side (when xdebug.debug=debug).

To debug the issue I tried to setup the same environment but without Symfony, just index.php. In this case I did not face the same issue.

Steps to reproduce:

/Dockerfile

# also tried FROM dunglas/frankenphp:1.1.5-php8.2
FROM dunglas/frankenphp:1.1.5-php8.3

RUN install-php-extensions \
    xdebug

COPY Caddyfile /etc/caddy/Caddyfile
COPY ./project /app
COPY --link ./xdebug.ini /usr/local/etc/php/conf.d/50_xdebug.ini

WORKDIR /app

/xdebug.ini

zend_extension=xdebug
xdebug.mode=debug
xdebug.discover_client_host=1
xdebug.idekey=PHPSTORM
xdebug.client_host=host.docker.internal
error_log=/app/var/log/php_error.log

/Caddfile

{
	# Debug
	{$CADDY_DEBUG}

	frankenphp {
		worker {
			file /app/public/index.php
			num 1
		}
	}

	auto_https off
}

:80

log
route {
	root * public/
	# Add trailing slash for directory requests
	@canonicalPath {
		file {path}/index.php
		not path */
	}
	redir @canonicalPath {path}/ 308

	# If the requested file does not exist, try index files
	@indexFiles file {
		try_files {path} {path}/index.php index.php
		split_path .php
	}
	rewrite @indexFiles {http.matchers.file.relative}

	# FrankenPHP!
	@phpFiles path *.php
	php @phpFiles
	encode zstd gzip
	file_server

	respond 404
}

/docker-compose.yaml

services:
  web:
    build:
      context: .
      dockerfile: ./Dockerfile
    container_name: web
    environment:
      - CADDY_DEBUG=debug
      - FRANKENPHP_LOOP_MAX=1
    volumes:
      - ./project:/app
    ports:
      - "80:80"
    extra_hosts:
      - "host.docker.internal:host-gateway"
    networks:
      application:
    # comment the following line in production, it allows to have nice human-readable logs in dev
    tty: true

networks:
  application:
    driver: bridge

install symfony project into /project folder

 composer create-project symfony/skeleton:"6.4.*" project

run composer require runtime/frankenphp-symfony
add runtime path into composer.json extra

        "runtime": {
            "class": "Runtime\\FrankenPhpSymfony\\Runtime"
        }

/project/src/HomeController.php

<?php

declare(strict_types=1);

namespace App\Controller;

use Symfony\Bundle\FrameworkBundle\Controller\AbstractController;
use Symfony\Component\HttpFoundation\JsonResponse;
use Symfony\Component\Routing\Annotation\Route;

class HomeController extends AbstractController
{
    public function __construct(
    ) {
    }

    #[Route('/', name: 'home')]
    public function index(): JsonResponse
    {
        return $this->json(['message' => 'Welcome to your new controller!']);
    }
}

run composer dump-autoload && bin/console cache:clear

Now start the container and request 2 times.

Build Type

Docker (Debian Bookworm)

Worker Mode

Yes

Operating System

macOS

CPU Architecture

Apple Silicon

PHP configuration

Relevant log output

2024-08-14T09:39:20.834843836Z 2024/08/14 09:39:20.833	INFO	using provided configuration	{"config_file": "/etc/caddy/Caddyfile", "config_adapter": "caddyfile"}
2024-08-14T09:39:20.835222086Z 2024/08/14 09:39:20.835	INFO	admin	admin endpoint started	{"address": "localhost:2019", "enforce_origin": false, "origins": ["//localhost:2019", "//[::1]:2019", "//127.0.0.1:2019"]}
2024-08-14T09:39:20.835738877Z 2024/08/14 09:39:20.835	WARN	http.auto_https	automatic HTTPS is completely disabled for server	{"server_name": "srv0"}
2024-08-14T09:39:20.835747211Z 2024/08/14 09:39:20.835	DEBUG	http.auto_https	adjusted config	{"tls": {"automation":{"policies":[{}]}}, "http": {"servers":{"srv0":{"listen":[":80"],"routes":[{"handle":[{"handler":"subroute","routes":[{"handle":[{"handler":"vars","root":"public/"}]},{"handle":[{"handler":"static_response","headers":{"Location":["{http.request.uri.path}/"]},"status_code":308}],"match":[{"file":{"try_files":["{http.request.uri.path}/index.php"]},"not":[{"path":["*/"]}]}]},{"group":"group0","handle":[{"handler":"rewrite","uri":"{http.matchers.file.relative}"}],"match":[{"file":{"split_path":[".php"],"try_files":["{http.request.uri.path}","{http.request.uri.path}/index.php","index.php"]}}]},{"handle":[{"handler":"php"}],"match":[{"path":["*.php"]}]},{"handle":[{"encodings":{"gzip":{},"zstd":{}},"handler":"encode","prefer":["zstd","gzip"]},{"handler":"file_server","hide":["/etc/caddy/Caddyfile"]},{"handler":"static_response","status_code":404}]}]}]}],"automatic_https":{"disable":true},"logs":{}}}}}
2024-08-14T09:39:20.835754211Z 2024/08/14 09:39:20.835	DEBUG	starting	{"worker": "/app/public/index.php"}
2024-08-14T09:39:20.835766127Z 2024/08/14 09:39:20.835	INFO	tls.cache.maintenance	started background certificate maintenance	{"cache": "0x400017be80"}
2024-08-14T09:39:20.838666044Z Cannot load Xdebug - it was already loaded
2024-08-14T09:39:20.985663669Z 2024/08/14 09:39:20.985	INFO	FrankenPHP started 🐘	{"php_version": "8.3.7"}
2024-08-14T09:39:20.985678252Z 2024/08/14 09:39:20.985	DEBUG	http	starting server loop	{"address": "[::]:80", "tls": false, "http3": false}
2024-08-14T09:39:20.985680836Z 2024/08/14 09:39:20.985	INFO	http.log	server running	{"name": "srv0", "protocols": ["h1", "h2", "h3"]}
2024-08-14T09:39:20.985719294Z 2024/08/14 09:39:20.985	INFO	autosaved config (load with --resume flag)	{"file": "/config/caddy/autosave.json"}
2024-08-14T09:39:20.985722836Z 2024/08/14 09:39:20.985	INFO	serving initial configuration
2024-08-14T09:39:20.985791127Z 2024/08/14 09:39:20.985	DEBUG	waiting for request	{"worker": "/app/public/index.php"}
2024-08-14T09:39:20.988017461Z 2024/08/14 09:39:20.987	WARN	tls	storage cleaning happened too recently; skipping for now	{"storage": "FileStorage:/data/caddy", "instance": "292a0d7a-379a-4c91-8d9e-75c4b1d324a4", "try_again": "2024/08/15 09:39:20.987", "try_again_in": 86399.999999709}
2024-08-14T09:39:20.988026294Z 2024/08/14 09:39:20.987	INFO	tls	finished cleaning storage units
2024-08-14T09:39:50.858852419Z 2024/08/14 09:39:50.858	DEBUG	admin.api	received request	{"method": "GET", "host": "localhost:2019", "uri": "/metrics", "remote_ip": "127.0.0.1", "remote_port": "34446", "headers": {"Accept":["*/*"],"User-Agent":["curl/7.88.1"]}}
2024-08-14T09:40:02.023880633Z 2024/08/14 09:40:02.023	DEBUG	http.handlers.rewrite	rewrote request	{"request": {"remote_ip": "192.168.96.1", "remote_port": "40944", "client_ip": "192.168.96.1", "proto": "HTTP/1.1", "method": "GET", "host": "localhost:8085", "uri": "/", "headers": {"Sec-Ch-Ua-Mobile": ["?0"], "Sec-Ch-Ua-Platform": ["\"macOS\""], "Connection": ["keep-alive"], "Cache-Control": ["max-age=0"], "Sec-Fetch-Site": ["none"], "Accept-Encoding": ["gzip, deflate, br, zstd"], "Upgrade-Insecure-Requests": ["1"], "User-Agent": ["Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/127.0.0.0 Safari/537.36"], "Sec-Fetch-Mode": ["navigate"], "Accept-Language": ["en-GB,en-US;q=0.9,en;q=0.8,ru;q=0.7"], "Sec-Ch-Ua": ["\"Not)A;Brand\";v=\"99\", \"Google Chrome\";v=\"127\", \"Chromium\";v=\"127\""], "Accept": ["text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.7"], "Sec-Fetch-User": ["?1"], "Sec-Fetch-Dest": ["document"]}}, "method": "GET", "uri": "/index.php"}
2024-08-14T09:40:02.023969049Z 2024/08/14 09:40:02.023	DEBUG	request handling started	{"worker": "/app/public/index.php", "url": "/index.php"}
2024-08-14T09:40:02.218584966Z 2024/08/14 09:40:02.218	DEBUG	request handling finished	{"url": "/index.php"}
2024-08-14T09:40:02.218611549Z 2024/08/14 09:40:02.218	DEBUG	request handling finished	{"url": "/index.php"}
2024-08-14T09:40:02.218614008Z 2024/08/14 09:40:02.218	INFO	http.log.access	handled request	{"request": {"remote_ip": "192.168.96.1", "remote_port": "40944", "client_ip": "192.168.96.1", "proto": "HTTP/1.1", "method": "GET", "host": "localhost:8085", "uri": "/", "headers": {"Sec-Ch-Ua": ["\"Not)A;Brand\";v=\"99\", \"Google Chrome\";v=\"127\", \"Chromium\";v=\"127\""], "Accept": ["text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.7"], "Sec-Fetch-User": ["?1"], "Sec-Fetch-Dest": ["document"], "Accept-Language": ["en-GB,en-US;q=0.9,en;q=0.8,ru;q=0.7"], "Sec-Ch-Ua-Mobile": ["?0"], "Sec-Ch-Ua-Platform": ["\"macOS\""], "Connection": ["keep-alive"], "Cache-Control": ["max-age=0"], "Sec-Fetch-Site": ["none"], "Accept-Encoding": ["gzip, deflate, br, zstd"], "Upgrade-Insecure-Requests": ["1"], "User-Agent": ["Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/127.0.0.0 Safari/537.36"], "Sec-Fetch-Mode": ["navigate"]}}, "bytes_read": 0, "user_id": "", "duration": 0.195407625, "size": 45, "status": 200, "resp_headers": {"X-Debug-Token-Link": ["http://localhost:8085/_profiler/c2e43a"], "X-Robots-Tag": ["noindex"], "Server": ["Caddy"], "X-Powered-By": ["PHP/8.3.7"], "Cache-Control": ["no-cache, private"], "Date": ["Wed, 14 Aug 2024 09:40:02 GMT"], "Content-Type": ["application/json"], "X-Debug-Token": ["c2e43a"]}}
2024-08-14T09:40:02.233312883Z 2024/08/14 09:40:02.233	DEBUG	waiting for request	{"worker": "/app/public/index.php"}
2024-08-14T09:40:09.660583011Z 2024/08/14 09:40:09.660	DEBUG	http.handlers.rewrite	rewrote request	{"request": {"remote_ip": "192.168.96.1", "remote_port": "40944", "client_ip": "192.168.96.1", "proto": "HTTP/1.1", "method": "GET", "host": "localhost:8085", "uri": "/", "headers": {"Sec-Ch-Ua-Mobile": ["?0"], "Sec-Ch-Ua-Platform": ["\"macOS\""], "User-Agent": ["Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/127.0.0.0 Safari/537.36"], "Sec-Fetch-Site": ["none"], "Sec-Fetch-Mode": ["navigate"], "Connection": ["keep-alive"], "Accept": ["text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.7"], "Sec-Fetch-User": ["?1"], "Accept-Encoding": ["gzip, deflate, br, zstd"], "Accept-Language": ["en-GB,en-US;q=0.9,en;q=0.8,ru;q=0.7"], "Cache-Control": ["max-age=0"], "Sec-Ch-Ua": ["\"Not)A;Brand\";v=\"99\", \"Google Chrome\";v=\"127\", \"Chromium\";v=\"127\""], "Upgrade-Insecure-Requests": ["1"], "Sec-Fetch-Dest": ["document"]}}, "method": "GET", "uri": "/index.php"}
2024-08-14T09:40:09.661128345Z 2024/08/14 09:40:09.660	DEBUG	request handling started	{"worker": "/app/public/index.php", "url": "/index.php"}
2024-08-14T09:40:09.669451220Z 2024/08/14 09:40:09.669	DEBUG	request handling finished	{"url": "/index.php"}
2024-08-14T09:40:09.669472803Z 2024/08/14 09:40:09.669	DEBUG	request handling finished	{"url": "/index.php"}
2024-08-14T09:40:09.669627636Z 2024/08/14 09:40:09.669	INFO	http.log.access	handled request	{"request": {"remote_ip": "192.168.96.1", "remote_port": "40944", "client_ip": "192.168.96.1", "proto": "HTTP/1.1", "method": "GET", "host": "localhost:8085", "uri": "/", "headers": {"Sec-Fetch-User": ["?1"], "Accept-Encoding": ["gzip, deflate, br, zstd"], "Accept-Language": ["en-GB,en-US;q=0.9,en;q=0.8,ru;q=0.7"], "Connection": ["keep-alive"], "Accept": ["text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.7"], "Upgrade-Insecure-Requests": ["1"], "Sec-Fetch-Dest": ["document"], "Cache-Control": ["max-age=0"], "Sec-Ch-Ua": ["\"Not)A;Brand\";v=\"99\", \"Google Chrome\";v=\"127\", \"Chromium\";v=\"127\""], "Sec-Ch-Ua-Platform": ["\"macOS\""], "User-Agent": ["Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/127.0.0.0 Safari/537.36"], "Sec-Ch-Ua-Mobile": ["?0"], "Sec-Fetch-Site": ["none"], "Sec-Fetch-Mode": ["navigate"]}}, "bytes_read": 0, "user_id": "", "duration": 0.009450792, "size": 45, "status": 200, "resp_headers": {"X-Debug-Token-Link": ["http://localhost:8085/_profiler/e90488"], "X-Robots-Tag": ["noindex"], "Server": ["Caddy"], "X-Powered-By": ["PHP/8.3.7"], "Cache-Control": ["no-cache, private"], "Date": ["Wed, 14 Aug 2024 09:40:09 GMT"], "Content-Type": ["application/json"], "X-Debug-Token": ["e90488"]}}
2024-08-14T09:40:15.777566042Z 2024/08/14 09:40:15.776	DEBUG	http.handlers.rewrite	rewrote request	{"request": {"remote_ip": "192.168.96.1", "remote_port": "40944", "client_ip": "192.168.96.1", "proto": "HTTP/1.1", "method": "GET", "host": "localhost:8085", "uri": "/", "headers": {"Sec-Ch-Ua": ["\"Not)A;Brand\";v=\"99\", \"Google Chrome\";v=\"127\", \"Chromium\";v=\"127\""], "User-Agent": ["Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/127.0.0.0 Safari/537.36"], "Connection": ["keep-alive"], "Accept": ["text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.7"], "Accept-Language": ["en-GB,en-US;q=0.9,en;q=0.8,ru;q=0.7"], "Sec-Ch-Ua-Mobile": ["?0"], "Sec-Ch-Ua-Platform": ["\"macOS\""], "Sec-Fetch-Mode": ["navigate"], "Sec-Fetch-Dest": ["document"], "Accept-Encoding": ["gzip, deflate, br, zstd"], "Cache-Control": ["max-age=0"], "Upgrade-Insecure-Requests": ["1"], "Sec-Fetch-Site": ["none"], "Sec-Fetch-User": ["?1"]}}, "method": "GET", "uri": "/index.php"}

Aug 14 '24 14:08 nuryagdym

If you just exit at a random place in the script, does it still not work?

Aug 14 '24 16:08 withinboredom

When I put exit into the public/index.php from the start worker is restarting continuously. I let the first worker start and then put exit at the start of index.php. Then I make the first request, this request works because it is already in memory. Then second request goes into infinite loading, no new logs in container logs, seems like index.php is not run at all.

Weirdly setting xdebug.start_with_request=yes fixes the issue.

Aug 15 '24 07:08 nuryagdym

Interesting. If you turn on xdebug logs, does it give any useful information? I wonder if this might be an xdebug bug?

Aug 15 '24 07:08 withinboredom

For the first request I see following logs

[281472447540704] Log opened at 2024-08-15 07:40:47.634757
[281472447540704] [Config] INFO: Control socket set up succesfully: '@xdebug-ctrl.281472447540704'
[281472447540704] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[281472447540704] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating

But no zdebug logs for the second request

Aug 15 '24 07:08 nuryagdym

I'm able to reproduce on a project I'm working on. Disabling xdebug seems to solve it. I'll step through with gdb later and see what causes it—like yours, it seems to be an issue with ending the request.

Aug 15 '24 08:08 withinboredom

I tried now without a worker mode, it is working properly when worker mode is disabled.

Aug 15 '24 13:08 nuryagdym