From 4ff34b3e538433f749695683e36252e9e18549cd Mon Sep 17 00:00:00 2001 From: Nicola Murino Date: Mon, 11 Nov 2019 15:20:00 +0100 Subject: [PATCH] logger: add specific logs for failed attempts to initialize a connection This should allow for better integration in tools like fail2ban. Hopefully fix #59 --- README.md | 9 +++++++++ logger/logger.go | 29 +++++++++++++++++++++++------ logger/request_logger.go | 24 +++++++++++++++--------- sftpd/server.go | 29 +++++++++++++++++++++-------- utils/utils.go | 11 +++++++++++ 5 files changed, 79 insertions(+), 23 deletions(-) diff --git a/README.md b/README.md index 35166ce4..f8c90db6 100644 --- a/README.md +++ b/README.md @@ -452,6 +452,15 @@ The logs can be divided into the following categories: - `resp_size` integer. Size in bytes of the HTTP response - `elapsed_ms` int64. Elapsed time, as milliseconds, to complete the request - `request_id` string. Unique request identifier +- **"connection_failed"**, logs failed attempts to initialize a connection. A connection can fail for an authentication error or other errors such as a client abort or a time out if the login does not happen in two minutes + - `sender` string. `connection_failed` + - `level` string + - `username`, string. Can be empty if the client open the connection and don't try to login + - `host` string. + - `login_type` string. Can be `public_key`, `password` or `no_auth_tryed` + - `error` string. Optional error description + +The `connection_failed` logs can be used for better integration in tools such as [Fail2ban](http://www.fail2ban.org/) ## Acknowledgements diff --git a/logger/logger.go b/logger/logger.go index 9cae4a9b..38ef24e1 100644 --- a/logger/logger.go +++ b/logger/logger.go @@ -19,7 +19,7 @@ import ( ) const ( - dateFormat = "2006-01-02T15:04.05.000" // YYYY-MM-DDTHH:MM.SS.ZZZ + dateFormat = "2006-01-02T15:04:05.000" // YYYY-MM-DDTHH:MM:SS.ZZZ ) // LogLevel defines log levels. @@ -61,7 +61,7 @@ func InitLogger(logFilePath string, logMaxSize int, logMaxBackups int, logMaxAge lock: new(sync.Mutex)}) consoleLogger = zerolog.Nop() } - logger = logger.With().Timestamp().Logger().Level(level) + logger.Level(level) } // DisableLogger disable the main logger. @@ -97,22 +97,22 @@ func Log(level LogLevel, sender string, connectionID string, format string, v .. // Debug logs at debug level for the specified sender func Debug(sender string, connectionID string, format string, v ...interface{}) { - logger.Debug().Str("sender", sender).Str("connection_id", connectionID).Msg(fmt.Sprintf(format, v...)) + logger.Debug().Timestamp().Str("sender", sender).Str("connection_id", connectionID).Msg(fmt.Sprintf(format, v...)) } // Info logs at info level for the specified sender func Info(sender string, connectionID string, format string, v ...interface{}) { - logger.Info().Str("sender", sender).Str("connection_id", connectionID).Msg(fmt.Sprintf(format, v...)) + logger.Info().Timestamp().Str("sender", sender).Str("connection_id", connectionID).Msg(fmt.Sprintf(format, v...)) } // Warn logs at warn level for the specified sender func Warn(sender string, connectionID string, format string, v ...interface{}) { - logger.Warn().Str("sender", sender).Str("connection_id", connectionID).Msg(fmt.Sprintf(format, v...)) + logger.Warn().Timestamp().Str("sender", sender).Str("connection_id", connectionID).Msg(fmt.Sprintf(format, v...)) } // Error logs at error level for the specified sender func Error(sender string, connectionID string, format string, v ...interface{}) { - logger.Error().Str("sender", sender).Str("connection_id", connectionID).Msg(fmt.Sprintf(format, v...)) + logger.Error().Timestamp().Str("sender", sender).Str("connection_id", connectionID).Msg(fmt.Sprintf(format, v...)) } // DebugToConsole logs at debug level to stdout @@ -138,6 +138,7 @@ func ErrorToConsole(format string, v ...interface{}) { // TransferLog logs an SFTP/SCP upload or download func TransferLog(operation string, path string, elapsed int64, size int64, user string, connectionID string, protocol string) { logger.Info(). + Timestamp(). Str("sender", operation). Int64("elapsed_ms", elapsed). Int64("size_bytes", size). @@ -151,6 +152,7 @@ func TransferLog(operation string, path string, elapsed int64, size int64, user // CommandLog logs an SFTP/SCP command func CommandLog(command string, path string, target string, user string, connectionID string, protocol string) { logger.Info(). + Timestamp(). Str("sender", command). Str("username", user). Str("file_path", path). @@ -159,3 +161,18 @@ func CommandLog(command string, path string, target string, user string, connect Str("protocol", protocol). Msg("") } + +// ConnectionFailedLog logs failed attempts to initialize a connection. +// A connection can fail for an authentication error or other errors such as +// a client abort or a time out if the login does not happen in two minutes. +// These logs are useful for better integration with Fail2ban and similar tools. +func ConnectionFailedLog(user, ip, loginType, errorString string) { + logger.Debug(). + Timestamp(). + Str("sender", "connection_failed"). + Str("host", ip). + Str("username", user). + Str("login_type", loginType). + Str("error", errorString). + Msg("") +} diff --git a/logger/request_logger.go b/logger/request_logger.go index df8edc85..e9dd4d14 100644 --- a/logger/request_logger.go +++ b/logger/request_logger.go @@ -56,17 +56,23 @@ func (l *StructuredLogger) NewLogEntry(r *http.Request) middleware.LogEntry { // Write logs a new entry at the end of the HTTP request func (l *StructuredLoggerEntry) Write(status, bytes int, elapsed time.Duration) { metrics.HTTPRequestServed(status) - l.Logger.Info().Fields(l.fields).Int( - "resp_status", status).Int( - "resp_size", bytes).Int64( - "elapsed_ms", elapsed.Nanoseconds()/1000000).Str( - "sender", "httpd").Msg( - "") + l.Logger.Info(). + Timestamp(). + Str("sender", "httpd"). + Fields(l.fields). + Int("resp_status", status). + Int("resp_size", bytes). + Int64("elapsed_ms", elapsed.Nanoseconds()/1000000). + Msg("") } // Panic logs panics func (l *StructuredLoggerEntry) Panic(v interface{}, stack []byte) { - l.Logger.Error().Fields(l.fields).Str( - "stack", string(stack)).Str( - "panic", fmt.Sprintf("%+v", v)).Msg("") + l.Logger.Error(). + Timestamp(). + Str("sender", "httpd"). + Fields(l.fields). + Str("stack", string(stack)). + Str("panic", fmt.Sprintf("%+v", v)). + Msg("") } diff --git a/sftpd/server.go b/sftpd/server.go index 0c1c73e6..f7f161cd 100644 --- a/sftpd/server.go +++ b/sftpd/server.go @@ -7,7 +7,6 @@ import ( "encoding/hex" "encoding/json" "encoding/pem" - "errors" "fmt" "io" "io/ioutil" @@ -87,6 +86,14 @@ type Key struct { PrivateKey string `json:"private_key" mapstructure:"private_key"` } +type authenticationError struct { + err string +} + +func (e *authenticationError) Error() string { + return fmt.Sprintf("Authentication error: %s", e.err) +} + // Initialize the SFTP server and add a persistent listener to handle inbound SFTP connections. func (c Configuration) Initialize(configDir string) error { umask, err := strconv.ParseUint(c.Umask, 8, 8) @@ -102,7 +109,7 @@ func (c Configuration) Initialize(configDir string) error { PasswordCallback: func(conn ssh.ConnMetadata, pass []byte) (*ssh.Permissions, error) { sp, err := c.validatePasswordCredentials(conn, pass) if err != nil { - return nil, errors.New("could not validate credentials") + return nil, &authenticationError{err: fmt.Sprintf("could not validate password credentials: %v", err)} } return sp, nil @@ -110,7 +117,7 @@ func (c Configuration) Initialize(configDir string) error { PublicKeyCallback: func(conn ssh.ConnMetadata, pubKey ssh.PublicKey) (*ssh.Permissions, error) { sp, err := c.validatePublicKeyCredentials(conn, string(pubKey.Marshal())) if err != nil { - return nil, errors.New("could not validate credentials") + return nil, &authenticationError{err: fmt.Sprintf("could not validate public key credentials: %v", err)} } return sp, nil @@ -207,16 +214,18 @@ func (c Configuration) AcceptInboundConnection(conn net.Conn, config *ssh.Server // Before beginning a handshake must be performed on the incoming net.Conn // we'll set a Deadline for handshake to complete, the default is 2 minutes as OpenSSH conn.SetDeadline(time.Now().Add(handshakeTimeout)) + remoteAddr := conn.RemoteAddr() sconn, chans, reqs, err := ssh.NewServerConn(conn, config) if err != nil { logger.Warn(logSender, "", "failed to accept an incoming connection: %v", err) + if _, ok := err.(*ssh.ServerAuthError); !ok { + logger.ConnectionFailedLog("", utils.GetIPFromRemoteAddress(remoteAddr.String()), "no_auth_tryed", err.Error()) + } return } // handshake completed so remove the deadline, we'll use IdleTimeout configuration from now on conn.SetDeadline(time.Time{}) - logger.Debug(logSender, "", "accepted inbound connection, ip: %v", conn.RemoteAddr().String()) - var user dataprovider.User var loginType string @@ -230,15 +239,15 @@ func (c Configuration) AcceptInboundConnection(conn net.Conn, config *ssh.Server ID: connectionID, User: user, ClientVersion: string(sconn.ClientVersion()), - RemoteAddr: conn.RemoteAddr(), + RemoteAddr: remoteAddr, StartTime: time.Now(), lastActivity: time.Now(), lock: new(sync.Mutex), netConn: conn, channel: nil, } - connection.Log(logger.LevelInfo, logSender, "User id: %d, logged in with: %#v, username: %#v, home_dir: %#v", - user.ID, loginType, user.Username, user.HomeDir) + connection.Log(logger.LevelInfo, logSender, "User id: %d, logged in with: %#v, username: %#v, home_dir: %#v remote addr: %#v", + user.ID, loginType, user.Username, user.HomeDir, remoteAddr.String()) go ssh.DiscardRequests(reqs) @@ -385,6 +394,8 @@ func (c Configuration) validatePublicKeyCredentials(conn ssh.ConnMetadata, pubKe metrics.AddLoginAttempt(true) if user, keyID, err = dataprovider.CheckUserAndPubKey(dataProvider, conn.User(), pubKey); err == nil { sshPerm, err = loginUser(user, "public_key:"+keyID) + } else { + logger.ConnectionFailedLog(conn.User(), utils.GetIPFromRemoteAddress(conn.RemoteAddr().String()), "public_key", err.Error()) } metrics.AddLoginResult(true, err) return sshPerm, err @@ -398,6 +409,8 @@ func (c Configuration) validatePasswordCredentials(conn ssh.ConnMetadata, pass [ metrics.AddLoginAttempt(false) if user, err = dataprovider.CheckUserAndPass(dataProvider, conn.User(), string(pass)); err == nil { sshPerm, err = loginUser(user, "password") + } else { + logger.ConnectionFailedLog(conn.User(), utils.GetIPFromRemoteAddress(conn.RemoteAddr().String()), "password", err.Error()) } metrics.AddLoginResult(false, err) return sshPerm, err diff --git a/utils/utils.go b/utils/utils.go index 1b2039ba..299e5168 100644 --- a/utils/utils.go +++ b/utils/utils.go @@ -3,6 +3,7 @@ package utils import ( "fmt" + "net" "os" "path/filepath" "runtime" @@ -133,3 +134,13 @@ func byteCount(b int64, unit int64) string { return fmt.Sprintf("%.1f %ciB", float64(b)/float64(div), "KMGTPE"[exp]) } + +// GetIPFromRemoteAddress returns the IP from the remote address. +// If the given remote address cannot be parsed it will be returned unchanged +func GetIPFromRemoteAddress(remoteAddress string) string { + ip, _, err := net.SplitHostPort(remoteAddress) + if err == nil { + return ip + } + return remoteAddress +}