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

@@ -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
 

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("")
+}

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("")
 }

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

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
+}