summaryrefslogtreecommitdiffhomepage
path: root/runsc
diff options
context:
space:
mode:
authorFabricio Voznika <fvoznika@google.com>2019-06-06 10:48:19 -0700
committerShentubot <shentubot@google.com>2019-06-06 10:49:43 -0700
commit720ec3590d9bbf6dc2f9533ed5ef2cbc0b01627a (patch)
treefde2a6a7c707e18c8ae182ef824eb4a5472f2e98 /runsc
parent85be01b42d4ac48698d1e8f50a4cf2607a4fc50b (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/BUILD1
-rw-r--r--runsc/cmd/cmd.go19
-rw-r--r--runsc/cmd/create.go1
-rw-r--r--runsc/cmd/error.go72
-rw-r--r--runsc/cmd/exec.go28
-rw-r--r--runsc/cmd/start.go1
-rw-r--r--runsc/main.go60
-rw-r--r--runsc/test/integration/exec_test.go23
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)
+ }
+}