Add connectionID to as many entries as possible

Signed-off-by: Jo Vandeginste <Jo.Vandeginste@kuleuven.be>

api/api_test.go

@@ -58,7 +58,7 @@ func TestMain(m *testing.M) {
 
 	err := dataprovider.Initialize(providerConf, configDir)
 	if err != nil {
-		logger.Warn(logSender, "error initializing data provider: %v", err)
+		logger.Warn(logSender, "", "error initializing data provider: %v", err)
 		os.Exit(1)
 	}
 	dataProvider := dataprovider.GetProvider()
@@ -72,7 +72,7 @@ func TestMain(m *testing.M) {
 	api.SetDataProvider(dataProvider)
 
 	go func() {
-		logger.Debug(logSender, "initializing HTTP server with config %+v", httpdConf)
+		logger.Debug(logSender, "", "initializing HTTP server with config %+v", httpdConf)
 		s := &http.Server{
 			Addr:           fmt.Sprintf("%s:%d", httpdConf.BindAddress, httpdConf.BindPort),
 			Handler:        router,
@@ -81,7 +81,7 @@ func TestMain(m *testing.M) {
 			MaxHeaderBytes: 1 << 20, // 1MB
 		}
 		if err := s.ListenAndServe(); err != nil {
-			logger.Error(logSender, "could not start HTTP server: %v", err)
+			logger.Error(logSender, "", "could not start HTTP server: %v", err)
 		}
 	}()
 

api/quota.go

@@ -31,10 +31,10 @@ func startQuotaScan(w http.ResponseWriter, r *http.Request) {
 		go func() {
 			numFiles, size, _, err := utils.ScanDirContents(user.HomeDir)
 			if err != nil {
-				logger.Warn(logSender, "error scanning user home dir %v: %v", user.HomeDir, err)
+				logger.Warn(logSender, "", "error scanning user home dir %v: %v", user.HomeDir, err)
 			} else {
 				err := dataprovider.UpdateUserQuota(dataProvider, user, numFiles, size, true)
-				logger.Debug(logSender, "user dir scanned, user: %v, dir: %v, error: %v", user.Username, user.HomeDir, err)
+				logger.Debug(logSender, "", "user dir scanned, user: %v, dir: %v, error: %v", user.Username, user.HomeDir, err)
 			}
 			sftpd.RemoveQuotaScan(user.Username)
 		}()

cmd/serve.go

@@ -127,7 +127,7 @@ func startServe() {
 		logLevel = zerolog.InfoLevel
 	}
 	logger.InitLogger(logFilePath, logMaxSize, logMaxBackups, logMaxAge, logCompress, logLevel)
-	logger.Info(logSender, "starting SFTPGo, config dir: %v, config file: %v, log max size: %v log max backups: %v "+
+	logger.Info(logSender, "", "starting SFTPGo, config dir: %v, config file: %v, log max size: %v log max backups: %v "+
 		"log max age: %v log verbose: %v, log compress: %v", configDir, configFile, logMaxSize, logMaxBackups, logMaxAge,
 		logVerbose, logCompress)
 	config.LoadConfig(configDir, configFile)
@@ -135,7 +135,7 @@ func startServe() {
 
 	err := dataprovider.Initialize(providerConf, configDir)
 	if err != nil {
-		logger.Error(logSender, "error initializing data provider: %v", err)
+		logger.Error(logSender, "", "error initializing data provider: %v", err)
 		logger.ErrorToConsole("error initializing data provider: %v", err)
 		os.Exit(1)
 	}
@@ -149,9 +149,9 @@ func startServe() {
 	shutdown := make(chan bool)
 
 	go func() {
-		logger.Debug(logSender, "initializing SFTP server with config %+v", sftpdConf)
+		logger.Debug(logSender, "", "initializing SFTP server with config %+v", sftpdConf)
 		if err := sftpdConf.Initialize(configDir); err != nil {
-			logger.Error(logSender, "could not start SFTP server: %v", err)
+			logger.Error(logSender, "", "could not start SFTP server: %v", err)
 			logger.ErrorToConsole("could not start SFTP server: %v", err)
 		}
 		shutdown <- true
@@ -162,7 +162,7 @@ func startServe() {
 		api.SetDataProvider(dataProvider)
 
 		go func() {
-			logger.Debug(logSender, "initializing HTTP server with config %+v", httpdConf)
+			logger.Debug(logSender, "", "initializing HTTP server with config %+v", httpdConf)
 			s := &http.Server{
 				Addr:           fmt.Sprintf("%s:%d", httpdConf.BindAddress, httpdConf.BindPort),
 				Handler:        router,
@@ -171,13 +171,13 @@ func startServe() {
 				MaxHeaderBytes: 1 << 20, // 1MB
 			}
 			if err := s.ListenAndServe(); err != nil {
-				logger.Error(logSender, "could not start HTTP server: %v", err)
+				logger.Error(logSender, "", "could not start HTTP server: %v", err)
 				logger.ErrorToConsole("could not start HTTP server: %v", err)
 			}
 			shutdown <- true
 		}()
 	} else {
-		logger.Debug(logSender, "HTTP server not started, disabled in config file")
+		logger.Debug(logSender, "", "HTTP server not started, disabled in config file")
 		logger.DebugToConsole("HTTP server not started, disabled in config file")
 	}
 

config/config.go

@@ -114,13 +114,13 @@ func LoadConfig(configDir, configName string) error {
 	viper.AddConfigPath(".")
 	viper.SetConfigName(configName)
 	if err = viper.ReadInConfig(); err != nil {
-		logger.Warn(logSender, "error loading configuration file: %v. Default configuration will be used: %+v", err, globalConf)
+		logger.Warn(logSender, "", "error loading configuration file: %v. Default configuration will be used: %+v", err, globalConf)
 		logger.WarnToConsole("error loading configuration file: %v. Default configuration will be used.", err)
 		return err
 	}
 	err = viper.Unmarshal(&globalConf)
 	if err != nil {
-		logger.Warn(logSender, "error parsing configuration file: %v. Default configuration will be used: %+v", err, globalConf)
+		logger.Warn(logSender, "", "error parsing configuration file: %v. Default configuration will be used: %+v", err, globalConf)
 		logger.WarnToConsole("error parsing configuration file: %v. Default configuration will be used.", err)
 		return err
 	}
@@ -131,9 +131,9 @@ func LoadConfig(configDir, configName string) error {
 		err = fmt.Errorf("Invalid upload_mode 0 and 1 are supported, configured: %v reset upload_mode to 0",
 			globalConf.SFTPD.UploadMode)
 		globalConf.SFTPD.UploadMode = 0
-		logger.Warn(logSender, "Configuration error: %v", err)
+		logger.Warn(logSender, "", "Configuration error: %v", err)
 		logger.WarnToConsole("Configuration error: %v", err)
 	}
-	logger.Debug(logSender, "config file used: '%v', config loaded: %+v", viper.ConfigFileUsed(), globalConf)
+	logger.Debug(logSender, "", "config file used: '%v', config loaded: %+v", viper.ConfigFileUsed(), globalConf)
 	return err
 }

dataprovider/bolt.go

@@ -34,13 +34,13 @@ func initializeBoltProvider(basePath string) error {
 		FreelistType: bolt.FreelistArrayType,
 		Timeout:      5 * time.Second})
 	if err == nil {
-		logger.Debug(logSender, "bolt key store handle created")
+		logger.Debug(logSender, "", "bolt key store handle created")
 		err = dbHandle.Update(func(tx *bolt.Tx) error {
 			_, e := tx.CreateBucketIfNotExists(usersBucket)
 			return e
 		})
 		if err != nil {
-			logger.Warn(logSender, "error creating users bucket: %v", err)
+			logger.Warn(logSender, "", "error creating users bucket: %v", err)
 			return err
 		}
 		err = dbHandle.Update(func(tx *bolt.Tx) error {
@@ -48,12 +48,12 @@ func initializeBoltProvider(basePath string) error {
 			return e
 		})
 		if err != nil {
-			logger.Warn(logSender, "error creating username idx bucket: %v", err)
+			logger.Warn(logSender, "", "error creating username idx bucket: %v", err)
 			return err
 		}
 		provider = BoltProvider{dbHandle: dbHandle}
 	} else {
-		logger.Warn(logSender, "error creating bolt key/value store handler: %v", err)
+		logger.Warn(logSender, "", "error creating bolt key/value store handler: %v", err)
 	}
 	return err
 }
@@ -65,7 +65,7 @@ func (p BoltProvider) validateUserAndPass(username string, password string) (Use
 	}
 	user, err := p.userExists(username)
 	if err != nil {
-		logger.Warn(logSender, "error authenticating user: %v, error: %v", username, err)
+		logger.Warn(logSender, "", "error authenticating user: %v, error: %v", username, err)
 		return user, err
 	}
 	return checkUserAndPass(user, password)
@@ -78,7 +78,7 @@ func (p BoltProvider) validateUserAndPubKey(username string, pubKey string) (Use
 	}
 	user, err := p.userExists(username)
 	if err != nil {
-		logger.Warn(logSender, "error authenticating user: %v, error: %v", username, err)
+		logger.Warn(logSender, "", "error authenticating user: %v, error: %v", username, err)
 		return user, err
 	}
 	return checkUserAndPubKey(user, pubKey)
@@ -140,7 +140,7 @@ func (p BoltProvider) updateQuota(username string, filesAdd int, sizeAdd int64,
 func (p BoltProvider) getUsedQuota(username string) (int, int64, error) {
 	user, err := p.userExists(username)
 	if err != nil {
-		logger.Warn(logSender, "unable to get quota for user '%v' error: %v", username, err)
+		logger.Warn(logSender, "", "unable to get quota for user '%v' error: %v", username, err)
 		return 0, 0, err
 	}
 	return user.UsedQuotaFiles, user.UsedQuotaSize, err

dataprovider/dataprovider.go

@@ -275,19 +275,19 @@ func checkUserAndPass(user User, password string) (User, error) {
 	if strings.HasPrefix(user.Password, argonPwdPrefix) {
 		match, err = argon2id.ComparePasswordAndHash(password, user.Password)
 		if err != nil {
-			logger.Warn(logSender, "error comparing password with argon hash: %v", err)
+			logger.Warn(logSender, "", "error comparing password with argon hash: %v", err)
 			return user, err
 		}
 	} else if strings.HasPrefix(user.Password, bcryptPwdPrefix) {
 		if err = bcrypt.CompareHashAndPassword([]byte(user.Password), []byte(password)); err != nil {
-			logger.Warn(logSender, "error comparing password with bcrypt hash: %v", err)
+			logger.Warn(logSender, "", "error comparing password with bcrypt hash: %v", err)
 			return user, err
 		}
 		match = true
 	} else if utils.IsStringPrefixInSlice(user.Password, pbkdfPwdPrefixes) {
 		match, err = comparePbkdf2PasswordAndHash(password, user.Password)
 		if err != nil {
-			logger.Warn(logSender, "error comparing password with pbkdf2 sha256 hash: %v", err)
+			logger.Warn(logSender, "", "error comparing password with pbkdf2 sha256 hash: %v", err)
 			return user, err
 		}
 	}
@@ -304,7 +304,7 @@ func checkUserAndPubKey(user User, pubKey string) (User, error) {
 	for i, k := range user.PublicKeys {
 		storedPubKey, _, _, _, err := ssh.ParseAuthorizedKey([]byte(k))
 		if err != nil {
-			logger.Warn(logSender, "error parsing stored public key %d for user %v: %v", i, user.Username, err)
+			logger.Warn(logSender, "", "error parsing stored public key %d for user %v: %v", i, user.Username, err)
 			return user, err
 		}
 		if string(storedPubKey.Marshal()) == pubKey {

dataprovider/mysql.go

@@ -26,13 +26,13 @@ func initializeMySQLProvider() error {
 	dbHandle, err := sql.Open("mysql", connectionString)
 	if err == nil {
 		numCPU := runtime.NumCPU()
-		logger.Debug(logSender, "mysql database handle created, connection string: '%v', pool size: %v", connectionString, numCPU)
+		logger.Debug(logSender, "", "mysql database handle created, connection string: '%v', pool size: %v", connectionString, numCPU)
 		dbHandle.SetMaxIdleConns(numCPU)
 		dbHandle.SetMaxOpenConns(numCPU)
 		dbHandle.SetConnMaxLifetime(1800 * time.Second)
 		provider = MySQLProvider{dbHandle: dbHandle}
 	} else {
-		logger.Warn(logSender, "error creating mysql database handler, connection string: '%v', error: %v", connectionString, err)
+		logger.Warn(logSender, "", "error creating mysql database handler, connection string: '%v', error: %v", connectionString, err)
 	}
 	return err
 }
@@ -52,7 +52,7 @@ func (p MySQLProvider) getUserByID(ID int64) (User, error) {
 func (p MySQLProvider) updateQuota(username string, filesAdd int, sizeAdd int64, reset bool) error {
 	tx, err := p.dbHandle.Begin()
 	if err != nil {
-		logger.Warn(logSender, "error starting transaction to update quota for user %v: %v", username, err)
+		logger.Warn(logSender, "", "error starting transaction to update quota for user %v: %v", username, err)
 		return err
 	}
 	err = sqlCommonUpdateQuota(username, filesAdd, sizeAdd, reset, p.dbHandle)
@@ -62,7 +62,7 @@ func (p MySQLProvider) updateQuota(username string, filesAdd int, sizeAdd int64,
 		err = tx.Rollback()
 	}
 	if err != nil {
-		logger.Warn(logSender, "error closing transaction to update quota for user %v: %v", username, err)
+		logger.Warn(logSender, "", "error closing transaction to update quota for user %v: %v", username, err)
 	}
 	return err
 }

dataprovider/pgsql.go

@@ -25,12 +25,12 @@ func initializePGSQLProvider() error {
 	dbHandle, err := sql.Open("postgres", connectionString)
 	if err == nil {
 		numCPU := runtime.NumCPU()
-		logger.Debug(logSender, "postgres database handle created, connection string: '%v', pool size: %v", connectionString, numCPU)
+		logger.Debug(logSender, "", "postgres database handle created, connection string: '%v', pool size: %v", connectionString, numCPU)
 		dbHandle.SetMaxIdleConns(numCPU)
 		dbHandle.SetMaxOpenConns(numCPU)
 		provider = PGSQLProvider{dbHandle: dbHandle}
 	} else {
-		logger.Warn(logSender, "error creating postgres database handler, connection string: '%v', error: %v", connectionString, err)
+		logger.Warn(logSender, "", "error creating postgres database handler, connection string: '%v', error: %v", connectionString, err)
 	}
 	return err
 }
@@ -50,7 +50,7 @@ func (p PGSQLProvider) getUserByID(ID int64) (User, error) {
 func (p PGSQLProvider) updateQuota(username string, filesAdd int, sizeAdd int64, reset bool) error {
 	tx, err := p.dbHandle.Begin()
 	if err != nil {
-		logger.Warn(logSender, "error starting transaction to update quota for user %v: %v", username, err)
+		logger.Warn(logSender, "", "error starting transaction to update quota for user %v: %v", username, err)
 		return err
 	}
 	err = sqlCommonUpdateQuota(username, filesAdd, sizeAdd, reset, p.dbHandle)
@@ -60,7 +60,7 @@ func (p PGSQLProvider) updateQuota(username string, filesAdd int, sizeAdd int64,
 		err = tx.Rollback()
 	}
 	if err != nil {
-		logger.Warn(logSender, "error closing transaction to update quota for user %v: %v", username, err)
+		logger.Warn(logSender, "", "error closing transaction to update quota for user %v: %v", username, err)
 	}
 	return err
 }

dataprovider/sqlcommon.go

@@ -15,7 +15,7 @@ func getUserByUsername(username string, dbHandle *sql.DB) (User, error) {
 	q := getUserByUsernameQuery()
 	stmt, err := dbHandle.Prepare(q)
 	if err != nil {
-		logger.Debug(logSender, "error preparing database query %v: %v", q, err)
+		logger.Debug(logSender, "", "error preparing database query %v: %v", q, err)
 		return user, err
 	}
 	defer stmt.Close()
@@ -31,7 +31,7 @@ func sqlCommonValidateUserAndPass(username string, password string, dbHandle *sq
 	}
 	user, err := getUserByUsername(username, dbHandle)
 	if err != nil {
-		logger.Warn(logSender, "error authenticating user: %v, error: %v", username, err)
+		logger.Warn(logSender, "", "error authenticating user: %v, error: %v", username, err)
 		return user, err
 	}
 	return checkUserAndPass(user, password)
@@ -44,7 +44,7 @@ func sqlCommonValidateUserAndPubKey(username string, pubKey string, dbHandle *sq
 	}
 	user, err := getUserByUsername(username, dbHandle)
 	if err != nil {
-		logger.Warn(logSender, "error authenticating user: %v, error: %v", username, err)
+		logger.Warn(logSender, "", "error authenticating user: %v, error: %v", username, err)
 		return user, err
 	}
 	return checkUserAndPubKey(user, pubKey)
@@ -55,7 +55,7 @@ func sqlCommonGetUserByID(ID int64, dbHandle *sql.DB) (User, error) {
 	q := getUserByIDQuery()
 	stmt, err := dbHandle.Prepare(q)
 	if err != nil {
-		logger.Debug(logSender, "error preparing database query %v: %v", q, err)
+		logger.Debug(logSender, "", "error preparing database query %v: %v", q, err)
 		return user, err
 	}
 	defer stmt.Close()
@@ -68,16 +68,16 @@ func sqlCommonUpdateQuota(username string, filesAdd int, sizeAdd int64, reset bo
 	q := getUpdateQuotaQuery(reset)
 	stmt, err := dbHandle.Prepare(q)
 	if err != nil {
-		logger.Debug(logSender, "error preparing database query %v: %v", q, err)
+		logger.Debug(logSender, "", "error preparing database query %v: %v", q, err)
 		return err
 	}
 	defer stmt.Close()
 	_, err = stmt.Exec(sizeAdd, filesAdd, utils.GetTimeAsMsSinceEpoch(time.Now()), username)
 	if err == nil {
-		logger.Debug(logSender, "quota updated for user %v, files increment: %v size increment: %v is reset? %v",
+		logger.Debug(logSender, "", "quota updated for user %v, files increment: %v size increment: %v is reset? %v",
 			username, filesAdd, sizeAdd, reset)
 	} else {
-		logger.Warn(logSender, "error updating quota for username %v: %v", username, err)
+		logger.Warn(logSender, "", "error updating quota for username %v: %v", username, err)
 	}
 	return err
 }
@@ -86,7 +86,7 @@ func sqlCommonGetUsedQuota(username string, dbHandle *sql.DB) (int, int64, error
 	q := getQuotaQuery()
 	stmt, err := dbHandle.Prepare(q)
 	if err != nil {
-		logger.Warn(logSender, "error preparing database query %v: %v", q, err)
+		logger.Warn(logSender, "", "error preparing database query %v: %v", q, err)
 		return 0, 0, err
 	}
 	defer stmt.Close()
@@ -95,7 +95,7 @@ func sqlCommonGetUsedQuota(username string, dbHandle *sql.DB) (int, int64, error
 	var usedSize int64
 	err = stmt.QueryRow(username).Scan(&usedSize, &usedFiles)
 	if err != nil {
-		logger.Warn(logSender, "error getting user quota: %v, error: %v", username, err)
+		logger.Warn(logSender, "", "error getting user quota: %v, error: %v", username, err)
 		return 0, 0, err
 	}
 	return usedFiles, usedSize, err
@@ -106,7 +106,7 @@ func sqlCommonCheckUserExists(username string, dbHandle *sql.DB) (User, error) {
 	q := getUserByUsernameQuery()
 	stmt, err := dbHandle.Prepare(q)
 	if err != nil {
-		logger.Warn(logSender, "error preparing database query %v: %v", q, err)
+		logger.Warn(logSender, "", "error preparing database query %v: %v", q, err)
 		return user, err
 	}
 	defer stmt.Close()
@@ -122,7 +122,7 @@ func sqlCommonAddUser(user User, dbHandle *sql.DB) error {
 	q := getAddUserQuery()
 	stmt, err := dbHandle.Prepare(q)
 	if err != nil {
-		logger.Warn(logSender, "error preparing database query %v: %v", q, err)
+		logger.Warn(logSender, "", "error preparing database query %v: %v", q, err)
 		return err
 	}
 	defer stmt.Close()
@@ -147,7 +147,7 @@ func sqlCommonUpdateUser(user User, dbHandle *sql.DB) error {
 	q := getUpdateUserQuery()
 	stmt, err := dbHandle.Prepare(q)
 	if err != nil {
-		logger.Warn(logSender, "error preparing database query %v: %v", q, err)
+		logger.Warn(logSender, "", "error preparing database query %v: %v", q, err)
 		return err
 	}
 	defer stmt.Close()
@@ -168,7 +168,7 @@ func sqlCommonDeleteUser(user User, dbHandle *sql.DB) error {
 	q := getDeleteUserQuery()
 	stmt, err := dbHandle.Prepare(q)
 	if err != nil {
-		logger.Warn(logSender, "error preparing database query %v: %v", q, err)
+		logger.Warn(logSender, "", "error preparing database query %v: %v", q, err)
 		return err
 	}
 	defer stmt.Close()
@@ -181,7 +181,7 @@ func sqlCommonGetUsers(limit int, offset int, order string, username string, dbH
 	q := getUsersQuery(order, username)
 	stmt, err := dbHandle.Prepare(q)
 	if err != nil {
-		logger.Warn(logSender, "error preparing database query %v: %v", q, err)
+		logger.Warn(logSender, "", "error preparing database query %v: %v", q, err)
 		return nil, err
 	}
 	defer stmt.Close()

dataprovider/sqlite.go

@@ -25,7 +25,7 @@ func initializeSQLiteProvider(basePath string) error {
 		}
 		fi, err := os.Stat(dbPath)
 		if err != nil {
-			logger.Warn(logSender, "sqlite database file does not exists, please be sure to create and initialize"+
+			logger.Warn(logSender, "", "sqlite database file does not exists, please be sure to create and initialize"+
 				" a database before starting sftpgo")
 			return err
 		}
@@ -39,11 +39,11 @@ func initializeSQLiteProvider(basePath string) error {
 	}
 	dbHandle, err := sql.Open("sqlite3", connectionString)
 	if err == nil {
-		logger.Debug(logSender, "sqlite database handle created, connection string: '%v'", connectionString)
+		logger.Debug(logSender, "", "sqlite database handle created, connection string: '%v'", connectionString)
 		dbHandle.SetMaxOpenConns(1)
 		provider = SQLiteProvider{dbHandle: dbHandle}
 	} else {
-		logger.Warn(logSender, "error creating sqlite database handler, connection string: '%v', error: %v", connectionString, err)
+		logger.Warn(logSender, "", "error creating sqlite database handler, connection string: '%v', error: %v", connectionString, err)
 	}
 	return err
 }

logger/logger.go

@@ -59,23 +59,23 @@ func InitLogger(logFilePath string, logMaxSize int, logMaxBackups int, logMaxAge
 }
 
 // Debug logs at debug level for the specified sender
-func Debug(sender string, format string, v ...interface{}) {
-	logger.Debug().Str("sender", sender).Msg(fmt.Sprintf(format, v...))
+func Debug(sender string, connectionID string, format string, v ...interface{}) {
+	logger.Debug().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, format string, v ...interface{}) {
-	logger.Info().Str("sender", sender).Msg(fmt.Sprintf(format, v...))
+func Info(sender string, connectionID string, format string, v ...interface{}) {
+	logger.Info().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, format string, v ...interface{}) {
-	logger.Warn().Str("sender", sender).Msg(fmt.Sprintf(format, v...))
+func Warn(sender string, connectionID string, format string, v ...interface{}) {
+	logger.Warn().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, format string, v ...interface{}) {
-	logger.Error().Str("sender", sender).Msg(fmt.Sprintf(format, v...))
+func Error(sender string, connectionID string, format string, v ...interface{}) {
+	logger.Error().Str("sender", sender).Str("connection_id", connectionID).Msg(fmt.Sprintf(format, v...))
 }
 
 // DebugToConsole logs at debug level to stdout

sftpd/handler.go

@@ -62,11 +62,11 @@ func (c Connection) Fileread(request *sftp.Request) (io.ReaderAt, error) {
 
 	file, err := os.Open(p)
 	if err != nil {
-		logger.Error(logSender, "could not open file %#v for reading: %v", p, err)
+		logger.Error(logSender, c.ID, "could not open file %#v for reading: %v", p, err)
 		return nil, sftp.ErrSshFxFailure
 	}
 
-	logger.Debug(logSender, "fileread requested for path: %#v, user: %v", p, c.User.Username)
+	logger.Debug(logSender, c.ID, "fileread requested for path: %#v, user: %v", p, c.User.Username)
 
 	transfer := Transfer{
 		file:          file,
@@ -113,13 +113,13 @@ func (c Connection) Filewrite(request *sftp.Request) (io.WriterAt, error) {
 	}
 
 	if statErr != nil {
-		logger.Error(logSender, "error performing file stat %#v: %v", p, statErr)
+		logger.Error(logSender, c.ID, "error performing file stat %#v: %v", p, statErr)
 		return nil, sftp.ErrSshFxFailure
 	}
 
 	// This happen if we upload a file that has the same name of an existing directory
 	if stat.IsDir() {
-		logger.Warn(logSender, "attempted to open a directory for writing to: %#v", p)
+		logger.Warn(logSender, c.ID, "attempted to open a directory for writing to: %#v", p)
 		return nil, sftp.ErrSshFxOpUnsupported
 	}
 
@@ -141,7 +141,7 @@ func (c Connection) Filecmd(request *sftp.Request) error {
 		return sftp.ErrSshFxOpUnsupported
 	}
 
-	logger.Debug(logSender, "new cmd, method: %v user: %v sourcePath: %#v, targetPath: %#v", request.Method, c.User.Username,
+	logger.Debug(logSender, c.ID, "new cmd, method: %v user: %v sourcePath: %#v, targetPath: %#v", request.Method, c.User.Username,
 		p, target)
 
 	switch request.Method {
@@ -204,11 +204,11 @@ func (c Connection) Filelist(request *sftp.Request) (sftp.ListerAt, error) {
 			return nil, sftp.ErrSshFxPermissionDenied
 		}
 
-		logger.Debug(logSender, "requested list file for dir: %#v user: %v", p, c.User.Username)
+		logger.Debug(logSender, c.ID, "requested list file for dir: %#v user: %v", p, c.User.Username)
 
 		files, err := ioutil.ReadDir(p)
 		if err != nil {
-			logger.Error(logSender, "error listing directory: %#v", err)
+			logger.Error(logSender, c.ID, "error listing directory: %#v", err)
 			return nil, sftp.ErrSshFxFailure
 		}
 
@@ -218,12 +218,12 @@ func (c Connection) Filelist(request *sftp.Request) (sftp.ListerAt, error) {
 			return nil, sftp.ErrSshFxPermissionDenied
 		}
 
-		logger.Debug(logSender, "requested stat for file: %#v user: %v", p, c.User.Username)
+		logger.Debug(logSender, c.ID, "requested stat for file: %#v user: %v", p, c.User.Username)
 		s, err := os.Stat(p)
 		if os.IsNotExist(err) {
 			return nil, sftp.ErrSshFxNoSuchFile
 		} else if err != nil {
-			logger.Error(logSender, "error running STAT on file: %#v", err)
+			logger.Error(logSender, c.ID, "error running STAT on file: %#v", err)
 			return nil, sftp.ErrSshFxFailure
 		}
 
@@ -253,7 +253,7 @@ func (c Connection) handleSFTPRename(sourcePath string, targetPath string) error
 		return sftp.ErrSshFxPermissionDenied
 	}
 	if err := os.Rename(sourcePath, targetPath); err != nil {
-		logger.Error(logSender, "failed to rename file, source: %#v target: %#v: %v", sourcePath, targetPath, err)
+		logger.Error(logSender, c.ID, "failed to rename file, source: %#v target: %#v: %v", sourcePath, targetPath, err)
 		return sftp.ErrSshFxFailure
 	}
 	logger.CommandLog(renameLogSender, sourcePath, targetPath, c.User.Username, c.ID, c.protocol)
@@ -268,11 +268,11 @@ func (c Connection) handleSFTPRmdir(path string) error {
 
 	numFiles, size, fileList, err := utils.ScanDirContents(path)
 	if err != nil {
-		logger.Error(logSender, "failed to remove directory %#v, scanning error: %v", path, err)
+		logger.Error(logSender, c.ID, "failed to remove directory %#v, scanning error: %v", path, err)
 		return sftp.ErrSshFxFailure
 	}
 	if err := os.RemoveAll(path); err != nil {
-		logger.Error(logSender, "failed to remove directory %#v: %v", path, err)
+		logger.Error(logSender, c.ID, "failed to remove directory %#v: %v", path, err)
 		return sftp.ErrSshFxFailure
 	}
 
@@ -289,7 +289,7 @@ func (c Connection) handleSFTPSymlink(sourcePath string, targetPath string) erro
 		return sftp.ErrSshFxPermissionDenied
 	}
 	if err := os.Symlink(sourcePath, targetPath); err != nil {
-		logger.Warn(logSender, "failed to create symlink %#v -> %#v: %v", sourcePath, targetPath, err)
+		logger.Warn(logSender, c.ID, "failed to create symlink %#v -> %#v: %v", sourcePath, targetPath, err)
 		return sftp.ErrSshFxFailure
 	}
 
@@ -303,7 +303,7 @@ func (c Connection) handleSFTPMkdir(path string) error {
 	}
 
 	if err := c.createMissingDirs(filepath.Join(path, "testfile")); err != nil {
-		logger.Error(logSender, "error making missing dir for path %#v: %v", path, err)
+		logger.Error(logSender, c.ID, "error making missing dir for path %#v: %v", path, err)
 		return sftp.ErrSshFxFailure
 	}
 	logger.CommandLog(mkdirLogSender, path, "", c.User.Username, c.ID, c.protocol)
@@ -319,12 +319,12 @@ func (c Connection) handleSFTPRemove(path string) error {
 	var fi os.FileInfo
 	var err error
 	if fi, err = os.Lstat(path); err != nil {
-		logger.Error(logSender, "failed to remove a file %#v: stat error: %v", path, err)
+		logger.Error(logSender, c.ID, "failed to remove a file %#v: stat error: %v", path, err)
 		return sftp.ErrSshFxFailure
 	}
 	size = fi.Size()
 	if err := os.Remove(path); err != nil {
-		logger.Error(logSender, "failed to remove a file/symlink %#v: %v", path, err)
+		logger.Error(logSender, c.ID, "failed to remove a file/symlink %#v: %v", path, err)
 		return sftp.ErrSshFxFailure
 	}
 
@@ -339,7 +339,7 @@ func (c Connection) handleSFTPRemove(path string) error {
 
 func (c Connection) handleSFTPUploadToNewFile(requestPath, filePath string) (io.WriterAt, error) {
 	if !c.hasSpace(true) {
-		logger.Info(logSender, "denying file write due to space limit")
+		logger.Info(logSender, c.ID, "denying file write due to space limit")
 		return nil, sftp.ErrSshFxFailure
 	}
 
@@ -351,13 +351,13 @@ func (c Connection) handleSFTPUploadToNewFile(requestPath, filePath string) (io.
 
 	err := c.createMissingDirs(requestPath)
 	if err != nil {
-		logger.Error(logSender, "error making missing dir for path %#v: %v", requestPath, err)
+		logger.Error(logSender, c.ID, "error making missing dir for path %#v: %v", requestPath, err)
 		return nil, sftp.ErrSshFxFailure
 	}
 
 	file, err := os.Create(filePath)
 	if err != nil {
-		logger.Error(logSender, "error creating file %#v: %v", requestPath, err)
+		logger.Error(logSender, c.ID, "error creating file %#v: %v", requestPath, err)
 		return nil, sftp.ErrSshFxFailure
 	}
 
@@ -384,7 +384,7 @@ func (c Connection) handleSFTPUploadToExistingFile(pflags sftp.FileOpenFlags, re
 	fileSize int64) (io.WriterAt, error) {
 	var err error
 	if !c.hasSpace(false) {
-		logger.Info(logSender, "denying file write due to space limit")
+		logger.Info(logSender, c.ID, "denying file write due to space limit")
 		return nil, sftp.ErrSshFxFailure
 	}
 
@@ -392,7 +392,7 @@ func (c Connection) handleSFTPUploadToExistingFile(pflags sftp.FileOpenFlags, re
 
 	if osFlags&os.O_TRUNC == 0 {
 		// see https://github.com/pkg/sftp/issues/295
-		logger.Info(logSender, "upload resume is not supported, returning error for file: %#v user: %v", requestPath,
+		logger.Info(logSender, c.ID, "upload resume is not supported, returning error for file: %#v user: %v", requestPath,
 			c.User.Username)
 		return nil, sftp.ErrSshFxOpUnsupported
 	}
@@ -400,7 +400,7 @@ func (c Connection) handleSFTPUploadToExistingFile(pflags sftp.FileOpenFlags, re
 	if uploadMode == uploadModeAtomic {
 		err = os.Rename(requestPath, filePath)
 		if err != nil {
-			logger.Error(logSender, "error renaming existing file for atomic upload, source: %#v, dest: %#v, err: %v",
+			logger.Error(logSender, c.ID, "error renaming existing file for atomic upload, source: %#v, dest: %#v, err: %v",
 				requestPath, filePath, err)
 			return nil, sftp.ErrSshFxFailure
 		}
@@ -408,7 +408,7 @@ func (c Connection) handleSFTPUploadToExistingFile(pflags sftp.FileOpenFlags, re
 	// we use 0666 so the umask is applied
 	file, err := os.OpenFile(filePath, osFlags, 0666)
 	if err != nil {
-		logger.Error(logSender, "error opening existing file, flags: %v, source: %#v, err: %v", pflags, filePath, err)
+		logger.Error(logSender, c.ID, "error opening existing file, flags: %v, source: %#v, err: %v", pflags, filePath, err)
 		return nil, sftp.ErrSshFxFailure
 	}
 
@@ -440,15 +440,15 @@ func (c Connection) hasSpace(checkFiles bool) bool {
 		numFile, size, err := dataprovider.GetUsedQuota(dataProvider, c.User.Username)
 		if err != nil {
 			if _, ok := err.(*dataprovider.MethodDisabledError); ok {
-				logger.Warn(logSender, "quota enforcement not possible for user %v: %v", c.User.Username, err)
+				logger.Warn(logSender, c.ID, "quota enforcement not possible for user %v: %v", c.User.Username, err)
 				return true
 			}
-			logger.Warn(logSender, "error getting used quota for %v: %v", c.User.Username, err)
+			logger.Warn(logSender, c.ID, "error getting used quota for %v: %v", c.User.Username, err)
 			return false
 		}
 		if (checkFiles && c.User.QuotaFiles > 0 && numFile >= c.User.QuotaFiles) ||
 			(c.User.QuotaSize > 0 && size >= c.User.QuotaSize) {
-			logger.Debug(logSender, "quota exceed for user %v, num files: %v/%v, size: %v/%v check files: %v",
+			logger.Debug(logSender, c.ID, "quota exceed for user %v, num files: %v/%v, size: %v/%v check files: %v",
 				c.User.Username, numFile, c.User.QuotaFiles, size, c.User.QuotaSize, checkFiles)
 			return false
 		}
@@ -469,14 +469,14 @@ func (c Connection) buildPath(rawPath string) (string, error) {
 		// path chain until we hit a directory that _does_ exist and can be validated.
 		_, err = c.findFirstExistingDir(r)
 		if err != nil {
-			logger.Warn(logSender, "error resolving not existent path: %#v", err)
+			logger.Warn(logSender, c.ID, "error resolving not existent path: %#v", err)
 		}
 		return r, err
 	}
 
 	err = c.isSubDir(p)
 	if err != nil {
-		logger.Warn(logSender, "Invalid path resolution, dir: %#v outside user home: %#v err: %v", p, c.User.HomeDir, err)
+		logger.Warn(logSender, c.ID, "Invalid path resolution, dir: %#v outside user home: %#v err: %v", p, c.User.HomeDir, err)
 	}
 	return r, err
 }
@@ -503,7 +503,7 @@ func (c Connection) findNonexistentDirs(path string) ([]string, error) {
 	}
 	err = c.isSubDir(p)
 	if err != nil {
-		logger.Warn(logSender, "Error finding non existing dir: %v", err)
+		logger.Warn(logSender, c.ID, "Error finding non existing dir: %v", err)
 	}
 	return results, err
 }
@@ -512,7 +512,7 @@ func (c Connection) findNonexistentDirs(path string) ([]string, error) {
 func (c Connection) findFirstExistingDir(path string) (string, error) {
 	results, err := c.findNonexistentDirs(path)
 	if err != nil {
-		logger.Warn(logSender, "unable to find non existent dirs: %v", err)
+		logger.Warn(logSender, c.ID, "unable to find non existent dirs: %v", err)
 		return "", err
 	}
 	var parent string
@@ -543,11 +543,11 @@ func (c Connection) isSubDir(sub string) error {
 	// home dir must exist and it is already a validated absolute path
 	parent, err := filepath.EvalSymlinks(c.User.HomeDir)
 	if err != nil {
-		logger.Warn(logSender, "invalid home dir %#v: %v", c.User.HomeDir, err)
+		logger.Warn(logSender, c.ID, "invalid home dir %#v: %v", c.User.HomeDir, err)
 		return err
 	}
 	if !strings.HasPrefix(sub, parent) {
-		logger.Warn(logSender, "dir %#v is not inside: %#v ", sub, parent)
+		logger.Warn(logSender, c.ID, "dir %#v is not inside: %#v ", sub, parent)
 		return fmt.Errorf("dir %#v is not inside: %#v", sub, parent)
 	}
 	return nil
@@ -562,7 +562,7 @@ func (c Connection) createMissingDirs(filePath string) error {
 	for i := range dirsToCreate {
 		d := dirsToCreate[last-i]
 		if err := os.Mkdir(d, 0777); err != nil {
-			logger.Error(logSender, "error creating missing dir: %#v", d)
+			logger.Error(logSender, c.ID, "error creating missing dir: %#v", d)
 			return err
 		}
 		utils.SetPathPermissions(d, c.User.GetUID(), c.User.GetGID())

sftpd/scp.go

@@ -44,7 +44,7 @@ func (c *scpCommand) handle() error {
 	defer removeConnection(c.connection.ID)
 	destPath := c.getDestPath()
 	commandType := c.getCommandType()
-	logger.Debug(logSenderSCP, "handle scp command, args: %v user: %v command type: %v, dest path: %v",
+	logger.Debug(logSenderSCP, c.connection.ID, "handle scp command, args: %v user: %v command type: %v, dest path: %#v",
 		c.args, c.connection.User.Username, commandType, destPath)
 	if commandType == "-t" {
 		// -t means "to", so upload
@@ -85,7 +85,7 @@ func (c *scpCommand) handleRecursiveUpload() error {
 		}
 		if strings.HasPrefix(command, "E") {
 			numDirs--
-			logger.Debug(logSenderSCP, "received end dir command, num dirs: %v", numDirs)
+			logger.Debug(logSenderSCP, c.connection.ID, "received end dir command, num dirs: %v", numDirs)
 			if numDirs == 0 {
 				// upload is now complete send confirmation message
 				err = c.sendConfirmationMessage()
@@ -108,7 +108,7 @@ func (c *scpCommand) handleRecursiveUpload() error {
 				if err != nil {
 					return err
 				}
-				logger.Debug(logSenderSCP, "received start dir command, num dirs: %v destPath: %v", numDirs, destPath)
+				logger.Debug(logSenderSCP, c.connection.ID, "received start dir command, num dirs: %v destPath: %v", numDirs, destPath)
 			} else if strings.HasPrefix(command, "C") {
 				err = c.handleUpload(c.getFileUploadDestPath(destPath, name), sizeToRead)
 				if err != nil {
@@ -127,14 +127,14 @@ func (c *scpCommand) handleCreateDir(dirPath string) error {
 	updateConnectionActivity(c.connection.ID)
 	if !c.connection.User.HasPerm(dataprovider.PermCreateDirs) {
 		err := fmt.Errorf("Permission denied")
-		logger.Warn(logSenderSCP, "error creating dir: %v, permission denied", dirPath)
+		logger.Warn(logSenderSCP, c.connection.ID, "error creating dir: %v, permission denied", dirPath)
 		c.sendErrorMessage(err.Error())
 		return err
 	}
 
 	p, err := c.connection.buildPath(dirPath)
 	if err != nil {
-		logger.Warn(logSenderSCP, "error creating dir: %v, invalid file path, err: %v", dirPath, err)
+		logger.Warn(logSenderSCP, c.connection.ID, "error creating dir: %v, invalid file path, err: %v", dirPath, err)
 		c.sendErrorMessage(err.Error())
 		return err
 	}
@@ -191,7 +191,7 @@ func (c *scpCommand) getUploadFileData(sizeToRead int64, transfer *Transfer) err
 func (c *scpCommand) handleUploadFile(requestPath, filePath string, sizeToRead int64, isNewFile bool) error {
 	if !c.connection.hasSpace(true) {
 		err := fmt.Errorf("denying file write due to space limit")
-		logger.Warn(logSenderSCP, "error uploading file: %v, err: %v", filePath, err)
+		logger.Warn(logSenderSCP, c.connection.ID, "error uploading file: %v, err: %v", filePath, err)
 		c.sendErrorMessage(err.Error())
 		return err
 	}
@@ -199,7 +199,7 @@ func (c *scpCommand) handleUploadFile(requestPath, filePath string, sizeToRead i
 	if _, err := os.Stat(filepath.Dir(requestPath)); os.IsNotExist(err) {
 		if !c.connection.User.HasPerm(dataprovider.PermCreateDirs) {
 			err := fmt.Errorf("Permission denied")
-			logger.Warn(logSenderSCP, "error uploading file: %v, permission denied", requestPath)
+			logger.Warn(logSenderSCP, c.connection.ID, "error uploading file: %v, permission denied", requestPath)
 			c.sendErrorMessage(err.Error())
 			return err
 		}
@@ -238,14 +238,14 @@ func (c *scpCommand) handleUpload(uploadFilePath string, sizeToRead int64) error
 	updateConnectionActivity(c.connection.ID)
 	if !c.connection.User.HasPerm(dataprovider.PermUpload) {
 		err := fmt.Errorf("Permission denied")
-		logger.Warn(logSenderSCP, "error uploading file: %v, permission denied", uploadFilePath)
+		logger.Warn(logSenderSCP, c.connection.ID, "error uploading file: %v, permission denied", uploadFilePath)
 		c.sendErrorMessage(err.Error())
 		return err
 	}
 
 	p, err := c.connection.buildPath(uploadFilePath)
 	if err != nil {
-		logger.Warn(logSenderSCP, "error uploading file: %v, err: %v", uploadFilePath, err)
+		logger.Warn(logSenderSCP, c.connection.ID, "error uploading file: %v, err: %v", uploadFilePath, err)
 		c.sendErrorMessage(err.Error())
 		return err
 	}
@@ -265,7 +265,7 @@ func (c *scpCommand) handleUpload(uploadFilePath string, sizeToRead int64) error
 	}
 
 	if stat.IsDir() {
-		logger.Warn(logSenderSCP, "attempted to open a directory for writing to: %v", p)
+		logger.Warn(logSenderSCP, c.connection.ID, "attempted to open a directory for writing to: %v", p)
 		err = fmt.Errorf("Attempted to open a directory for writing: %v", p)
 		c.sendErrorMessage(err.Error())
 		return err
@@ -315,7 +315,7 @@ func (c *scpCommand) sendDownloadProtocolMessages(dirPath string, stat os.FileIn
 func (c *scpCommand) handleRecursiveDownload(dirPath string, stat os.FileInfo) error {
 	var err error
 	if c.isRecursive() {
-		logger.Debug(logSenderSCP, "recursive download, dir path: %v", dirPath)
+		logger.Debug(logSenderSCP, c.connection.ID, "recursive download, dir path: %v", dirPath)
 		err = c.sendDownloadProtocolMessages(dirPath, stat)
 		if err != nil {
 			return err
@@ -425,21 +425,21 @@ func (c *scpCommand) handleDownload(filePath string) error {
 
 	if !c.connection.User.HasPerm(dataprovider.PermDownload) {
 		err := fmt.Errorf("Permission denied")
-		logger.Warn(logSenderSCP, "error downloading file: %v, permission denied", filePath)
+		logger.Warn(logSenderSCP, c.connection.ID, "error downloading file: %v, permission denied", filePath)
 		c.sendErrorMessage(err.Error())
 		return err
 	}
 	p, err := c.connection.buildPath(filePath)
 	if err != nil {
 		err := fmt.Errorf("Invalid file path")
-		logger.Warn(logSenderSCP, "error downloading file: %v, invalid file path", filePath)
+		logger.Warn(logSenderSCP, c.connection.ID, "error downloading file: %v, invalid file path", filePath)
 		c.sendErrorMessage(err.Error())
 		return err
 	}
 
 	var stat os.FileInfo
 	if stat, err = os.Stat(p); os.IsNotExist(err) {
-		logger.Warn(logSenderSCP, "error downloading file: %v, err: %v", p, err)
+		logger.Warn(logSenderSCP, c.connection.ID, "error downloading file: %v, err: %v", p, err)
 		c.sendErrorMessage(err.Error())
 		return err
 	}
@@ -579,7 +579,7 @@ func (c *scpCommand) sendConfirmationMessage() error {
 func (c *scpCommand) sendProtocolMessage(message string) error {
 	_, err := c.channel.Write([]byte(message))
 	if err != nil {
-		logger.Warn(logSenderSCP, "error sending protocol message: %v, err: %v", message, err)
+		logger.Warn(logSenderSCP, c.connection.ID, "error sending protocol message: %v, err: %v", message, err)
 		c.channel.Close()
 	}
 	return err
@@ -594,7 +594,7 @@ func (c *scpCommand) sendExitStatus(err error) {
 	ex := exitStatusMsg{
 		Status: status,
 	}
-	logger.Debug(logSenderSCP, "send exit status for command with args: %v user: %v err: %v",
+	logger.Debug(logSenderSCP, c.connection.ID, "send exit status for command with args: %v user: %v err: %v",
 		c.args, c.connection.User.Username, err)
 	c.channel.SendRequest("exit-status", false, ssh.Marshal(&ex))
 	c.channel.Close()
@@ -645,7 +645,7 @@ func (c *scpCommand) parseUploadMessage(command string) (int64, string, error) {
 	if !strings.HasPrefix(command, "C") && !strings.HasPrefix(command, "D") {
 		err = fmt.Errorf("unknown or invalid upload message: %v args: %v user: %v",
 			command, c.args, c.connection.User.Username)
-		logger.Warn(logSenderSCP, "error: %v", err)
+		logger.Warn(logSenderSCP, c.connection.ID, "error: %v", err)
 		c.sendErrorMessage(err.Error())
 		return size, name, err
 	}
@@ -653,20 +653,20 @@ func (c *scpCommand) parseUploadMessage(command string) (int64, string, error) {
 	if len(parts) == 3 {
 		size, err = strconv.ParseInt(parts[1], 10, 64)
 		if err != nil {
-			logger.Warn(logSenderSCP, "error getting size from upload message: %v", err)
+			logger.Warn(logSenderSCP, c.connection.ID, "error getting size from upload message: %v", err)
 			c.sendErrorMessage(fmt.Sprintf("Error getting size: %v", err))
 			return size, name, err
 		}
 		name = parts[2]
 		if len(name) == 0 {
 			err = fmt.Errorf("error getting name from upload message, cannot be empty")
-			logger.Warn(logSenderSCP, "error: %v", err)
+			logger.Warn(logSenderSCP, c.connection.ID, "error: %v", err)
 			c.sendErrorMessage(err.Error())
 			return size, name, err
 		}
 	} else {
 		err = fmt.Errorf("Error splitting upload message: %v", command)
-		logger.Warn(logSenderSCP, "error: %v", err)
+		logger.Warn(logSenderSCP, c.connection.ID, "error: %v", err)
 		c.sendErrorMessage(err.Error())
 		return size, name, err
 	}

sftpd/server.go

@@ -87,7 +87,7 @@ func (c Configuration) Initialize(configDir string) error {
 	if err == nil {
 		utils.SetUmask(int(umask), c.Umask)
 	} else {
-		logger.Warn(logSender, "error reading umask, please fix your config file: %v", err)
+		logger.Warn(logSender, "", "error reading umask, please fix your config file: %v", err)
 		logger.WarnToConsole("error reading umask, please fix your config file: %v", err)
 	}
 	serverConfig := &ssh.ServerConfig{
@@ -122,7 +122,7 @@ func (c Configuration) Initialize(configDir string) error {
 		if !filepath.IsAbs(privateFile) {
 			privateFile = filepath.Join(configDir, privateFile)
 		}
-		logger.Info(logSender, "Loading private key: %s", privateFile)
+		logger.Info(logSender, "", "Loading private key: %s", privateFile)
 
 		privateBytes, err := ioutil.ReadFile(privateFile)
 		if err != nil {
@@ -143,13 +143,13 @@ func (c Configuration) Initialize(configDir string) error {
 
 	listener, err := net.Listen("tcp", fmt.Sprintf("%s:%d", c.BindAddress, c.BindPort))
 	if err != nil {
-		logger.Warn(logSender, "error starting listener on address %s:%d: %v", c.BindAddress, c.BindPort, err)
+		logger.Warn(logSender, "", "error starting listener on address %s:%d: %v", c.BindAddress, c.BindPort, err)
 		return err
 	}
 
 	actions = c.Actions
 	uploadMode = c.UploadMode
-	logger.Info(logSender, "server listener registered address: %v", listener.Addr().String())
+	logger.Info(logSender, "", "server listener registered address: %v", listener.Addr().String())
 	if c.IdleTimeout > 0 {
 		startIdleTimer(time.Duration(c.IdleTimeout) * time.Minute)
 	}
@@ -189,7 +189,7 @@ func (c Configuration) configureLoginBanner(serverConfig *ssh.ServerConfig, conf
 			}
 		} else {
 			logger.WarnToConsole("unable to read login banner file: %v", err)
-			logger.Warn(logSender, "unable to read login banner file: %v", err)
+			logger.Warn(logSender, "", "unable to read login banner file: %v", err)
 		}
 	}
 	return err
@@ -202,19 +202,19 @@ func (c Configuration) AcceptInboundConnection(conn net.Conn, config *ssh.Server
 	// Before beginning a handshake must be performed on the incoming net.Conn
 	sconn, chans, reqs, err := ssh.NewServerConn(conn, config)
 	if err != nil {
-		logger.Warn(logSender, "failed to accept an incoming connection: %v", err)
+		logger.Warn(logSender, "", "failed to accept an incoming connection: %v", err)
 		return
 	}
 	defer sconn.Close()
 
-	logger.Debug(logSender, "accepted inbound connection, ip: %v", conn.RemoteAddr().String())
+	logger.Debug(logSender, "", "accepted inbound connection, ip: %v", conn.RemoteAddr().String())
 
 	var user dataprovider.User
 
 	err = json.Unmarshal([]byte(sconn.Permissions.Extensions["user"]), &user)
 
 	if err != nil {
-		logger.Warn(logSender, "Unable to deserialize user info, cannot serve connection: %v", err)
+		logger.Warn(logSender, "", "Unable to deserialize user info, cannot serve connection: %v", err)
 		return
 	}
 
@@ -237,14 +237,14 @@ func (c Configuration) AcceptInboundConnection(conn net.Conn, config *ssh.Server
 		// If its not a session channel we just move on because its not something we
 		// know how to handle at this point.
 		if newChannel.ChannelType() != "session" {
-			logger.Debug(logSender, "received an unknown channel type: %v", newChannel.ChannelType())
+			logger.Debug(logSender, connectionID, "received an unknown channel type: %v", newChannel.ChannelType())
 			newChannel.Reject(ssh.UnknownChannelType, "unknown channel type")
 			continue
 		}
 
 		channel, requests, err := newChannel.Accept()
 		if err != nil {
-			logger.Warn(logSender, "could not accept a channel: %v", err)
+			logger.Warn(logSender, connectionID, "could not accept a channel: %v", err)
 			continue
 		}
 
@@ -266,7 +266,7 @@ func (c Configuration) AcceptInboundConnection(conn net.Conn, config *ssh.Server
 						var msg execMsg
 						if err := ssh.Unmarshal(req.Payload, &msg); err == nil {
 							name, scpArgs, err := parseCommandPayload(msg.Command)
-							logger.Debug(logSender, "new exec command: %v args: %v user: %v, error: %v", name, scpArgs,
+							logger.Debug(logSender, connectionID, "new exec command: %v args: %v user: %v, error: %v", name, scpArgs,
 								connection.User.Username, err)
 							if err == nil && name == "scp" && len(scpArgs) >= 2 {
 								ok = true
@@ -296,10 +296,10 @@ func (c Configuration) handleSftpConnection(channel io.ReadWriteCloser, connecti
 	server := sftp.NewRequestServer(channel, handler)
 
 	if err := server.Serve(); err == io.EOF {
-		logger.Debug(logSender, "connection closed, id: %v", connection.ID)
+		logger.Debug(logSender, connection.ID, "connection closed, id: %v", connection.ID)
 		server.Close()
 	} else if err != nil {
-		logger.Error(logSender, "sftp connection closed with error id %v: %v", connection.ID, err)
+		logger.Error(logSender, connection.ID, "sftp connection closed with error id %v: %v", connection.ID, err)
 	}
 
 	removeConnection(connection.ID)
@@ -317,12 +317,12 @@ func (c Configuration) createHandler(connection Connection) sftp.Handlers {
 
 func loginUser(user dataprovider.User) (*ssh.Permissions, error) {
 	if !filepath.IsAbs(user.HomeDir) {
-		logger.Warn(logSender, "user %v has invalid home dir: %v. Home dir must be an absolute path, login not allowed",
+		logger.Warn(logSender, "", "user %v has invalid home dir: %v. Home dir must be an absolute path, login not allowed",
 			user.Username, user.HomeDir)
 		return nil, fmt.Errorf("Cannot login user with invalid home dir: %v", user.HomeDir)
 	}
 	if _, err := os.Stat(user.HomeDir); os.IsNotExist(err) {
-		logger.Debug(logSender, "home directory \"%v\" for user %v does not exist, try to create", user.HomeDir, user.Username)
+		logger.Debug(logSender, "", "home directory \"%v\" for user %v does not exist, try to create", user.HomeDir, user.Username)
 		err := os.MkdirAll(user.HomeDir, 0777)
 		if err == nil {
 			utils.SetPathPermissions(user.HomeDir, user.GetUID(), user.GetGID())
@@ -332,7 +332,7 @@ func loginUser(user dataprovider.User) (*ssh.Permissions, error) {
 	if user.MaxSessions > 0 {
 		activeSessions := getActiveSessions(user.Username)
 		if activeSessions >= user.MaxSessions {
-			logger.Debug(logSender, "authentication refused for user: %v, too many open sessions: %v/%v", user.Username,
+			logger.Debug(logSender, "", "authentication refused for user: %v, too many open sessions: %v/%v", user.Username,
 				activeSessions, user.MaxSessions)
 			return nil, fmt.Errorf("Too many open sessions: %v", activeSessions)
 		}
@@ -340,7 +340,7 @@ func loginUser(user dataprovider.User) (*ssh.Permissions, error) {
 
 	json, err := json.Marshal(user)
 	if err != nil {
-		logger.Warn(logSender, "error serializing user info: %v, authentication rejected", err)
+		logger.Warn(logSender, "", "error serializing user info: %v, authentication rejected", err)
 		return nil, err
 	}
 	p := &ssh.Permissions{}
@@ -355,8 +355,8 @@ func (c *Configuration) checkHostKeys(configDir string) error {
 	if len(c.Keys) == 0 {
 		autoFile := filepath.Join(configDir, defaultPrivateKeyName)
 		if _, err = os.Stat(autoFile); os.IsNotExist(err) {
-			logger.Info(logSender, "No host keys configured and %s does not exist; creating new private key for server", autoFile)
-			logger.InfoToConsole("No host keys configured and %s does not exist; creating new private key for server", autoFile)
+			logger.Info(logSender, "", "No host keys configured and %#v does not exist; creating new private key for server", autoFile)
+			logger.InfoToConsole("No host keys configured and %#v does not exist; creating new private key for server", autoFile)
 			err = c.generatePrivateKey(autoFile)
 		}
 

sftpd/sftpd.go

@@ -159,7 +159,7 @@ func RemoveQuotaScan(username string) error {
 		activeQuotaScans[indexToRemove] = activeQuotaScans[len(activeQuotaScans)-1]
 		activeQuotaScans = activeQuotaScans[:len(activeQuotaScans)-1]
 	} else {
-		logger.Warn(logSender, "quota scan to remove not found for user: %v", username)
+		logger.Warn(logSender, "", "quota scan to remove not found for user: %v", username)
 		err = fmt.Errorf("quota scan to remove not found for user: %v", username)
 	}
 	return err
@@ -173,7 +173,7 @@ func CloseActiveConnection(connectionID string) bool {
 	defer mutex.RUnlock()
 	for _, c := range openConnections {
 		if c.ID == connectionID {
-			logger.Debug(logSender, "closing connection with id: %v", connectionID)
+			logger.Debug(logSender, "", "closing connection with id: %v", connectionID)
 			c.sshConn.Close()
 			result = true
 			break
@@ -231,7 +231,7 @@ func startIdleTimer(maxIdleTime time.Duration) {
 	idleTimeout = maxIdleTime
 	go func() {
 		for t := range idleConnectionTicker.C {
-			logger.Debug(logSender, "idle connections check ticker %v", t)
+			logger.Debug(logSender, "", "idle connections check ticker %v", t)
 			CheckIdleConnections()
 		}
 	}()
@@ -247,33 +247,33 @@ func CheckIdleConnections() {
 			if t.connectionID == c.ID {
 				transferIdleTime := time.Since(t.lastActivity)
 				if transferIdleTime < idleTime {
-					logger.Debug(logSender, "idle time: %v setted to transfer idle time: %v connection id: %v",
+					logger.Debug(logSender, "", "idle time: %v setted to transfer idle time: %v connection id: %v",
 						idleTime, transferIdleTime, c.ID)
 					idleTime = transferIdleTime
 				}
 			}
 		}
 		if idleTime > idleTimeout {
-			logger.Debug(logSender, "close idle connection id: %v idle time: %v", c.ID, idleTime)
+			logger.Debug(logSender, "", "close idle connection id: %v idle time: %v", c.ID, idleTime)
 			err := c.sshConn.Close()
-			logger.Debug(logSender, "idle connection closed id: %v, err: %v", c.ID, err)
+			logger.Debug(logSender, "", "idle connection closed id: %v, err: %v", c.ID, err)
 		}
 	}
-	logger.Debug(logSender, "check idle connections ended")
+	logger.Debug(logSender, "", "check idle connections ended")
 }
 
 func addConnection(id string, conn Connection) {
 	mutex.Lock()
 	defer mutex.Unlock()
 	openConnections[id] = conn
-	logger.Debug(logSender, "connection added, num open connections: %v", len(openConnections))
+	logger.Debug(logSender, id, "connection added, num open connections: %v", len(openConnections))
 }
 
 func removeConnection(id string) {
 	mutex.Lock()
 	defer mutex.Unlock()
 	delete(openConnections, id)
-	logger.Debug(logSender, "connection removed, num open connections: %v", len(openConnections))
+	logger.Debug(logSender, id, "connection removed, num open connections: %v", len(openConnections))
 }
 
 func addTransfer(transfer *Transfer) {
@@ -297,7 +297,7 @@ func removeTransfer(transfer *Transfer) error {
 		activeTransfers[indexToRemove] = activeTransfers[len(activeTransfers)-1]
 		activeTransfers = activeTransfers[:len(activeTransfers)-1]
 	} else {
-		logger.Warn(logSender, "transfer to remove not found!")
+		logger.Warn(logSender, "", "transfer to remove not found!")
 		err = fmt.Errorf("transfer to remove not found")
 	}
 	return err
@@ -321,13 +321,13 @@ func executeAction(operation string, username string, path string, target string
 		if _, err = os.Stat(actions.Command); err == nil {
 			command := exec.Command(actions.Command, operation, username, path, target)
 			err = command.Start()
-			logger.Debug(logSender, "start command \"%v\" with arguments: %v, %v, %v, %v, error: %v",
+			logger.Debug(logSender, "", "start command \"%v\" with arguments: %v, %v, %v, %v, error: %v",
 				actions.Command, operation, username, path, target, err)
 			if err == nil {
 				go command.Wait()
 			}
 		} else {
-			logger.Warn(logSender, "Invalid action command \"%v\" : %v", actions.Command, err)
+			logger.Warn(logSender, "", "Invalid action command \"%v\" : %v", actions.Command, err)
 		}
 	}
 	if len(actions.HTTPNotificationURL) > 0 {
@@ -353,11 +353,11 @@ func executeAction(operation string, username string, path string, target string
 					respCode = resp.StatusCode
 					resp.Body.Close()
 				}
-				logger.Debug(logSender, "notified action to URL: %v status code: %v, elapsed: %v err: %v",
+				logger.Debug(logSender, "", "notified action to URL: %v status code: %v, elapsed: %v err: %v",
 					url.String(), respCode, time.Since(startTime), err)
 			}()
 		} else {
-			logger.Warn(logSender, "Invalid http_notification_url \"%v\" : %v", actions.HTTPNotificationURL, err)
+			logger.Warn(logSender, "", "Invalid http_notification_url \"%v\" : %v", actions.HTTPNotificationURL, err)
 		}
 	}
 	return err

sftpd/sftpd_test.go

@@ -97,7 +97,7 @@ func TestMain(m *testing.M) {
 
 	err := dataprovider.Initialize(providerConf, configDir)
 	if err != nil {
-		logger.Warn(logSender, "error initializing data provider: %v", err)
+		logger.Warn(logSender, "", "error initializing data provider: %v", err)
 		os.Exit(1)
 	}
 	dataProvider := dataprovider.GetProvider()
@@ -141,20 +141,20 @@ func TestMain(m *testing.M) {
 
 	scpPath, err = exec.LookPath("scp")
 	if err != nil {
-		logger.Warn(logSender, "unable to get scp command. SCP tests will be skipped, err: %v", err)
+		logger.Warn(logSender, "", "unable to get scp command. SCP tests will be skipped, err: %v", err)
 		logger.WarnToConsole("unable to get scp command. SCP tests will be skipped, err: %v", err)
 		scpPath = ""
 	}
 
 	go func() {
-		logger.Debug(logSender, "initializing SFTP server with config %+v", sftpdConf)
+		logger.Debug(logSender, "", "initializing SFTP server with config %+v", sftpdConf)
 		if err := sftpdConf.Initialize(configDir); err != nil {
-			logger.Error(logSender, "could not start SFTP server: %v", err)
+			logger.Error(logSender, "", "could not start SFTP server: %v", err)
 		}
 	}()
 
 	go func() {
-		logger.Debug(logSender, "initializing HTTP server with config %+v", httpdConf)
+		logger.Debug(logSender, "", "initializing HTTP server with config %+v", httpdConf)
 		s := &http.Server{
 			Addr:           fmt.Sprintf("%s:%d", httpdConf.BindAddress, httpdConf.BindPort),
 			Handler:        router,
@@ -163,7 +163,7 @@ func TestMain(m *testing.M) {
 			MaxHeaderBytes: 1 << 20, // 1MB
 		}
 		if err := s.ListenAndServe(); err != nil {
-			logger.Error(logSender, "could not start HTTP server: %v", err)
+			logger.Error(logSender, "", "could not start HTTP server: %v", err)
 		}
 	}()
 

sftpd/transfer.go

@@ -60,7 +60,7 @@ func (t *Transfer) Close() error {
 	err := t.file.Close()
 	if t.transferType == transferUpload && t.file.Name() != t.path {
 		err = os.Rename(t.file.Name(), t.path)
-		logger.Debug(logSender, "atomic upload completed, rename: \"%v\" -> \"%v\", error: %v",
+		logger.Debug(logSender, t.connectionID, "atomic upload completed, rename: \"%v\" -> \"%v\", error: %v",
 			t.file.Name(), t.path, err)
 	}
 	elapsed := time.Since(t.start).Nanoseconds() / 1000000

utils/umask_unix.go

@@ -10,6 +10,6 @@ import (
 
 // SetUmask sets umask on unix systems
 func SetUmask(umask int, configValue string) {
-	logger.Debug(logSender, "set umask to %v (%v)", configValue, umask)
+	logger.Debug(logSender, "", "set umask to %v (%v)", configValue, umask)
 	syscall.Umask(umask)
 }

utils/umask_windows.go

@@ -4,5 +4,5 @@ import "github.com/drakkan/sftpgo/logger"
 
 // SetUmask does nothing on windows
 func SetUmask(umask int, configValue string) {
-	logger.Debug(logSender, "umask not available on windows, configured value %v (%v)", configValue, umask)
+	logger.Debug(logSender, "", "umask not available on windows, configured value %v (%v)", configValue, umask)
 }

utils/utils.go

@@ -77,7 +77,7 @@ func isDirectory(path string) (bool, error) {
 func SetPathPermissions(path string, uid int, gid int) {
 	if runtime.GOOS != "windows" {
 		if err := os.Chown(path, uid, gid); err != nil {
-			logger.Warn(logSender, "error chowning path %v: %v", path, err)
+			logger.Warn(logSender, "", "error chowning path %v: %v", path, err)
 		}
 	}
 }