Standardize timestamps in runsc log filenames.

Prior to this change, the log files each have their own timestamp computed
independently. For example, this means that the coverage log file, the panic
log file, the debug log file, the first Gofer's log file, and the profile
files for the same Sentry may all have different timestamps in their
filenames. Now they are the same.

This change introduces a central `runsc/starttime` package for which the sole
purpose is to hold the start time of the `runsc` process, for easy plumbing
in all places that need it.

PiperOrigin-RevId: 646667986

runsc/cli/BUILD

@@ -25,6 +25,7 @@ go_library(
         "//runsc/config",
         "//runsc/flag",
         "//runsc/specutils",
+        "//runsc/starttime",
         "//runsc/version",
         "@com_github_google_subcommands//:go_default_library",
         "@org_golang_x_sys//unix:go_default_library",

runsc/cli/main.go

@@ -41,6 +41,7 @@ import (
 	"gvisor.dev/gvisor/runsc/config"
 	"gvisor.dev/gvisor/runsc/flag"
 	"gvisor.dev/gvisor/runsc/specutils"
+	"gvisor.dev/gvisor/runsc/starttime"
 	"gvisor.dev/gvisor/runsc/version"
 )
 
@@ -133,14 +134,17 @@ func Main() {
 	// case that does not occur.
 	_ = time.Local.String()
 
+	// Set the start time as soon as possible.
+	startTime := starttime.Get()
+
 	var emitters log.MultiEmitter
 	if *debugLogFD > -1 {
 		f := os.NewFile(uintptr(*debugLogFD), "debug log file")
 
 		emitters = append(emitters, newEmitter(conf.DebugLogFormat, f))
 
 	} else if len(conf.DebugLog) > 0 && specutils.IsDebugCommand(conf, subcommand) {
-		f, err := specutils.DebugLogFile(conf.DebugLog, subcommand, "" /* name */)
+		f, err := specutils.DebugLogFile(conf.DebugLog, subcommand, "" /* name */, startTime)
 		if err != nil {
 			util.Fatalf("error opening debug log file in %q: %v", conf.DebugLog, err)
 		}

runsc/container/BUILD

@@ -33,8 +33,10 @@ go_library(
         "//runsc/config",
         "//runsc/console",
         "//runsc/donation",
+        "//runsc/profile",
         "//runsc/sandbox",
         "//runsc/specutils",
+        "//runsc/starttime",
         "@com_github_cenkalti_backoff//:go_default_library",
         "@com_github_gofrs_flock//:go_default_library",
         "@com_github_opencontainers_runtime_spec//specs-go:go_default_library",

runsc/container/container.go

@@ -47,8 +47,10 @@ import (
 	"gvisor.dev/gvisor/runsc/config"
 	"gvisor.dev/gvisor/runsc/console"
 	"gvisor.dev/gvisor/runsc/donation"
+	"gvisor.dev/gvisor/runsc/profile"
 	"gvisor.dev/gvisor/runsc/sandbox"
 	"gvisor.dev/gvisor/runsc/specutils"
+	"gvisor.dev/gvisor/runsc/starttime"
 )
 
 const cgroupParentAnnotation = "dev.gvisor.spec.cgroup-parent"
@@ -1200,7 +1202,18 @@ func (c *Container) createGoferProcess(spec *specs.Spec, conf *config.Config, bu
 			}
 		}
 		if specutils.IsDebugCommand(conf, "gofer") {
-			if err := donations.DonateDebugLogFile("debug-log-fd", conf.DebugLog, "gofer", test); err != nil {
+			// The startTime here can mean one of two things:
+			// - If this is the first gofer started at the same time as the sandbox,
+			//   then this starttime will exactly match the one used by the sandbox
+			//   itself (i.e. `Sandbox.StartTime`). This is desirable, such that the
+			//   first gofer's log filename will have the exact same timestamp as
+			//   the sandbox's log filename timestamp.
+			// - If this is not the first gofer, then this starttime will be later
+			//   than the sandbox start time; this is desirable such that we can
+			//   distinguish the gofer log filenames between each other.
+			// In either case, `starttime.Get` gets us the timestamp we want.
+			startTime := starttime.Get()
+			if err := donations.DonateDebugLogFile("debug-log-fd", conf.DebugLog, "gofer", test, startTime); err != nil {
 				return nil, nil, nil, err
 			}
 		}
@@ -1701,6 +1714,7 @@ func (c *Container) donateGoferProfileFDs(conf *config.Config, donations *donati
 	// into a single file.
 	profSuffix := ".gofer." + c.ID
 	const profFlags = os.O_CREATE | os.O_WRONLY | os.O_TRUNC
+	profile.UpdatePaths(conf, starttime.Get())
 	if conf.ProfileBlock != "" {
 		if err := donations.OpenAndDonate("profile-block-fd", conf.ProfileBlock+profSuffix, profFlags); err != nil {
 			return err

runsc/donation/donation.go

@@ -20,6 +20,7 @@ import (
 	"fmt"
 	"os"
 	"os/exec"
+	"time"
 
 	"gvisor.dev/gvisor/pkg/log"
 	"gvisor.dev/gvisor/runsc/specutils"
@@ -75,11 +76,11 @@ func (f *Agency) OpenAndDonate(flag, path string, flags int) error {
 // DonateDebugLogFile is similar to DonateAndClose but handles the opening of
 // the file using specutils.DebugLogFile() for convenience. It's a noop, if
 // path is empty.
-func (f *Agency) DonateDebugLogFile(flag, logPattern, command, test string) error {
+func (f *Agency) DonateDebugLogFile(flag, logPattern, command, test string, timestamp time.Time) error {
 	if len(logPattern) == 0 {
 		return nil
 	}
-	file, err := specutils.DebugLogFile(logPattern, command, test)
+	file, err := specutils.DebugLogFile(logPattern, command, test, timestamp)
 	if err != nil {
 		return fmt.Errorf("opening debug log file in %q: %v", logPattern, err)
 	}

runsc/profile/BUILD

@@ -14,6 +14,7 @@ go_library(
     deps = [
         "//pkg/log",
         "//pkg/sentry/control",
+        "//runsc/config",
         "//runsc/flag",
     ],
 )

runsc/profile/profile.go

@@ -16,13 +16,17 @@
 package profile
 
 import (
+	"fmt"
 	"os"
 	"runtime"
 	"runtime/pprof"
 	"runtime/trace"
+	"strings"
+	"time"
 
 	"gvisor.dev/gvisor/pkg/log"
 	"gvisor.dev/gvisor/pkg/sentry/control"
+	"gvisor.dev/gvisor/runsc/config"
 	"gvisor.dev/gvisor/runsc/flag"
 )
 
@@ -177,3 +181,26 @@ func Start(opts Opts) func() {
 
 	return stopProfiling
 }
+
+// UpdatePaths updates profiling-related file paths in the given config.
+func UpdatePaths(conf *config.Config, timestamp time.Time) {
+	if !conf.ProfileEnable {
+		return
+	}
+	conf.ProfileCPU = updatePath(conf.ProfileCPU, timestamp)
+	conf.ProfileHeap = updatePath(conf.ProfileHeap, timestamp)
+	conf.ProfileMutex = updatePath(conf.ProfileMutex, timestamp)
+	conf.ProfileBlock = updatePath(conf.ProfileBlock, timestamp)
+}
+
+func updatePath(path string, now time.Time) string {
+	path = strings.ReplaceAll(path, "%TIMESTAMP%", fmt.Sprintf("%d", now.Unix()))
+	path = strings.ReplaceAll(path, "%YYYY%", now.Format("2006"))
+	path = strings.ReplaceAll(path, "%MM%", now.Format("01"))
+	path = strings.ReplaceAll(path, "%DD%", now.Format("02"))
+	path = strings.ReplaceAll(path, "%HH%", now.Format("15"))
+	path = strings.ReplaceAll(path, "%II%", now.Format("04"))
+	path = strings.ReplaceAll(path, "%SS%", now.Format("05"))
+	path = strings.ReplaceAll(path, "%NN%", fmt.Sprintf("%09d", now.Nanosecond()))
+	return path
+}

runsc/sandbox/BUILD

@@ -48,8 +48,10 @@ go_library(
         "//runsc/config",
         "//runsc/console",
         "//runsc/donation",
+        "//runsc/profile",
         "//runsc/sandbox/bpf",
         "//runsc/specutils",
+        "//runsc/starttime",
         "//tools/xdp/cmd",
         "@com_github_cenkalti_backoff//:go_default_library",
         "@com_github_cilium_ebpf//:go_default_library",

runsc/sandbox/sandbox.go

@@ -60,7 +60,9 @@ import (
 	"gvisor.dev/gvisor/runsc/config"
 	"gvisor.dev/gvisor/runsc/console"
 	"gvisor.dev/gvisor/runsc/donation"
+	"gvisor.dev/gvisor/runsc/profile"
 	"gvisor.dev/gvisor/runsc/specutils"
+	"gvisor.dev/gvisor/runsc/starttime"
 )
 
 const (
@@ -188,6 +190,9 @@ type Sandbox struct {
 	// to the entire pod.
 	MountHints *boot.PodMountHints `json:"mountHints"`
 
+	// StartTime is the time the sandbox was started.
+	StartTime time.Time `json:"startTime"`
+
 	// child is set if a sandbox process is a child of the current process.
 	//
 	// This field isn't saved to json, because only a creator of sandbox
@@ -285,6 +290,7 @@ func New(conf *config.Config, args *Args) (*Sandbox, error) {
 		MetricMetadata:      conf.MetricMetadata(),
 		MetricServerAddress: conf.MetricServer,
 		MountHints:          args.MountHints,
+		StartTime:           starttime.Get(),
 	}
 	if args.Spec != nil && args.Spec.Annotations != nil {
 		s.PodName = args.Spec.Annotations[podNameAnnotation]
@@ -763,19 +769,19 @@ func (s *Sandbox) createSandboxProcess(conf *config.Config, args *Args, startSyn
 		}
 	}
 	if specutils.IsDebugCommand(conf, "boot") {
-		if err := donations.DonateDebugLogFile("debug-log-fd", conf.DebugLog, "boot", test); err != nil {
+		if err := donations.DonateDebugLogFile("debug-log-fd", conf.DebugLog, "boot", test, s.StartTime); err != nil {
 			return err
 		}
 	}
-	if err := donations.DonateDebugLogFile("panic-log-fd", conf.PanicLog, "panic", test); err != nil {
+	if err := donations.DonateDebugLogFile("panic-log-fd", conf.PanicLog, "panic", test, s.StartTime); err != nil {
 		return err
 	}
 	covFilename := conf.CoverageReport
 	if covFilename == "" {
 		covFilename = os.Getenv("GO_COVERAGE_FILE")
 	}
 	if covFilename != "" && coverage.Available() {
-		if err := donations.DonateDebugLogFile("coverage-fd", covFilename, "cov", test); err != nil {
+		if err := donations.DonateDebugLogFile("coverage-fd", covFilename, "cov", test, s.StartTime); err != nil {
 			return err
 		}
 	}
@@ -817,6 +823,7 @@ func (s *Sandbox) createSandboxProcess(conf *config.Config, args *Args, startSyn
 		return err
 	}
 	const profFlags = os.O_CREATE | os.O_WRONLY | os.O_TRUNC
+	profile.UpdatePaths(conf, s.StartTime)
 	if err := donations.OpenAndDonate("profile-block-fd", conf.ProfileBlock, profFlags); err != nil {
 		return err
 	}
@@ -1095,7 +1102,7 @@ func (s *Sandbox) createSandboxProcess(conf *config.Config, args *Args, startSyn
 		donations.Donate("profiling-metrics-fd", stdios[1])
 		cmd.Args = append(cmd.Args, "--profiling-metrics-fd-lossy=true")
 	} else if conf.ProfilingMetricsLog != "" {
-		if err := donations.DonateDebugLogFile("profiling-metrics-fd", conf.ProfilingMetricsLog, "metrics", test); err != nil {
+		if err := donations.DonateDebugLogFile("profiling-metrics-fd", conf.ProfilingMetricsLog, "metrics", test, s.StartTime); err != nil {
 			return err
 		}
 		cmd.Args = append(cmd.Args, "--profiling-metrics-fd-lossy=false")

runsc/specutils/specutils.go

@@ -528,12 +528,12 @@ func WaitForReady(pid int, timeout time.Duration, ready func() (bool, error)) er
 //     <yyyymmdd-hhmmss.uuuuuu>
 //   - %COMMAND%: is replaced with 'command'
 //   - %TEST%: is replaced with 'test' (omitted by default)
-func DebugLogFile(logPattern, command, test string) (*os.File, error) {
+func DebugLogFile(logPattern, command, test string, timestamp time.Time) (*os.File, error) {
 	if strings.HasSuffix(logPattern, "/") {
 		// Default format: <debug-log>/runsc.log.<yyyymmdd-hhmmss.uuuuuu>.<command>.txt
 		logPattern += "runsc.log.%TIMESTAMP%.%COMMAND%.txt"
 	}
-	logPattern = strings.Replace(logPattern, "%TIMESTAMP%", time.Now().Format("20060102-150405.000000"), -1)
+	logPattern = strings.Replace(logPattern, "%TIMESTAMP%", timestamp.Format("20060102-150405.000000"), -1)
 	logPattern = strings.Replace(logPattern, "%COMMAND%", command, -1)
 	logPattern = strings.Replace(logPattern, "%TEST%", test, -1)
 

runsc/starttime/BUILD

@@ -0,0 +1,14 @@
+load("//tools:defs.bzl", "go_library")
+
+package(
+    default_applicable_licenses = ["//:license"],
+    licenses = ["notice"],
+)
+
+go_library(
+    name = "starttime",
+    srcs = [
+        "starttime.go",
+    ],
+    visibility = ["//runsc:__subpackages__"],
+)

runsc/starttime/starttime.go

@@ -0,0 +1,35 @@
+// Copyright 2024 The gVisor Authors.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+// Package starttime holds the time the `runsc` command started.
+// It is useful in order to plumb this time wherever needed.
+package starttime
+
+import (
+	"sync"
+	"time"
+)
+
+var (
+	setOnce   sync.Once
+	startTime time.Time
+)
+
+// Get returns the time the `runsc` command started.
+func Get() time.Time {
+	setOnce.Do(func() {
+		startTime = time.Now()
+	})
+	return startTime
+}