From 4893cdac7471ffd01773ec27fd7afe847c5dbd12 Mon Sep 17 00:00:00 2001 From: Kristoffer Dalby Date: Mon, 8 Sep 2025 11:18:42 +0200 Subject: [PATCH] integration: make timestamp const Signed-off-by: Kristoffer Dalby --- integration/auth_oidc_test.go | 6 +++--- integration/dockertestutil/config.go | 8 ++++++- integration/general_test.go | 16 +++++++------- integration/route_test.go | 32 +++++++++++++--------------- integration/utils.go | 9 ++++++++ 5 files changed, 42 insertions(+), 29 deletions(-) diff --git a/integration/auth_oidc_test.go b/integration/auth_oidc_test.go index 0fe1fe12..751a8d11 100644 --- a/integration/auth_oidc_test.go +++ b/integration/auth_oidc_test.go @@ -592,7 +592,7 @@ func TestOIDCReloginSameNodeNewUser(t *testing.T) { assertNoErr(t, err) t.Logf("Logged out take one") - t.Log("timestamp: " + time.Now().Format("2006-01-02T15-04-05.999999999") + "\n") + t.Log("timestamp: " + time.Now().Format(TimestampFormat) + "\n") // TODO(kradalby): Not sure why we need to logout twice, but it fails and // logs in immediately after the first logout and I cannot reproduce it @@ -601,7 +601,7 @@ func TestOIDCReloginSameNodeNewUser(t *testing.T) { assertNoErr(t, err) t.Logf("Logged out take two") - t.Log("timestamp: " + time.Now().Format("2006-01-02T15-04-05.999999999") + "\n") + t.Log("timestamp: " + time.Now().Format(TimestampFormat) + "\n") // Wait for logout to complete and then do second logout assert.EventuallyWithT(t, func(ct *assert.CollectT) { @@ -627,7 +627,7 @@ func TestOIDCReloginSameNodeNewUser(t *testing.T) { }, 30*time.Second, 1*time.Second) t.Logf("Logged back in") - t.Log("timestamp: " + time.Now().Format("2006-01-02T15-04-05.999999999") + "\n") + t.Log("timestamp: " + time.Now().Format(TimestampFormat) + "\n") assert.EventuallyWithT(t, func(ct *assert.CollectT) { listUsers, err := headscale.ListUsers() diff --git a/integration/dockertestutil/config.go b/integration/dockertestutil/config.go index dc8391d7..c0c57a3e 100644 --- a/integration/dockertestutil/config.go +++ b/integration/dockertestutil/config.go @@ -10,6 +10,12 @@ import ( "github.com/ory/dockertest/v3" ) +const ( + // TimestampFormatRunID is used for generating unique run identifiers + // Format: "20060102-150405" provides compact date-time for file/directory names. + TimestampFormatRunID = "20060102-150405" +) + // GetIntegrationRunID returns the run ID for the current integration test session. // This is set by the hi tool and passed through environment variables. func GetIntegrationRunID() string { @@ -36,7 +42,7 @@ func DockerAddIntegrationLabels(opts *dockertest.RunOptions, testType string) { // Format: YYYYMMDD-HHMMSS-HASH (e.g., 20250619-143052-a1b2c3). func GenerateRunID() string { now := time.Now() - timestamp := now.Format("20060102-150405") + timestamp := now.Format(TimestampFormatRunID) // Add a short random hash to ensure uniqueness randomHash := util.MustGenerateRandomStringDNSSafe(6) diff --git a/integration/general_test.go b/integration/general_test.go index cb6d83dd..65131af0 100644 --- a/integration/general_test.go +++ b/integration/general_test.go @@ -1009,7 +1009,7 @@ func TestPingAllByIPManyUpDown(t *testing.T) { t.Logf("%d successful pings out of %d", success, len(allClients)*len(allIps)) for run := range 3 { - t.Logf("Starting DownUpPing run %d at %s", run+1, time.Now().Format("2006-01-02T15-04-05.999999999")) + t.Logf("Starting DownUpPing run %d at %s", run+1, time.Now().Format(TimestampFormat)) // Create fresh errgroup with timeout for each run ctx, cancel := context.WithTimeout(context.Background(), 30*time.Second) @@ -1026,7 +1026,7 @@ func TestPingAllByIPManyUpDown(t *testing.T) { if err := wg.Wait(); err != nil { t.Fatalf("failed to take down all nodes: %s", err) } - t.Logf("All nodes taken down at %s", time.Now().Format("2006-01-02T15-04-05.999999999")) + t.Logf("All nodes taken down at %s", time.Now().Format(TimestampFormat)) // After taking down all nodes, verify all systems show nodes offline requireAllClientsOnline(t, headscale, expectedNodes, false, fmt.Sprintf("Run %d: all nodes should be offline after Down()", run+1), 120*time.Second) @@ -1042,7 +1042,7 @@ func TestPingAllByIPManyUpDown(t *testing.T) { if err := wg.Wait(); err != nil { t.Fatalf("failed to bring up all nodes: %s", err) } - t.Logf("All nodes brought up at %s", time.Now().Format("2006-01-02T15-04-05.999999999")) + t.Logf("All nodes brought up at %s", time.Now().Format(TimestampFormat)) // After bringing up all nodes, verify batcher shows all reconnected requireAllClientsOnline(t, headscale, expectedNodes, true, fmt.Sprintf("Run %d: all nodes should be reconnected after Up()", run+1), 120*time.Second) @@ -1051,7 +1051,7 @@ func TestPingAllByIPManyUpDown(t *testing.T) { err = scenario.WaitForTailscaleSync() assert.NoError(t, err) - t.Logf("All nodes synced up %s", time.Now().Format("2006-01-02T15-04-05.999999999")) + t.Logf("All nodes synced up %s", time.Now().Format(TimestampFormat)) requireAllClientsOnline(t, headscale, expectedNodes, true, fmt.Sprintf("Run %d: all systems should show nodes online after reconnection", run+1), 60*time.Second) @@ -1184,7 +1184,7 @@ func requireAllClientsOnline(t *testing.T, headscale ControlServer, expectedNode t.Helper() startTime := time.Now() - t.Logf("requireAllSystemsOnline: Starting validation at %s - %s", startTime.Format("2006-01-02T15:04:05.000"), message) + t.Logf("requireAllSystemsOnline: Starting validation at %s - %s", startTime.Format(TimestampFormat), message) var prevReport string require.EventuallyWithT(t, func(c *assert.CollectT) { @@ -1306,11 +1306,11 @@ func requireAllClientsOnline(t *testing.T, headscale ControlServer, expectedNode t.Log("Diff between reports:") t.Logf("Prev report: \n%s\n", prevReport) t.Logf("New report: \n%s\n", failureReport.String()) - t.Log("timestamp: " + time.Now().Format("2006-01-02T15-04-05.999999999") + "\n") + t.Log("timestamp: " + time.Now().Format(TimestampFormat) + "\n") prevReport = failureReport.String() } - failureReport.WriteString("timestamp: " + time.Now().Format("2006-01-02T15-04-05.999999999") + "\n") + failureReport.WriteString("timestamp: " + time.Now().Format(TimestampFormat) + "\n") assert.Fail(c, failureReport.String()) } @@ -1324,5 +1324,5 @@ func requireAllClientsOnline(t *testing.T, headscale ControlServer, expectedNode endTime := time.Now() duration := endTime.Sub(startTime) - t.Logf("requireAllSystemsOnline: Completed validation at %s - Duration: %v - %s", endTime.Format("2006-01-02T15:04:05.000"), duration, message) + t.Logf("requireAllSystemsOnline: Completed validation at %s - Duration: %v - %s", endTime.Format(TimestampFormat), duration, message) } diff --git a/integration/route_test.go b/integration/route_test.go index 66db271d..9af24f77 100644 --- a/integration/route_test.go +++ b/integration/route_test.go @@ -34,8 +34,6 @@ import ( "tailscale.com/wgengine/filter" ) -const timestampFormat = "15:04:05.000" - var allPorts = filter.PortRange{First: 0, Last: 0xffff} // This test is both testing the routes command and the propagation of @@ -305,7 +303,7 @@ func TestHASubnetRouterFailover(t *testing.T) { t.Logf("%s (%s) picked as client", client.Hostname(), client.MustID()) t.Logf("=== Initial Route Advertisement - Setting up HA configuration with 3 routers ===") - t.Logf("[%s] Starting test section", time.Now().Format(timestampFormat)) + t.Logf("[%s] Starting test section", time.Now().Format(TimestampFormat)) t.Logf(" - Router 1 (%s): Advertising route %s - will become PRIMARY when approved", subRouter1.Hostname(), pref.String()) t.Logf(" - Router 2 (%s): Advertising route %s - will be STANDBY when approved", subRouter2.Hostname(), pref.String()) t.Logf(" - Router 3 (%s): Advertising route %s - will be STANDBY when approved", subRouter3.Hostname(), pref.String()) @@ -363,7 +361,7 @@ func TestHASubnetRouterFailover(t *testing.T) { // Helper function to check test failure and print route map if needed checkFailureAndPrintRoutes := func(t *testing.T, client TailscaleClient) { if t.Failed() { - t.Logf("[%s] Test failed at this checkpoint", time.Now().Format(timestampFormat)) + t.Logf("[%s] Test failed at this checkpoint", time.Now().Format(TimestampFormat)) status, err := client.Status() if err == nil { printCurrentRouteMap(t, xmaps.Values(status.Peer)...) @@ -382,7 +380,7 @@ func TestHASubnetRouterFailover(t *testing.T) { // Enable route on node 1 t.Logf("=== Approving route on router 1 (%s) - Single router mode (no HA yet) ===", subRouter1.Hostname()) - t.Logf("[%s] Starting test section", time.Now().Format(timestampFormat)) + t.Logf("[%s] Starting test section", time.Now().Format(TimestampFormat)) t.Logf(" Expected: Router 1 becomes PRIMARY with route %s active", pref.String()) t.Logf(" Expected: Routers 2 & 3 remain with advertised but unapproved routes") t.Logf(" Expected: Client can access webservice through router 1 only") @@ -445,7 +443,7 @@ func TestHASubnetRouterFailover(t *testing.T) { }, propagationTime, 200*time.Millisecond, "Verifying Router 1 is PRIMARY with routes after approval") t.Logf("=== Validating connectivity through PRIMARY router 1 (%s) to webservice at %s ===", must.Get(subRouter1.IPv4()).String(), webip.String()) - t.Logf("[%s] Starting test section", time.Now().Format(timestampFormat)) + t.Logf("[%s] Starting test section", time.Now().Format(TimestampFormat)) t.Logf(" Expected: Traffic flows through router 1 as it's the only approved route") assert.EventuallyWithT(t, func(c *assert.CollectT) { result, err := client.Curl(weburl) @@ -478,7 +476,7 @@ func TestHASubnetRouterFailover(t *testing.T) { // Enable route on node 2, now we will have a HA subnet router t.Logf("=== Enabling High Availability by approving route on router 2 (%s) ===", subRouter2.Hostname()) - t.Logf("[%s] Starting test section", time.Now().Format(timestampFormat)) + t.Logf("[%s] Starting test section", time.Now().Format(TimestampFormat)) t.Logf(" Current state: Router 1 is PRIMARY and actively serving traffic") t.Logf(" Expected: Router 2 becomes STANDBY (approved but not primary)") t.Logf(" Expected: Router 1 remains PRIMARY (no flapping - stability preferred)") @@ -556,7 +554,7 @@ func TestHASubnetRouterFailover(t *testing.T) { checkFailureAndPrintRoutes(t, client) t.Logf("=== Validating HA configuration - Router 1 PRIMARY, Router 2 STANDBY ===") - t.Logf("[%s] Starting test section", time.Now().Format(timestampFormat)) + t.Logf("[%s] Starting test section", time.Now().Format(TimestampFormat)) t.Logf(" Current routing: Traffic through router 1 (%s) to %s", must.Get(subRouter1.IPv4()), webip.String()) t.Logf(" Expected: Router 1 continues to handle all traffic (no change from before)") t.Logf(" Expected: Router 2 is ready to take over if router 1 fails") @@ -593,7 +591,7 @@ func TestHASubnetRouterFailover(t *testing.T) { // Enable route on node 3, now we will have a second standby and all will // be enabled. t.Logf("=== Adding second STANDBY router by approving route on router 3 (%s) ===", subRouter3.Hostname()) - t.Logf("[%s] Starting test section", time.Now().Format(timestampFormat)) + t.Logf("[%s] Starting test section", time.Now().Format(TimestampFormat)) t.Logf(" Current state: Router 1 PRIMARY, Router 2 STANDBY") t.Logf(" Expected: Router 3 becomes second STANDBY (approved but not primary)") t.Logf(" Expected: Router 1 remains PRIMARY, Router 2 remains first STANDBY") @@ -699,7 +697,7 @@ func TestHASubnetRouterFailover(t *testing.T) { // Take down the current primary t.Logf("=== FAILOVER TEST: Taking down PRIMARY router 1 (%s) ===", subRouter1.Hostname()) - t.Logf("[%s] Starting test section", time.Now().Format(timestampFormat)) + t.Logf("[%s] Starting test section", time.Now().Format(TimestampFormat)) t.Logf(" Current state: Router 1 PRIMARY (serving traffic), Router 2 & 3 STANDBY") t.Logf(" Action: Shutting down router 1 to simulate failure") t.Logf(" Expected: Router 2 (%s) should automatically become new PRIMARY", subRouter2.Hostname()) @@ -777,7 +775,7 @@ func TestHASubnetRouterFailover(t *testing.T) { // Take down subnet router 2, leaving none available t.Logf("=== FAILOVER TEST: Taking down NEW PRIMARY router 2 (%s) ===", subRouter2.Hostname()) - t.Logf("[%s] Starting test section", time.Now().Format(timestampFormat)) + t.Logf("[%s] Starting test section", time.Now().Format(TimestampFormat)) t.Logf(" Current state: Router 1 OFFLINE, Router 2 PRIMARY (serving traffic), Router 3 STANDBY") t.Logf(" Action: Shutting down router 2 to simulate cascading failure") t.Logf(" Expected: Router 3 (%s) should become new PRIMARY (last remaining router)", subRouter3.Hostname()) @@ -847,7 +845,7 @@ func TestHASubnetRouterFailover(t *testing.T) { // Bring up subnet router 1, making the route available from there. t.Logf("=== RECOVERY TEST: Bringing router 1 (%s) back online ===", subRouter1.Hostname()) - t.Logf("[%s] Starting test section", time.Now().Format(timestampFormat)) + t.Logf("[%s] Starting test section", time.Now().Format(TimestampFormat)) t.Logf(" Current state: Router 1 OFFLINE, Router 2 OFFLINE, Router 3 PRIMARY (only router)") t.Logf(" Action: Starting router 1 to restore HA capability") t.Logf(" Expected: Router 3 remains PRIMARY (stability - no unnecessary failover)") @@ -925,7 +923,7 @@ func TestHASubnetRouterFailover(t *testing.T) { // Bring up subnet router 2, should result in no change. t.Logf("=== FULL RECOVERY TEST: Bringing router 2 (%s) back online ===", subRouter2.Hostname()) - t.Logf("[%s] Starting test section", time.Now().Format(timestampFormat)) + t.Logf("[%s] Starting test section", time.Now().Format(TimestampFormat)) t.Logf(" Current state: Router 1 STANDBY, Router 2 OFFLINE, Router 3 PRIMARY") t.Logf(" Action: Starting router 2 to restore full HA (3 routers)") t.Logf(" Expected: Router 3 (%s) remains PRIMARY (stability - avoid unnecessary failovers)", subRouter3.Hostname()) @@ -1004,7 +1002,7 @@ func TestHASubnetRouterFailover(t *testing.T) { checkFailureAndPrintRoutes(t, client) t.Logf("=== ROUTE DISABLE TEST: Removing approved route from PRIMARY router 3 (%s) ===", subRouter3.Hostname()) - t.Logf("[%s] Starting test section", time.Now().Format(timestampFormat)) + t.Logf("[%s] Starting test section", time.Now().Format(TimestampFormat)) t.Logf(" Current state: Router 1 STANDBY, Router 2 STANDBY, Router 3 PRIMARY") t.Logf(" Action: Disabling route approval on router 3 (route still advertised but not approved)") t.Logf(" Expected: Router 1 (%s) should become new PRIMARY (lowest ID with approved route)", subRouter1.Hostname()) @@ -1090,7 +1088,7 @@ func TestHASubnetRouterFailover(t *testing.T) { // Disable the route of subnet router 1, making it failover to 2 t.Logf("=== ROUTE DISABLE TEST: Removing approved route from NEW PRIMARY router 1 (%s) ===", subRouter1.Hostname()) - t.Logf("[%s] Starting test section", time.Now().Format(timestampFormat)) + t.Logf("[%s] Starting test section", time.Now().Format(TimestampFormat)) t.Logf(" Current state: Router 1 PRIMARY, Router 2 STANDBY, Router 3 advertised-only") t.Logf(" Action: Disabling route approval on router 1") t.Logf(" Expected: Router 2 (%s) should become new PRIMARY (only remaining approved route)", subRouter2.Hostname()) @@ -1176,7 +1174,7 @@ func TestHASubnetRouterFailover(t *testing.T) { // enable the route of subnet router 1, no change expected t.Logf("=== ROUTE RE-ENABLE TEST: Re-approving route on router 1 (%s) ===", subRouter1.Hostname()) - t.Logf("[%s] Starting test section", time.Now().Format(timestampFormat)) + t.Logf("[%s] Starting test section", time.Now().Format(TimestampFormat)) t.Logf(" Current state: Router 1 advertised-only, Router 2 PRIMARY, Router 3 advertised-only") t.Logf(" Action: Re-enabling route approval on router 1") t.Logf(" Expected: Router 2 (%s) remains PRIMARY (stability - no unnecessary flapping)", subRouter2.Hostname()) @@ -1260,7 +1258,7 @@ func TestHASubnetRouterFailover(t *testing.T) { // Enable route on node 3, we now have all routes re-enabled t.Logf("=== ROUTE RE-ENABLE TEST: Re-approving route on router 3 (%s) - Full HA Restoration ===", subRouter3.Hostname()) - t.Logf("[%s] Starting test section", time.Now().Format(timestampFormat)) + t.Logf("[%s] Starting test section", time.Now().Format(TimestampFormat)) t.Logf(" Current state: Router 1 STANDBY, Router 2 PRIMARY, Router 3 advertised-only") t.Logf(" Action: Re-enabling route approval on router 3") t.Logf(" Expected: Router 2 (%s) remains PRIMARY (stability preferred)", subRouter2.Hostname()) diff --git a/integration/utils.go b/integration/utils.go index 2e70b793..117bdab7 100644 --- a/integration/utils.go +++ b/integration/utils.go @@ -28,6 +28,15 @@ const ( // derpPingCount defines the number of ping attempts for DERP connectivity tests // Higher count provides better reliability assessment of DERP connectivity. derpPingCount = 10 + + // TimestampFormat is the standard timestamp format used across all integration tests + // Format: "2006-01-02T15-04-05.999999999" provides high precision timestamps + // suitable for debugging and log correlation in integration tests. + TimestampFormat = "2006-01-02T15-04-05.999999999" + + // TimestampFormatRunID is used for generating unique run identifiers + // Format: "20060102-150405" provides compact date-time for file/directory names. + TimestampFormatRunID = "20060102-150405" ) func assertNoErr(t *testing.T, err error) {