From 0737c672f5115decd5501bbd871b3500d74e80b7 Mon Sep 17 00:00:00 2001 From: Jo Vandeginste Date: Thu, 5 Sep 2019 16:21:35 +0200 Subject: [PATCH] Add connectionID to as many entries as possible Signed-off-by: Jo Vandeginste --- api/api_test.go | 6 ++-- api/quota.go | 4 +-- cmd/serve.go | 14 ++++---- config/config.go | 8 ++--- dataprovider/bolt.go | 14 ++++---- dataprovider/dataprovider.go | 8 ++--- dataprovider/mysql.go | 8 ++--- dataprovider/pgsql.go | 8 ++--- dataprovider/sqlcommon.go | 28 +++++++-------- dataprovider/sqlite.go | 6 ++-- logger/logger.go | 16 ++++----- sftpd/handler.go | 66 ++++++++++++++++++------------------ sftpd/scp.go | 40 +++++++++++----------- sftpd/server.go | 38 ++++++++++----------- sftpd/sftpd.go | 28 +++++++-------- sftpd/sftpd_test.go | 12 +++---- sftpd/transfer.go | 2 +- utils/umask_unix.go | 2 +- utils/umask_windows.go | 2 +- utils/utils.go | 2 +- 20 files changed, 156 insertions(+), 156 deletions(-) diff --git a/api/api_test.go b/api/api_test.go index b26138b0..1a760a45 100644 --- a/api/api_test.go +++ b/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) } }() diff --git a/api/quota.go b/api/quota.go index c930f643..a8570d63 100644 --- a/api/quota.go +++ b/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) }() diff --git a/cmd/serve.go b/cmd/serve.go index b6fb69f5..e103bf64 100644 --- a/cmd/serve.go +++ b/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") } diff --git a/config/config.go b/config/config.go index 6ac49acf..1deea29f 100644 --- a/config/config.go +++ b/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 } diff --git a/dataprovider/bolt.go b/dataprovider/bolt.go index b2ba61be..6c44f772 100644 --- a/dataprovider/bolt.go +++ b/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 diff --git a/dataprovider/dataprovider.go b/dataprovider/dataprovider.go index 17f9695d..6d62369c 100644 --- a/dataprovider/dataprovider.go +++ b/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 { diff --git a/dataprovider/mysql.go b/dataprovider/mysql.go index 92ba0992..4aa1c84b 100644 --- a/dataprovider/mysql.go +++ b/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 } diff --git a/dataprovider/pgsql.go b/dataprovider/pgsql.go index 20a01125..02face93 100644 --- a/dataprovider/pgsql.go +++ b/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 } diff --git a/dataprovider/sqlcommon.go b/dataprovider/sqlcommon.go index 51f7e19b..c9b836a3 100644 --- a/dataprovider/sqlcommon.go +++ b/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() diff --git a/dataprovider/sqlite.go b/dataprovider/sqlite.go index b032b59d..2649a3e3 100644 --- a/dataprovider/sqlite.go +++ b/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 } diff --git a/logger/logger.go b/logger/logger.go index 9ad4222c..f642f1d5 100644 --- a/logger/logger.go +++ b/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 diff --git a/sftpd/handler.go b/sftpd/handler.go index bf89ecfa..5ce02356 100644 --- a/sftpd/handler.go +++ b/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()) diff --git a/sftpd/scp.go b/sftpd/scp.go index 4d3540ec..c2378489 100644 --- a/sftpd/scp.go +++ b/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 } diff --git a/sftpd/server.go b/sftpd/server.go index a0166642..bc7b4460 100644 --- a/sftpd/server.go +++ b/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) } diff --git a/sftpd/sftpd.go b/sftpd/sftpd.go index 5b39a814..7dbcdf83 100644 --- a/sftpd/sftpd.go +++ b/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 diff --git a/sftpd/sftpd_test.go b/sftpd/sftpd_test.go index 57d3d763..e0cac1b4 100644 --- a/sftpd/sftpd_test.go +++ b/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) } }() diff --git a/sftpd/transfer.go b/sftpd/transfer.go index 5b333a3d..f10bef40 100644 --- a/sftpd/transfer.go +++ b/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 diff --git a/utils/umask_unix.go b/utils/umask_unix.go index 006984d7..04e8bc36 100644 --- a/utils/umask_unix.go +++ b/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) } diff --git a/utils/umask_windows.go b/utils/umask_windows.go index 5ac774fc..beb365d7 100644 --- a/utils/umask_windows.go +++ b/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) } diff --git a/utils/utils.go b/utils/utils.go index a2a5b82d..92ed9002 100644 --- a/utils/utils.go +++ b/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) } } }