Allow to change logging options using 'runsc debug'

New options are:
  runsc debug --strace=off|all|function1,function2
  runsc debug --log-level=warning|info|debug
  runsc debug --log-packets=true|false

Updates #407

PiperOrigin-RevId: 254843128

pkg/log/log.go

@@ -50,6 +50,19 @@ const (
 	Debug
 )
 
+func (l Level) String() string {
+	switch l {
+	case Warning:
+		return "Warning"
+	case Info:
+		return "Info"
+	case Debug:
+		return "Debug"
+	default:
+		return fmt.Sprintf("Invalid level: %d", l)
+	}
+}
+
 // Emitter is the final destination for logs.
 type Emitter interface {
 	// Emit emits the given log statement. This allows for control over the

pkg/sentry/control/BUILD

@@ -6,6 +6,7 @@ go_library(
     name = "control",
     srcs = [
         "control.go",
+        "logging.go",
         "pprof.go",
         "proc.go",
         "state.go",
@@ -26,8 +27,10 @@ go_library(
         "//pkg/sentry/kernel/time",
         "//pkg/sentry/limits",
         "//pkg/sentry/state",
+        "//pkg/sentry/strace",
         "//pkg/sentry/usage",
         "//pkg/sentry/watchdog",
+        "//pkg/tcpip/link/sniffer",
         "//pkg/urpc",
     ],
 )

pkg/sentry/control/logging.go

@@ -0,0 +1,136 @@
+// Copyright 2019 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 control
+
+import (
+	"fmt"
+	"sync/atomic"
+
+	"gvisor.dev/gvisor/pkg/log"
+	"gvisor.dev/gvisor/pkg/sentry/strace"
+	"gvisor.dev/gvisor/pkg/tcpip/link/sniffer"
+)
+
+// LoggingArgs are the arguments to use for changing the logging
+// level and strace list.
+type LoggingArgs struct {
+	// SetLevel is a flag used to indicate that we should update
+	// the logging level. We should be able to change the strace
+	// list without affecting the logging level and vice versa.
+	SetLevel bool
+
+	// Level is the log level that will be set if SetLevel is true.
+	Level log.Level
+
+	// SetLogPackets indicates that we should update the log packets flag.
+	SetLogPackets bool
+
+	// LogPackets is the actual value to set for LogPackets.
+	// SetLogPackets must be enabled to indicate that we're changing
+	// the value.
+	LogPackets bool
+
+	// SetStrace is a flag used to indicate that strace related
+	// arguments were passed in.
+	SetStrace bool
+
+	// EnableStrace is a flag from the CLI that specifies whether to
+	// enable strace at all. If this flag is false then a completely
+	// pristine copy of the syscall table will be swapped in. This
+	// approach is used to remain consistent with an empty strace
+	// whitelist meaning trace all system calls.
+	EnableStrace bool
+
+	// Strace is the whitelist of syscalls to trace to log. If this
+	// and StraceEventWhitelist are empty trace all system calls.
+	StraceWhitelist []string
+
+	// SetEventStrace is a flag used to indicate that event strace
+	// related arguments were passed in.
+	SetEventStrace bool
+
+	// StraceEventWhitelist is the whitelist of syscalls to trace
+	// to event log.
+	StraceEventWhitelist []string
+}
+
+// Logging provides functions related to logging.
+type Logging struct{}
+
+// Change will change the log level and strace arguments. Although
+// this functions signature requires an error it never acctually
+// return san error. It's required by the URPC interface.
+// Additionally, it may look odd that this is the only method
+// attached to an empty struct but this is also part of how
+// URPC dispatches.
+func (l *Logging) Change(args *LoggingArgs, code *int) error {
+	if args.SetLevel {
+		// Logging uses an atomic for the level so this is thread safe.
+		log.SetLevel(args.Level)
+	}
+
+	if args.SetLogPackets {
+		if args.LogPackets {
+			atomic.StoreUint32(&sniffer.LogPackets, 1)
+		} else {
+			atomic.StoreUint32(&sniffer.LogPackets, 0)
+		}
+		log.Infof("LogPackets set to: %v", atomic.LoadUint32(&sniffer.LogPackets))
+	}
+
+	if args.SetStrace {
+		if err := l.configureStrace(args); err != nil {
+			return fmt.Errorf("error configuring strace: %v", err)
+		}
+	}
+
+	if args.SetEventStrace {
+		if err := l.configureEventStrace(args); err != nil {
+			return fmt.Errorf("error configuring event strace: %v", err)
+		}
+	}
+
+	return nil
+}
+
+func (l *Logging) configureStrace(args *LoggingArgs) error {
+	if args.EnableStrace {
+		// Install the whitelist specified.
+		if len(args.StraceWhitelist) > 0 {
+			if err := strace.Enable(args.StraceWhitelist, strace.SinkTypeLog); err != nil {
+				return err
+			}
+		} else {
+			// For convenience, if strace is enabled but whitelist
+			// is empty, enable everything to log.
+			strace.EnableAll(strace.SinkTypeLog)
+		}
+	} else {
+		// Uninstall all strace functions.
+		strace.Disable(strace.SinkTypeLog)
+	}
+	return nil
+}
+
+func (l *Logging) configureEventStrace(args *LoggingArgs) error {
+	if len(args.StraceEventWhitelist) > 0 {
+		if err := strace.Enable(args.StraceEventWhitelist, strace.SinkTypeEvent); err != nil {
+			return err
+		}
+	} else {
+		strace.Disable(strace.SinkTypeEvent)
+	}
+	return nil
+}

runsc/boot/controller.go

@@ -96,8 +96,10 @@ const (
 
 	// SandboxStacks collects sandbox stacks for debugging.
 	SandboxStacks = "debug.Stacks"
+)
 
-	// Profiling related commands (see pprof.go for more details).
+// Profiling related commands (see pprof.go for more details).
+const (
 	StartCPUProfile = "Profile.StartCPUProfile"
 	StopCPUProfile  = "Profile.StopCPUProfile"
 	HeapProfile     = "Profile.HeapProfile"
@@ -105,6 +107,11 @@ const (
 	StopTrace       = "Profile.StopTrace"
 )
 
+// Logging related commands (see logging.go for more details).
+const (
+	ChangeLogging = "Logging.Change"
+)
+
 // ControlSocketAddr generates an abstract unix socket name for the given ID.
 func ControlSocketAddr(id string) string {
 	return fmt.Sprintf("\x00runsc-sandbox.%s", id)
@@ -143,6 +150,7 @@ func newController(fd int, l *Loader) (*controller, error) {
 	}
 
 	srv.Register(&debug{})
+	srv.Register(&control.Logging{})
 	if l.conf.ProfileEnable {
 		srv.Register(&control.Profile{})
 	}

runsc/cmd/debug.go

@@ -17,12 +17,15 @@ package cmd
 import (
 	"context"
 	"os"
+	"strconv"
+	"strings"
 	"syscall"
 	"time"
 
 	"flag"
 	"github.com/google/subcommands"
 	"gvisor.dev/gvisor/pkg/log"
+	"gvisor.dev/gvisor/pkg/sentry/control"
 	"gvisor.dev/gvisor/runsc/boot"
 	"gvisor.dev/gvisor/runsc/container"
 )
@@ -36,6 +39,9 @@ type Debug struct {
 	profileCPU   string
 	profileDelay int
 	trace        string
+	strace       string
+	logLevel     string
+	logPackets   string
 }
 
 // Name implements subcommands.Command.
@@ -62,6 +68,9 @@ func (d *Debug) SetFlags(f *flag.FlagSet) {
 	f.IntVar(&d.profileDelay, "profile-delay", 5, "amount of time to wait before stoping CPU profile")
 	f.StringVar(&d.trace, "trace", "", "writes an execution trace to the given file.")
 	f.IntVar(&d.signal, "signal", -1, "sends signal to the sandbox")
+	f.StringVar(&d.strace, "strace", "", `A comma separated list of syscalls to trace. "all" enables all traces, "off" disables all`)
+	f.StringVar(&d.logLevel, "log-level", "", "The log level to set: warning (0), info (1), or debug (2).")
+	f.StringVar(&d.logPackets, "log-packets", "", "A boolean value to enable or disable packet logging: true or false.")
 }
 
 // Execute implements subcommands.Command.Execute.
@@ -78,7 +87,7 @@ func (d *Debug) Execute(_ context.Context, f *flag.FlagSet, args ...interface{})
 		var err error
 		c, err = container.Load(conf.RootDir, f.Arg(0))
 		if err != nil {
-			Fatalf("loading container %q: %v", f.Arg(0), err)
+			return Errorf("loading container %q: %v", f.Arg(0), err)
 		}
 	} else {
 		if f.NArg() != 0 {
@@ -88,12 +97,12 @@ func (d *Debug) Execute(_ context.Context, f *flag.FlagSet, args ...interface{})
 		// Go over all sandboxes and find the one that matches PID.
 		ids, err := container.List(conf.RootDir)
 		if err != nil {
-			Fatalf("listing containers: %v", err)
+			return Errorf("listing containers: %v", err)
 		}
 		for _, id := range ids {
 			candidate, err := container.Load(conf.RootDir, id)
 			if err != nil {
-				Fatalf("loading container %q: %v", id, err)
+				return Errorf("loading container %q: %v", id, err)
 			}
 			if candidate.SandboxPid() == d.pid {
 				c = candidate
@@ -101,38 +110,38 @@ func (d *Debug) Execute(_ context.Context, f *flag.FlagSet, args ...interface{})
 			}
 		}
 		if c == nil {
-			Fatalf("container with PID %d not found", d.pid)
+			return Errorf("container with PID %d not found", d.pid)
 		}
 	}
 
 	if c.Sandbox == nil || !c.Sandbox.IsRunning() {
-		Fatalf("container sandbox is not running")
+		return Errorf("container sandbox is not running")
 	}
 	log.Infof("Found sandbox %q, PID: %d", c.Sandbox.ID, c.Sandbox.Pid)
 
 	if d.signal > 0 {
 		log.Infof("Sending signal %d to process: %d", d.signal, c.Sandbox.Pid)
 		if err := syscall.Kill(c.Sandbox.Pid, syscall.Signal(d.signal)); err != nil {
-			Fatalf("failed to send signal %d to processs %d", d.signal, c.Sandbox.Pid)
+			return Errorf("failed to send signal %d to processs %d", d.signal, c.Sandbox.Pid)
 		}
 	}
 	if d.stacks {
 		log.Infof("Retrieving sandbox stacks")
 		stacks, err := c.Sandbox.Stacks()
 		if err != nil {
-			Fatalf("retrieving stacks: %v", err)
+			return Errorf("retrieving stacks: %v", err)
 		}
 		log.Infof("     *** Stack dump ***\n%s", stacks)
 	}
 	if d.profileHeap != "" {
 		f, err := os.Create(d.profileHeap)
 		if err != nil {
-			Fatalf(err.Error())
+			return Errorf(err.Error())
 		}
 		defer f.Close()
 
 		if err := c.Sandbox.HeapProfile(f); err != nil {
-			Fatalf(err.Error())
+			return Errorf(err.Error())
 		}
 		log.Infof("Heap profile written to %q", d.profileHeap)
 	}
@@ -142,7 +151,7 @@ func (d *Debug) Execute(_ context.Context, f *flag.FlagSet, args ...interface{})
 		delay = true
 		f, err := os.Create(d.profileCPU)
 		if err != nil {
-			Fatalf(err.Error())
+			return Errorf(err.Error())
 		}
 		defer func() {
 			f.Close()
@@ -152,7 +161,7 @@ func (d *Debug) Execute(_ context.Context, f *flag.FlagSet, args ...interface{})
 			log.Infof("CPU profile written to %q", d.profileCPU)
 		}()
 		if err := c.Sandbox.StartCPUProfile(f); err != nil {
-			Fatalf(err.Error())
+			return Errorf(err.Error())
 		}
 		log.Infof("CPU profile started for %d sec, writing to %q", d.profileDelay, d.profileCPU)
 	}
@@ -160,7 +169,7 @@ func (d *Debug) Execute(_ context.Context, f *flag.FlagSet, args ...interface{})
 		delay = true
 		f, err := os.Create(d.trace)
 		if err != nil {
-			Fatalf(err.Error())
+			return Errorf(err.Error())
 		}
 		defer func() {
 			f.Close()
@@ -170,15 +179,71 @@ func (d *Debug) Execute(_ context.Context, f *flag.FlagSet, args ...interface{})
 			log.Infof("Trace written to %q", d.trace)
 		}()
 		if err := c.Sandbox.StartTrace(f); err != nil {
-			Fatalf(err.Error())
+			return Errorf(err.Error())
 		}
 		log.Infof("Tracing started for %d sec, writing to %q", d.profileDelay, d.trace)
 
 	}
 
+	if d.strace != "" || len(d.logLevel) != 0 || len(d.logPackets) != 0 {
+		args := control.LoggingArgs{}
+		switch strings.ToLower(d.strace) {
+		case "":
+			// strace not set, nothing to do here.
+
+		case "off":
+			log.Infof("Disabling strace")
+			args.SetStrace = true
+
+		case "all":
+			log.Infof("Enabling all straces")
+			args.SetStrace = true
+			args.EnableStrace = true
+
+		default:
+			log.Infof("Enabling strace for syscalls: %s", d.strace)
+			args.SetStrace = true
+			args.EnableStrace = true
+			args.StraceWhitelist = strings.Split(d.strace, ",")
+		}
+
+		if len(d.logLevel) != 0 {
+			args.SetLevel = true
+			switch strings.ToLower(d.logLevel) {
+			case "warning", "0":
+				args.Level = log.Warning
+			case "info", "1":
+				args.Level = log.Info
+			case "debug", "2":
+				args.Level = log.Debug
+			default:
+				return Errorf("invalid log level %q", d.logLevel)
+			}
+			log.Infof("Setting log level %v", args.Level)
+		}
+
+		if len(d.logPackets) != 0 {
+			args.SetLogPackets = true
+			lp, err := strconv.ParseBool(d.logPackets)
+			if err != nil {
+				return Errorf("invalid value for log_packets %q", d.logPackets)
+			}
+			args.LogPackets = lp
+			if args.LogPackets {
+				log.Infof("Enabling packet logging")
+			} else {
+				log.Infof("Disabling packet logging")
+			}
+		}
+
+		if err := c.Sandbox.ChangeLogging(args); err != nil {
+			return Errorf(err.Error())
+		}
+		log.Infof("Logging options changed")
+	}
+
 	if delay {
 		time.Sleep(time.Duration(d.profileDelay) * time.Second)
-
 	}
 
 	return subcommands.ExitSuccess

runsc/sandbox/sandbox.go

@@ -960,7 +960,7 @@ func (s *Sandbox) StartTrace(f *os.File) error {
 	return nil
 }
 
-// StopTrace stops a previously started trace..
+// StopTrace stops a previously started trace.
 func (s *Sandbox) StopTrace() error {
 	log.Debugf("Trace stop %q", s.ID)
 	conn, err := s.sandboxConnect()
@@ -975,6 +975,21 @@ func (s *Sandbox) StopTrace() error {
 	return nil
 }
 
+// ChangeLogging changes logging options.
+func (s *Sandbox) ChangeLogging(args control.LoggingArgs) error {
+	log.Debugf("Change logging start %q", s.ID)
+	conn, err := s.sandboxConnect()
+	if err != nil {
+		return err
+	}
+	defer conn.Close()
+
+	if err := conn.Call(boot.ChangeLogging, &args, nil); err != nil {
+		return fmt.Errorf("changing sandbox %q logging: %v", s.ID, err)
+	}
+	return nil
+}
+
 // DestroyContainer destroys the given container. If it is the root container,
 // then the entire sandbox is destroyed.
 func (s *Sandbox) DestroyContainer(cid string) error {