test failure: omicron-omdb::test_all_output test_omdb_success_cases

[smklein]

On branch main commit 5bf5f09, I saw this test failure:

running commands with args: ["nexus", "blueprints", "show", "b1e4b4bd-a186-416b-99ed-63b8d88d7b89"]
running commands with args: ["nexus", "blueprints", "show", "current-target"]
running commands with args: ["nexus", "blueprints", "diff", "b1e4b4bd-a186-416b-99ed-63b8d88d7b89", "current-target"]
@@ -563,11 +563,11 @@
 task: "metrics_producer_gc"
   configured period: every 1m
   currently executing: no
   last completed activation: <REDACTED ITERATIONS>, triggered by a periodic timer firing
     started at <REDACTED     TIMESTAMP> (<REDACTED DURATION>s ago) and ran for <REDACTED DURATION>ms
-warning: unknown background task: "metrics_producer_gc" (don't know how to interpret details: Object {"expiration": String("<REDACTED           TIMESTAMP>"), "pruned": Array []})
+warning: unknown background task: "metrics_producer_gc" (don't know how to interpret details: Object {"expiration": String("<REDACTED        TIMESTAMP>"), "pruned": Array []})
 
 task: "phantom_disks"
   configured period: every <REDACTED_DURATION>s
   currently executing: no
   last completed activation: <REDACTED ITERATIONS>, triggered by a periodic timer firing
@@ -990,11 +990,11 @@
 task: "metrics_producer_gc"
   configured period: every 1m
   currently executing: no
   last completed activation: <REDACTED ITERATIONS>, triggered by a periodic timer firing
     started at <REDACTED     TIMESTAMP> (<REDACTED DURATION>s ago) and ran for <REDACTED DURATION>ms
-warning: unknown background task: "metrics_producer_gc" (don't know how to interpret details: Object {"expiration": String("<REDACTED           TIMESTAMP>"), "pruned": Array []})
+warning: unknown background task: "metrics_producer_gc" (don't know how to interpret details: Object {"expiration": String("<REDACTED        TIMESTAMP>"), "pruned": Array []})
 
 task: "phantom_disks"
   configured period: every <REDACTED_DURATION>s
   currently executing: no
   last completed activation: <REDACTED ITERATIONS>, triggered by a periodic timer firing

test test_omdb_success_cases ... FAILED

failures:

failures:
    test_omdb_success_cases

I was actually trying to reproduce #6505 locally, but this looks like a different error. Notably, I'm seeing differences in the whitespace between REDACTED...TIMESTAMP.

[smklein]

Other notes: This was on Helios, after running cargo nt -p omicron-omdb -- test_omdb_success_cases in a loop for almost 100 iterations.

[davepacheco]

It looks like the code that does the timestamp redactions attempts to preserve the width (in characters) of the timestamp:

omicron/test-utils/src/dev/test_cmds.rs

Lines 175 to 177 in eb54c1c

	for _ in 0..(m.len() - "<REDACTEDTIMESTAMP>".len()) {
	new_s.push(' ');
	}

It sounds like most of the time, the width matches what's in the expected output file. In this case, it was 3 characters shorter. In the past I've seen that some ways of formatting timestamps implicitly vary the precision based on the value -- e.g., if the milliseconds happens to be exactly 0, then they get left out.

On a regular run I saw this value:

warning: unknown background task: "metrics_producer_gc" (don't know how to interpret details: Object {"expiration": String("2024-09-03T17:29:27.850928397Z"), "pruned": Array []})

So (1) we're doing the string formatting on the server, and (2) my guess is that the nanoseconds component was 0 in the case we saw and the serialization just left it out.