Improve shim debug logging

- Add log statements in service entry points.
- Propagate `-debug` flag from shim invokation to the service
- Load options when shim process is invoked to ensure runsc commands
  use the correct set of options, e.g. --debug --debug-logs=...
- Add debug options to the shim configuration directly, so it doesn't
  rely on containerd configuration (and restart) to enable shim debug.
- Save shim logs to dedicated file, so it's easier to read logs. They
  would be mixed with containerd logs and hard to distinguish
  otherwise.

PiperOrigin-RevId: 342179868

g3doc/user_guide/containerd/configuration.md

@@ -36,7 +36,7 @@ sudo systemctl restart containerd
 > located in the runtime root. By default, this is `/run/containerd/runsc`.
 
 The set of options that can be configured can be found in
-[options.go](https://github.com/google/gvisor/blob/master/pkg/shim/v2/options/options.go).
+[options.go](https://github.com/google/gvisor/blob/master/pkg/shim/v2/options.go).
 
 #### Example: Enable the KVM platform
 

pkg/shim/runsc/runsc.go

@@ -13,6 +13,7 @@
 // See the License for the specific language governing permissions and
 // limitations under the License.
 
+// Package runsc provides an API to interact with runsc command line.
 package runsc
 
 import (
@@ -33,12 +34,32 @@ import (
 	specs "github.com/opencontainers/runtime-spec/specs-go"
 )
 
-// Monitor is the default process monitor to be used by runsc.
-var Monitor runc.ProcessMonitor = runc.Monitor
-
 // DefaultCommand is the default command for Runsc.
 const DefaultCommand = "runsc"
 
+// Monitor is the default process monitor to be used by runsc.
+var Monitor runc.ProcessMonitor = &LogMonitor{Next: runc.Monitor}
+
+// LogMonitor implements the runc.ProcessMonitor interface, logging the command
+// that is getting executed, and then forwarding the call to another
+// implementation.
+type LogMonitor struct {
+	Next runc.ProcessMonitor
+}
+
+// Start implements runc.ProcessMonitor.
+func (l *LogMonitor) Start(cmd *exec.Cmd) (chan runc.Exit, error) {
+	log.L.Debugf("Executing: %s", cmd.Args)
+	return l.Next.Start(cmd)
+}
+
+// Wait implements runc.ProcessMonitor.
+func (l *LogMonitor) Wait(cmd *exec.Cmd, ch chan runc.Exit) (int, error) {
+	status, err := l.Next.Wait(cmd, ch)
+	log.L.Debugf("Command exit code: %d, err: %v", status, err)
+	return status, err
+}
+
 // Runsc is the client to the runsc cli.
 type Runsc struct {
 	Command      string
@@ -370,9 +391,10 @@ func (r *Runsc) Stats(context context.Context, id string) (*runc.Stats, error) {
 	}()
 	var e runc.Event
 	if err := json.NewDecoder(rd).Decode(&e); err != nil {
+		log.L.Debugf("Parsing events error: %v", err)
 		return nil, err
 	}
-	log.L.Debugf("Stats returned: %+v", e.Stats)
+	log.L.Debugf("Stats returned, type: %s, stats: %+v", e.Type, e.Stats)
 	if e.Type != "stats" {
 		return nil, fmt.Errorf(`unexpected event type %q, wanted "stats"`, e.Type)
 	}

pkg/shim/runsc/utils.go

@@ -36,9 +36,20 @@ func putBuf(b *bytes.Buffer) {
 	bytesBufferPool.Put(b)
 }
 
-// FormatLogPath parses runsc config, and fill in %ID% in the log path.
-func FormatLogPath(id string, config map[string]string) {
+// FormatRunscLogPath parses runsc config, and fill in %ID% in the log path.
+func FormatRunscLogPath(id string, config map[string]string) {
 	if path, ok := config["debug-log"]; ok {
 		config["debug-log"] = strings.Replace(path, "%ID%", id, -1)
 	}
 }
+
+// FormatShimLogPath creates the file path to the log file. It replaces %ID%
+// in the path with the provided "id". It also uses a default log name if the
+// path end with '/'.
+func FormatShimLogPath(path string, id string) string {
+	if strings.HasSuffix(path, "/") {
+		// Default format: <path>/runsc-shim-<ID>.log
+		path += "runsc-shim-%ID%.log"
+	}
+	return strings.Replace(path, "%ID%", id, -1)
+}

pkg/shim/v1/proc/init.go

@@ -397,7 +397,7 @@ func (p *Init) Exec(ctx context.Context, path string, r *ExecConfig) (process.Pr
 }
 
 // exec returns a new exec'd process.
-func (p *Init) exec(ctx context.Context, path string, r *ExecConfig) (process.Process, error) {
+func (p *Init) exec(path string, r *ExecConfig) (process.Process, error) {
 	// process exec request
 	var spec specs.Process
 	if err := json.Unmarshal(r.Spec.Value, &spec); err != nil {

pkg/shim/v1/proc/init_state.go

@@ -95,7 +95,7 @@ func (s *createdState) SetExited(status int) {
 }
 
 func (s *createdState) Exec(ctx context.Context, path string, r *ExecConfig) (process.Process, error) {
-	return s.p.exec(ctx, path, r)
+	return s.p.exec(path, r)
 }
 
 type runningState struct {
@@ -137,7 +137,7 @@ func (s *runningState) SetExited(status int) {
 }
 
 func (s *runningState) Exec(ctx context.Context, path string, r *ExecConfig) (process.Process, error) {
-	return s.p.exec(ctx, path, r)
+	return s.p.exec(path, r)
 }
 
 type stoppedState struct {

pkg/shim/v1/proc/types.go

@@ -40,7 +40,6 @@ type CreateConfig struct {
 	Stdin    string
 	Stdout   string
 	Stderr   string
-	Options  *types.Any
 }
 
 // ExecConfig holds exec creation configuration.

pkg/shim/v1/proc/utils.go

@@ -67,24 +67,6 @@ func getLastRuntimeError(r *runsc.Runsc) (string, error) {
 	return errMsg, nil
 }
 
-func copyFile(to, from string) error {
-	ff, err := os.Open(from)
-	if err != nil {
-		return err
-	}
-	defer ff.Close()
-	tt, err := os.Create(to)
-	if err != nil {
-		return err
-	}
-	defer tt.Close()
-
-	p := bufPool.Get().(*[]byte)
-	defer bufPool.Put(p)
-	_, err = io.CopyBuffer(tt, ff, *p)
-	return err
-}
-
 func hasNoIO(r *CreateConfig) bool {
 	return r.Stdin == "" && r.Stdout == "" && r.Stderr == ""
 }

pkg/shim/v1/shim/service.go

@@ -130,7 +130,6 @@ func (s *Service) Create(ctx context.Context, r *shim.CreateTaskRequest) (_ *shi
 		Stdin:    r.Stdin,
 		Stdout:   r.Stdout,
 		Stderr:   r.Stderr,
-		Options:  r.Options,
 	}
 	defer func() {
 		if err != nil {
@@ -150,7 +149,6 @@ func (s *Service) Create(ctx context.Context, r *shim.CreateTaskRequest) (_ *shi
 		}
 	}
 	process, err := newInit(
-		ctx,
 		s.config.Path,
 		s.config.WorkDir,
 		s.config.RuntimeRoot,
@@ -158,6 +156,7 @@ func (s *Service) Create(ctx context.Context, r *shim.CreateTaskRequest) (_ *shi
 		s.config.RunscConfig,
 		s.platform,
 		config,
+		r.Options,
 	)
 	if err := process.Create(ctx, config); err != nil {
 		return nil, errdefs.ToGRPC(err)
@@ -533,14 +532,14 @@ func getTopic(ctx context.Context, e interface{}) string {
 	return runtime.TaskUnknownTopic
 }
 
-func newInit(ctx context.Context, path, workDir, runtimeRoot, namespace string, config map[string]string, platform stdio.Platform, r *proc.CreateConfig) (*proc.Init, error) {
-	var options runctypes.CreateOptions
-	if r.Options != nil {
-		v, err := typeurl.UnmarshalAny(r.Options)
+func newInit(path, workDir, runtimeRoot, namespace string, config map[string]string, platform stdio.Platform, r *proc.CreateConfig, options *types.Any) (*proc.Init, error) {
+	var opts runctypes.CreateOptions
+	if options != nil {
+		v, err := typeurl.UnmarshalAny(options)
 		if err != nil {
 			return nil, err
 		}
-		options = *v.(*runctypes.CreateOptions)
+		opts = *v.(*runctypes.CreateOptions)
 	}
 
 	spec, err := utils.ReadSpec(r.Bundle)
@@ -551,7 +550,7 @@ func newInit(ctx context.Context, path, workDir, runtimeRoot, namespace string,
 		return nil, fmt.Errorf("update volume annotations: %w", err)
 	}
 
-	runsc.FormatLogPath(r.ID, config)
+	runsc.FormatRunscLogPath(r.ID, config)
 	rootfs := filepath.Join(path, "rootfs")
 	runtime := proc.NewRunsc(runtimeRoot, path, namespace, r.Runtime, config)
 	p := proc.New(r.ID, runtime, stdio.Stdio{
@@ -564,8 +563,8 @@ func newInit(ctx context.Context, path, workDir, runtimeRoot, namespace string,
 	p.Platform = platform
 	p.Rootfs = rootfs
 	p.WorkDir = workDir
-	p.IoUID = int(options.IoUid)
-	p.IoGID = int(options.IoGid)
+	p.IoUID = int(opts.IoUid)
+	p.IoGID = int(opts.IoGid)
 	p.Sandbox = utils.IsSandbox(spec)
 	p.UserLog = utils.UserLogPath(spec)
 	p.Monitor = reaper.Default

pkg/shim/v2/BUILD

@@ -7,15 +7,17 @@ go_library(
     srcs = [
         "api.go",
         "epoll.go",
+        "options.go",
         "service.go",
         "service_linux.go",
+        "state.go",
     ],
     visibility = ["//shim:__subpackages__"],
     deps = [
+        "//pkg/cleanup",
         "//pkg/shim/runsc",
         "//pkg/shim/v1/proc",
         "//pkg/shim/v1/utils",
-        "//pkg/shim/v2/options",
         "//pkg/shim/v2/runtimeoptions",
         "//runsc/specutils",
         "@com_github_burntsushi_toml//:go_default_library",
@@ -38,6 +40,7 @@ go_library(
         "@com_github_containerd_fifo//:go_default_library",
         "@com_github_containerd_typeurl//:go_default_library",
         "@com_github_gogo_protobuf//types:go_default_library",
+        "@com_github_sirupsen_logrus//:go_default_library",
         "@org_golang_x_sys//unix:go_default_library",
     ],
 )

pkg/shim/v2/options.go

@@ -0,0 +1,50 @@
+// Copyright 2018 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
+//
+//     https://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 v2
+
+const optionsType = "io.containerd.runsc.v1.options"
+
+// options is runtime options for io.containerd.runsc.v1.
+type options struct {
+	// ShimCgroup is the cgroup the shim should be in.
+	ShimCgroup string `toml:"shim_cgroup" json:"shimCgroup"`
+
+	// IoUID is the I/O's pipes uid.
+	IoUID uint32 `toml:"io_uid" json:"ioUid"`
+
+	// IoGID is the I/O's pipes gid.
+	IoGID uint32 `toml:"io_gid" json:"ioGid"`
+
+	// BinaryName is the binary name of the runsc binary.
+	BinaryName string `toml:"binary_name" json:"binaryName"`
+
+	// Root is the runsc root directory.
+	Root string `toml:"root" json:"root"`
+
+	// LogLevel sets the logging level. Some of the possible values are: debug,
+	// info, warning.
+	//
+	// This configuration only applies when the shim is running as a service.
+	LogLevel string `toml:"log_level" json:"logLevel"`
+
+	// LogPath is the path to log directory. %ID% tags inside the string are
+	// replaced with the container ID.
+	//
+	// This configuration only applies when the shim is running as a service.
+	LogPath string `toml:"log_path" json:"logPath"`
+
+	// RunscConfig is a key/value map of all runsc flags.
+	RunscConfig map[string]string `toml:"runsc_config" json:"runscConfig"`
+}

pkg/shim/v2/options/BUILD

@@ -1,11 +0,0 @@
-load("//tools:defs.bzl", "go_library")
-
-package(licenses = ["notice"])
-
-go_library(
-    name = "options",
-    srcs = [
-        "options.go",
-    ],
-    visibility = ["//:sandbox"],
-)

pkg/shim/v2/options/options.go

@@ -1,33 +0,0 @@
-// Copyright 2018 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
-//
-//     https://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 options
-
-const OptionType = "io.containerd.runsc.v1.options"
-
-// Options is runtime options for io.containerd.runsc.v1.
-type Options struct {
-	// ShimCgroup is the cgroup the shim should be in.
-	ShimCgroup string `toml:"shim_cgroup"`
-	// IoUid is the I/O's pipes uid.
-	IoUid uint32 `toml:"io_uid"`
-	// IoUid is the I/O's pipes gid.
-	IoGid uint32 `toml:"io_gid"`
-	// BinaryName is the binary name of the runsc binary.
-	BinaryName string `toml:"binary_name"`
-	// Root is the runsc root directory.
-	Root string `toml:"root"`
-	// RunscConfig is a key/value map of all runsc flags.
-	RunscConfig map[string]string `toml:"runsc_config"`
-}

pkg/shim/v2/state.go

@@ -0,0 +1,48 @@
+// Copyright 2020 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
+//
+//     https://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 v2
+
+import (
+	"encoding/json"
+	"io/ioutil"
+	"path/filepath"
+)
+
+const filename = "state.json"
+
+// state holds information needed between shim invocations.
+type state struct {
+	// Rootfs is the full path to the location rootfs was mounted.
+	Rootfs string `json:"rootfs"`
+
+	// Options is the configuration loaded from config.toml.
+	Options options `json:"options"`
+}
+
+func (s state) load(path string) error {
+	data, err := ioutil.ReadFile(filepath.Join(path, filename))
+	if err != nil {
+		return err
+	}
+	return json.Unmarshal(data, &s)
+}
+
+func (s state) save(path string) error {
+	data, err := json.Marshal(&s)
+	if err != nil {
+		return err
+	}
+	return ioutil.WriteFile(filepath.Join(path, filename), data, 0644)
+}