Always emit exec command and exit code.

Due to the scp being inherently vulnerable to command injection, always
make sure the full command and exit code is recorded in the Audit Log
for accountability purposes.

For more details about scp, see the following.

https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=327019
https://bugzilla.mindrot.org/show_bug.cgi?id=1998

lib/srv/exec.go

@@ -71,7 +71,7 @@ type Exec interface {
 	Start(channel ssh.Channel) (*ExecResult, error)
 
 	// Wait will block while the command executes.
-	Wait() (*ExecResult, error)
+	Wait() *ExecResult
 }
 
 // NewExecRequest creates a new local or remote Exec.
@@ -158,33 +158,42 @@ func (e *localExec) Start(channel ssh.Channel) (*ExecResult, error) {
 	}()
 
 	if err := e.Cmd.Start(); err != nil {
-		e.Ctx.Warningf("%v start failure err: %v", e, err)
-		execResult, err := collectLocalStatus(e.Cmd, trace.ConvertSystemError(err))
+		e.Ctx.Warningf("Local command %v failed to start: %v", e.GetCommand(), err)
 
-		// emit the result of execution to the audit log
-		emitExecAuditEvent(e.Ctx, e.GetCommand(), execResult, err)
+		// Emit the result of execution to the audit log
+		emitExecAuditEvent(e.Ctx, e.GetCommand(), err)
 
-		return execResult, trace.Wrap(err)
+		return &ExecResult{
+			Command: e.GetCommand(),
+			Code:    exitCode(err),
+		}, trace.ConvertSystemError(err)
 	}
-	e.Ctx.Infof("[LOCAL EXEC] Started command: %q", e.Command)
+	e.Ctx.Infof("Started local command execution: %q", e.Command)
 
 	return nil, nil
 }
 
 // Wait will block while the command executes.
-func (e *localExec) Wait() (*ExecResult, error) {
+func (e *localExec) Wait() *ExecResult {
 	if e.Cmd.Process == nil {
 		e.Ctx.Errorf("no process")
 	}
 
-	// wait for the command to complete, then figure out if the command
-	// successfully exited or if it exited in failure
-	execResult, err := collectLocalStatus(e.Cmd, e.Cmd.Wait())
+	// Block until the command is finished executing.
+	err := e.Cmd.Wait()
+	if err != nil {
+		e.Ctx.Debugf("Local command failed: %v.", err)
+	} else {
+		e.Ctx.Debugf("Local command successfully executed.")
+	}
 
-	// emit the result of execution to the audit log
-	emitExecAuditEvent(e.Ctx, e.GetCommand(), execResult, err)
+	// Emit the result of execution to the Audit Log.
+	emitExecAuditEvent(e.Ctx, e.GetCommand(), err)
 
-	return execResult, trace.Wrap(err)
+	return &ExecResult{
+		Command: e.GetCommand(),
+		Code:    exitCode(err),
+	}
 }
 
 func (e *localExec) String() string {
@@ -410,21 +419,6 @@ func prepareCommand(ctx *ServerContext) (*exec.Cmd, error) {
 	return c, nil
 }
 
-func collectLocalStatus(cmd *exec.Cmd, err error) (*ExecResult, error) {
-	if err != nil {
-		if exitErr, ok := err.(*exec.ExitError); ok {
-			status := exitErr.Sys().(syscall.WaitStatus)
-			return &ExecResult{Code: status.ExitStatus(), Command: cmd.Path}, nil
-		}
-		return nil, err
-	}
-	status, ok := cmd.ProcessState.Sys().(syscall.WaitStatus)
-	if !ok {
-		return nil, fmt.Errorf("unknown exit status: %T(%v)", cmd.ProcessState.Sys(), cmd.ProcessState.Sys())
-	}
-	return &ExecResult{Code: status.ExitStatus(), Command: cmd.Path}, nil
-}
-
 // remoteExec is used to run an "exec" SSH request and return the result.
 type remoteExec struct {
 	command string
@@ -467,44 +461,26 @@ func (r *remoteExec) Start(ch ssh.Channel) (*ExecResult, error) {
 	return nil, nil
 }
 
-// Wait will block while the command executes then return the result as well
-// as emit an event to the Audit Log.
-func (r *remoteExec) Wait() (*ExecResult, error) {
-	// block until the command is finished and then figure out if the command
-	// successfully exited or if it exited in failure
-	execResult, err := r.collectRemoteStatus(r.session.Wait())
-
-	// emit the result of execution to the audit log
-	emitExecAuditEvent(r.ctx, r.command, execResult, err)
-
-	return execResult, trace.Wrap(err)
-}
-
-func (r *remoteExec) collectRemoteStatus(err error) (*ExecResult, error) {
-	if err == nil {
-		return &ExecResult{
-			Code:    teleport.RemoteCommandSuccess,
-			Command: r.GetCommand(),
-		}, nil
+// Wait will block while the command executes.
+func (r *remoteExec) Wait() *ExecResult {
+	// Block until the command is finished executing.
+	err := r.session.Wait()
+	if err != nil {
+		r.ctx.Debugf("Remote command failed: %v.", err)
+	} else {
+		r.ctx.Debugf("Remote command successfully executed.")
 	}
 
-	// if we got an ssh.ExitError, return the status code
-	if exitErr, ok := err.(*ssh.ExitError); ok {
-		return &ExecResult{
-			Code:    exitErr.ExitStatus(),
-			Command: r.GetCommand(),
-		}, err
-	}
+	// Emit the result of execution to the Audit Log.
+	emitExecAuditEvent(r.ctx, r.command, err)
 
-	// if we don't know what type of error occurred, return a generic 255 command
-	// failed code
 	return &ExecResult{
-		Code:    teleport.RemoteCommandFailure,
 		Command: r.GetCommand(),
-	}, err
+		Code:    exitCode(err),
+	}
 }
 
-func emitExecAuditEvent(ctx *ServerContext, cmd string, status *ExecResult, execErr error) {
+func emitExecAuditEvent(ctx *ServerContext, cmd string, execErr error) {
 	// Report the result of this exec event to the audit logger.
 	auditLog := ctx.srv.GetAuditLog()
 	if auditLog == nil {
@@ -521,12 +497,17 @@ func emitExecAuditEvent(ctx *ServerContext, cmd string, status *ExecResult, exec
 		events.LocalAddr:      ctx.Conn.LocalAddr().String(),
 		events.RemoteAddr:     ctx.Conn.RemoteAddr().String(),
 		events.EventNamespace: ctx.srv.GetNamespace(),
+		// Due to scp being inherently vulnerable to command injection, always
+		// make sure the full command and exit code is recorded for accountability.
+		// For more details, see the following.
+		//
+		// https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=327019
+		// https://bugzilla.mindrot.org/show_bug.cgi?id=1998
+		events.ExecEventCode:    strconv.Itoa(exitCode(execErr)),
+		events.ExecEventCommand: cmd,
 	}
 	if execErr != nil {
 		fields[events.ExecEventError] = execErr.Error()
-		if status != nil {
-			fields[events.ExecEventCode] = strconv.Itoa(status.Code)
-		}
 	}
 
 	// Parse the exec command to find out if it was SCP or not.
@@ -555,7 +536,6 @@ func emitExecAuditEvent(ctx *ServerContext, cmd string, status *ExecResult, exec
 			}
 		}
 	} else {
-		fields[events.ExecEventCommand] = cmd
 		if execErr != nil {
 			event = events.ExecFailure
 		} else {
@@ -653,3 +633,28 @@ func parseSecureCopy(path string) (string, string, bool, error) {
 		return "", "", false, nil
 	}
 }
+
+// exitCode extracts and returns the exit code from the error.
+func exitCode(err error) int {
+	// If no error occurred, return 0 (success).
+	if err == nil {
+		return teleport.RemoteCommandSuccess
+	}
+
+	switch v := err.(type) {
+	// Local execution.
+	case *exec.ExitError:
+		waitStatus, ok := v.Sys().(syscall.WaitStatus)
+		if !ok {
+			return teleport.RemoteCommandFailure
+		}
+		return waitStatus.ExitStatus()
+	// Remote execution.
+	case *ssh.ExitError:
+		return v.ExitStatus()
+	// An error occurred, but the type is unknown, return a generic 255 code.
+	default:
+		log.Debugf("Unknown error returned when executing command: %T: %v.", err, err)
+		return teleport.RemoteCommandFailure
+	}
+}

lib/srv/exec_test.go

@@ -25,10 +25,13 @@ import (
 	"os/user"
 	"path"
 	"path/filepath"
+	"strconv"
 	"testing"
+	"time"
 
 	"golang.org/x/crypto/ssh"
 
+	"github.com/gravitational/teleport"
 	"github.com/gravitational/teleport/lib/auth"
 	authority "github.com/gravitational/teleport/lib/auth/testauthority"
 	"github.com/gravitational/teleport/lib/backend/lite"
@@ -39,12 +42,11 @@ import (
 	"github.com/gravitational/teleport/lib/utils"
 
 	"github.com/docker/docker/pkg/term"
+	"github.com/gravitational/trace"
 	"github.com/jonboulle/clockwork"
 	"gopkg.in/check.v1"
 )
 
-func TestExec(t *testing.T) { check.TestingT(t) }
-
 // ExecSuite also implements ssh.ConnMetadata
 type ExecSuite struct {
 	usr        *user.User
@@ -89,7 +91,14 @@ func (s *ExecSuite) SetUpSuite(c *check.C) {
 	c.Assert(err, check.IsNil)
 
 	s.usr, _ = user.Current()
-	s.ctx = &ServerContext{IsTestStub: true, srv: &fakeServer{accessPoint: a, id: "00000000-0000-0000-0000-000000000000"}}
+	s.ctx = &ServerContext{
+		IsTestStub: true,
+		srv: &fakeServer{
+			accessPoint: a,
+			auditLog:    &fakeLog{},
+			id:          "00000000-0000-0000-0000-000000000000",
+		},
+	}
 	s.ctx.Identity.Login = s.usr.Username
 	s.ctx.session = &session{id: "xxx", term: &fakeTerminal{f: f}}
 	s.ctx.Identity.TeleportUser = "galt"
@@ -164,6 +173,47 @@ func (s *ExecSuite) TestLoginDefsParser(c *check.C) {
 	c.Assert(getDefaultEnvPath("1000", "bad/file"), check.Equals, defaultEnvPath)
 }
 
+// TestEmitExecAuditEvent make sure the full command and exit code for a
+// command is always recorded.
+func (s *ExecSuite) TestEmitExecAuditEvent(c *check.C) {
+	fakeLog, ok := s.ctx.srv.GetAuditLog().(*fakeLog)
+	c.Assert(ok, check.Equals, true)
+
+	var tests = []struct {
+		inCommand  string
+		inError    error
+		outCommand string
+		outCode    string
+	}{
+		// Successful execution.
+		{
+			inCommand:  "exit 0",
+			inError:    nil,
+			outCommand: "exit 0",
+			outCode:    strconv.Itoa(teleport.RemoteCommandSuccess),
+		},
+		// Exited with error.
+		{
+			inCommand:  "exit 255",
+			inError:    fmt.Errorf("unknown error"),
+			outCommand: "exit 255",
+			outCode:    strconv.Itoa(teleport.RemoteCommandFailure),
+		},
+		// Command injection.
+		{
+			inCommand:  "/bin/teleport scp --remote-addr=127.0.0.1:50862 --local-addr=127.0.0.1:54895 -f ~/file.txt && touch /tmp/new.txt",
+			inError:    fmt.Errorf("unknown error"),
+			outCommand: "/bin/teleport scp --remote-addr=127.0.0.1:50862 --local-addr=127.0.0.1:54895 -f ~/file.txt && touch /tmp/new.txt",
+			outCode:    strconv.Itoa(teleport.RemoteCommandFailure),
+		},
+	}
+	for _, tt := range tests {
+		emitExecAuditEvent(s.ctx, tt.inCommand, tt.inError)
+		c.Assert(fakeLog.lastEvent.GetString(events.ExecEventCommand), check.Equals, tt.outCommand)
+		c.Assert(fakeLog.lastEvent.GetString(events.ExecEventCode), check.Equals, tt.outCode)
+	}
+}
+
 // implementation of ssh.Conn interface
 func (s *ExecSuite) User() string                                           { return s.usr.Username }
 func (s *ExecSuite) SessionID() []byte                                      { return []byte{1, 2, 3} }
@@ -261,6 +311,7 @@ func (f *fakeTerminal) SetTermType(string) {
 
 // fakeServer is stub for tests
 type fakeServer struct {
+	auditLog    events.IAuditLog
 	accessPoint auth.AccessPoint
 	id          string
 }
@@ -289,7 +340,7 @@ func (s *fakeServer) EmitAuditEvent(events.Event, events.EventFields) {
 }
 
 func (f *fakeServer) GetAuditLog() events.IAuditLog {
-	return nil
+	return f.auditLog
 }
 
 func (f *fakeServer) GetAccessPoint() auth.AccessPoint {
@@ -319,3 +370,45 @@ func (f *fakeServer) GetInfo() services.Server {
 func (f *fakeServer) UseTunnel() bool {
 	return false
 }
+
+// fakeLog is used in tests to obtain the last event emit to the Audit Log.
+type fakeLog struct {
+	lastEvent events.EventFields
+}
+
+func (a *fakeLog) EmitAuditEvent(e events.Event, f events.EventFields) error {
+	a.lastEvent = f
+	return nil
+}
+
+func (a *fakeLog) PostSessionSlice(s events.SessionSlice) error {
+	return trace.NotImplemented("not implemented")
+}
+
+func (a *fakeLog) UploadSessionRecording(r events.SessionRecording) error {
+	return trace.NotImplemented("not implemented")
+}
+
+func (a *fakeLog) GetSessionChunk(namespace string, sid rsession.ID, offsetBytes int, maxBytes int) ([]byte, error) {
+	return nil, trace.NotFound("")
+}
+
+func (a *fakeLog) GetSessionEvents(namespace string, sid rsession.ID, after int, includePrintEvents bool) ([]events.EventFields, error) {
+	return nil, trace.NotFound("")
+}
+
+func (a *fakeLog) SearchEvents(fromUTC, toUTC time.Time, query string, limit int) ([]events.EventFields, error) {
+	return nil, trace.NotFound("")
+}
+
+func (a *fakeLog) SearchSessionEvents(fromUTC time.Time, toUTC time.Time, limit int) ([]events.EventFields, error) {
+	return nil, trace.NotFound("")
+}
+
+func (a *fakeLog) WaitForDelivery(context.Context) error {
+	return trace.NotImplemented("not implemented")
+}
+
+func (a *fakeLog) Close() error {
+	return trace.NotFound("")
+}

lib/srv/keepalive_test.go

@@ -35,7 +35,7 @@ type KeepAliveSuite struct{}
 var _ = fmt.Printf
 var _ = check.Suite(&KeepAliveSuite{})
 
-func Test(t *testing.T) { check.TestingT(t) }
+func TestSrv(t *testing.T) { check.TestingT(t) }
 
 func (s *KeepAliveSuite) SetUpSuite(c *check.C) {
 	utils.InitLoggerForTests()

lib/srv/regular/sshserver_test.go

@@ -50,7 +50,7 @@ import (
 	. "gopkg.in/check.v1"
 )
 
-func TestSrv(t *testing.T) { TestingT(t) }
+func TestRegular(t *testing.T) { TestingT(t) }
 
 type SrvSuite struct {
 	srv         *Server

lib/srv/termhandlers.go

@@ -88,10 +88,7 @@ func (t *TermHandlers) HandleExec(ch ssh.Channel, req *ssh.Request, ctx *ServerC
 	// in case if result is nil and no error, this means that program is
 	// running in the background
 	go func() {
-		result, err = execRequest.Wait()
-		if err != nil {
-			ctx.Errorf("Exec request (%v) wait failed: %v", execRequest, err)
-		}
+		result = execRequest.Wait()
 		if result != nil {
 			ctx.SendExecResult(*result)
 		}

lib/sshutils/scp/scp.go

@@ -197,7 +197,7 @@ type command struct {
 	log *log.Entry
 }
 
-// Execute() implements SSH file copy (SCP). It is called on both tsh (client)
+// Execute implements SSH file copy (SCP). It is called on both tsh (client)
 // and teleport (server) side.
 func (cmd *command) Execute(ch io.ReadWriter) (err error) {
 	if cmd.Flags.Source {
@@ -206,14 +206,7 @@ func (cmd *command) Execute(ch io.ReadWriter) (err error) {
 		err = cmd.serveSink(ch)
 	}
 	if err != nil {
-		if cmd.Config.RunOnServer == false {
-			return trace.Wrap(err)
-		} else {
-			// when 'teleport scp' encounters an error, it SHOULD NOT be logged
-			// to stderr (i.e. we should not return an error here) and instead
-			// it should be sent back to scp client using scp protocol
-			cmd.sendError(ch, err)
-		}
+		return trace.Wrap(err)
 	}
 	return nil
 }