FTP: enable ftpserverlib logging and make debug mode configurable

.github/workflows/development.yml

@@ -228,7 +228,7 @@ jobs:
           gzip output/man/man1/*
           cp sftpgo output/
 
-      - uses: uraimo/run-on-arch-action@v2.0.10
+      - uses: uraimo/run-on-arch-action@v2.1.0
         if: ${{ matrix.arch != 'amd64' }}
         name: Build for ${{ matrix.arch }}
         id: build

.github/workflows/release.yml

@@ -250,7 +250,7 @@ jobs:
         env:
           SFTPGO_VERSION: ${{ steps.get_version.outputs.SFTPGO_VERSION }}
 
-      - uses: uraimo/run-on-arch-action@v2.0.10
+      - uses: uraimo/run-on-arch-action@v2.1.0
         if: ${{ matrix.arch != 'amd64' }}
         name: Build for ${{ matrix.arch }}
         id: build

config/config.go

@@ -742,6 +742,12 @@ func getFTPDBindingFromEnv(idx int) {
 		isSet = true
 	}
 
+	debug, ok := lookupBoolFromEnv(fmt.Sprintf("SFTPGO_FTPD__BINDINGS__%v__DEBUG", idx))
+	if ok {
+		binding.Debug = debug
+		isSet = true
+	}
+
 	if isSet {
 		if len(globalConf.FTPD.Bindings) > idx {
 			globalConf.FTPD.Bindings[idx] = binding

config/config_test.go

@@ -479,6 +479,7 @@ func TestFTPDBindingsFromEnv(t *testing.T) {
 	os.Setenv("SFTPGO_FTPD__BINDINGS__9__TLS_MODE", "1")
 	os.Setenv("SFTPGO_FTPD__BINDINGS__9__FORCE_PASSIVE_IP", "127.0.1.1")
 	os.Setenv("SFTPGO_FTPD__BINDINGS__9__CLIENT_AUTH_TYPE", "2")
+	os.Setenv("SFTPGO_FTPD__BINDINGS__9__DEBUG", "1")
 
 	t.Cleanup(func() {
 		os.Unsetenv("SFTPGO_FTPD__BINDINGS__0__ADDRESS")
@@ -492,6 +493,7 @@ func TestFTPDBindingsFromEnv(t *testing.T) {
 		os.Unsetenv("SFTPGO_FTPD__BINDINGS__9__TLS_MODE")
 		os.Unsetenv("SFTPGO_FTPD__BINDINGS__9__FORCE_PASSIVE_IP")
 		os.Unsetenv("SFTPGO_FTPD__BINDINGS__9__CLIENT_AUTH_TYPE")
+		os.Unsetenv("SFTPGO_FTPD__BINDINGS__9__DEBUG")
 	})
 
 	configDir := ".."
@@ -508,6 +510,7 @@ func TestFTPDBindingsFromEnv(t *testing.T) {
 	require.Len(t, bindings[0].TLSCipherSuites, 2)
 	require.Equal(t, "TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305_SHA256", bindings[0].TLSCipherSuites[0])
 	require.Equal(t, "TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256", bindings[0].TLSCipherSuites[1])
+	require.False(t, bindings[0].Debug)
 	require.Equal(t, 2203, bindings[1].Port)
 	require.Equal(t, "127.0.1.1", bindings[1].Address)
 	require.True(t, bindings[1].ApplyProxyConfig) // default value
@@ -515,6 +518,7 @@ func TestFTPDBindingsFromEnv(t *testing.T) {
 	require.Equal(t, "127.0.1.1", bindings[1].ForcePassiveIP)
 	require.Equal(t, 2, bindings[1].ClientAuthType)
 	require.Nil(t, bindings[1].TLSCipherSuites)
+	require.True(t, bindings[1].Debug)
 }
 
 func TestWebDAVBindingsFromEnv(t *testing.T) {

docs/custom-actions.md

@@ -56,7 +56,7 @@ If the `hook` defines an HTTP URL then this URL will be invoked as HTTP POST. Th
 - `action`
 - `username`
 - `path`
-- `target_path`, included for `rename` action
+- `target_path`, included for `rename` action and `sftpgo-copy` SSH command
 - `ssh_cmd`, included for `ssh_cmd` action
 - `file_size`, included for `pre-upload`, `upload`, `download`, `delete` actions if the file size is greater than `0`
 - `fs_provider`, `0` for local filesystem, `1` for S3 backend, `2` for Google Cloud Storage (GCS) backend, `3` for Azure Blob Storage backend, `4` for local encrypted backend, `5` for SFTP backend

docs/full-configuration.md

@@ -115,6 +115,7 @@ The configuration file contains the following sections:
     - `force_passive_ip`, ip address. External IP address to expose for passive connections. Leavy empty to autodetect. If not empty, it must be a valid IPv4 address. Defaut: "".
     - `client_auth_type`, integer. Set to `1` to require a client certificate and verify it. Set to `2` to request a client certificate during the TLS handshake and verify it if given, in this mode the client is allowed not to send a certificate. At least one certification authority must be defined in order to verify client certificates. If no certification authority is defined, this setting is ignored. Default: 0.
     - `tls_cipher_suites`, list of strings. List of supported cipher suites for TLS version 1.2. If empty, a default list of secure cipher suites is used, with a preference order based on hardware performance. Note that TLS 1.3 ciphersuites are not configurable. The supported ciphersuites names are defined [here](https://github.com/golang/go/blob/master/src/crypto/tls/cipher_suites.go#L52). Any invalid name will be silently ignored. The order matters, the ciphers listed first will be the preferred ones. Default: empty.
+    - `debug`, boolean. If enabled any FTP command will be logged. This will generate a lot of logs. Enable only if you are investigating a client compatibility issue or something similar. You shouldn't leave this setting enabled for production servers. Default `false`.
   - `banner`, string. Greeting banner displayed when a connection first comes in. Leave empty to use the default banner. Default `SFTPGo <version> ready`, for example `SFTPGo 1.0.0-dev ready`.
   - `banner_file`, path to the banner file. The contents of the specified file, if any, are displayed when someone connects to the server. It can be a path relative to the config dir or an absolute one. If set, it overrides the banner string provided by the `banner` option. Leave empty to disable.
   - `active_transfers_port_non_20`, boolean. Do not impose the port 20 for active data transfers. Enabling this option allows to run SFTPGo with less privilege. Default: false.

ftpd/ftpd.go

@@ -51,7 +51,9 @@ type Binding struct {
 	// any invalid name will be silently ignored.
 	// The order matters, the ciphers listed first will be the preferred ones.
 	TLSCipherSuites []string `json:"tls_cipher_suites" mapstructure:"tls_cipher_suites"`
-	ciphers         []uint16
+	// Debug enables the FTP debug mode. In debug mode, every FTP command will be logged
+	Debug   bool `json:"debug" mapstructure:"debug"`
+	ciphers []uint16
 }
 
 func (b *Binding) setCiphers() {
@@ -217,7 +219,9 @@ func (c *Configuration) Initialize(configDir string) error {
 		server := NewServer(c, configDir, binding, idx)
 
 		go func(s *Server) {
+			ftpLogger := logger.LeveledLogger{Sender: "ftpserverlib"}
 			ftpServer := ftpserver.NewFtpServer(s)
+			ftpServer.Logger = ftpLogger.With("server_id", fmt.Sprintf("FTP_%v", s.ID))
 			logger.Info(logSender, "", "starting FTP serving, binding: %v", s.binding.GetAddress())
 			util.CheckTCP4Port(s.binding.Port)
 			exitChannel <- ftpServer.ListenAndServe()

ftpd/server.go

@@ -135,6 +135,7 @@ func (s *Server) GetSettings() (*ftpserver.Settings, error) {
 
 // ClientConnected is called to send the very first welcome message
 func (s *Server) ClientConnected(cc ftpserver.ClientContext) (string, error) {
+	cc.SetDebug(s.binding.Debug)
 	ipAddr := util.GetIPFromRemoteAddress(cc.RemoteAddr().String())
 	common.Connections.AddClientConnection(ipAddr)
 	if common.IsBanned(ipAddr) {

logger/logger.go

@@ -15,6 +15,7 @@ import (
 	"path/filepath"
 	"runtime"
 
+	ftpserverlog "github.com/fclairamb/ftpserverlib/log"
 	"github.com/rs/zerolog"
 	lumberjack "gopkg.in/natefinch/lumberjack.v2"
 )
@@ -60,7 +61,8 @@ func (l *StdLoggerWrapper) Write(p []byte) (n int, err error) {
 
 // LeveledLogger is a logger that accepts a message string and a variadic number of key-value pairs
 type LeveledLogger struct {
-	Sender string
+	Sender            string
+	additionalKeyVals []interface{}
 }
 
 func addKeysAndValues(ev *zerolog.Event, keysAndValues ...interface{}) {
@@ -81,6 +83,9 @@ func addKeysAndValues(ev *zerolog.Event, keysAndValues ...interface{}) {
 func (l *LeveledLogger) Error(msg string, keysAndValues ...interface{}) {
 	ev := logger.Error()
 	ev.Timestamp().Str("sender", l.Sender)
+	if len(l.additionalKeyVals) > 0 {
+		addKeysAndValues(ev, l.additionalKeyVals...)
+	}
 	addKeysAndValues(ev, keysAndValues...)
 	ev.Msg(msg)
 }
@@ -89,6 +94,9 @@ func (l *LeveledLogger) Error(msg string, keysAndValues ...interface{}) {
 func (l *LeveledLogger) Info(msg string, keysAndValues ...interface{}) {
 	ev := logger.Info()
 	ev.Timestamp().Str("sender", l.Sender)
+	if len(l.additionalKeyVals) > 0 {
+		addKeysAndValues(ev, l.additionalKeyVals...)
+	}
 	addKeysAndValues(ev, keysAndValues...)
 	ev.Msg(msg)
 }
@@ -97,6 +105,9 @@ func (l *LeveledLogger) Info(msg string, keysAndValues ...interface{}) {
 func (l *LeveledLogger) Debug(msg string, keysAndValues ...interface{}) {
 	ev := logger.Debug()
 	ev.Timestamp().Str("sender", l.Sender)
+	if len(l.additionalKeyVals) > 0 {
+		addKeysAndValues(ev, l.additionalKeyVals...)
+	}
 	addKeysAndValues(ev, keysAndValues...)
 	ev.Msg(msg)
 }
@@ -105,10 +116,21 @@ func (l *LeveledLogger) Debug(msg string, keysAndValues ...interface{}) {
 func (l *LeveledLogger) Warn(msg string, keysAndValues ...interface{}) {
 	ev := logger.Warn()
 	ev.Timestamp().Str("sender", l.Sender)
+	if len(l.additionalKeyVals) > 0 {
+		addKeysAndValues(ev, l.additionalKeyVals...)
+	}
 	addKeysAndValues(ev, keysAndValues...)
 	ev.Msg(msg)
 }
 
+// With returns a LeveledLogger with additional context specific keyvals
+func (l *LeveledLogger) With(keysAndValues ...interface{}) ftpserverlog.Logger {
+	return &LeveledLogger{
+		Sender:            l.Sender,
+		additionalKeyVals: append(l.additionalKeyVals, keysAndValues...),
+	}
+}
+
 // GetLogger get the configured logger instance
 func GetLogger() *zerolog.Logger {
 	return &logger

sftpgo.json

@@ -82,7 +82,8 @@
         "tls_mode": 0,
         "force_passive_ip": "",
         "client_auth_type": 0,
-        "tls_cipher_suites": []
+        "tls_cipher_suites": [],
+        "debug": false
       }
     ],
     "banner": "",