Unclear signing status / signing just never seems to stop

[jpmens]

This is most definitely not a bug but actually something that amused me; I knew I had chopped the (generated) zone in vi at 5000 lines (with a formatted SOA record), so 4k looked strange:

Maybe 4.9K ? :-) (ed: The fractional value issue has been split out to #460)

I then add three more records, bump the SOA serial to 2, and run cascade zone reload c1.aa:

Status report for zone 'c1.aa' using policy 'csk13-hsm'
✔ Waited for a new version of the c1.aa zone
✔ Loaded version 2
  Loaded at 2025-10-09T08:31:18+00:00 (1m 46s ago)
  Loaded 160 KB and 5K records from the filesystem in 0 seconds
✔ Auto approving signing of version 2, no checks enabled in policy.
✔ Approval received to sign version 2, signing requested
✔ Signed version 2 as version 1759997164
  Signing requested at 2025-10-09T08:06:04+00:00 (27m ago)
  Signing started at 2025-10-09T08:17:21+00:00 (15m 42s ago)
  Signing finished at 2025-10-09T08:17:21+00:00 (15m 42s ago)
  Collected 4K records in 0s, sorted in 0s
  Generated 4K NSEC(3) records in 0s
  Generated 9K signatures in 11m 17s (14 sig/s)
  Inserted signatures in 11m 17s (14 sig/s)
  Took 11m 17s in total, using 7 threads
  Current action: Finished
✔ Waited for approval to publish version 1759997164
✔ Published version 1759997164
  Published zone available on 127.0.0.1:4543

Is this zone signed or being signed? I cannot determine that from the output:

• ✔ Signed version 2 as version 1759997164: for me this means my SOA serial 2 is signed
• Collected 4K records in 0s, sorted in 0s: this, though is still the 4K display, whereas higher up it says 5K records

Signing started / Signing finished seems to indicate signing has finished, but the blinkenlights on my HSM are flashing furiously, so I'm sure the zone is still being signed, and activity in kmip2pkcs11 also indicates that that is the case:

[2025-10-09T10:36:52] [INFO] Processing batch of 1 items from peer 127.0.0.1:43872 on thread Thread { id: ThreadId(29), name: Some("kmip2pkcs11-worker"), .. }
...

[jpmens]

After many minutes, I see a difference. The green checkmarks still confuse me, however, I see we're not done yet: <serial number not yet known>

$ cascade zone status c1.aa 
Status report for zone 'c1.aa' using policy 'csk13-hsm'
✔ Waited for a new version of the c1.aa zone
✔ Loaded version 2
  Loaded at 2025-10-09T08:31:18+00:00 (33m 45s ago)
  Loaded 160 KB and 5K records from the filesystem in 0 seconds
✔ Auto approving signing of version 2, no checks enabled in policy.
✔ Approval received to sign version 2, signing requested
✔ Signed version 2 as <serial number not yet known>
  Signing requested at 2025-10-09T08:06:04+00:00 (59m ago)
  Signing started at 2025-10-09T08:17:21+00:00 (47m 42s ago)
  Signing finished at 2025-10-09T08:17:21+00:00 (47m 42s ago)
  Collected 4K records in 0s, sorted in 0s
  Generated 4K NSEC(3) records in 0s
  Generated 9K signatures in 11m 17s (14 sig/s)
  Inserted signatures in 11m 17s (14 sig/s)
  Took 11m 17s in total, using 7 threads
  Current action: Finished
✔ Waited for approval to publish <serial number not yet known>
✔ Published <serial number not yet known>
  Published zone available on 127.0.0.1:4543

$ diff c1.aa.status.signing*
4c4
<   Loaded at 2025-10-09T08:31:18+00:00 (17m 23s ago)
---
>   Loaded at 2025-10-09T08:31:18+00:00 (33m 45s ago)
8,11c8,11
< ✔ Signed version 2 as version 1759998376
<   Signing requested at 2025-10-09T08:06:04+00:00 (42m 37s ago)
<   Signing started at 2025-10-09T08:17:21+00:00 (31m 20s ago)
<   Signing finished at 2025-10-09T08:17:21+00:00 (31m 20s ago)
---
> ✔ Signed version 2 as <serial number not yet known>
>   Signing requested at 2025-10-09T08:06:04+00:00 (59m ago)
>   Signing started at 2025-10-09T08:17:21+00:00 (47m 42s ago)
>   Signing finished at 2025-10-09T08:17:21+00:00 (47m 42s ago)
18,19c18,19
< ✔ Waited for approval to publish version 1759998376
< ✔ Published version 1759998376
---
> ✔ Waited for approval to publish <serial number not yet known>
> ✔ Published <serial number not yet known>

[jpmens]

Something is not right: the blinkenlights are still blinking. It's pretty, of course, but not really what I'm expecting ...

$ cascade zone status c1.aa
Status report for zone 'c1.aa' using policy 'csk13-hsm'
✔ Waited for a new version of the c1.aa zone
✔ Loaded version 2
  Loaded at 2025-10-09T08:31:18+00:00 (1h 6m 4s ago)
  Loaded 160 KB and 5K records from the filesystem in 0 seconds
✔ Auto approving signing of version 2, no checks enabled in policy.
✔ Approval received to sign version 2, signing requested
✔ Signed version 2 as <serial number not yet known>
  Signing requested at 2025-10-09T08:06:04+00:00 (1h 31m 19s ago)
  Signing started at 2025-10-09T08:17:21+00:00 (1h 20m 1s ago)
  Signing finished at 2025-10-09T08:17:21+00:00 (1h 20m 1s ago)
  Collected 4K records in 0s, sorted in 0s
  Generated 4K NSEC(3) records in 0s
  Generated 9K signatures in 11m 17s (14 sig/s)
  Inserted signatures in 11m 17s (14 sig/s)
  Took 11m 17s in total, using 7 threads
  Current action: Finished
✔ Waited for approval to publish <serial number not yet known>
✔ Published <serial number not yet known>
  Published zone available on 127.0.0.1:4543

4c4
<   Loaded at 2025-10-09T08:31:18+00:00 (33m 45s ago)
---
>   Loaded at 2025-10-09T08:31:18+00:00 (1h 7m 52s ago)
9,11c9,11
<   Signing requested at 2025-10-09T08:06:04+00:00 (59m ago)
<   Signing started at 2025-10-09T08:17:21+00:00 (47m 42s ago)
<   Signing finished at 2025-10-09T08:17:21+00:00 (47m 42s ago)
---
>   Signing requested at 2025-10-09T08:06:04+00:00 (1h 33m 6s ago)
>   Signing started at 2025-10-09T08:17:21+00:00 (1h 21m 48s ago)
>   Signing finished at 2025-10-09T08:17:21+00:00 (1h 21m 48s ago)

Also, I have cmd-hook configured for the policy which simply appends an ISO date stamp to a file, and the file now contains:

$ cat c1.aa
2025-10-09T09:19:51Z
2025-10-09T09:22:44Z
2025-10-09T09:34:02Z
2025-10-09T09:45:20Z

which indicates to me the signing has "completed" four times already since I added three (3) records to it and bumped the SOA serial to 2.

and here we go again:

Oct 09 11:34:02 think cascaded[9281]: think cascaded[9281]: [RS2]: Executed hook '/etc/cascade/review-signed-zone.sh' for signed zone 'c1.aa' at serial 1760001764
Oct 09 11:34:02 think cascaded[9281]: think cascaded[9281]: [CC]: Passing back zone review
Oct 09 11:34:02 think cascaded[9281]: think cascaded[9281]: Pending signed zone 'c1.aa' approved at serial 1760001764.
Oct 09 11:34:02 think cascaded[9281]: think cascaded[9281]: [CC]: Instructing publication server to publish the signed zone
Oct 09 11:34:02 think cascaded[9281]: think cascaded[9281]: [PS]: Publishing signed zone 'c1.aa' at serial 1760001764.
Oct 09 11:34:02 think cascaded[9281]: think cascaded[9281]: [PS]: Adding 'c1.aa' to the set of published zones.
Oct 09 11:34:02 think cascaded[9281]: think cascaded[9281]: [PS]: Found 0 NOTIFY targets
Oct 09 11:34:02 think cascaded[9281]: think cascaded[9281]: SIGNER: Using 7 threads to sign 4970 owners in chunks of 710.
Oct 09 11:36:51 think cascaded[9281]: think cascaded[9281]: Executing keyset command keyset -c /var/lib/cascade/keys/c1.aa.cfg cron
Oct 09 11:36:51 think cascaded[9281]: think cascaded[9281]: [CC]: Instructing zone signer to re-sign the zone
Oct 09 11:36:51 think cascaded[9281]: think cascaded[9281]: [ZS]: Waiting to enqueue signing operation for zone 'c1.aa'.
Oct 09 11:42:46 think cascaded[9281]: think cascaded[9281]: preprocess; request_ip=127.0.0.1
Oct 09 11:43:11 think cascaded[9281]: think cascaded[9281]: preprocess; request_ip=127.0.0.1
Oct 09 11:43:40 think cascaded[9281]: think cascaded[9281]: preprocess; request_ip=127.0.0.1
Oct 09 11:43:48 think cascaded[9281]: think cascaded[9281]: preprocess; request_ip=127.0.0.1
Oct 09 11:45:05 think cascaded[9281]: think cascaded[9281]: preprocess; request_ip=127.0.0.1
Oct 09 11:45:20 think cascaded[9281]: think cascaded[9281]: Signing statistics for c1.aa serial: 1760002442:
Oct 09 11:45:20 think cascaded[9281]: think cascaded[9281]: [ZS]: Waiting to start signing operation for zone 'c1.aa': 0 signing operations are in progress and 1 operations are queued ahead of us.
Oct 09 11:45:20 think cascaded[9281]: think cascaded[9281]: [ZS]: Starting signing operation for zone 'c1.aa'
Oct 09 11:45:20 think cascaded[9281]: think cascaded[9281]: [CC]: Instructing review server to publish the signed zone
Oct 09 11:45:20 think cascaded[9281]: think cascaded[9281]: [ZS]: Serials for zone 'c1.aa': last signed=Some(Serial(1760002442)), current=1760002442, serial policy=unix time, new=1760003120
Oct 09 11:45:20 think cascaded[9281]: think cascaded[9281]: [RS2]: Seeking approval for signed zone 'c1.aa' at serial 1760002442.
Oct 09 11:45:20 think cascaded[9281]: think cascaded[9281]: [RS2]: Executed hook '/etc/cascade/review-signed-zone.sh' for signed zone 'c1.aa' at serial 1760002442
Oct 09 11:45:20 think cascaded[9281]: think cascaded[9281]: [CC]: Passing back zone review
Oct 09 11:45:20 think cascaded[9281]: think cascaded[9281]: Pending signed zone 'c1.aa' approved at serial 1760002442.
Oct 09 11:45:20 think cascaded[9281]: think cascaded[9281]: [CC]: Instructing publication server to publish the signed zone
Oct 09 11:45:20 think cascaded[9281]: think cascaded[9281]: [PS]: Publishing signed zone 'c1.aa' at serial 1760002442.
Oct 09 11:45:20 think cascaded[9281]: think cascaded[9281]: [PS]: Adding 'c1.aa' to the set of published zones.
Oct 09 11:45:20 think cascaded[9281]: think cascaded[9281]: [PS]: Found 0 NOTIFY targets
Oct 09 11:45:20 think cascaded[9281]: think cascaded[9281]: SIGNER: Using 7 threads to sign 4970 owners in chunks of 710.
Oct 09 11:46:56 think cascaded[9281]: think cascaded[9281]: Executing keyset command keyset -c /var/lib/cascade/keys/c1.aa.cfg cron
Oct 09 11:46:56 think cascaded[9281]: think cascaded[9281]: [CC]: Instructing zone signer to re-sign the zone
Oct 09 11:46:56 think cascaded[9281]: think cascaded[9281]: [ZS]: Waiting to enqueue signing operation for zone 'c1.aa'.

There's something worrysome going on: I had four (now five) zones configured, and I can list them:

$ cascade zone list
a3.aa
b1.aa
a2.aa
c1.aa
a1.aa

But Cascade no longer serves them:

$ dig @127.0.0.1 -p 4543 a1.aa. SOA +norec

; <<>> DiG 9.21.12 <<>> @127.0.0.1 -p 4543 a1.aa. SOA +norec
; (1 server found)
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NXDOMAIN, id: 60504                       <----------------------- NXDOMAIN ?
;; flags: qr; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 0
;; QUESTION SECTION:
;a1.aa.				IN	SOA

;; Query time: 0 msec
;; SERVER: 127.0.0.1#4543(127.0.0.1) (UDP)
;; WHEN: Thu Oct 09 11:49:38 CEST 2025
;; MSG SIZE  rcvd: 34



$ dig @127.0.0.1 -p 4543 c1.aa. SOA +norec

; <<>> DiG 9.21.12 <<>> @127.0.0.1 -p 4543 c1.aa. SOA +norec
; (1 server found)
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 400                     <----------------------- NOERROR/NODATA ?
;; flags: qr aa; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 0
;; QUESTION SECTION:
;c1.aa.				IN	SOA

;; Query time: 0 msec
;; SERVER: 127.0.0.1#4543(127.0.0.1) (UDP)
;; WHEN: Thu Oct 09 11:50:08 CEST 2025
;; MSG SIZE  rcvd: 34

[jpmens]

I restarted cascaded, and none of the zones are queryable.

[ximon18]

Hi @jpmens,

I think we need to somehow split this out into separate feature request for the original fractional K value and a bug report(s) for the issue(s) you're encountering.

Thankyou very much for the various issues you're reporting, please keep them coming, they are very appreciated!

Ximon

[jpmens]

@ximon18 you've labeled 'enhacement', for which thank you, but I think this issue also documents a bug.

[ximon18]

@jpmens: Do you see errors or warnings in the log?

[ximon18]

@ximon18 you've labeled 'enhacement', for which thank you, but I think this issue also documents a bug.

I just added the bug label immediately before I saw this comment 😉

[jpmens]

No, I do not, at least not since the restart with a log file. (I didn't notice anything untoward in the systemd journal before that).

Here's the full log:

[2025-10-09T10:10:27.075Z] INFO cascaded: Successfully loaded the global state file
[2025-10-09T10:10:27.079Z] INFO cascade::manager: Starting target 'CC'
[2025-10-09T10:10:27.079Z] INFO cascade::manager: Starting unit 'ZL'
[2025-10-09T10:10:27.079Z] INFO cascade::manager: Starting unit 'RS'
[2025-10-09T10:10:27.079Z] INFO cascade::manager: Starting unit 'KM'
[2025-10-09T10:10:27.079Z] INFO cascade::units::zone_loader: [ZL]: Adding at most 3 zones at once.
[2025-10-09T10:10:27.079Z] INFO cascade::manager: Starting unit 'ZS'
[2025-10-09T10:10:27.079Z] INFO cascade::units::zone_server: [RS]: Obtaining UDP socket for address 127.0.0.1:4541
[2025-10-09T10:10:27.079Z] INFO cascade::manager: Starting unit 'RS2'
[2025-10-09T10:10:27.079Z] INFO cascade::units::zone_loader: [ZL]: Waiting to add zone 'a1.aa' with source 'Zonefile { path: "/etc/cascade/zones/a1.aa" }'
[2025-10-09T10:10:27.079Z] INFO cascade::units::zone_loader: [ZL]: Waiting to add zone 'a3.aa' with source 'Zonefile { path: "/etc/cascade/zones/a3.aa" }'
[2025-10-09T10:10:27.079Z] INFO cascade::units::zone_loader: [ZL]: Waiting to add zone 'b1.aa' with source 'Zonefile { path: "/etc/cascade/zones/b1.aa" }'
[2025-10-09T10:10:27.079Z] INFO cascade::units::zone_loader: [ZL]: Adding zone 'a1.aa' with source 'Zonefile { path: "/etc/cascade/zones/a1.aa" }'
[2025-10-09T10:10:27.079Z] INFO cascade::units::zone_loader: [ZL]: Adding zone 'a3.aa' with source 'Zonefile { path: "/etc/cascade/zones/a3.aa" }'
[2025-10-09T10:10:27.079Z] INFO cascade::units::zone_loader: [ZL]: Waiting to add zone 'c1.aa' with source 'Zonefile { path: "/etc/cascade/zones/c1.aa" }'
[2025-10-09T10:10:27.079Z] INFO cascade::units::zone_loader: [ZL]: Adding zone 'b1.aa' with source 'Zonefile { path: "/etc/cascade/zones/b1.aa" }'
[2025-10-09T10:10:27.079Z] INFO cascade::units::zone_loader: [ZL]: Waiting to add zone 'a2.aa' with source 'Zonefile { path: "/etc/cascade/zones/a2.aa" }'
[2025-10-09T10:10:27.079Z] INFO cascade::units::zone_server: [RS]: Obtaining TCP listener for address 127.0.0.1:4541
[2025-10-09T10:10:27.079Z] INFO cascade::units::zone_server: [RS]: Obtaining UDP socket for address [::1]:4541
[2025-10-09T10:10:27.079Z] INFO cascade::units::zone_server: [RS]: Obtaining TCP listener for address [::1]:4541
[2025-10-09T10:10:27.079Z] INFO cascade::units::zone_server: [RS2]: Obtaining UDP socket for address 127.0.0.1:4542
[2025-10-09T10:10:27.079Z] INFO cascade::units::zone_server: [RS2]: Obtaining TCP listener for address 127.0.0.1:4542
[2025-10-09T10:10:27.079Z] INFO cascade::units::zone_server: [RS2]: Obtaining UDP socket for address [::1]:4542
[2025-10-09T10:10:27.079Z] INFO cascade::units::zone_server: [RS2]: Obtaining TCP listener for address [::1]:4542
[2025-10-09T10:10:27.079Z] INFO cascade::units::zone_loader: [ZL]: Loading primary zone 'a3.aa' from '/etc/cascade/zones/a3.aa'..
[2025-10-09T10:10:27.079Z] INFO cascade::units::zone_loader: [ZL]: Loading primary zone 'a1.aa' from '/etc/cascade/zones/a1.aa'..
[2025-10-09T10:10:27.079Z] INFO cascade::units::zone_loader: [ZL]: Loading primary zone 'b1.aa' from '/etc/cascade/zones/b1.aa'..
[2025-10-09T10:10:27.079Z] INFO cascade::units::zone_loader: Loaded 138 bytes from '/etc/cascade/zones/a3.aa' in 0 secs
[2025-10-09T10:10:27.079Z] INFO cascade::units::zone_loader: Loaded 138 bytes from '/etc/cascade/zones/a1.aa' in 0 secs
[2025-10-09T10:10:27.079Z] INFO cascade::units::zone_loader: Loaded 138 bytes from '/etc/cascade/zones/b1.aa' in 0 secs
[2025-10-09T10:10:27.079Z] INFO cascade::units::zone_loader: [ZL]: Adding zone 'c1.aa' with source 'Zonefile { path: "/etc/cascade/zones/c1.aa" }'
[2025-10-09T10:10:27.080Z] INFO cascade::units::zone_loader: [ZL]: Adding zone 'a2.aa' with source 'Zonefile { path: "/etc/cascade/zones/a2.aa" }'
[2025-10-09T10:10:27.080Z] INFO cascade::units::zone_loader: [ZL]: Received a new copy of zone 'a3.aa' at serial 2
[2025-10-09T10:10:27.080Z] INFO cascade::units::zone_loader: [ZL]: Loading primary zone 'c1.aa' from '/etc/cascade/zones/c1.aa'..
[2025-10-09T10:10:27.080Z] INFO cascade::units::zone_loader: [ZL]: Received a new copy of zone 'a1.aa' at serial 1
[2025-10-09T10:10:27.080Z] INFO cascade::units::zone_loader: [ZL]: Loading primary zone 'a2.aa' from '/etc/cascade/zones/a2.aa'..
[2025-10-09T10:10:27.080Z] INFO cascade::units::zone_loader: [ZL]: Received a new copy of zone 'b1.aa' at serial 1
[2025-10-09T10:10:27.080Z] INFO cascade::targets::central_command: [CC]: Instructing review server to publish the unsigned zone
[2025-10-09T10:10:27.080Z] INFO cascade::targets::central_command: [CC]: Instructing review server to publish the unsigned zone
[2025-10-09T10:10:27.080Z] INFO cascade::units::zone_loader: Loaded 138 bytes from '/etc/cascade/zones/a2.aa' in 0 secs
[2025-10-09T10:10:27.080Z] INFO cascade::targets::central_command: [CC]: Instructing review server to publish the unsigned zone
[2025-10-09T10:10:27.080Z] INFO cascade::units::zone_loader: [ZL]: Received a new copy of zone 'a2.aa' at serial 1
[2025-10-09T10:10:27.080Z] INFO cascade::targets::central_command: [CC]: Instructing review server to publish the unsigned zone
[2025-10-09T10:10:27.079Z] INFO cascade::manager: Starting unit 'HS'
[2025-10-09T10:10:27.080Z] INFO cascade::manager: Starting unit 'PS'
[2025-10-09T10:10:27.080Z] INFO cascade::units::zone_server: [PS]: Obtaining UDP socket for address 127.0.0.1:4543
[2025-10-09T10:10:27.080Z] INFO cascade::units::zone_server: [PS]: Obtaining TCP listener for address 127.0.0.1:4543
[2025-10-09T10:10:27.080Z] INFO cascade::units::zone_server: [PS]: Obtaining UDP socket for address [::1]:4543
[2025-10-09T10:10:27.080Z] INFO cascade::units::zone_server: [PS]: Obtaining TCP listener for address [::1]:4543
[2025-10-09T10:10:27.080Z] INFO cascade::units::zone_server: [PS]: Receieved additional UDP socket 127.0.0.1:4540
[2025-10-09T10:10:27.080Z] INFO cascade::units::zone_server: [PS]: Receieved additional UDP socket [::1]:4540
[2025-10-09T10:10:27.080Z] INFO cascade::units::zone_server: [PS]: Receieved additional TCP listener 127.0.0.1:4540
[2025-10-09T10:10:27.080Z] INFO cascade::units::zone_server: [PS]: Receieved additional TCP listener [::1]:4540
[2025-10-09T10:10:27.080Z] INFO cascade::manager: All units report ready.
[2025-10-09T10:10:27.080Z] INFO cascade::targets::central_command: [CC]: Instructing zone signer to sign the approved zone
[2025-10-09T10:10:27.080Z] INFO cascade::targets::central_command: [CC]: Instructing zone signer to sign the approved zone
[2025-10-09T10:10:27.080Z] INFO cascade::targets::central_command: [CC]: Instructing zone signer to sign the approved zone
[2025-10-09T10:10:27.080Z] INFO cascade::targets::central_command: [CC]: Instructing zone signer to sign the approved zone
[2025-10-09T10:10:27.080Z] INFO cascade::units::zone_signer: [ZS]: Waiting to enqueue signing operation for zone 'a2.aa'.
[2025-10-09T10:10:27.080Z] INFO cascade::units::zone_signer: [ZS]: Waiting to enqueue signing operation for zone 'a3.aa'.
[2025-10-09T10:10:27.080Z] INFO cascade::units::zone_signer: [ZS]: Waiting to enqueue signing operation for zone 'a1.aa'.
[2025-10-09T10:10:27.080Z] INFO cascade::units::zone_signer: [ZS]: Waiting to start signing operation for zone 'a2.aa': 0 signing operations are in progress and 0 operations are queued ahead of us.
[2025-10-09T10:10:27.080Z] INFO cascade::units::zone_signer: [ZS]: Waiting to start signing operation for zone 'a3.aa': 0 signing operations are in progress and 1 operations are queued ahead of us.
[2025-10-09T10:10:27.080Z] INFO cascade::units::zone_signer: [ZS]: Waiting to enqueue signing operation for zone 'b1.aa'.
[2025-10-09T10:10:27.080Z] INFO cascade::units::zone_signer: [ZS]: Waiting to start signing operation for zone 'a1.aa': 0 signing operations are in progress and 2 operations are queued ahead of us.
[2025-10-09T10:10:27.081Z] INFO cascade::units::zone_signer: [ZS]: Starting signing operation for zone 'a2.aa'
[2025-10-09T10:10:27.081Z] INFO cascade::units::zone_signer: [ZS]: Waiting to start signing operation for zone 'b1.aa': 1 signing operations are in progress and 3 operations are queued ahead of us.
[2025-10-09T10:10:27.081Z] INFO cascade::units::zone_signer: [ZS]: Serials for zone 'a2.aa': last signed=Some(Serial(1760003697)), current=1, serial policy=unix time, new=1760004627
[2025-10-09T10:10:27.081Z] INFO cascade::units::zone_signer: Reading KMIP server state from '/var/lib/cascade/kmip/kmip2pkcs11'
[2025-10-09T10:10:27.104Z] INFO cascade::units::zone_loader: Loaded 160701 bytes from '/etc/cascade/zones/c1.aa' in 0 secs
[2025-10-09T10:10:27.104Z] INFO cascade::units::zone_loader: [ZL]: Received a new copy of zone 'c1.aa' at serial 2
[2025-10-09T10:10:27.104Z] INFO cascade::targets::central_command: [CC]: Instructing review server to publish the unsigned zone
[2025-10-09T10:10:27.104Z] INFO cascade::targets::central_command: [CC]: Instructing zone signer to sign the approved zone
[2025-10-09T10:10:27.105Z] INFO cascade::units::zone_signer: [ZS]: Waiting to enqueue signing operation for zone 'c1.aa'.
[2025-10-09T10:10:27.105Z] INFO cascade::units::zone_signer: [ZS]: Waiting to start signing operation for zone 'c1.aa': 1 signing operations are in progress and 4 operations are queued ahead of us.
[2025-10-09T10:10:27.162Z] INFO cascade::units::zone_signer: SIGNER: Using 1 threads to sign 1 owners in chunks of 1.
[2025-10-09T10:10:27.505Z] INFO cascade::units::zone_signer: Signing statistics for a2.aa serial: 1760004627:
Collected 4 records in 0.0s, sorted in 0.0s
Generated 4 NSEC(3) records in 0.0s
Generated 5 signatures in 0.3s (5000sig/s)
            Inserted signatures in 0.3s (5000sig/s)
Took 0.4s in total, using 1 threads
[2025-10-09T10:10:27.505Z] INFO cascade::units::zone_signer: [ZS]: Starting signing operation for zone 'a3.aa'
[2025-10-09T10:10:27.505Z] INFO cascade::units::zone_signer: [ZS]: Starting signing operation for zone 'a1.aa'
[2025-10-09T10:10:27.505Z] INFO cascade::units::zone_signer: [ZS]: Starting signing operation for zone 'b1.aa'
[2025-10-09T10:10:27.505Z] INFO cascade::units::zone_signer: [ZS]: Serials for zone 'b1.aa': last signed=Some(Serial(1760003696)), current=1, serial policy=unix time, new=1760004627
[2025-10-09T10:10:27.505Z] INFO cascade::targets::central_command: [CC]: Instructing review server to publish the signed zone
[2025-10-09T10:10:27.505Z] INFO cascade::units::zone_server: [RS2]: Seeking approval for signed zone 'a2.aa' at serial 1760004627.
[2025-10-09T10:10:27.506Z] INFO cascade::units::zone_server: [RS2]: Executed hook '/etc/cascade/review-signed-zone.sh' for signed zone 'a2.aa' at serial 1760004627
[2025-10-09T10:10:27.518Z] INFO cascade::targets::central_command: [CC]: Passing back zone review
[2025-10-09T10:10:27.518Z] INFO cascade::units::zone_server: Pending signed zone 'a2.aa' approved at serial 1760004627.
[2025-10-09T10:10:27.518Z] INFO cascade::targets::central_command: [CC]: Instructing publication server to publish the signed zone
[2025-10-09T10:10:27.518Z] INFO cascade::units::zone_server: [PS]: Publishing signed zone 'a2.aa' at serial 1760004627.
[2025-10-09T10:10:27.518Z] INFO cascade::units::zone_server: [PS]: Adding 'a2.aa' to the set of published zones.
[2025-10-09T10:10:27.518Z] INFO cascade::units::zone_server: [PS]: Found 0 NOTIFY targets
[2025-10-09T10:10:27.532Z] INFO cascade::units::zone_signer: SIGNER: Using 1 threads to sign 1 owners in chunks of 1.
[2025-10-09T10:10:27.879Z] INFO cascade::units::zone_signer: Signing statistics for b1.aa serial: 1760004627:
Collected 4 records in 0.0s, sorted in 0.0s
Generated 3 NSEC(3) records in 0.0s
Generated 5 signatures in 0.3s (5000sig/s)
            Inserted signatures in 0.3s (5000sig/s)
Took 0.4s in total, using 1 threads
[2025-10-09T10:10:27.879Z] INFO cascade::units::zone_signer: [ZS]: Starting signing operation for zone 'c1.aa'
[2025-10-09T10:10:27.879Z] INFO cascade::units::zone_signer: [ZS]: Serials for zone 'c1.aa': last signed=Some(Serial(1760002442)), current=2, serial policy=unix time, new=1760004627
[2025-10-09T10:10:27.879Z] INFO cascade::targets::central_command: [CC]: Instructing review server to publish the signed zone
[2025-10-09T10:10:27.880Z] INFO cascade::units::zone_server: [RS2]: Seeking approval for signed zone 'b1.aa' at serial 1760004627.
[2025-10-09T10:10:27.881Z] INFO cascade::units::zone_server: [RS2]: Executed hook '/etc/cascade/review-signed-zone.sh' for signed zone 'b1.aa' at serial 1760004627
[2025-10-09T10:10:27.888Z] INFO cascade::targets::central_command: [CC]: Passing back zone review
[2025-10-09T10:10:27.888Z] INFO cascade::units::zone_server: Pending signed zone 'b1.aa' approved at serial 1760004627.
[2025-10-09T10:10:27.888Z] INFO cascade::targets::central_command: [CC]: Instructing publication server to publish the signed zone
[2025-10-09T10:10:27.888Z] INFO cascade::units::zone_server: [PS]: Publishing signed zone 'b1.aa' at serial 1760004627.
[2025-10-09T10:10:27.888Z] INFO cascade::units::zone_server: [PS]: Found 0 NOTIFY targets
[2025-10-09T10:10:27.929Z] INFO cascade::units::zone_signer: SIGNER: Using 7 threads to sign 4970 owners in chunks of 710.
[2025-10-09T10:10:44.285Z] INFO domain::net::server::middleware::cookies: preprocess; request_ip=127.0.0.1
[2025-10-09T10:10:48.883Z] INFO domain::net::server::middleware::cookies: preprocess; request_ip=127.0.0.1
[2025-10-09T10:13:12.081Z] INFO cascade::units::key_manager: Executing keyset command keyset -c /var/lib/cascade/keys/c1.aa.cfg cron
[2025-10-09T10:13:12.341Z] INFO cascade::targets::central_command: [CC]: Instructing zone signer to re-sign the zone
[2025-10-09T10:13:12.341Z] INFO cascade::units::zone_signer: [ZS]: Waiting to enqueue signing operation for zone 'c1.aa'.
[2025-10-09T10:15:37.080Z] INFO cascade::units::key_manager: Executing keyset command keyset -c /var/lib/cascade/keys/b1.aa.cfg cron
[2025-10-09T10:15:37.135Z] INFO cascade::targets::central_command: [CC]: Instructing zone signer to re-sign the zone
[2025-10-09T10:15:37.135Z] INFO cascade::units::zone_signer: [ZS]: Waiting to enqueue signing operation for zone 'b1.aa'.

[jpmens]

The earlier zones appear to be a bit kaputt ...:

$ cascade zone status a1.aa
Status report for zone 'a1.aa' using policy 'hsm'
✔ Waited for a new version of the a1.aa zone
✔ Loaded <serial number not yet known>
  Loaded at 2025-10-09T10:10:27+00:00 (7m 41s ago)
  Loaded 138 B and 4 records from the filesystem in 0 seconds
✔ Auto approving signing of <serial number not yet known>, no checks enabled in policy.
• Approval received to sign <serial number not yet known>, signing requested

What does 'waited for' mean? The zone is on disk.

(ed: The "waited for" issue has been split out to #461)

$ l zones/a1.aa
-rw-r--r-- 1 root root 138 Oct  8 13:02 zones/a1.aa

$ cat zones/a1.aa
$ORIGIN a1.aa.
$TTL 60
@	3600	IN	SOA	a1.aa. noc.a1.aa. 1 7200 3600 1209600 3600
			NS	localhost.
			A	127.0.0.1
			TXT	"DNS is innocent"

ah, in the state file (/var/lib/cascade/zone-state/a1.aa.db) I see something new:

  "source": {
        "nanos_since_epoch": 947853044
      },
      "serial": 1,
      "event": {
        "SigningFailed": {
          "trigger": "ZoneChangesApproved",
          "reason": "Failed to create a key pair from private and public keys: a problem occurred while communicating with the KMIP server: a problem occurred while communicating with the KMIP server: Server error: Error while attempting to acquire KMIP connection from pool: timed out waiting for connection: Server error: I/O error: Connection refused (os error 111)"
        }
      }
    },

which surprises me as the key pair had already been created. Assuming the KMIP2PKCS was indeed not running at that moment, wouldn't Cascade retry the connection?

I have cascade zone reload a1.aa

No visible change in zone status (other than " ago")

[jpmens]

@ximon18 I will now stop this experiment, and will reset everything mid next week.

In spite or due to restarting the cascaded process, the signing just never seems to stop (all zones are *.aa and these are the hook timestamps):

$ grep . *.aa
a1.aa:2025-10-09T09:53:42Z
a1.aa:2025-10-09T09:54:57Z
a1.aa:2025-10-09T10:34:34Z
a1.aa:2025-10-09T10:34:51Z
a2.aa:2025-10-09T09:54:58Z
a2.aa:2025-10-09T10:10:27Z
a2.aa:2025-10-09T10:21:45Z
a3.aa:2025-10-09T09:53:42Z
b1.aa:2025-10-09T09:53:42Z
b1.aa:2025-10-09T09:54:57Z
b1.aa:2025-10-09T10:10:27Z
b1.aa:2025-10-09T10:34:52Z
c1.aa:2025-10-09T09:19:51Z
c1.aa:2025-10-09T09:22:44Z
c1.aa:2025-10-09T09:34:02Z
c1.aa:2025-10-09T09:45:20Z
c1.aa:2025-10-09T10:21:45Z
c1.aa:2025-10-09T10:34:34Z
c1.aa:2025-10-09T10:46:09Z

c1.aa has a DNSKEY, but no signatures:

$ dig @127.0.0.1 -p 4543 c1.aa. DNSKEY +norec +dnssec +nocrypto

; <<>> DiG 9.21.12 <<>> @127.0.0.1 -p 4543 c1.aa. DNSKEY +norec +dnssec +nocrypto
; (1 server found)
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 21536
;; flags: qr aa; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 0
;; QUESTION SECTION:
;c1.aa.				IN	DNSKEY

;; ANSWER SECTION:
c1.aa.			3600	IN	DNSKEY	257 3 13 [key id = 44654]

Kaputt. 🥲