Http workers stay in "invalid" status after ttl is reached

[Aleksa1996]

Hello,

I am having issues with http.pool.supervisor.ttl option after upgrade from v2023.1.2 to v2023.2.1
When workers reach ttl, they stay in status "invalid". I am expecting restart and them to become in status ready again. But they are stuck in that invalid status.

Output from command bin/rr workers -i

This is the config that i am using:

version: '3'

server:
    command: "php public/index.php"
    env:
        - APP_RUNTIME: Baldinof\RoadRunnerBundle\Runtime\Runtime
        - APP_ENV: prod

rpc:
    listen: tcp://127.0.0.1:6001

http:
    address: 0.0.0.0:80
    middleware: [ "static", "gzip" ]
    uploads:
        forbid: [ ".php", ".exe", ".bat", ".sh" ]
    static:
        dir: "public"
        forbid: [ ".php", ".htaccess" ]
    pool:
        num_workers: 12
        debug: false
        max_jobs: 100
        supervisor:
            watch_tick: 1s
            ttl: 1800s
            idle_ttl: 0s
            max_worker_memory: 350
            exec_ttl: 180s

status:
    address: localhost:2114

logs:
    mode: production
    output: stderr

metrics:
    address: "0.0.0.0:9180"

Thanks for this wonderful project.

[rustatian]

Hey @Aleksa1996 👋🏻
Does this problem only occur in the 2023.2.x release ?

[Aleksa1996]

Wow, that answer speed, hello there :)

In this v2023.1.2 version all works as expected.

Then i upgraded to this v2023.2.1 version because of #1561.
And this started happening.

Here are the logs:

DBG ts=1691166952918454300 logger=server msg=ttl reason=ttl is reached pid=127 internal_event_name=EventTTL

DBG ts=1691166952918711000 logger=server msg=ttl reason=ttl is reached pid=125 internal_event_name=EventTTL

DBG ts=1691166952918947000 logger=server msg=ttl reason=ttl is reached pid=128 internal_event_name=EventTTL

DBG ts=1691166952919233800 logger=server msg=ttl reason=ttl is reached pid=117 internal_event_name=EventTTL

DBG ts=1691166952919539000 logger=server msg=ttl reason=ttl is reached pid=119 internal_event_name=EventTTL

DBG ts=1691166952919688000 logger=server msg=ttl reason=ttl is reached pid=121 internal_event_name=EventTTL

DBG ts=1691166952919835000 logger=server msg=ttl reason=ttl is reached pid=124 internal_event_name=EventTTL

DBG ts=1691166952919971600 logger=server msg=ttl reason=ttl is reached pid=126 internal_event_name=EventTTL

DBG ts=1691166952920330800 logger=server msg=ttl reason=ttl is reached pid=122 internal_event_name=EventTTL

DBG ts=1691166952920530400 logger=server msg=ttl reason=ttl is reached pid=123 internal_event_name=EventTTL

DBG ts=1691166952920764200 logger=server msg=ttl reason=ttl is reached pid=118 internal_event_name=EventTTL

DBG ts=1691167253918422300 logger=server msg=ttl reason=ttl is reached pid=311 internal_event_name=EventTTL

stop signal received, grace timeout is: 30 seconds

INF ts=1691167331850969300 logger=server msg=destroy signal received timeout=60

DBG ts=1691167331861239300 logger=server msg=sending stop request to the worker pid=125

DBG ts=1691167331861514800 logger=server msg=sending stop request to the worker pid=128

DBG ts=1691167331861239300 logger=server msg=sending stop request to the worker pid=122

DBG ts=1691167331861590000 logger=server msg=sending stop request to the worker pid=117

DBG ts=1691167331861640700 logger=server msg=sending stop request to the worker pid=124

DBG ts=1691167331861648400 logger=server msg=sending stop request to the worker pid=119

DBG ts=1691167331861753900 logger=server msg=sending stop request to the worker pid=121

DBG ts=1691167331861759700 logger=server msg=sending stop request to the worker pid=126

DBG ts=1691167331861857500 logger=server msg=sending stop request to the worker pid=311

DBG ts=1691167331861862000 logger=server msg=sending stop request to the worker pid=127

DBG ts=1691167331861919500 logger=server msg=sending stop request to the worker pid=123

DBG ts=1691167331861920500 logger=server msg=sending stop request to the worker pid=118

DBG ts=1691167332034086000 logger=server msg=worker destroyed pid=117 internal_event_name=EventWorkerDestruct

DBG ts=1691167332034119700 logger=server msg=worker destroyed pid=311 internal_event_name=EventWorkerDestruct

DBG ts=1691167332034129200 logger=server msg=worker destroyed pid=122 internal_event_name=EventWorkerDestruct

DBG ts=1691167332034137900 logger=server msg=worker destroyed pid=118 internal_event_name=EventWorkerDestruct

DBG ts=1691167332034249500 logger=server msg=worker destroyed pid=123 internal_event_name=EventWorkerDestruct

DBG ts=1691167332034146800 logger=server msg=worker destroyed pid=121 internal_event_name=EventWorkerDestruct

DBG ts=1691167332034354200 logger=server msg=worker destroyed pid=125 internal_event_name=EventWorkerDestruct

DBG ts=1691167332034308400 logger=server msg=worker destroyed pid=119 internal_event_name=EventWorkerDestruct

DBG ts=1691167332034316500 logger=server msg=worker destroyed pid=128 internal_event_name=EventWorkerDestruct

DBG ts=1691167332034324700 logger=server msg=worker destroyed pid=124 internal_event_name=EventWorkerDestruct

DBG ts=1691167332034337000 logger=server msg=worker destroyed pid=127 internal_event_name=EventWorkerDestruct

DBG ts=1691167332034346500 logger=server msg=worker destroyed pid=126 internal_event_name=EventWorkerDestruct

DBG ts=1691167333034713600 logger=lock msg=received stop signal, acquiring lock/release mutexes

DBG ts=1691167333034845700 logger=lock msg=acquired muCh and releaseMuCh mutexes resource=stop-internal id=stop-internal

DBG ts=1691167333034857000 logger=lock msg=acquired stop mutex

DBG ts=1691167333034863600 logger=lock msg=releaseMuCh lock returned resource=internal-stop id=internal-stop

DBG ts=1691167333034868500 logger=lock msg=signal sent to all resources

[rustatian]

Thanks for bisecting the issue, I'll have a look shortly 👍🏻

[Aleksa1996]

Ive been playing a little with ttl option and this is what i discovered:

Set ttl to 30s. When workers reach ttl (30 seconds), they go into invalid state and sit in invalid state until new request arrives.

Im using docker with the following healthcheck:

HEALTHCHECK --interval=30s --timeout=30s \
  CMD curl http://localhost:2114/health?plugin=http -s -f -m 3 -o /dev/null || exit 1

Healthchecks are not passing because workers are in invalid state.

root@ccaa6b319570:/var/www/html# curl http://localhost:2114/health?plugin=http
plugin: http, status: 503

But when request arrives on http.address in my case 0.0.0.0:80 RR instantly restarts all workers and proceeds with request handling. And all workers become ready again.

[rustatian]

Yes, this is the usual behavior (which was previously fixed, but somehow appeared now). All workers are in the internal queue and their state is marked asyncroniously. When you send a request, RR checks the state of the worker and reallocates it if the state is not Ready. So, in general, it is safe to use RR while you see that all workers are in the Invalid state. This will be fixed in the 2023.2.2 release.

[Aleksa1996]

Thanks!

[rustatian]

@Aleksa1996 Done: