Skip to content

Commit e6854df

Browse files
lixmallixmal
committed
Improve session logging
1 parent 6f14134 commit e6854df

File tree

6 files changed

+43
-39
lines changed

6 files changed

+43
-39
lines changed

‎client/ssh/server/command_execution.go‎

Lines changed: 8 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -14,15 +14,14 @@ import (
1414

1515
// handleCommand executes an SSH command with privilege validation
1616
func (s *Server) handleCommand(logger *log.Entry, session ssh.Session, privilegeResult PrivilegeCheckResult, winCh <-chan ssh.Window) {
17-
localUser := privilegeResult.User
1817
hasPty := winCh != nil
1918

2019
commandType := "command"
2120
if hasPty {
2221
commandType = "Pty command"
2322
}
2423

25-
logger.Infof("executing %s for %s from %s: %s", commandType, localUser.Username, session.RemoteAddr(), safeLogCommand(session.Command()))
24+
logger.Infof("executing %s: %s", commandType, safeLogCommand(session.Command()))
2625

2726
execCmd, err := s.createCommand(privilegeResult, session, hasPty)
2827
if err != nil {
@@ -38,7 +37,7 @@ func (s *Server) handleCommand(logger *log.Entry, session ssh.Session, privilege
3837
logger.Debugf(errWriteSession, writeErr)
3938
}
4039
if err := session.Exit(1); err != nil {
41-
logger.Debugf(errExitSession, err)
40+
logSessionExitError(logger, err)
4241
}
4342
return
4443
}
@@ -74,7 +73,7 @@ func (s *Server) executeCommand(logger *log.Entry, session ssh.Session, execCmd
7473
if err != nil {
7574
logger.Errorf("create stdin pipe: %v", err)
7675
if err := session.Exit(1); err != nil {
77-
logger.Debugf(errExitSession, err)
76+
logSessionExitError(logger, err)
7877
}
7978
return false
8079
}
@@ -93,7 +92,7 @@ func (s *Server) executeCommand(logger *log.Entry, session ssh.Session, execCmd
9392
logger.Errorf("command start failed: %v", err)
9493
// no user message for exec failure, just exit
9594
if err := session.Exit(1); err != nil {
96-
logger.Debugf(errExitSession, err)
95+
logSessionExitError(logger, err)
9796
}
9897
return false
9998
}
@@ -135,7 +134,7 @@ func (s *Server) waitForCommandCleanup(logger *log.Entry, session ssh.Session, e
135134
}
136135

137136
if err := session.Exit(130); err != nil {
138-
logger.Debugf(errExitSession, err)
137+
logSessionExitError(logger, err)
139138
}
140139
return false
141140

@@ -160,20 +159,20 @@ func (s *Server) handleCommandCompletion(logger *log.Entry, session ssh.Session,
160159
func (s *Server) handleSessionExit(session ssh.Session, err error, logger *log.Entry) {
161160
if err == nil {
162161
if err := session.Exit(0); err != nil {
163-
logger.Debugf(errExitSession, err)
162+
logSessionExitError(logger, err)
164163
}
165164
return
166165
}
167166

168167
var exitError *exec.ExitError
169168
if errors.As(err, &exitError) {
170169
if err := session.Exit(exitError.ExitCode()); err != nil {
171-
logger.Debugf(errExitSession, err)
170+
logSessionExitError(logger, err)
172171
}
173172
} else {
174173
logger.Debugf("non-exit error in command execution: %v", err)
175174
if err := session.Exit(1); err != nil {
176-
logger.Debugf(errExitSession, err)
175+
logSessionExitError(logger, err)
177176
}
178177
}
179178
}

‎client/ssh/server/command_execution_unix.go‎

Lines changed: 12 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -99,8 +99,7 @@ func (pm *ptyManager) File() *os.File {
9999

100100
func (s *Server) handlePty(logger *log.Entry, session ssh.Session, privilegeResult PrivilegeCheckResult, ptyReq ssh.Pty, winCh <-chan ssh.Window) bool {
101101
cmd := session.Command()
102-
localUser := privilegeResult.User
103-
logger.Infof("executing Pty command for %s from %s: %s", localUser.Username, session.RemoteAddr(), safeLogCommand(cmd))
102+
logger.Infof("executing Pty command: %s", safeLogCommand(cmd))
104103

105104
execCmd, err := s.createPtyCommand(privilegeResult, ptyReq, session)
106105
if err != nil {
@@ -110,7 +109,7 @@ func (s *Server) handlePty(logger *log.Entry, session ssh.Session, privilegeResu
110109
logger.Debugf(errWriteSession, writeErr)
111110
}
112111
if err := session.Exit(1); err != nil {
113-
logger.Debugf(errExitSession, err)
112+
logSessionExitError(logger, err)
114113
}
115114
return false
116115
}
@@ -119,7 +118,7 @@ func (s *Server) handlePty(logger *log.Entry, session ssh.Session, privilegeResu
119118
if err != nil {
120119
logger.Errorf("Pty start failed: %v", err)
121120
if err := session.Exit(1); err != nil {
122-
logger.Debugf(errExitSession, err)
121+
logSessionExitError(logger, err)
123122
}
124123
return false
125124
}
@@ -178,18 +177,22 @@ func (s *Server) handlePtyIO(logger *log.Entry, session ssh.Session, ptyMgr *pty
178177

179178
go func() {
180179
if _, err := io.Copy(ptmx, session); err != nil {
181-
logger.Debugf("Pty input copy error: %v", err)
180+
if !errors.Is(err, io.EOF) && !errors.Is(err, syscall.EIO) {
181+
logger.Warnf("Pty input copy error: %v", err)
182+
}
182183
}
183184
}()
184185

185186
go func() {
186187
defer func() {
187-
if err := session.Close(); err != nil {
188+
if err := session.Close(); err != nil && !errors.Is(err, io.EOF) {
188189
logger.Debugf("session close error: %v", err)
189190
}
190191
}()
191192
if _, err := io.Copy(session, ptmx); err != nil {
192-
logger.Debugf("Pty output copy error: %v", err)
193+
if !errors.Is(err, io.EOF) && !errors.Is(err, syscall.EIO) {
194+
logger.Warnf("Pty output copy error: %v", err)
195+
}
193196
}
194197
}()
195198
}
@@ -229,7 +232,7 @@ func (s *Server) handlePtySessionCancellation(logger *log.Entry, session ssh.Ses
229232
}
230233

231234
if err := session.Exit(130); err != nil {
232-
logger.Debugf(errExitSession, err)
235+
logSessionExitError(logger, err)
233236
}
234237
}
235238

@@ -243,7 +246,7 @@ func (s *Server) handlePtyCommandCompletion(logger *log.Entry, session ssh.Sessi
243246
// Normal completion
244247
logger.Debugf("Pty command completed successfully")
245248
if err := session.Exit(0); err != nil {
246-
logger.Debugf(errExitSession, err)
249+
logSessionExitError(logger, err)
247250
}
248251
}
249252

‎client/ssh/server/command_execution_windows.go‎

Lines changed: 2 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -266,9 +266,8 @@ func (s *Server) prepareCommandEnv(localUser *user.User, session ssh.Session) []
266266
}
267267

268268
func (s *Server) handlePty(logger *log.Entry, session ssh.Session, privilegeResult PrivilegeCheckResult, ptyReq ssh.Pty, winCh <-chan ssh.Window) bool {
269-
localUser := privilegeResult.User
270269
cmd := session.Command()
271-
logger.Infof("executing Pty command for %s from %s: %s", localUser.Username, session.RemoteAddr(), safeLogCommand(cmd))
270+
logger.Infof("executing Pty command: %s", safeLogCommand(cmd))
272271

273272
// Always use user switching on Windows - no direct execution
274273
s.handlePtyWithUserSwitching(logger, session, privilegeResult, ptyReq, winCh, cmd)
@@ -317,7 +316,7 @@ func (s *Server) handlePtyWithUserSwitching(logger *log.Entry, session ssh.Sessi
317316
logger.Debugf(errWriteSession, writeErr)
318317
}
319318
if err := session.Exit(1); err != nil {
320-
logger.Debugf(errExitSession, err)
319+
logSessionExitError(logger, err)
321320
}
322321
return
323322
}

‎client/ssh/server/server.go‎

Lines changed: 12 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -6,6 +6,7 @@ import (
66
"encoding/json"
77
"errors"
88
"fmt"
9+
"io"
910
"net"
1011
"net/netip"
1112
"strings"
@@ -80,10 +81,17 @@ func (e *UserNotFoundError) Unwrap() error {
8081
return e.Cause
8182
}
8283

84+
// logSessionExitError logs session exit errors, ignoring EOF (normal close) errors
85+
func logSessionExitError(logger *log.Entry, err error) {
86+
if err != nil && !errors.Is(err, io.EOF) {
87+
logger.Warnf(errExitSession, err)
88+
}
89+
}
90+
8391
// safeLogCommand returns a safe representation of the command for logging
8492
func safeLogCommand(cmd []string) string {
8593
if len(cmd) == 0 {
86-
return "<empty>"
94+
return "<interactive shell>"
8795
}
8896
if len(cmd) == 1 {
8997
return cmd[0]
@@ -623,19 +631,19 @@ func (s *Server) directTCPIPHandler(srv *ssh.Server, conn *cryptossh.ServerConn,
623631
s.mu.RUnlock()
624632

625633
if !allowLocal {
626-
log.Debugf("direct-tcpip rejected: local port forwarding disabled")
634+
log.Warnf("local port forwarding denied for %s:%d: disabled by configuration", payload.Host, payload.Port)
627635
_ = newChan.Reject(cryptossh.Prohibited, "local port forwarding disabled")
628636
return
629637
}
630638

631639
// Check privilege requirements for the destination port
632640
if err := s.checkPortForwardingPrivileges(ctx, "local", payload.Port); err != nil {
633-
log.Infof("direct-tcpip denied: %v", err)
641+
log.Warnf("local port forwarding denied for %s:%d: %v", payload.Host, payload.Port, err)
634642
_ = newChan.Reject(cryptossh.Prohibited, "insufficient privileges")
635643
return
636644
}
637645

638-
log.Debugf("direct-tcpip request: %s:%d", payload.Host, payload.Port)
646+
log.Infof("local port forwarding: %s:%d", payload.Host, payload.Port)
639647

640648
ssh.DirectTCPIPHandler(srv, conn, newChan, ctx)
641649
}

‎client/ssh/server/session_handlers.go‎

Lines changed: 8 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -16,22 +16,19 @@ import (
1616
// sessionHandler handles SSH sessions
1717
func (s *Server) sessionHandler(session ssh.Session) {
1818
sessionKey := s.registerSession(session)
19+
logger := log.WithField("session", sessionKey)
20+
logger.Infof("SSH session started")
1921
sessionStart := time.Now()
2022

21-
logger := log.WithField("session", sessionKey)
2223
defer s.unregisterSession(sessionKey, session)
2324
defer func() {
24-
duration := time.Since(sessionStart)
25-
if err := session.Close(); err != nil {
26-
logger.Debugf("close session after %v: %v", duration, err)
27-
return
25+
duration := time.Since(sessionStart).Round(time.Millisecond)
26+
if err := session.Close(); err != nil && !errors.Is(err, io.EOF) {
27+
logger.Warnf("close session after %v: %v", duration, err)
2828
}
29-
30-
logger.Debugf("session closed after %v", duration)
29+
logger.Infof("SSH session closed after %v", duration)
3130
}()
3231

33-
logger.Infof("establishing SSH session for %s from %s", session.User(), session.RemoteAddr())
34-
3532
privilegeResult, err := s.userPrivilegeCheck(session.User())
3633
if err != nil {
3734
s.handlePrivError(logger, session, err)
@@ -61,7 +58,7 @@ func (s *Server) rejectInvalidSession(logger *log.Entry, session ssh.Session) {
6158
logger.Debugf(errWriteSession, err)
6259
}
6360
if err := session.Exit(1); err != nil {
64-
logger.Debugf(errExitSession, err)
61+
logSessionExitError(logger, err)
6562
}
6663
logger.Infof("rejected non-Pty session without command from %s", session.RemoteAddr())
6764
}
@@ -86,7 +83,6 @@ func (s *Server) registerSession(session ssh.Session) SessionKey {
8683
s.sessions[sessionKey] = session
8784
s.mu.Unlock()
8885

89-
log.WithField("session", sessionKey).Debugf("registered SSH session")
9086
return sessionKey
9187
}
9288

@@ -111,7 +107,6 @@ func (s *Server) unregisterSession(sessionKey SessionKey, _ ssh.Session) {
111107
}
112108

113109
s.mu.Unlock()
114-
log.WithField("session", sessionKey).Debugf("unregistered SSH session")
115110
}
116111

117112
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
123118
logger.Debugf(errWriteSession, writeErr)
124119
}
125120
if exitErr := session.Exit(1); exitErr != nil {
126-
logger.Debugf(errExitSession, exitErr)
121+
logSessionExitError(logger, exitErr)
127122
}
128123
}
129124

‎client/ssh/server/session_handlers_js.go‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -16,7 +16,7 @@ func (s *Server) handlePty(logger *log.Entry, session ssh.Session, _ PrivilegeCh
1616
logger.Debugf(errWriteSession, err)
1717
}
1818
if err := session.Exit(1); err != nil {
19-
logger.Debugf(errExitSession, err)
19+
logSessionExitError(logger, err)
2020
}
2121
return false
2222
}

0 commit comments

Comments
 (0)