From b4ca91450fb6012629a535b5751fbdf67944e7a7 Mon Sep 17 00:00:00 2001 From: Etienne Perot Date: Tue, 25 Jun 2024 17:44:54 -0700 Subject: [PATCH] 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 | 1 + runsc/cli/main.go | 6 +++++- runsc/container/BUILD | 2 ++ runsc/container/container.go | 16 +++++++++++++++- runsc/donation/donation.go | 5 +++-- runsc/profile/BUILD | 1 + runsc/profile/profile.go | 27 +++++++++++++++++++++++++++ runsc/sandbox/BUILD | 2 ++ runsc/sandbox/sandbox.go | 15 +++++++++++---- runsc/specutils/specutils.go | 4 ++-- runsc/starttime/BUILD | 14 ++++++++++++++ runsc/starttime/starttime.go | 35 +++++++++++++++++++++++++++++++++++ 12 files changed, 118 insertions(+), 10 deletions(-) create mode 100644 runsc/starttime/BUILD create mode 100644 runsc/starttime/starttime.go diff --git a/runsc/cli/BUILD b/runsc/cli/BUILD index df7226ca0..208754bc4 100644 --- a/runsc/cli/BUILD +++ b/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", diff --git a/runsc/cli/main.go b/runsc/cli/main.go index 0e79ef39b..3f7e5b48b 100644 --- a/runsc/cli/main.go +++ b/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,6 +134,9 @@ 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") @@ -140,7 +144,7 @@ func Main() { 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) } diff --git a/runsc/container/BUILD b/runsc/container/BUILD index db792464a..135a918cb 100644 --- a/runsc/container/BUILD +++ b/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", diff --git a/runsc/container/container.go b/runsc/container/container.go index e00154370..35495fc5a 100644 --- a/runsc/container/container.go +++ b/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 diff --git a/runsc/donation/donation.go b/runsc/donation/donation.go index f128eafed..0ea2297b7 100644 --- a/runsc/donation/donation.go +++ b/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) } diff --git a/runsc/profile/BUILD b/runsc/profile/BUILD index 16c055a5c..af5e1f0c9 100644 --- a/runsc/profile/BUILD +++ b/runsc/profile/BUILD @@ -14,6 +14,7 @@ go_library( deps = [ "//pkg/log", "//pkg/sentry/control", + "//runsc/config", "//runsc/flag", ], ) diff --git a/runsc/profile/profile.go b/runsc/profile/profile.go index 64b5369f1..f01c9b6c9 100644 --- a/runsc/profile/profile.go +++ b/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 +} diff --git a/runsc/sandbox/BUILD b/runsc/sandbox/BUILD index 8a76fa2da..83ba8ba60 100644 --- a/runsc/sandbox/BUILD +++ b/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", diff --git a/runsc/sandbox/sandbox.go b/runsc/sandbox/sandbox.go index 0724ad338..76e582319 100644 --- a/runsc/sandbox/sandbox.go +++ b/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,11 +769,11 @@ 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 @@ -775,7 +781,7 @@ func (s *Sandbox) createSandboxProcess(conf *config.Config, args *Args, startSyn 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") diff --git a/runsc/specutils/specutils.go b/runsc/specutils/specutils.go index 0503e2258..e6373e8c9 100644 --- a/runsc/specutils/specutils.go +++ b/runsc/specutils/specutils.go @@ -528,12 +528,12 @@ func WaitForReady(pid int, timeout time.Duration, ready func() (bool, error)) er // // - %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: /runsc.log...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) diff --git a/runsc/starttime/BUILD b/runsc/starttime/BUILD new file mode 100644 index 000000000..1b86ab3b0 --- /dev/null +++ b/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__"], +) diff --git a/runsc/starttime/starttime.go b/runsc/starttime/starttime.go new file mode 100644 index 000000000..62a91019f --- /dev/null +++ b/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 +}