Skip to content

investigate why run_on_stop doesn't work consistently #17108

New issue
New issue
Closed
Bug
#17227
Closed
investigate why run_on_stop doesn't work consistently#17108
Bug
#17227
Assignees
mafredri

Description

@aslilac
aslilac
opened on Feb 24, 2025

while working on #16660, I was unable to get a shutdown script to ever run. that's bad!

we should figure out why agents aren't runnning shutdown scripts and fix it.

when we do, we should move the make clean of the aforementioned pr into a shutdown script.

Activity

  1. matifali
    added the
    Bug
    issue type on Feb 27, 2025

  2. matifali commented on Feb 27, 2025

    @matifali
    matifali
    on Feb 27, 2025
    Member

    At least 2 community members also reported this:
    https://discord.com/channels/747933592273027093/1329720357472567296/1329720357472567296

  3. aslilac
    self-assigned this
    on Feb 27, 2025
  4. matifali
    transferred this issue fromcoder/internalon Mar 26, 2025
  5. matifali
    added the
    Bug
    issue type on Mar 26, 2025

  6. mafredri commented on Mar 26, 2025

    @mafredri
    mafredri
    on Mar 26, 2025
    Member

    @aslilac have you seen #6174 (also #6175)?

    Unless the provider is configured, it's very likely that either a wrong signal is sent or a timeout is hit early, killing the workspace before shutdown script has started or completed.

  7. aslilac commented on Mar 26, 2025

    @aslilac
    aslilac
    on Mar 26, 2025
    MemberAuthor

    I wonder if we could add some sort of warning when a stop script is specified and it doesn't complete

    If that's really all that's going on, our dogfood template isn't set up correctly to allow for run_on_stop scripts

  8. mafredri commented on Mar 26, 2025

    @mafredri
    mafredri
    on Mar 26, 2025
    Member

    You're right, it wasn't. I actually merged a fix for that earlier today: #17110

    I wonder if we could add some sort of warning when a stop script is specified and it doesn't complete

    Hmm, perhaps we could. We could infer it from script timings and whether or not one was sent in for the stop script. But I'm not sure how/where we'd surface this info though.

  9. mafredri commented on Apr 1, 2025

    @mafredri
    mafredri
    on Apr 1, 2025
    Member

    I discovered an issued related to this, and I believe it may be what you observed @aslilac. Sometimes shutdown scripts run, other times they don't.

    During shutdown the agent seems to be stuck in a loop trying to re-connect to coderd.

    @spikecurtis had a few ideas for how to deal with this:

    1. Coderd could be a little more graceful in its communication, and directly tell the agent that it should shut down, rather than unceremoniously killing the connection
    2. When we get the SIGINT, we could tell the agent to stop trying to dial coderd, and proceed with any shutdown scripts it already knows about.

    We do probably want both the network message and the signal --- if coderd tells the agent to shut down, you probably don't want it to actually exit until it gets an OS signal, lest it be restarted by K8s or whatever
    -- Spike

    For now, option 2 may be more robust and easier to implement. Let's say, for arguments sake, the agent loses network connectivity as part of a down provision, then option 1 may not complete as expected.

    Down the line, we should also consider #6175.

    Here we see that the new workspace build provision has started and invalidated the agent token:

    2025-04-01 10:31:29.246 [debu]  batch updating metadata
2025-04-01 10:31:29.255 [info]  stdlib: [ERR] yamux: Failed to read header: failed to get reader: failed to read frame header: EOF
2025-04-01 10:31:29.255 [debu]  disconnected from derp map RPC
2025-04-01 10:31:29.255 [debu]  failed to read from protocol  error="context canceled"
2025-04-01 10:31:29.255 [debu]  batch update metadata complete  error="context canceled"
2025-04-01 10:31:29.255 [debu]  routine exited  name="derp map subscriber" ...
    error= recv DERPMap error:
               github.com/coder/coder/v2/agent.(*agent).runDERPMapSubscriber
                   /home/runner/work/coder/coder/agent/agent.go:1569
             - context canceled
2025-04-01 10:31:29.255 [debu]  net.tailnet: setAllPeersLost marked peer lost  peer_id=49b82ef0-c3da-41fb-ae24-e10856122d89  key_id=[OwvDr]
2025-04-01 10:31:29.255 [debu]  log sender send loop exiting
2025-04-01 10:31:29.255 [debu]  reportLoop exiting
2025-04-01 10:31:29.255 [debu]  disconnected from coordination RPC
2025-04-01 10:31:29.255 [debu]  routine exited  name="stats report loop"  error=<nil>
2025-04-01 10:31:29.255 [debu]  swallowing context canceled  name="report connections"
2025-04-01 10:31:29.255 [debu]  swallowing context canceled  name="report lifecycle"
2025-04-01 10:31:29.255 [debu]  swallowing context canceled  name="send logs"
2025-04-01 10:31:29.255 [debu]  routine exited  name="app health reporter"  error=<nil>
2025-04-01 10:31:29.255 [debu]  swallowing context canceled  name="report metadata"
2025-04-01 10:31:29.255 [debu]  swallowing context canceled  name="fetch service banner loop"
2025-04-01 10:31:29.255 [debu]  swallowing context canceled  name=coordination
2025-04-01 10:31:29.255 [warn]  run exited with error ...
    error= error in routine derp map subscriber:
               github.com/coder/coder/v2/agent.(*apiConnRoutineManager).startTailnetAPI.func1
                   /home/runner/work/coder/coder/agent/agent.go:2031
             - recv DERPMap error:
               github.com/coder/coder/v2/agent.(*agent).runDERPMapSubscriber
                   /home/runner/work/coder/coder/agent/agent.go:1569
             - context canceled
2025-04-01 10:31:29.418 [info]  connecting to coderd
2025-04-01 10:31:29.778 [warn]  run exited with error ...
    error= GET https://dev.coder.com/api/v2/workspaceagents/me/rpc?version=2.4: unexpected status code 401: Workspace agent not authorized.: Try logging in using 'coder login'.
                Error: The agent cannot authenticate until the workspace provision job has been completed. If the job is no longer running, this agent is invalid.
[...]

    And we can observe that the agent shutdown has actually started:

    2025-04-01 10:31:35.122 [info]  shutting down agent
2025-04-01 10:31:35.122 [debu]  set lifecycle state  current={"state":"shutting_down","changed_at":"2025-04-01T10:31:35.122747Z"}  last={"state":"ready","changed_at":"2025-04-01T10:16:23.548304Z"}
2025-04-01 10:31:35.122 [info]  ssh-server: ssh connection complete  remote_addr=[fd60:627a:a42b:4614:8f53:422e:ca6f:d41b]:52127  local_addr=[fd60:627a:a42b:404f:ac4f:2009:affb:427f]:1  error=EOF
2025-04-01 10:31:35.122 [info]  ssh-server: stopped serving listener  listen_addr={} ...
    error= tailnet:
               github.com/coder/coder/v2/tailnet.(*listener).Accept
                   /home/runner/work/coder/coder/tailnet/conn.go:952
             - use of closed network connection
2025-04-01 10:31:35.122 [info]  ssh-server: stopped serving listener  listen_addr={} ...
    error= tailnet:
               github.com/coder/coder/v2/tailnet.(*listener).Accept
                   /home/runner/work/coder/coder/tailnet/conn.go:952
             - use of closed network connection
2025-04-01 10:31:35.136 [debu]  ssh-server: copy output done  remote_addr=[fd60:627a:a42b:4614:8f53:422e:ca6f:d41b]:52127  local_addr=[fd60:627a:a42b:404f:ac4f:2009:affb:427f]:1  id=27952be9-f348-46a5-b151-213a57b9316b  bytes=43936  error=<nil>
2025-04-01 10:31:35.137 [info]  ssh-server: ssh session returned  remote_addr=[fd60:627a:a42b:4614:8f53:422e:ca6f:d41b]:52127  local_addr=[fd60:627a:a42b:404f:ac4f:2009:affb:427f]:1  id=27952be9-f348-46a5-b151-213a57b9316b  error="signal: killed"  process_exit_code=-1  exit_code=255
2025-04-01 10:31:37.553 [info]  connecting to coderd
2025-04-01 10:31:37.672 [warn]  run exited with error ...
    error= GET https://dev.coder.com/api/v2/workspaceagents/me/rpc?version=2.4: unexpected status code 401: Workspace agent not authorized.: Try logging in using 'coder login'.
                Error: The agent cannot authenticate until the workspace provision job has been completed. If the job is no longer running, this agent is invalid.
2025-04-01 10:31:42.372 [info]  connecting to coderd
[...]

    But the shutdown scripts are never executed and connecting to coderd is stuck in a loop.

  10. mafredri
    assigned
    mafredri
    and unassigned
    aslilac
    on Apr 2, 2025
  11. mafredri
    added a commit that references this issue on Apr 2, 2025

    fix(agent): improve SSH server shutdown and continue after timeout

    337dddf
  12. mafredri
    closed this as completedin #17227on Apr 3, 2025
  13. mafredri
    added a commit that references this issue on Apr 3, 2025

    fix(agent): ensure SSH server shutdown with process groups (#17227)

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

Metadata

Metadata

Assignees

Labels

No labels
No labels

Type

Bug

Projects

No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions