Server Node Doesn't Open Port 4646 After Restart with Systemctl

[msherman13]

Nomad version

Nomad v1.10.0
BuildDate 2025-04-09T16:40:54Z
Revision e26a2bd

Operating system and Environment details

Rocky 9.3

Issue

When server node is restarted with systemctl restart nomad, it often never opens port 4646 (although sometimes it does). The only way to fix this is to stop the service, wait 30 seconds or more, then start the service.

Reproduction steps

Restart nomad systemctl service

Expected Result

Port 4646 opens

Actual Result

Port 4646 never opens, although 4648 and 4647 do open.

$ ss -ltnp | grep nomad
LISTEN 0      4096               *:4648            *:*    users:(("nomad",pid=216756,fd=9))                                                                                                                                  
LISTEN 0      4096               *:4647            *:*    users:(("nomad",pid=216756,fd=6))                                                                                                                                  

Nomad Server logs (if appropriate)

Nothing is notable in the server logs when this occurs:

Mar 27 00:37:18 nomad[216705]:  nomad: setting up raft bolt store: no_freelist_sync=false
Mar 27 00:37:18 nomad[216705]:  nomad.raft: starting restore from snapshot: id=76-3907612-1774483368628 last-index=3907612 last-term=76 size-in-bytes=6376122982
Mar 27 00:37:29 nomad[216705]:  nomad.raft: snapshot restore progress: id=76-3907612-1774483368628 last-index=3907612 last-term=76 size-in-bytes=6376122982 read-bytes=6376122982 percent-complete="100.00%"
Mar 27 00:37:29 nomad[216705]:  nomad.raft: restored from snapshot: id=76-3907612-1774483368628 last-index=3907612 last-term=76 size-in-bytes=6376122982
Mar 27 00:37:29 nomad[216705]:  nomad.raft: initial configuration: index=1 servers="[{Suffrage:Voter ID:c87212c8-5294-bfb3-6dab-701eb4b32dc3 Address:10.0.35.52:4647}]"
Mar 27 00:37:29 nomad[216705]:  nomad.raft: entering follower state: follower="Node at 10.0.35.52:4647 [Follower]" leader-address= leader-id=
Mar 27 00:37:29 nomad[216705]:  nomad: serf: EventMemberJoin: nomad-server0.global 10.0.35.52
Mar 27 00:37:29 nomad[216705]:  nomad: starting scheduling worker(s): num_workers=4 schedulers=["batch", "system", "_core", "service"]
Mar 27 00:37:29 nomad[216705]:  nomad: started scheduling worker(s): num_workers=4 schedulers=["batch", "system", "_core", "service"]
Mar 27 00:37:29 nomad[216705]:  nomad: serf: Failed to re-join any previously known node
Mar 27 00:37:29 nomad[216705]:  nomad: adding server: server="nomad-server0.global (Addr: 10.0.35.52:4647) (DC: aws-us-east-1)"
Mar 27 00:37:31 nomad[216705]:  nomad.raft: heartbeat timeout reached, starting election: last-leader-addr= last-leader-id=
Mar 27 00:37:31 nomad[216705]:  nomad.raft: entering candidate state: node="Node at 10.0.35.52:4647 [Candidate]" term=77
Mar 27 00:37:31 nomad[216705]:  nomad.raft: pre-vote successful, starting election: term=77 tally=1 refused=0 votesNeeded=1
Mar 27 00:37:31 nomad[216705]:  nomad.raft: election won: term=77 tally=1
Mar 27 00:37:31 nomad[216705]:  nomad.raft: entering leader state: leader="Node at 10.0.35.52:4647 [Leader]"
Mar 27 00:37:31 nomad[216705]:  nomad: cluster leadership acquired
Mar 27 00:37:31 nomad[216705]:  nomad: eval broker status modified: paused=false
Mar 27 00:37:31 nomad[216705]:  nomad: blocked evals status modified: paused=false

[tgross]

Hi @msherman13! This is a weird one, for sure! During agent startup, a few top-level goroutines get kicked off to run various trees of components. The server component, which includes things like the RPC server, Raft, the keyring, and the eval broker is one top-level component. Whereas the HTTP server is mostly independent -- it has to be so that we can run the HTTP server on the clients too. But these top-level components startup in order, and we block on the server setup to be complete.

So this strongly suggests that those server components are getting stuck somewhere during startup. I suspect you're hitting an issue with the keyring because there were some bugs in that at one point in the 1.9.x era, but I can't be sure. The bugs we knew about should be fixed in 1.10.0 in any case, but we'd really love to know if there's something we missed. It might help to know if you have "legacy" pre-1.9.0 keys in the keyring. If you do nomad operator root keyring list and then compare this to the list of the on-disk keystore files, (not their contents, just the file names) that'd be helpful.

In Nomad 1.10.1 we actually added a server_timeout option on the config (#25803) to down the server in this case, which would then let your systemd unit file restart the agent. Not ideal because we shouldn't be getting stuck at all, but it'd get you unstuck.

Something you can do to help us debug this is to send a stuck agent SIGQUIT instead of just restarting it. That'll dump a stack trace in the logs, and we can use that stack trace to pinpoint exactly where it's getting stuck. Ideally after waiting at least 60s so that the stack trace shows which goroutines are stuck vs just waiting for something that'll shortly unblock. (And I know this is painful for prod environments so no worries if you can't wait.)

[msherman13]

@tgross thanks for the quick reply. I will take a look at all of this and follow up here when I have more data.

[msherman13]

@tgross ,

Here is the keyring list from the operator command, and then the keystore on disk:

Key       State         Create Time           Publish Time
13710b48  inactive      2025-08-27T22:57:41Z  2025-09-11T22:48:36Z
16b16e49  inactive      2025-10-11T23:20:39Z  2025-10-26T23:14:31Z
19a4c8c8  inactive      2025-12-25T23:58:08Z  2026-01-09T23:52:31Z
24e1d152  inactive      2026-02-09T00:20:29Z  2026-02-24T00:17:34Z
2a207426  inactive      2026-01-10T00:08:23Z  2026-01-24T23:58:08Z
34df63d1  inactive      2025-11-25T23:47:10Z  2025-12-10T23:38:33Z
35e2e7af  inactive      2025-12-10T23:52:31Z  2025-12-25T23:47:10Z
48e9d79e  inactive      2025-10-26T23:30:04Z  2025-11-10T23:20:39Z
4efaf191  inactive      2025-06-13T22:17:13Z  2025-06-28T22:03:49Z
4fb04d9c  inactive      2025-08-12T22:48:36Z  2025-08-27T22:43:40Z
52d86b41  inactive      2025-07-13T22:36:40Z  2025-07-28T22:27:13Z
577d06c3  inactive      2025-05-29T22:03:49Z  2025-06-13T21:58:53Z
74f254be  inactive      2026-02-24T00:37:18Z  2026-03-11T00:20:29Z
91400e0c  inactive      2025-09-11T23:00:37Z  2025-09-26T22:57:41Z
970dd868  inactive      2025-03-30T21:28:53Z  <none>
a3221368  inactive      2024-05-15T00:57:09Z  <none>
a7f7f72e  inactive      2025-07-28T22:43:40Z  2025-08-12T22:36:40Z
ac918939  inactive      2025-04-29T21:48:53Z  <none>
afb79713  inactive      2025-09-26T23:14:31Z  2025-10-11T23:00:37Z
d66d72e7  prepublished  2026-03-26T00:47:57Z  2026-04-10T00:37:18Z
e3a94e4e  inactive      2025-04-14T21:38:53Z  <none>
e3f9617d  inactive      2026-01-25T00:17:34Z  2026-02-09T00:08:23Z
e6383df6  active        2026-03-11T00:37:18Z  2026-03-26T00:37:18Z
e6bdb09a  inactive      2025-06-28T22:27:13Z  2025-07-13T22:17:13Z
eafdb2fe  inactive      2025-11-10T23:38:33Z  2025-11-25T23:30:04Z
f5be6a00  inactive      2025-05-14T21:58:53Z  2025-05-29T21:48:53Z

-rw-------. 1 nomad bin 2166 Mar 30  2025 970dd868-6c5f-0e1e-ba54-3101c62cdaa7.aead.nks.json
-rw-------. 1 nomad bin  306 Mar 16  2025 a3221368-3882-69f2-b45d-a275edc3db05.nks.json
-rw-------. 1 nomad bin 2166 May 14  2025 ac918939-0670-24f5-6d1b-05109c21cc03.aead.nks.json
-rw-------. 1 nomad bin 2162 Apr 29  2025 e3a94e4e-f760-f8c7-5c3a-14d0b39836bd.aead.nks.json
-rw-------. 1 nomad bin 2186 May 14  2025 f5be6a00-f12c-bb96-2080-d79789142acb.aead.nks.json

I will have to wait for this weekend to do the SIGQUIT test, but maybe the above is informative.

[tgross]

It might be worth seeing if you can manually delete a3221368-3882-69f2-b45d-a275edc3db05, as that's quite old and the key file itself looks like it might be corrupt (306 bytes seems weirdly small, but maybe if this is old enough to only have Ed25519 keys?). Alternately, you might want to compare that file across servers to see if it matches across all of them.

[msherman13]

@tgross the file itself doesn't seem corrupted (valid json), the key just looks pretty short. we only have one server instance so the mismatch across servers isn't an issue. this weekend i can try to move that key file out of the directory and restart.

[msherman13]

@tgross ,

Seems like moving that key file out of the keystore did not help. I was able to capture a stack trace with SIGQUIT while the server was stuck. See attached log from the whole run from start to SIGQUIT to finish.

nomad_trace.txt

[tgross]

Hi @msherman13! Thanks for this stack trace.

Seems like moving that key file out of the keystore did not help.

Yeah, unless the key metadata has been deleted from the state store as well, I wouldn't expect it to. Because now the encrypter will definitely get stuck trying to startup because it has a key that might be in use that can't be decrypted.

I extracted the dump out of the logs into the pprof debug=2 format and then ran it through goroutine-explore to do some querying.

Exactly as I'd expected with the removed key, we're stuck in the IsReady method of the encrypter (encrypter.go#L195), which is being called from server.go#L553. In newer version of Nomad, there's a timeout there (server.go#L573-L582).

goroutine 1 gp=0x40000021c0 m=nil [select]:
runtime.gopark(0x4000bad140?, 0x2?, 0x8?, 0xd0?, 0x4000bad104?)
        runtime/proc.go:435 +0xc8 fp=0x4000bacf90 sp=0x4000bacf70 pc=0x47cc78
runtime.selectgo(0x4000bad140, 0x4000bad100, 0x400bad128?, 0x0, 0xffff8c8e2a78?, 0x1)
        runtime/select.go:351 +0x6c4 fp=0x4000bad0c0 sp=0x4000bacf90 pc=0x45a444
github.com/hashicorp/nomad/helper.WithBackoffFunc({0x412de28, 0x4000af7ae0}, 0x5f5e100, 0x3b9aca00, 0x4000bad1b8)
        github.com/hashicorp/nomad/helper/backoff.go:44 +0xd0 fp=0x4000bad180 sp=0x4000bad0c0 pc=0x11d9df0
github.com/hashicorp/nomad/nomad.(*Encrypter).IsReady(0x4000ac4f08?, {0x412de28?, 0x4000af7ae0?})
        github.com/hashicorp/nomad/nomad/encrypter.go:195 +0x50 fp=0x4000bad1d0 sp=0x4000bad180 pc=0x23c1430
github.com/hashicorp/nomad/nomad.NewServer(0x4000813808, {0x4114aa8, 0x40001538a0}, 0x4000af8f70)
        github.com/hashicorp/nomad/nomad/server.go:553 +0x17dc fp=0x4000bad460 sp=0x4000bad1d0 pc=0x245131c
github.com/hashicorp/nomad/command/agent.(*Agent).setupServer(0x4000b0c800)
        github.com/hashicorp/nomad/command/agent/agent.go:1033 +0x138 fp=0x4000bad850 sp=0x4000bad460 pc=0x29e2808
github.com/hashicorp/nomad/command/agent.NewAgent(0x4000afaa08, {0x415b588, 0x4000b160f0}, {0x40ea918, 0x4000917cb0}, 0x4000af74f0)
        github.com/hashicorp/nomad/command/agent/agent.go:158 +0x194 fp=0x4000bad8b0 sp=0x4000bad850 pc=0x29deb94
github.com/hashicorp/nomad/command/agent.(*Command).setupAgent(0x40002e5ce0, 0x4000afaa08, {0x415b588, 0x4000b160f0}, {0x40ea918, 0x4000917cb0}, 0x4000af74f0)
        github.com/hashicorp/nomad/command/agent/command.go:628 +0x70 fp=0x4000bad950 sp=0x4000bad8b0 pc=0x29f8a60
github.com/hashicorp/nomad/command/agent.(*Command).Run(0x40002e5ce0, {0x40000702c0, 0x1, 0x1})
        github.com/hashicorp/nomad/command/agent/command.go:838 +0x47c fp=0x4000badd00 sp=0x4000bad950 pc=0x29fbabc
github.com/hashicorp/cli.(*CLI).Run(0x400015f2c0)
        github.com/hashicorp/cli@v1.1.7/cli.go:265 +0x450 fp=0x4000badde0 sp=0x4000badd00 pc=0x1adf290
main.Run({0x40000702b0, 0x2, 0x2})
        github.com/hashicorp/nomad/main.go:112 +0x210 fp=0x4000badf10 sp=0x4000badde0 pc=0x2bbdcc0
main.main()
        github.com/hashicorp/nomad/main.go:82 +0x54 fp=0x4000badf40 sp=0x4000badf10 pc=0x2bbda84
runtime.main()
        runtime/proc.go:283 +0x284 fp=0x4000badfd0 sp=0x4000badf40 pc=0x446694
runtime.goexit({})
        runtime/asm_arm64.s:1223 +0x4 fp=0x4000badfd0 sp=0x4000badfd0 pc=0x4851c4

This means that the server has keys that it is trying to decrypt but cannot, which is exactly what I'd expect given you removed a key. The only other goroutine that's in the encrypter is at encrypter.go#L985 which is used to replicate legacy key material between servers (and as you said, you only have 1 server).

We'd probably want to see this same SIGQUIT stack without a removed key to see if it lines up with the same behavior, but I have a pretty good hunch it'll show the same thing. Something somewhere in the legacy key material decrypt is not working correctly but in a way that's racy. Unfortunately 1.10.0 doesn't have any of the debug logging that's been since added to help debug this either.

Otherwise, it looks like the rest of the server component (pre-HTTP) is up and healthy. The scheduler workers are running. There are Nomad client nodes appear to be connecting as expected and running their allocations. We can see 132 goroutines in Variables.Read RPC handlers, and 824 in ServiceRegistration.GetService, 16 in ServiceRegistration.Read (all probably from template blocks), 21 in Node.GetClientAllocs. All normal stuff.

If I sort your keys I see you have a whole mess of them that are older:

$ cat keys.txt | sort -k3
a3221368  inactive      2024-05-15T00:57:09Z  <none>
970dd868  inactive      2025-03-30T21:28:53Z  <none>
e3a94e4e  inactive      2025-04-14T21:38:53Z  <none>
ac918939  inactive      2025-04-29T21:48:53Z  <none>
f5be6a00  inactive      2025-05-14T21:58:53Z  2025-05-29T21:48:53Z
577d06c3  inactive      2025-05-29T22:03:49Z  2025-06-13T21:58:53Z
4efaf191  inactive      2025-06-13T22:17:13Z  2025-06-28T22:03:49Z
e6bdb09a  inactive      2025-06-28T22:27:13Z  2025-07-13T22:17:13Z
52d86b41  inactive      2025-07-13T22:36:40Z  2025-07-28T22:27:13Z
a7f7f72e  inactive      2025-07-28T22:43:40Z  2025-08-12T22:36:40Z
4fb04d9c  inactive      2025-08-12T22:48:36Z  2025-08-27T22:43:40Z
13710b48  inactive      2025-08-27T22:57:41Z  2025-09-11T22:48:36Z
91400e0c  inactive      2025-09-11T23:00:37Z  2025-09-26T22:57:41Z
afb79713  inactive      2025-09-26T23:14:31Z  2025-10-11T23:00:37Z
16b16e49  inactive      2025-10-11T23:20:39Z  2025-10-26T23:14:31Z
48e9d79e  inactive      2025-10-26T23:30:04Z  2025-11-10T23:20:39Z
eafdb2fe  inactive      2025-11-10T23:38:33Z  2025-11-25T23:30:04Z
34df63d1  inactive      2025-11-25T23:47:10Z  2025-12-10T23:38:33Z
35e2e7af  inactive      2025-12-10T23:52:31Z  2025-12-25T23:47:10Z
19a4c8c8  inactive      2025-12-25T23:58:08Z  2026-01-09T23:52:31Z
2a207426  inactive      2026-01-10T00:08:23Z  2026-01-24T23:58:08Z
e3f9617d  inactive      2026-01-25T00:17:34Z  2026-02-09T00:08:23Z
24e1d152  inactive      2026-02-09T00:20:29Z  2026-02-24T00:17:34Z
74f254be  inactive      2026-02-24T00:37:18Z  2026-03-11T00:20:29Z
e6383df6  active        2026-03-11T00:37:18Z  2026-03-26T00:37:18Z
d66d72e7  prepublished  2026-03-26T00:47:57Z  2026-04-10T00:37:18Z

This means that there are encrypted variables that were encrypted with the old keys, so even though they're far older than the root_key_gc_threshold they can't be removed.

Without being able to debug this further in those logs, I'd recommend doing a nomad operator root keyring rotate -full to decrypt and re-encrypt all the variables (as a one-off thing). That'd let the periodic GC clear out the old keys and that could narrow down where the problem is happening.

[msherman13]

@tgross I can do more testing this evening but something I forgot to mention is that the trace I provided was after I put the key file back in the key store. So the keys were all present for this stack trace.

[msherman13]

@tgross after running the rotate command, it seems that I can consistently restart without the server getting stuck. Thanks for your help, not sure how we ended up in this state.