diff options
author | Fabricio Voznika <fvoznika@google.com> | 2019-06-06 10:48:19 -0700 |
---|---|---|
committer | Shentubot <shentubot@google.com> | 2019-06-06 10:49:43 -0700 |
commit | 720ec3590d9bbf6dc2f9533ed5ef2cbc0b01627a (patch) | |
tree | fde2a6a7c707e18c8ae182ef824eb4a5472f2e98 /runsc | |
parent | 85be01b42d4ac48698d1e8f50a4cf2607a4fc50b (diff) |
Send error message to docker/kubectl exec on failure
Containerd uses the last error message sent to the log to
print as failure cause for create/exec. This required a
few changes in the logging logic for runsc:
- cmd.Errorf/Fatalf: now writes a message with 'error'
level to containerd log, in addition to stderr and
debug logs, like before.
- log.Infof/Warningf/Fatalf: are not sent to containerd
log anymore. They are mostly used for debugging and not
useful to containerd. In most cases, --debug-log is
enabled and this avoids the logs messages from being
duplicated.
- stderr is not used as default log destination anymore.
Some commands assume stdio is for the container/process
running inside the sandbox and it's better to never use
it for logging. By default, logs are supressed now.
PiperOrigin-RevId: 251881815
Diffstat (limited to 'runsc')
-rw-r--r-- | runsc/cmd/BUILD | 1 | ||||
-rw-r--r-- | runsc/cmd/cmd.go | 19 | ||||
-rw-r--r-- | runsc/cmd/create.go | 1 | ||||
-rw-r--r-- | runsc/cmd/error.go | 72 | ||||
-rw-r--r-- | runsc/cmd/exec.go | 28 | ||||
-rw-r--r-- | runsc/cmd/start.go | 1 | ||||
-rw-r--r-- | runsc/main.go | 60 | ||||
-rw-r--r-- | runsc/test/integration/exec_test.go | 23 |
8 files changed, 142 insertions, 63 deletions
diff --git a/runsc/cmd/BUILD b/runsc/cmd/BUILD index b7551a5ab..173b7671e 100644 --- a/runsc/cmd/BUILD +++ b/runsc/cmd/BUILD @@ -14,6 +14,7 @@ go_library( "debug.go", "delete.go", "do.go", + "error.go", "events.go", "exec.go", "gofer.go", diff --git a/runsc/cmd/cmd.go b/runsc/cmd/cmd.go index a2fc377d1..5b4cc4a39 100644 --- a/runsc/cmd/cmd.go +++ b/runsc/cmd/cmd.go @@ -17,34 +17,15 @@ package cmd import ( "fmt" - "os" "runtime" "strconv" "syscall" - "github.com/google/subcommands" specs "github.com/opencontainers/runtime-spec/specs-go" "gvisor.googlesource.com/gvisor/pkg/log" "gvisor.googlesource.com/gvisor/runsc/specutils" ) -// Errorf logs to stderr and returns subcommands.ExitFailure. -func Errorf(s string, args ...interface{}) subcommands.ExitStatus { - // If runsc is being invoked by docker or cri-o, then we might not have - // access to stderr, so we log a serious-looking warning in addition to - // writing to stderr. - log.Warningf("FATAL ERROR: "+s, args...) - fmt.Fprintf(os.Stderr, s+"\n", args...) - // Return an error that is unlikely to be used by the application. - return subcommands.ExitFailure -} - -// Fatalf logs to stderr and exits with a failure status code. -func Fatalf(s string, args ...interface{}) { - Errorf(s, args...) - os.Exit(128) -} - // intFlags can be used with int flags that appear multiple times. type intFlags []int diff --git a/runsc/cmd/create.go b/runsc/cmd/create.go index 629c198fd..8bf9b7dcf 100644 --- a/runsc/cmd/create.go +++ b/runsc/cmd/create.go @@ -16,7 +16,6 @@ package cmd import ( "context" - "flag" "github.com/google/subcommands" "gvisor.googlesource.com/gvisor/runsc/boot" diff --git a/runsc/cmd/error.go b/runsc/cmd/error.go new file mode 100644 index 000000000..700b19f14 --- /dev/null +++ b/runsc/cmd/error.go @@ -0,0 +1,72 @@ +// 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 cmd + +import ( + "encoding/json" + "fmt" + "io" + "os" + "time" + + "github.com/google/subcommands" + "gvisor.googlesource.com/gvisor/pkg/log" +) + +// ErrorLogger is where error messages should be written to. These messages are +// consumed by containerd and show up to users of command line tools, +// like docker/kubectl. +var ErrorLogger io.Writer + +type jsonError struct { + Msg string `json:"msg"` + Level string `json:"level"` + Time time.Time `json:"time"` +} + +// Errorf logs error to containerd log (--log), to stderr, and debug logs. It +// returns subcommands.ExitFailure for convenience with subcommand.Execute() +// methods: +// return Errorf("Danger! Danger!") +// +func Errorf(format string, args ...interface{}) subcommands.ExitStatus { + // If runsc is being invoked by docker or cri-o, then we might not have + // access to stderr, so we log a serious-looking warning in addition to + // writing to stderr. + log.Warningf("FATAL ERROR: "+format, args...) + fmt.Fprintf(os.Stderr, format+"\n", args...) + + j := jsonError{ + Msg: fmt.Sprintf(format, args...), + Level: "error", + Time: time.Now(), + } + b, err := json.Marshal(j) + if err != nil { + panic(err) + } + if ErrorLogger != nil { + ErrorLogger.Write(b) + } + + return subcommands.ExitFailure +} + +// Fatalf logs the same way as Errorf() does, plus *exits* the process. +func Fatalf(format string, args ...interface{}) { + Errorf(format, args...) + // Return an error that is unlikely to be used by the application. + os.Exit(128) +} diff --git a/runsc/cmd/exec.go b/runsc/cmd/exec.go index 8cd070e61..0eeaaadba 100644 --- a/runsc/cmd/exec.go +++ b/runsc/cmd/exec.go @@ -143,13 +143,16 @@ func (ex *Exec) Execute(_ context.Context, f *flag.FlagSet, args ...interface{}) // write the child's PID to the pid file. So when the container returns, the // child process will also return and signal containerd. if ex.detach { - return ex.execAndWait(waitStatus) + return ex.execChildAndWait(waitStatus) } + return ex.exec(c, e, waitStatus) +} +func (ex *Exec) exec(c *container.Container, e *control.ExecArgs, waitStatus *syscall.WaitStatus) subcommands.ExitStatus { // Start the new process and get it pid. pid, err := c.Execute(e) if err != nil { - Fatalf("executing processes for container: %v", err) + return Errorf("executing processes for container: %v", err) } if e.StdioIsPty { @@ -163,29 +166,29 @@ func (ex *Exec) Execute(_ context.Context, f *flag.FlagSet, args ...interface{}) if ex.internalPidFile != "" { pidStr := []byte(strconv.Itoa(int(pid))) if err := ioutil.WriteFile(ex.internalPidFile, pidStr, 0644); err != nil { - Fatalf("writing internal pid file %q: %v", ex.internalPidFile, err) + return Errorf("writing internal pid file %q: %v", ex.internalPidFile, err) } } - // Generate the pid file after the internal pid file is generated, so that users - // can safely assume that the internal pid file is ready after `runsc exec -d` - // returns. + // Generate the pid file after the internal pid file is generated, so that + // users can safely assume that the internal pid file is ready after + // `runsc exec -d` returns. if ex.pidFile != "" { if err := ioutil.WriteFile(ex.pidFile, []byte(strconv.Itoa(os.Getpid())), 0644); err != nil { - Fatalf("writing pid file: %v", err) + return Errorf("writing pid file: %v", err) } } // Wait for the process to exit. ws, err := c.WaitPID(pid) if err != nil { - Fatalf("waiting on pid %d: %v", pid, err) + return Errorf("waiting on pid %d: %v", pid, err) } *waitStatus = ws return subcommands.ExitSuccess } -func (ex *Exec) execAndWait(waitStatus *syscall.WaitStatus) subcommands.ExitStatus { +func (ex *Exec) execChildAndWait(waitStatus *syscall.WaitStatus) subcommands.ExitStatus { var args []string for _, a := range os.Args[1:] { if !strings.Contains(a, "detach") { @@ -193,7 +196,7 @@ func (ex *Exec) execAndWait(waitStatus *syscall.WaitStatus) subcommands.ExitStat } } - // The command needs to write a pid file so that execAndWait can tell + // The command needs to write a pid file so that execChildAndWait can tell // when it has started. If no pid-file was provided, we should use a // filename in a temp directory. pidFile := ex.pidFile @@ -262,7 +265,10 @@ func (ex *Exec) execAndWait(waitStatus *syscall.WaitStatus) subcommands.ExitStat return false, nil } if err := specutils.WaitForReady(cmd.Process.Pid, 10*time.Second, ready); err != nil { - Fatalf("unexpected error waiting for PID file, err: %v", err) + // Don't log fatal error here, otherwise it will override the error logged + // by the child process that has failed to start. + log.Warningf("Unexpected error waiting for PID file, err: %v", err) + return subcommands.ExitFailure } *waitStatus = 0 diff --git a/runsc/cmd/start.go b/runsc/cmd/start.go index 657726251..31e8f42bb 100644 --- a/runsc/cmd/start.go +++ b/runsc/cmd/start.go @@ -16,7 +16,6 @@ package cmd import ( "context" - "flag" "github.com/google/subcommands" "gvisor.googlesource.com/gvisor/runsc/boot" diff --git a/runsc/main.go b/runsc/main.go index 44ad23cba..39c43507c 100644 --- a/runsc/main.go +++ b/runsc/main.go @@ -117,6 +117,22 @@ func main() { os.Exit(0) } + var errorLogger io.Writer + if *logFD > -1 { + errorLogger = os.NewFile(uintptr(*logFD), "error log file") + + } else if *logFilename != "" { + // We must set O_APPEND and not O_TRUNC because Docker passes + // the same log file for all commands (and also parses these + // log files), so we can't destroy them on each command. + var err error + errorLogger, err = os.OpenFile(*logFilename, os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0644) + if err != nil { + cmd.Fatalf("error opening log file %q: %v", *logFilename, err) + } + } + cmd.ErrorLogger = errorLogger + platformType, err := boot.MakePlatformType(*platform) if err != nil { cmd.Fatalf("%v", err) @@ -179,24 +195,7 @@ func main() { subcommand := flag.CommandLine.Arg(0) - var logFile io.Writer = os.Stderr - if *logFD > -1 { - logFile = os.NewFile(uintptr(*logFD), "log file") - } else if *logFilename != "" { - // We must set O_APPEND and not O_TRUNC because Docker passes - // the same log file for all commands (and also parses these - // log files), so we can't destroy them on each command. - f, err := os.OpenFile(*logFilename, os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0644) - if err != nil { - cmd.Fatalf("error opening log file %q: %v", *logFilename, err) - } - logFile = f - } else if subcommand == "do" { - logFile = ioutil.Discard - } - - e := newEmitter(*logFormat, logFile) - + var e log.Emitter if *debugLogFD > -1 { f := os.NewFile(uintptr(*debugLogFD), "debug log file") @@ -206,28 +205,27 @@ func main() { cmd.Fatalf("flag --debug-log-fd should only be passed to 'boot' and 'gofer' command, but was passed to %q", subcommand) } - // If we are the boot process, then we own our stdio FDs and - // can do what we want with them. Since Docker and Containerd - // both eat boot's stderr, we dup our stderr to the provided - // log FD so that panics will appear in the logs, rather than - // just disappear. + // If we are the boot process, then we own our stdio FDs and can do what we + // want with them. Since Docker and Containerd both eat boot's stderr, we + // dup our stderr to the provided log FD so that panics will appear in the + // logs, rather than just disappear. if err := syscall.Dup2(int(f.Fd()), int(os.Stderr.Fd())); err != nil { cmd.Fatalf("error dup'ing fd %d to stderr: %v", f.Fd(), err) } - if logFile == os.Stderr { - // Suppress logging to stderr when debug log is enabled. Otherwise all - // messages will be duplicated in the debug log (see Dup2() call above). - e = newEmitter(*debugLogFormat, f) - } else { - e = log.MultiEmitter{e, newEmitter(*debugLogFormat, f)} - } + e = newEmitter(*debugLogFormat, f) + } else if *debugLog != "" { f, err := specutils.DebugLogFile(*debugLog, subcommand) if err != nil { cmd.Fatalf("error opening debug log file in %q: %v", *debugLog, err) } - e = log.MultiEmitter{e, newEmitter(*debugLogFormat, f)} + e = newEmitter(*debugLogFormat, f) + + } else { + // Stderr is reserved for the application, just discard the logs if no debug + // log is specified. + e = newEmitter("text", ioutil.Discard) } log.SetTarget(e) diff --git a/runsc/test/integration/exec_test.go b/runsc/test/integration/exec_test.go index 7af064d79..7c0e61ac3 100644 --- a/runsc/test/integration/exec_test.go +++ b/runsc/test/integration/exec_test.go @@ -29,6 +29,7 @@ package integration import ( "fmt" "strconv" + "strings" "syscall" "testing" "time" @@ -136,3 +137,25 @@ func TestExecJobControl(t *testing.T) { t.Errorf("ws.ExitedStatus got %d, want %d", got, want) } } + +// Test that failure to exec returns proper error message. +func TestExecError(t *testing.T) { + if err := testutil.Pull("alpine"); err != nil { + t.Fatalf("docker pull failed: %v", err) + } + d := testutil.MakeDocker("exec-error-test") + + // Start the container. + if err := d.Run("alpine", "sleep", "1000"); err != nil { + t.Fatalf("docker run failed: %v", err) + } + defer d.CleanUp() + + _, err := d.Exec("no_can_find") + if err == nil { + t.Fatalf("docker exec didn't fail") + } + if want := `error finding executable "no_can_find" in PATH`; !strings.Contains(err.Error(), want) { + t.Fatalf("docker exec wrong error, got: %s, want: .*%s.*", err.Error(), want) + } +} |