Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[🐛 BUG]: Services directly killed when restarting or terminating #1814

Closed
1 task done
chazzbg opened this issue Dec 18, 2023 · 4 comments · Fixed by roadrunner-server/service#48
Closed
1 task done

[🐛 BUG]: Services directly killed when restarting or terminating #1814

chazzbg opened this issue Dec 18, 2023 · 4 comments · Fixed by roadrunner-server/service#48
Assignees
@rustatian
Labels
B-bug Bug: bug, exception B-regression Bug: regression bugs
Milestone
v2023.3.9

Comments

@chazzbg
Copy link

chazzbg commented Dec 18, 2023

No duplicates 🥲.

  • I have searched for a similar issue in our bug tracker and didn't find any solutions.

What happened?

Services are directly killed when their timeout is reached. The same happens when a termination command is send to the RPC.
As far as i understand, rr should send SIGINT and wait for the specified timeout to send SIGKILL but
none of this seems to be happening.

Test setup is dead simple, not much can go wrong and I'm not sure what else i could add.

Version (rr --version)

2023.3.8

How to reproduce the issue?

.rr.yaml

version: "3"
rpc:
  listen: tcp://0.0.0.0:6001

logs:
  mode: development
  channels:
    service:
      level: debug

service:
  dummy:
    command: "php service.php"
    process_num: 1
    exec_timeout: 10s
    remain_after_exit: true
    restart_sec: 5

service.php

<?php

function signalHandler($signo)
{
    echo "Got $signo ...\n";
    exit(0);
}
pcntl_signal(SIGTERM,  'signalHandler');
pcntl_signal(SIGHUP,  'signalHandler');
pcntl_signal(SIGINT,  'signalHandler');
pcntl_signal(SIGQUIT,  'signalHandler');
pcntl_signal(SIGUSR1,  'signalHandler');
pcntl_signal(SIGUSR2,  'signalHandler');

while (true) {
    pcntl_signal_dispatch();
    echo "Sleeping...\n";
    sleep(1);
}

Dockerfile

FROM php:8.2-cli

COPY --from=mlocati/php-extension-installer:2.1 /usr/bin/install-php-extensions /usr/local/bin
COPY --from=ghcr.io/roadrunner-server/roadrunner:2023.3.8 /usr/bin/rr /usr/local/bin/rr

RUN cp /usr/local/etc/php/php.ini-development /usr/local/etc/php/php.ini

RUN install-php-extensions pcntl

ADD . /app

WORKDIR /app


CMD ["rr", "serve"]

Relevant log output

# Log from rr serve
$ docker run --rm reproduce:latest
2023-12-18T16:46:13+0000        DEBUG   rpc             plugin was started      {"address": "tcp://0.0.0.0:6001", "list of the plugins with RPC methods:": ["lock", "service", "informer", "resetter", "app"]}
[INFO] RoadRunner server started; version: 2023.3.8, buildtime: 2023-12-14T16:05:26+0000
[INFO] sdnotify: not notified
2023-12-18T16:46:13+0000        INFO    service         service was started     {"name": "dummy", "command": "php service.php"}
2023-12-18T16:46:13+0000        INFO    service         Sleeping...
2023-12-18T16:46:14+0000        INFO    service         Sleeping...
2023-12-18T16:46:15+0000        INFO    service         Sleeping...
2023-12-18T16:46:16+0000        INFO    service         Sleeping...
2023-12-18T16:46:17+0000        INFO    service         Sleeping...
2023-12-18T16:46:18+0000        INFO    service         Sleeping...
2023-12-18T16:46:19+0000        INFO    service         Sleeping...
2023-12-18T16:46:20+0000        INFO    service         Sleeping...
2023-12-18T16:46:21+0000        INFO    service         Sleeping...
2023-12-18T16:46:22+0000        INFO    service         Sleeping...
2023-12-18T16:46:23+0000        ERROR   service         wait    {"error": "signal: killed"}
2023-12-18T16:46:28+0000        INFO    service         Sleeping...
2023-12-18T16:46:29+0000        INFO    service         Sleeping...
2023-12-18T16:46:30+0000        INFO    service         Sleeping...
2023-12-18T16:46:31+0000        INFO    service         Sleeping...
2023-12-18T16:46:32+0000        INFO    service         Sleeping...
2023-12-18T16:46:33+0000        INFO    service         Sleeping...
2023-12-18T16:46:34+0000        INFO    service         Sleeping...
2023-12-18T16:46:35+0000        INFO    service         Sleeping...
2023-12-18T16:46:36+0000        INFO    service         Sleeping...
2023-12-18T16:46:37+0000        INFO    service         Sleeping...
2023-12-18T16:46:38+0000        ERROR   service         wait    {"error": "signal: killed"}
^Cstop signal received, grace timeout is: 30 seconds
2023-12-18T16:46:39+0000        DEBUG   lock            received stop signal, acquiring lock/release mutexes
2023-12-18T16:46:39+0000        DEBUG   lock            acquired stop mutex
2023-12-18T16:46:39+0000        INFO    service         service was stopped     {"name": "dummy", "command": "php service.php"}
2023-12-18T16:46:39+0000        DEBUG   lock            signal sent to all resources

# Log from manually running and stopping ( with ctrl+c ) the same script
$ docker run --rm reproduce:latest php service.php
Sleeping...
Sleeping...
Sleeping...
^CGot 2 ...

# Log from stopping the container itself
$ docker run --rm reproduce:latest php service.php
Sleeping...
Sleeping...
Sleeping...
Sleeping...
Sleeping...
Got 15 ...
@chazzbg chazzbg added B-bug Bug: bug, exception F-need-verification labels Dec 18, 2023
@chazzbg
Copy link
Author

chazzbg commented Dec 18, 2023

version 2023.2.2 acts the same when service is restarting, but when server is stopped, service receives signal

$ docker run --rm reproduce:latest              
2023-12-18T16:58:25+0000        DEBUG   rpc             plugin was started      {"address": "tcp://0.0.0.0:6001", "list of the plugins with RPC methods:": ["service", "resetter", "app", "informer", "lock"]}
[INFO] RoadRunner server started; version: 2023.2.2, buildtime: 2023-08-10T16:38:29+0000
2023-12-18T16:58:25+0000        INFO    service         service was started     {"name": "dummy", "command": "php service.php"}
2023-12-18T16:58:25+0000        INFO    service         Sleeping...
2023-12-18T16:58:26+0000        INFO    service         Sleeping...
2023-12-18T16:58:27+0000        INFO    service         Sleeping...
2023-12-18T16:58:28+0000        INFO    service         Sleeping...
2023-12-18T16:58:29+0000        INFO    service         Sleeping...
2023-12-18T16:58:30+0000        INFO    service         Sleeping...
2023-12-18T16:58:31+0000        INFO    service         Sleeping...
2023-12-18T16:58:32+0000        INFO    service         Sleeping...
2023-12-18T16:58:33+0000        INFO    service         Sleeping...
2023-12-18T16:58:34+0000        INFO    service         Sleeping...
2023-12-18T16:58:35+0000        ERROR   service         wait    {"error": "signal: killed"}
2023-12-18T16:58:40+0000        INFO    service         Sleeping...
^Cstop signal received, grace timeout is: 30 seconds
2023-12-18T16:58:40+0000        INFO    service         service was stopped     {"name": "dummy", "command": "php service.php"}
2023-12-18T16:58:40+0000        DEBUG   lock            received stop signal, acquiring lock/release mutexes
2023-12-18T16:58:40+0000        DEBUG   lock            acquired muCh and releaseMuCh mutexes   {"resource": "stop-internal", "id": "stop-internal"}
2023-12-18T16:58:40+0000        DEBUG   lock            acquired stop mutex
2023-12-18T16:58:40+0000        DEBUG   lock            releaseMuCh lock returned       {"resource": "internal-stop", "id": "internal-stop"}
2023-12-18T16:58:40+0000        INFO    service         Got 2 ...
2023-12-18T16:58:40+0000        DEBUG   lock            signal sent to all resources

@rustatian
Copy link
Member

Hey @chazzbg 👋
Thanks for the report 👍

I'll double-check this case, but looks strange, since I'm sending SIGINT to the underlying process.
It might be context cancellation sends a different signal. Could you please check without the exec_timeout ?

@chazzbg
Copy link
Author

chazzbg commented Dec 18, 2023

I also find this quite odd.

Without exec_timeout, service process seems to get the signal

docker run --rm reproduce:latest
2023-12-18T20:30:22+0000        DEBUG   rpc             plugin was started      {"address": "tcp://0.0.0.0:6001", "list of the plugins with RPC methods:": ["lock", "service", "informer", "resetter", "app"]}
[INFO] RoadRunner server started; version: 2023.3.8, buildtime: 2023-12-14T16:05:26+0000
[INFO] sdnotify: not notified
2023-12-18T20:30:22+0000        INFO    service         service was started     {"name": "dummy", "command": "php service.php"}
2023-12-18T20:30:22+0000        INFO    service         Sleeping...
2023-12-18T20:30:23+0000        INFO    service         Sleeping...
2023-12-18T20:30:24+0000        INFO    service         Sleeping...
2023-12-18T20:30:25+0000        INFO    service         Sleeping...
2023-12-18T20:30:26+0000        INFO    service         Sleeping...
2023-12-18T20:30:27+0000        INFO    service         Sleeping...
2023-12-18T20:30:28+0000        INFO    service         Sleeping...
2023-12-18T20:30:29+0000        INFO    service         Sleeping...
2023-12-18T20:30:30+0000        INFO    service         Sleeping...
2023-12-18T20:30:31+0000        INFO    service         Sleeping...
2023-12-18T20:30:32+0000        INFO    service         Sleeping...
^Cstop signal received, grace timeout is: 30 seconds
2023-12-18T20:30:32+0000        DEBUG   lock            received stop signal, acquiring lock/release mutexes
2023-12-18T20:30:32+0000        DEBUG   lock            acquired stop mutex
2023-12-18T20:30:32+0000        DEBUG   lock            signal sent to all resources
2023-12-18T20:30:32+0000        INFO    service         Got 2 ...
2023-12-18T20:30:32+0000        INFO    service         service was stopped     {"name": "dummy", "command": "php service.php"}

@rustatian
Copy link
Member

Ok, thanks. Thus, I know where the bug is 😃

@rustatian rustatian mentioned this issue Dec 18, 2023
Merged
6 tasks
@rustatian rustatian added B-regression Bug: regression bugs and removed F-need-verification labels Dec 19, 2023
@rustatian rustatian moved this to ✅ Done in Jira 😄 Dec 19, 2023
@rustatian rustatian added this to the v2023.3.9 milestone Dec 19, 2023
@rustatian rustatian mentioned this issue Jan 11, 2024
Merged
6 tasks
@Porkepix Porkepix mentioned this issue Jan 11, 2024
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@rustatian rustatian

Labels
B-bug Bug: bug, exception B-regression Bug: regression bugs
Projects
Jira 😄
Status: ✅ Done
Milestone
v2023.3.9
Development

Successfully merging a pull request may close this issue.

fix: properly stop the process roadrunner-server/service
2 participants
@chazzbg @rustatian