Skip to content

Worker sends heartbeat but server does not receive it and removes the worker #890

Open
Open
Worker sends heartbeat but server does not receive it and removes the worker#890

Description

@lahwaacz
lahwaacz
opened on Apr 11, 2025

It turns out that the network connections between a login node and compute nodes on Metacentrum are not super stable, many workers just randomly die several of hours or even days after the start. I've been facing it for quite some time now but finally have some logs to share.

Debug logs for hq server:

[2025-04-11T20:45:00.694Z DEBUG tako::internal::server::rpc] Heartbeat received, worker=777
[2025-04-11T20:45:02.245Z DEBUG tako::internal::server::rpc] Heartbeat received, worker=779
[2025-04-11T20:45:02.381Z DEBUG tako::internal::server::rpc] Heartbeat received, worker=780
[2025-04-11T20:45:08.694Z DEBUG tako::internal::server::rpc] Heartbeat received, worker=777
[2025-04-11T20:45:10.245Z DEBUG tako::internal::server::rpc] Heartbeat received, worker=779
[2025-04-11T20:45:10.380Z DEBUG tako::internal::server::rpc] Heartbeat received, worker=780
[2025-04-11T20:45:16.043Z DEBUG hyperqueue::server::client] New client connection
[2025-04-11T20:45:16.044Z DEBUG tako::internal::transfer::auth] Worker authorization started
[2025-04-11T20:45:16.044Z DEBUG tako::internal::transfer::auth] Challenge verification started
[2025-04-11T20:45:16.044Z DEBUG tako::internal::transfer::auth] Challenge verification finished
[2025-04-11T20:45:16.091Z DEBUG hyperqueue::server::client] Client connection ended
[2025-04-11T20:45:16.694Z DEBUG tako::internal::server::rpc] Heartbeat received, worker=777
[2025-04-11T20:45:18.245Z DEBUG tako::internal::server::rpc] Heartbeat received, worker=779
[2025-04-11T20:45:18.380Z DEBUG tako::internal::server::rpc] Heartbeat received, worker=780
[2025-04-11T20:45:24.694Z DEBUG tako::internal::server::rpc] Heartbeat received, worker=777
[2025-04-11T20:45:26.245Z DEBUG tako::internal::server::rpc] Heartbeat received, worker=779
[2025-04-11T20:45:26.380Z DEBUG tako::internal::server::rpc] Heartbeat received, worker=780
[2025-04-11T20:45:32.694Z DEBUG tako::internal::server::rpc] Heartbeat received, worker=777
[2025-04-11T20:45:34.245Z DEBUG tako::internal::server::rpc] Heartbeat received, worker=779
[2025-04-11T20:45:34.380Z DEBUG tako::internal::server::rpc] Heartbeat received, worker=780
[2025-04-11T20:45:37.236Z DEBUG hyperqueue::server::autoalloc::process] No message received in 300000 ms, refreshing state
[2025-04-11T20:45:37.236Z DEBUG hyperqueue::server::autoalloc::process] Attempt to refresh allocations of queue 10
[2025-04-11T20:45:37.236Z DEBUG hyperqueue::server::autoalloc::process] Attempt to refresh allocations of queue 7
[2025-04-11T20:45:37.236Z DEBUG hyperqueue::server::autoalloc::process] Attempt to refresh allocations of queue 4
[2025-04-11T20:45:37.236Z DEBUG hyperqueue::server::autoalloc::process] Attempt to refresh allocations of queue 1
[2025-04-11T20:45:37.236Z DEBUG hyperqueue::server::autoalloc::process] Attempt to refresh allocations of queue 11
[2025-04-11T20:45:37.236Z DEBUG hyperqueue::server::autoalloc::queue::pbs] Running PBS command `qstat -f 10299845.pbs-m1.metacentrum.cz -F json -x`
[2025-04-11T20:46:11.931Z DEBUG tako::internal::server::rpc] Heartbeat not arrived, worker=777
[2025-04-11T20:46:11.931Z DEBUG tako::internal::server::rpc] Heartbeat loop terminated, worker=777
[2025-04-11T20:46:11.932Z INFO  tako::internal::server::rpc] Worker 777 connection closed (connection: 78.128.242.57:59160)
[2025-04-11T20:46:11.932Z DEBUG tako::internal::server::reactor] Removing worker 777
[2025-04-11T20:46:11.932Z DEBUG tako::internal::server::reactor] Removing task task=21474837139 from lost worker
[2025-04-11T20:46:11.932Z DEBUG tako::internal::server::reactor] Running tasks on lost worker 777: [TaskId(21474837139)]
[2025-04-11T20:46:11.932Z DEBUG tako::internal::server::rpc] Connection ended: 78.128.242.57:59160
[2025-04-11T20:46:11.932Z DEBUG tako::internal::server::rpc] Heartbeat not arrived, worker=779
[2025-04-11T20:46:11.932Z DEBUG tako::internal::server::rpc] Heartbeat loop terminated, worker=779
[2025-04-11T20:46:11.932Z INFO  tako::internal::server::rpc] Worker 779 connection closed (connection: 78.128.242.64:57454)
[2025-04-11T20:46:11.932Z DEBUG tako::internal::server::reactor] Removing worker 779
[2025-04-11T20:46:11.932Z DEBUG tako::internal::server::reactor] Removing task task=30064772402 from lost worker
[2025-04-11T20:46:11.932Z DEBUG tako::internal::server::reactor] Running tasks on lost worker 779: [TaskId(30064772402)]
[2025-04-11T20:46:11.932Z DEBUG tako::internal::server::rpc] Connection ended: 78.128.242.64:57454
[2025-04-11T20:46:11.932Z DEBUG tako::internal::server::rpc] Heartbeat not arrived, worker=780
[2025-04-11T20:46:11.932Z DEBUG tako::internal::server::rpc] Heartbeat loop terminated, worker=780
[2025-04-11T20:46:11.932Z INFO  tako::internal::server::rpc] Worker 780 connection closed (connection: 78.128.242.28:48496)
[2025-04-11T20:46:11.932Z DEBUG tako::internal::server::reactor] Removing worker 780
[2025-04-11T20:46:11.932Z DEBUG tako::internal::server::reactor] Removing task task=21474837083 from lost worker
[2025-04-11T20:46:11.932Z DEBUG tako::internal::server::reactor] Running tasks on lost worker 780: [TaskId(21474837083)]
[2025-04-11T20:46:11.933Z DEBUG tako::internal::server::rpc] Connection ended: 78.128.242.28:48496
[2025-04-11T20:46:11.933Z DEBUG hyperqueue::server::state] Worker lost id=777
[2025-04-11T20:46:11.933Z DEBUG hyperqueue::server::state] Worker lost id=779
[2025-04-11T20:46:11.933Z DEBUG hyperqueue::server::state] Worker lost id=780
[2025-04-11T20:46:21.920Z DEBUG hyperqueue::server::client] New client connection
[2025-04-11T20:46:21.920Z DEBUG tako::internal::transfer::auth] Worker authorization started
[2025-04-11T20:46:21.920Z DEBUG tako::internal::transfer::auth] Challenge verification started
[2025-04-11T20:46:21.920Z DEBUG tako::internal::transfer::auth] Challenge verification finished
[2025-04-11T20:46:21.963Z DEBUG hyperqueue::server::client] Client connection ended

Debug stderr of worker 777:

[2025-04-11T20:45:00.693Z DEBUG tako::internal::worker::rpc] Heartbeat sent
[2025-04-11T20:45:08.693Z DEBUG tako::internal::worker::rpc] Heartbeat sent
[2025-04-11T20:45:16.693Z DEBUG tako::internal::worker::rpc] Heartbeat sent
[2025-04-11T20:45:24.693Z DEBUG tako::internal::worker::rpc] Heartbeat sent
[2025-04-11T20:45:32.692Z DEBUG tako::internal::worker::rpc] Heartbeat sent
[2025-04-11T20:45:40.693Z DEBUG tako::internal::worker::rpc] Heartbeat sent
[2025-04-11T20:45:48.693Z DEBUG tako::internal::worker::rpc] Heartbeat sent
[2025-04-11T20:45:56.693Z DEBUG tako::internal::worker::rpc] Heartbeat sent
[2025-04-11T20:46:04.693Z DEBUG tako::internal::worker::rpc] Heartbeat sent
[2025-04-11T20:46:11.932Z DEBUG tako::internal::worker::rpc] Server read connection has disconnected
[2025-04-11T20:46:11.932Z DEBUG tako::internal::worker::state] Dropping non running tasks
[2025-04-11T20:46:11.932Z DEBUG tako::internal::worker::state] Canceling task 21474837139
[2025-04-11T20:46:11.932Z INFO  tako::internal::worker::rpc] Waiting for stopping running tasks
[2025-04-11T20:46:11.932Z DEBUG hyperqueue::worker::start::program] Received stop command, attempting to end task 5/659 with SIGINT
[2025-04-11T20:46:12.933Z DEBUG hyperqueue::worker::start::program] Task 5/659 has been killed
[2025-04-11T20:46:12.934Z DEBUG tako::internal::worker::reactor] Inner task canceled id=21474837139
[2025-04-11T20:46:12.934Z DEBUG tako::internal::worker::state] Removing running task id=21474837139
[2025-04-11T20:46:12.934Z DEBUG tako::internal::worker::comm] Notifying that worker is empty
[2025-04-11T20:46:12.934Z INFO  tako::internal::worker::rpc] All running tasks were stopped
IO error: Connection reset by peer (os error 104)

Caused by:
    Connection reset by peer (os error 104)

Debug stderr of worker 779:

[2025-04-11T20:45:02.244Z DEBUG tako::internal::worker::rpc] Heartbeat sent
[2025-04-11T20:45:10.244Z DEBUG tako::internal::worker::rpc] Heartbeat sent
[2025-04-11T20:45:18.244Z DEBUG tako::internal::worker::rpc] Heartbeat sent
[2025-04-11T20:45:26.244Z DEBUG tako::internal::worker::rpc] Heartbeat sent
[2025-04-11T20:45:34.244Z DEBUG tako::internal::worker::rpc] Heartbeat sent
[2025-04-11T20:45:42.244Z DEBUG tako::internal::worker::rpc] Heartbeat sent
[2025-04-11T20:45:50.244Z DEBUG tako::internal::worker::rpc] Heartbeat sent
[2025-04-11T20:45:58.244Z DEBUG tako::internal::worker::rpc] Heartbeat sent
[2025-04-11T20:46:06.244Z DEBUG tako::internal::worker::rpc] Heartbeat sent
[2025-04-11T20:46:11.933Z DEBUG tako::internal::worker::rpc] Server read connection has disconnected
[2025-04-11T20:46:11.933Z DEBUG tako::internal::worker::state] Dropping non running tasks
[2025-04-11T20:46:11.933Z DEBUG tako::internal::worker::state] Canceling task 30064772402
[2025-04-11T20:46:11.933Z INFO  tako::internal::worker::rpc] Waiting for stopping running tasks
[2025-04-11T20:46:11.933Z DEBUG hyperqueue::worker::start::program] Received stop command, attempting to end task 7/1330 with SIGINT
[2025-04-11T20:46:12.706Z DEBUG hyperqueue::worker::start::program] Task 7/1330 has ended gracefully after a signal
[2025-04-11T20:46:12.708Z DEBUG tako::internal::worker::reactor] Inner task canceled id=30064772402
[2025-04-11T20:46:12.708Z DEBUG tako::internal::worker::state] Removing running task id=30064772402
[2025-04-11T20:46:12.708Z DEBUG tako::internal::worker::comm] Notifying that worker is empty
[2025-04-11T20:46:12.708Z INFO  tako::internal::worker::rpc] All running tasks were stopped
IO error: Connection reset by peer (os error 104)

Caused by:
    Connection reset by peer (os error 104)

Debug stderr of worker 780:

[2025-04-11T20:45:02.380Z DEBUG tako::internal::worker::rpc] Heartbeat sent
[2025-04-11T20:45:10.379Z DEBUG tako::internal::worker::rpc] Heartbeat sent
[2025-04-11T20:45:18.379Z DEBUG tako::internal::worker::rpc] Heartbeat sent
[2025-04-11T20:45:26.379Z DEBUG tako::internal::worker::rpc] Heartbeat sent
[2025-04-11T20:45:34.379Z DEBUG tako::internal::worker::rpc] Heartbeat sent
[2025-04-11T20:45:42.379Z DEBUG tako::internal::worker::rpc] Heartbeat sent
[2025-04-11T20:45:50.379Z DEBUG tako::internal::worker::rpc] Heartbeat sent
[2025-04-11T20:45:58.379Z DEBUG tako::internal::worker::rpc] Heartbeat sent
[2025-04-11T20:46:06.380Z DEBUG tako::internal::worker::rpc] Heartbeat sent
[2025-04-11T20:46:11.933Z DEBUG tako::internal::worker::rpc] Server read connection has disconnected
[2025-04-11T20:46:11.933Z DEBUG tako::internal::worker::state] Dropping non running tasks
[2025-04-11T20:46:11.933Z DEBUG tako::internal::worker::state] Canceling task 21474837083
[2025-04-11T20:46:11.933Z INFO  tako::internal::worker::rpc] Waiting for stopping running tasks
[2025-04-11T20:46:11.933Z DEBUG hyperqueue::worker::start::program] Received stop command, attempting to end task 5/603 with SIGINT
[2025-04-11T20:46:12.638Z DEBUG hyperqueue::worker::start::program] Task 5/603 has ended gracefully after a signal
[2025-04-11T20:46:12.640Z DEBUG tako::internal::worker::reactor] Inner task canceled id=21474837083
[2025-04-11T20:46:12.640Z DEBUG tako::internal::worker::state] Removing running task id=21474837083
[2025-04-11T20:46:12.640Z DEBUG tako::internal::worker::comm] Notifying that worker is empty
[2025-04-11T20:46:12.640Z INFO  tako::internal::worker::rpc] All running tasks were stopped
IO error: Connection reset by peer (os error 104)

Caused by:
    Connection reset by peer (os error 104)

It seems that all three workers have been sending their heartbeats, but the server did not receive any heartbeats after 20:45:35. On the other hand, the timestamps of Heartbeat loop terminated on the server and Server read connection has disconnected on the workers match up to 1ms difference.

This seems very weird, what might have happened? Maybe the messages from workers got lost but the message from the server got through to the workers?

In any case, it would be better to let the workers reconnect on a new connection to the server instead of removing the worker on the first network problem.

Also note that there is not enough information with the INFO level: for example, worker 777 had

[2025-04-10T18:58:44.641Z INFO  tako::internal::worker::rpc] Connecting to server (candidate addresses = [78.128.246.43:40965, [2001:718:ff05:106::43]:40965])

and then just

[2025-04-11T20:46:11.932Z INFO  tako::internal::worker::rpc] Waiting for stopping running tasks
[2025-04-11T20:46:12.934Z INFO  tako::internal::worker::rpc] All running tasks were stopped

Before I enabled debug, I had no idea what was going on...

Activity

  1. spirali commented on Apr 12, 2025

    @spirali
    spirali
    on Apr 12, 2025
    Collaborator

    It is quite weird. But maybe the network failed in some unidirectional way, that data from server could be delivered and from worker not.

    I am not sure what intervention can we do on our side. The only thing that is my mind is to allow to configure how many missed heartbeats can server tolerate.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions