security: log non-interactive SSH commands at beginning of session (#16872)

* include exec command in session.start.initial_command

* trim oversized events

api/types/events/events.go

@@ -72,3 +72,50 @@ func (m *DatabaseSessionQuery) TrimToMaxSize(maxSize int) AuditEvent {
 	}
 	return out
 }
+
+// TrimToMaxSize trims the SessionStart event to the given maximum size.
+// Currently assumes that the largest field will be InitialCommand and tries to
+// trim that.
+func (e *SessionStart) TrimToMaxSize(maxSize int) AuditEvent {
+	size := e.Size()
+	if size <= maxSize {
+		return e
+	}
+
+	out := proto.Clone(e).(*SessionStart)
+	out.InitialCommand = nil
+
+	// Use 10% max size ballast + message size without InitialCommand
+	sizeBallast := maxSize/10 + out.Size()
+	maxSize -= sizeBallast
+
+	maxFieldSize := maxSizePerField(maxSize, len(e.InitialCommand))
+
+	out.InitialCommand = make([]string, len(e.InitialCommand))
+	for i, c := range e.InitialCommand {
+		out.InitialCommand[i] = trimN(c, maxFieldSize)
+	}
+
+	return out
+}
+
+// TrimToMaxSize trims the Exec event to the given maximum size.
+// Currently assumes that the largest field will be Command and tries to trim
+// that.
+func (e *Exec) TrimToMaxSize(maxSize int) AuditEvent {
+	size := e.Size()
+	if size <= maxSize {
+		return e
+	}
+
+	out := proto.Clone(e).(*Exec)
+	out.Command = ""
+
+	// Use 10% max size ballast + message size without Command
+	sizeBallast := maxSize/10 + out.Size()
+	maxSize -= sizeBallast
+
+	out.Command = trimN(e.Command, maxSize)
+
+	return out
+}

integration/integration_test.go

@@ -5401,27 +5401,38 @@ func testExecEvents(t *testing.T, suite *integrationTestSuite) {
 	tr := utils.NewTracer(utils.ThisFunction()).Start()
 	defer tr.Stop()
 
-	lsPath, err := exec.LookPath("ls")
-	require.NoError(t, err)
-
 	// Creates new teleport cluster
 	main := suite.newTeleport(t, nil, true)
 	defer main.StopAll()
 
+	// Max event size for file log (bufio.MaxScanTokenSize) should be 64k, make
+	// a command much larger than that.
+	lotsOfBytes := bytes.Repeat([]byte{'a'}, 100*1024)
+
 	execTests := []struct {
 		name          string
 		isInteractive bool
-		outCommand    string
+		command       string
 	}{
 		{
 			name:          "PTY allocated",
 			isInteractive: true,
-			outCommand:    lsPath,
+			command:       "echo 1",
 		},
 		{
 			name:          "PTY not allocated",
 			isInteractive: false,
-			outCommand:    lsPath,
+			command:       "echo 2",
+		},
+		{
+			name:          "long command interactive",
+			isInteractive: true,
+			command:       "true 1 " + string(lotsOfBytes),
+		},
+		{
+			name:          "long command uninteractive",
+			isInteractive: false,
+			command:       "true 2 " + string(lotsOfBytes),
 		},
 	}
 
@@ -5435,16 +5446,76 @@ func testExecEvents(t *testing.T, suite *integrationTestSuite) {
 				Port:        helpers.Port(t, main.SSH),
 				Interactive: tt.isInteractive,
 			}
-			_, err := runCommand(t, main, []string{lsPath}, clientConfig, 1)
+			_, err := runCommand(t, main, []string{tt.command}, clientConfig, 1)
+			require.NoError(t, err)
+
+			expectedCommandPrefix := tt.command
+			if len(expectedCommandPrefix) > 32 {
+				expectedCommandPrefix = expectedCommandPrefix[:32]
+			}
+
+			// Make sure the session start event was emitted to the audit log
+			// and includes (a prefix of) the command
+			_, err = findMatchingEventInLog(main, events.SessionStartEvent, func(fields events.EventFields) bool {
+				initialCommand := fields.GetStrings("initial_command")
+				return events.SessionStartCode == fields.GetCode() && len(initialCommand) == 1 &&
+					strings.HasPrefix(initialCommand[0], expectedCommandPrefix)
+			})
 			require.NoError(t, err)
 
 			// Make sure the exec event was emitted to the audit log.
-			eventFields, err := findEventInLog(main, events.ExecEvent)
+			_, err = findMatchingEventInLog(main, events.ExecEvent, func(fields events.EventFields) bool {
+				return events.ExecCode == fields.GetCode() &&
+					strings.HasPrefix(fields.GetString(events.ExecEventCommand), expectedCommandPrefix)
+			})
 			require.NoError(t, err)
-			require.Equal(t, events.ExecCode, eventFields.GetCode())
-			require.Equal(t, tt.outCommand, eventFields.GetString(events.ExecEventCommand))
 		})
 	}
+
+	t.Run("long running", func(t *testing.T) {
+		clientConfig := helpers.ClientConfig{
+			Login:       suite.Me.Username,
+			Cluster:     helpers.Site,
+			Host:        Host,
+			Port:        helpers.Port(t, main.SSH),
+			Interactive: false,
+		}
+		ctx, cancel := context.WithCancel(context.Background())
+
+		cmd := "sleep 10"
+
+		errC := make(chan error)
+		go func() {
+			_, err := runCommandWithContext(ctx, t, main, []string{cmd}, clientConfig, 1)
+			errC <- err
+		}()
+
+		// Make sure the session start event was emitted immediately to the audit log
+		// before waiting for the command to complete, and includes the command
+		startEvent, err := findMatchingEventInLog(main, events.SessionStartEvent, func(fields events.EventFields) bool {
+			initialCommand := fields.GetStrings("initial_command")
+			return len(initialCommand) == 1 && initialCommand[0] == cmd
+		})
+		require.NoError(t, err)
+
+		sessionID := startEvent.GetString(events.SessionEventID)
+		require.NotEmpty(t, sessionID)
+
+		cancel()
+		// This may or may not be an error, depending on whether we canceled it
+		// before the command died of natural causes, no need to test the value
+		// here but we'll wait for it in order to avoid leaking goroutines
+		<-errC
+
+		// Wait for the session end event to avoid writes to the tempdir after
+		// the test completes (and make sure it's actually sent)
+		require.Eventually(t, func() bool {
+			_, err := findMatchingEventInLog(main, events.SessionEndEvent, func(fields events.EventFields) bool {
+				return sessionID == fields.GetString(events.SessionEventID)
+			})
+			return err == nil
+		}, 30*time.Second, 1*time.Second)
+	})
 }
 
 func testSessionStartContainsAccessRequest(t *testing.T, suite *integrationTestSuite) {
@@ -5611,6 +5682,14 @@ func findEventInLog(t *helpers.TeleInstance, eventName string) (events.EventFiel
 
 // findCommandEventInLog polls the event log looking for an event of a particular type.
 func findCommandEventInLog(t *helpers.TeleInstance, eventName string, programName string) (events.EventFields, error) {
+	return findMatchingEventInLog(t, eventName, func(fields events.EventFields) bool {
+		eventType := fields[events.EventType]
+		eventPath := fields[events.Path]
+		return eventType == eventName && eventPath == programName
+	})
+}
+
+func findMatchingEventInLog(t *helpers.TeleInstance, eventName string, match func(events.EventFields) bool) (events.EventFields, error) {
 	for i := 0; i < 10; i++ {
 		eventFields, err := eventsInLog(t.Config.DataDir+"/log/events.log", eventName)
 		if err != nil {
@@ -5619,15 +5698,7 @@ func findCommandEventInLog(t *helpers.TeleInstance, eventName string, programNam
 		}
 
 		for _, fields := range eventFields {
-			eventType, ok := fields[events.EventType]
-			if !ok {
-				continue
-			}
-			eventPath, ok := fields[events.Path]
-			if !ok {
-				continue
-			}
-			if eventType == eventName && eventPath == programName {
+			if match(fields) {
 				return fields, nil
 			}
 		}

lib/srv/sess.go

@@ -682,6 +682,10 @@ func (s *session) BroadcastSystemMessage(format string, args ...interface{}) {
 
 // emitSessionStartEvent emits a session start event.
 func (s *session) emitSessionStartEvent(ctx *ServerContext) {
+	var initialCommand []string
+	if execRequest, err := ctx.GetExecRequest(); err == nil {
+		initialCommand = []string{execRequest.GetCommand()}
+	}
 	sessionStartEvent := &apievents.SessionStart{
 		Metadata: apievents.Metadata{
 			Type:        events.SessionStartEvent,
@@ -698,6 +702,7 @@ func (s *session) emitSessionStartEvent(ctx *ServerContext) {
 			RemoteAddr: ctx.ServerConn.RemoteAddr().String(),
 		},
 		SessionRecording: ctx.SessionRecordingConfig.GetMode(),
+		InitialCommand:   initialCommand,
 	}
 
 	if s.term != nil {