Improve session logging

This commit is contained in:
Viktor Liu
2025-10-28 17:40:17 +01:00
parent 6f14134988
commit e6854dfd99
6 changed files with 43 additions and 39 deletions

View File

@@ -14,7 +14,6 @@ import (
// handleCommand executes an SSH command with privilege validation
func (s *Server) handleCommand(logger *log.Entry, session ssh.Session, privilegeResult PrivilegeCheckResult, winCh <-chan ssh.Window) {
localUser := privilegeResult.User
hasPty := winCh != nil
commandType := "command"
@@ -22,7 +21,7 @@ func (s *Server) handleCommand(logger *log.Entry, session ssh.Session, privilege
commandType = "Pty command"
}
logger.Infof("executing %s for %s from %s: %s", commandType, localUser.Username, session.RemoteAddr(), safeLogCommand(session.Command()))
logger.Infof("executing %s: %s", commandType, safeLogCommand(session.Command()))
execCmd, err := s.createCommand(privilegeResult, session, hasPty)
if err != nil {
@@ -38,7 +37,7 @@ func (s *Server) handleCommand(logger *log.Entry, session ssh.Session, privilege
logger.Debugf(errWriteSession, writeErr)
}
if err := session.Exit(1); err != nil {
logger.Debugf(errExitSession, err)
logSessionExitError(logger, err)
}
return
}
@@ -74,7 +73,7 @@ func (s *Server) executeCommand(logger *log.Entry, session ssh.Session, execCmd
if err != nil {
logger.Errorf("create stdin pipe: %v", err)
if err := session.Exit(1); err != nil {
logger.Debugf(errExitSession, err)
logSessionExitError(logger, err)
}
return false
}
@@ -93,7 +92,7 @@ func (s *Server) executeCommand(logger *log.Entry, session ssh.Session, execCmd
logger.Errorf("command start failed: %v", err)
// no user message for exec failure, just exit
if err := session.Exit(1); err != nil {
logger.Debugf(errExitSession, err)
logSessionExitError(logger, err)
}
return false
}
@@ -135,7 +134,7 @@ func (s *Server) waitForCommandCleanup(logger *log.Entry, session ssh.Session, e
}
if err := session.Exit(130); err != nil {
logger.Debugf(errExitSession, err)
logSessionExitError(logger, err)
}
return false
@@ -160,7 +159,7 @@ func (s *Server) handleCommandCompletion(logger *log.Entry, session ssh.Session,
func (s *Server) handleSessionExit(session ssh.Session, err error, logger *log.Entry) {
if err == nil {
if err := session.Exit(0); err != nil {
logger.Debugf(errExitSession, err)
logSessionExitError(logger, err)
}
return
}
@@ -168,12 +167,12 @@ func (s *Server) handleSessionExit(session ssh.Session, err error, logger *log.E
var exitError *exec.ExitError
if errors.As(err, &exitError) {
if err := session.Exit(exitError.ExitCode()); err != nil {
logger.Debugf(errExitSession, err)
logSessionExitError(logger, err)
}
} else {
logger.Debugf("non-exit error in command execution: %v", err)
if err := session.Exit(1); err != nil {
logger.Debugf(errExitSession, err)
logSessionExitError(logger, err)
}
}
}

View File

@@ -99,8 +99,7 @@ func (pm *ptyManager) File() *os.File {
func (s *Server) handlePty(logger *log.Entry, session ssh.Session, privilegeResult PrivilegeCheckResult, ptyReq ssh.Pty, winCh <-chan ssh.Window) bool {
cmd := session.Command()
localUser := privilegeResult.User
logger.Infof("executing Pty command for %s from %s: %s", localUser.Username, session.RemoteAddr(), safeLogCommand(cmd))
logger.Infof("executing Pty command: %s", safeLogCommand(cmd))
execCmd, err := s.createPtyCommand(privilegeResult, ptyReq, session)
if err != nil {
@@ -110,7 +109,7 @@ func (s *Server) handlePty(logger *log.Entry, session ssh.Session, privilegeResu
logger.Debugf(errWriteSession, writeErr)
}
if err := session.Exit(1); err != nil {
logger.Debugf(errExitSession, err)
logSessionExitError(logger, err)
}
return false
}
@@ -119,7 +118,7 @@ func (s *Server) handlePty(logger *log.Entry, session ssh.Session, privilegeResu
if err != nil {
logger.Errorf("Pty start failed: %v", err)
if err := session.Exit(1); err != nil {
logger.Debugf(errExitSession, err)
logSessionExitError(logger, err)
}
return false
}
@@ -178,18 +177,22 @@ func (s *Server) handlePtyIO(logger *log.Entry, session ssh.Session, ptyMgr *pty
go func() {
if _, err := io.Copy(ptmx, session); err != nil {
logger.Debugf("Pty input copy error: %v", err)
if !errors.Is(err, io.EOF) && !errors.Is(err, syscall.EIO) {
logger.Warnf("Pty input copy error: %v", err)
}
}
}()
go func() {
defer func() {
if err := session.Close(); err != nil {
if err := session.Close(); err != nil && !errors.Is(err, io.EOF) {
logger.Debugf("session close error: %v", err)
}
}()
if _, err := io.Copy(session, ptmx); err != nil {
logger.Debugf("Pty output copy error: %v", err)
if !errors.Is(err, io.EOF) && !errors.Is(err, syscall.EIO) {
logger.Warnf("Pty output copy error: %v", err)
}
}
}()
}
@@ -229,7 +232,7 @@ func (s *Server) handlePtySessionCancellation(logger *log.Entry, session ssh.Ses
}
if err := session.Exit(130); err != nil {
logger.Debugf(errExitSession, err)
logSessionExitError(logger, err)
}
}
@@ -243,7 +246,7 @@ func (s *Server) handlePtyCommandCompletion(logger *log.Entry, session ssh.Sessi
// Normal completion
logger.Debugf("Pty command completed successfully")
if err := session.Exit(0); err != nil {
logger.Debugf(errExitSession, err)
logSessionExitError(logger, err)
}
}

View File

@@ -266,9 +266,8 @@ func (s *Server) prepareCommandEnv(localUser *user.User, session ssh.Session) []
}
func (s *Server) handlePty(logger *log.Entry, session ssh.Session, privilegeResult PrivilegeCheckResult, ptyReq ssh.Pty, winCh <-chan ssh.Window) bool {
localUser := privilegeResult.User
cmd := session.Command()
logger.Infof("executing Pty command for %s from %s: %s", localUser.Username, session.RemoteAddr(), safeLogCommand(cmd))
logger.Infof("executing Pty command: %s", safeLogCommand(cmd))
// Always use user switching on Windows - no direct execution
s.handlePtyWithUserSwitching(logger, session, privilegeResult, ptyReq, winCh, cmd)
@@ -317,7 +316,7 @@ func (s *Server) handlePtyWithUserSwitching(logger *log.Entry, session ssh.Sessi
logger.Debugf(errWriteSession, writeErr)
}
if err := session.Exit(1); err != nil {
logger.Debugf(errExitSession, err)
logSessionExitError(logger, err)
}
return
}

View File

@@ -6,6 +6,7 @@ import (
"encoding/json"
"errors"
"fmt"
"io"
"net"
"net/netip"
"strings"
@@ -80,10 +81,17 @@ func (e *UserNotFoundError) Unwrap() error {
return e.Cause
}
// logSessionExitError logs session exit errors, ignoring EOF (normal close) errors
func logSessionExitError(logger *log.Entry, err error) {
if err != nil && !errors.Is(err, io.EOF) {
logger.Warnf(errExitSession, err)
}
}
// safeLogCommand returns a safe representation of the command for logging
func safeLogCommand(cmd []string) string {
if len(cmd) == 0 {
return "<empty>"
return "<interactive shell>"
}
if len(cmd) == 1 {
return cmd[0]
@@ -623,19 +631,19 @@ func (s *Server) directTCPIPHandler(srv *ssh.Server, conn *cryptossh.ServerConn,
s.mu.RUnlock()
if !allowLocal {
log.Debugf("direct-tcpip rejected: local port forwarding disabled")
log.Warnf("local port forwarding denied for %s:%d: disabled by configuration", payload.Host, payload.Port)
_ = newChan.Reject(cryptossh.Prohibited, "local port forwarding disabled")
return
}
// Check privilege requirements for the destination port
if err := s.checkPortForwardingPrivileges(ctx, "local", payload.Port); err != nil {
log.Infof("direct-tcpip denied: %v", err)
log.Warnf("local port forwarding denied for %s:%d: %v", payload.Host, payload.Port, err)
_ = newChan.Reject(cryptossh.Prohibited, "insufficient privileges")
return
}
log.Debugf("direct-tcpip request: %s:%d", payload.Host, payload.Port)
log.Infof("local port forwarding: %s:%d", payload.Host, payload.Port)
ssh.DirectTCPIPHandler(srv, conn, newChan, ctx)
}

View File

@@ -16,22 +16,19 @@ import (
// sessionHandler handles SSH sessions
func (s *Server) sessionHandler(session ssh.Session) {
sessionKey := s.registerSession(session)
logger := log.WithField("session", sessionKey)
logger.Infof("SSH session started")
sessionStart := time.Now()
logger := log.WithField("session", sessionKey)
defer s.unregisterSession(sessionKey, session)
defer func() {
duration := time.Since(sessionStart)
if err := session.Close(); err != nil {
logger.Debugf("close session after %v: %v", duration, err)
return
duration := time.Since(sessionStart).Round(time.Millisecond)
if err := session.Close(); err != nil && !errors.Is(err, io.EOF) {
logger.Warnf("close session after %v: %v", duration, err)
}
logger.Debugf("session closed after %v", duration)
logger.Infof("SSH session closed after %v", duration)
}()
logger.Infof("establishing SSH session for %s from %s", session.User(), session.RemoteAddr())
privilegeResult, err := s.userPrivilegeCheck(session.User())
if err != nil {
s.handlePrivError(logger, session, err)
@@ -61,7 +58,7 @@ func (s *Server) rejectInvalidSession(logger *log.Entry, session ssh.Session) {
logger.Debugf(errWriteSession, err)
}
if err := session.Exit(1); err != nil {
logger.Debugf(errExitSession, err)
logSessionExitError(logger, err)
}
logger.Infof("rejected non-Pty session without command from %s", session.RemoteAddr())
}
@@ -86,7 +83,6 @@ func (s *Server) registerSession(session ssh.Session) SessionKey {
s.sessions[sessionKey] = session
s.mu.Unlock()
log.WithField("session", sessionKey).Debugf("registered SSH session")
return sessionKey
}
@@ -111,7 +107,6 @@ func (s *Server) unregisterSession(sessionKey SessionKey, _ ssh.Session) {
}
s.mu.Unlock()
log.WithField("session", sessionKey).Debugf("unregistered SSH session")
}
func (s *Server) handlePrivError(logger *log.Entry, session ssh.Session, err error) {
@@ -123,7 +118,7 @@ func (s *Server) handlePrivError(logger *log.Entry, session ssh.Session, err err
logger.Debugf(errWriteSession, writeErr)
}
if exitErr := session.Exit(1); exitErr != nil {
logger.Debugf(errExitSession, exitErr)
logSessionExitError(logger, exitErr)
}
}

View File

@@ -16,7 +16,7 @@ func (s *Server) handlePty(logger *log.Entry, session ssh.Session, _ PrivilegeCh
logger.Debugf(errWriteSession, err)
}
if err := session.Exit(1); err != nil {
logger.Debugf(errExitSession, err)
logSessionExitError(logger, err)
}
return false
}