From 4f1c2c094f6c066d81c07700533852d501a0459c Mon Sep 17 00:00:00 2001 From: Nicola Murino Date: Fri, 6 Sep 2019 15:19:01 +0200 Subject: [PATCH] improve logging this partially revert #45 --- dataprovider/bolt.go | 25 ++++-------- dataprovider/dataprovider.go | 21 ++++------ dataprovider/mysql.go | 20 ++++----- dataprovider/pgsql.go | 20 ++++----- dataprovider/sqlcommon.go | 41 +++++++------------ dataprovider/sqlite.go | 19 ++++----- logger/logger.go | 26 ++++++++++++ sftpd/handler.go | 79 ++++++++++++++++-------------------- sftpd/scp.go | 55 +++++++++++++------------ sftpd/server.go | 13 +++--- sftpd/sftpd.go | 17 +++----- 11 files changed, 155 insertions(+), 181 deletions(-) diff --git a/dataprovider/bolt.go b/dataprovider/bolt.go index f745ae4c..fc0cf0c5 100644 --- a/dataprovider/bolt.go +++ b/dataprovider/bolt.go @@ -8,6 +8,7 @@ import ( "path/filepath" "time" + "github.com/drakkan/sftpgo/logger" "github.com/drakkan/sftpgo/utils" bolt "go.etcd.io/bbolt" ) @@ -24,7 +25,7 @@ type BoltProvider struct { func initializeBoltProvider(basePath string) error { var err error - provider = BoltProvider{} + logSender = BoltDataProviderName dbPath := config.Name if !filepath.IsAbs(dbPath) { dbPath = filepath.Join(basePath, dbPath) @@ -34,13 +35,13 @@ func initializeBoltProvider(basePath string) error { FreelistType: bolt.FreelistArrayType, Timeout: 5 * time.Second}) if err == nil { - provider.log(Debug, "bolt key store handle created") + providerLog(logger.LevelDebug, "bolt key store handle created") err = dbHandle.Update(func(tx *bolt.Tx) error { _, e := tx.CreateBucketIfNotExists(usersBucket) return e }) if err != nil { - provider.log(Warn, "error creating users bucket: %v", err) + providerLog(logger.LevelWarn, "error creating users bucket: %v", err) return err } err = dbHandle.Update(func(tx *bolt.Tx) error { @@ -48,12 +49,12 @@ func initializeBoltProvider(basePath string) error { return e }) if err != nil { - provider.log(Warn, "error creating username idx bucket: %v", err) + providerLog(logger.LevelWarn, "error creating username idx bucket: %v", err) return err } provider = BoltProvider{dbHandle: dbHandle} } else { - provider.log(Warn, "error creating bolt key/value store handler: %v", err) + providerLog(logger.LevelWarn, "error creating bolt key/value store handler: %v", err) } return err } @@ -65,7 +66,7 @@ func (p BoltProvider) validateUserAndPass(username string, password string) (Use } user, err := p.userExists(username) if err != nil { - p.log(Warn, "error authenticating user: %v, error: %v", username, err) + providerLog(logger.LevelWarn, "error authenticating user: %v, error: %v", username, err) return user, err } return checkUserAndPass(user, password) @@ -78,7 +79,7 @@ func (p BoltProvider) validateUserAndPubKey(username string, pubKey string) (Use } user, err := p.userExists(username) if err != nil { - p.log(Warn, "error authenticating user: %v, error: %v", username, err) + providerLog(logger.LevelWarn, "error authenticating user: %v, error: %v", username, err) return user, "", err } return checkUserAndPubKey(user, pubKey) @@ -140,7 +141,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 { - p.log(Warn, "unable to get quota for user %v error: %v", username, err) + providerLog(logger.LevelWarn, "unable to get quota for user %v error: %v", username, err) return 0, 0, err } return user.UsedQuotaFiles, user.UsedQuotaSize, err @@ -313,11 +314,3 @@ func getBuckets(tx *bolt.Tx) (*bolt.Bucket, *bolt.Bucket, error) { } return bucket, idxBucket, err } - -func (p BoltProvider) log(level string, format string, v ...interface{}) { - sqlCommonLog(level, p.providerName(), format, v...) -} - -func (p BoltProvider) providerName() string { - return BoltDataProviderName -} diff --git a/dataprovider/dataprovider.go b/dataprovider/dataprovider.go index caaab55b..f9077a17 100644 --- a/dataprovider/dataprovider.go +++ b/dataprovider/dataprovider.go @@ -35,7 +35,6 @@ const ( // BoltDataProviderName name for bbolt key/value store provider BoltDataProviderName = "bolt" - logSender = "dataProvider" argonPwdPrefix = "$argon2id$" bcryptPwdPrefix = "$2a$" pbkdf2SHA1Prefix = "$pbkdf2-sha1$" @@ -43,11 +42,6 @@ const ( pbkdf2SHA512Prefix = "$pbkdf2-sha512$" manageUsersDisabledError = "please set manage_users to 1 in sftpgo.conf to enable this method" trackQuotaDisabledError = "please enable track_quota in sftpgo.conf to use this method" - - Debug = "debug" - Info = "info" - Warn = "warn" - Error = "error" ) var ( @@ -60,6 +54,7 @@ var ( PermCreateDirs, PermCreateSymlinks} hashPwdPrefixes = []string{argonPwdPrefix, bcryptPwdPrefix, pbkdf2SHA1Prefix, pbkdf2SHA256Prefix, pbkdf2SHA512Prefix} pbkdfPwdPrefixes = []string{pbkdf2SHA1Prefix, pbkdf2SHA256Prefix, pbkdf2SHA512Prefix} + logSender = "dataProvider" ) // Config provider configuration @@ -146,8 +141,6 @@ type Provider interface { deleteUser(user User) error getUsers(limit int, offset int, order string, username string) ([]User, error) getUserByID(ID int64) (User, error) - log(level string, format string, v ...interface{}) - providerName() string } // Initialize the data provider. @@ -282,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) + providerLog(logger.LevelWarn, "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) + providerLog(logger.LevelWarn, "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) + providerLog(logger.LevelWarn, "error comparing password with pbkdf2 sha256 hash: %v", err) return user, err } } @@ -311,7 +304,7 @@ func checkUserAndPubKey(user User, pubKey string) (User, string, error) { for i, k := range user.PublicKeys { storedPubKey, comment, _, _, 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) + providerLog(logger.LevelWarn, "error parsing stored public key %d for user %v: %v", i, user.Username, err) return user, "", err } if string(storedPubKey.Marshal()) == pubKey { @@ -377,3 +370,7 @@ func getSSLMode() string { } return "" } + +func providerLog(level logger.LogLevel, format string, v ...interface{}) { + logger.Log(level, logSender, "", format, v...) +} diff --git a/dataprovider/mysql.go b/dataprovider/mysql.go index 94a77dc1..0c69fbe9 100644 --- a/dataprovider/mysql.go +++ b/dataprovider/mysql.go @@ -5,6 +5,8 @@ import ( "fmt" "runtime" "time" + + "github.com/drakkan/sftpgo/logger" ) // MySQLProvider auth provider for MySQL/MariaDB database @@ -15,7 +17,7 @@ type MySQLProvider struct { func initializeMySQLProvider() error { var err error var connectionString string - provider = MySQLProvider{} + logSender = MySQLDataProviderName if len(config.ConnectionString) == 0 { connectionString = fmt.Sprintf("%v:%v@tcp([%v]:%v)/%v?charset=utf8&interpolateParams=true&timeout=10s&tls=%v", config.Username, config.Password, config.Host, config.Port, config.Name, getSSLMode()) @@ -25,13 +27,13 @@ func initializeMySQLProvider() error { dbHandle, err := sql.Open("mysql", connectionString) if err == nil { numCPU := runtime.NumCPU() - provider.log(Debug, "mysql database handle created, connection string: %#v, pool size: %v", connectionString, numCPU) + providerLog(logger.LevelDebug, "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 { - provider.log(Warn, "error creating mysql database handler, connection string: %#v, error: %v", connectionString, err) + providerLog(logger.LevelWarn, "error creating mysql database handler, connection string: %#v, error: %v", connectionString, err) } return err } @@ -51,7 +53,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 { - p.log(Warn, "error starting transaction to update quota for user %v: %v", username, err) + providerLog(logger.LevelWarn, "error starting transaction to update quota for user %v: %v", username, err) return err } err = sqlCommonUpdateQuota(username, filesAdd, sizeAdd, reset, p.dbHandle) @@ -61,7 +63,7 @@ func (p MySQLProvider) updateQuota(username string, filesAdd int, sizeAdd int64, err = tx.Rollback() } if err != nil { - p.log(Warn, "error closing transaction to update quota for user %v: %v", username, err) + providerLog(logger.LevelWarn, "error closing transaction to update quota for user %v: %v", username, err) } return err } @@ -89,11 +91,3 @@ func (p MySQLProvider) deleteUser(user User) error { func (p MySQLProvider) getUsers(limit int, offset int, order string, username string) ([]User, error) { return sqlCommonGetUsers(limit, offset, order, username, p.dbHandle) } - -func (p MySQLProvider) log(level string, format string, v ...interface{}) { - sqlCommonLog(level, p.providerName(), format, v...) -} - -func (p MySQLProvider) providerName() string { - return MySQLDataProviderName -} diff --git a/dataprovider/pgsql.go b/dataprovider/pgsql.go index 49a729b3..94a92de0 100644 --- a/dataprovider/pgsql.go +++ b/dataprovider/pgsql.go @@ -4,6 +4,8 @@ import ( "database/sql" "fmt" "runtime" + + "github.com/drakkan/sftpgo/logger" ) // PGSQLProvider auth provider for PostgreSQL database @@ -14,7 +16,7 @@ type PGSQLProvider struct { func initializePGSQLProvider() error { var err error var connectionString string - provider = PGSQLProvider{} + logSender = PGSQLDataProviderName if len(config.ConnectionString) == 0 { connectionString = fmt.Sprintf("host='%v' port=%v dbname='%v' user='%v' password='%v' sslmode=%v connect_timeout=10", config.Host, config.Port, config.Name, config.Username, config.Password, getSSLMode()) @@ -24,12 +26,12 @@ func initializePGSQLProvider() error { dbHandle, err := sql.Open("postgres", connectionString) if err == nil { numCPU := runtime.NumCPU() - provider.log(Debug, "postgres database handle created, connection string: %#v, pool size: %v", connectionString, numCPU) + providerLog(logger.LevelDebug, "postgres database handle created, connection string: %#v, pool size: %v", connectionString, numCPU) dbHandle.SetMaxIdleConns(numCPU) dbHandle.SetMaxOpenConns(numCPU) provider = PGSQLProvider{dbHandle: dbHandle} } else { - provider.log(Warn, "error creating postgres database handler, connection string: %#v, error: %v", connectionString, err) + providerLog(logger.LevelWarn, "error creating postgres database handler, connection string: %#v, error: %v", connectionString, err) } return err } @@ -49,7 +51,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 { - p.log(Warn, "error starting transaction to update quota for user %v: %v", username, err) + providerLog(logger.LevelWarn, "error starting transaction to update quota for user %v: %v", username, err) return err } err = sqlCommonUpdateQuota(username, filesAdd, sizeAdd, reset, p.dbHandle) @@ -59,7 +61,7 @@ func (p PGSQLProvider) updateQuota(username string, filesAdd int, sizeAdd int64, err = tx.Rollback() } if err != nil { - p.log(Warn, "error closing transaction to update quota for user %v: %v", username, err) + providerLog(logger.LevelWarn, "error closing transaction to update quota for user %v: %v", username, err) } return err } @@ -87,11 +89,3 @@ func (p PGSQLProvider) deleteUser(user User) error { func (p PGSQLProvider) getUsers(limit int, offset int, order string, username string) ([]User, error) { return sqlCommonGetUsers(limit, offset, order, username, p.dbHandle) } - -func (p PGSQLProvider) log(level string, format string, v ...interface{}) { - sqlCommonLog(level, p.providerName(), format, v...) -} - -func (p PGSQLProvider) providerName() string { - return PGSQLDataProviderName -} diff --git a/dataprovider/sqlcommon.go b/dataprovider/sqlcommon.go index 5af7c824..79fd1782 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.Warn(logSender, "", "error preparing database query %#v: %v", q, err) + providerLog(logger.LevelWarn, "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) + providerLog(logger.LevelWarn, "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) + providerLog(logger.LevelWarn, "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) + providerLog(logger.LevelWarn, "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) + providerLog(logger.LevelWarn, "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", + providerLog(logger.LevelDebug, "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) + providerLog(logger.LevelWarn, "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) + providerLog(logger.LevelWarn, "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 quota for user: %v, error: %v", username, err) + providerLog(logger.LevelWarn, "error getting quota for user: %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) + providerLog(logger.LevelWarn, "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) + providerLog(logger.LevelWarn, "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) + providerLog(logger.LevelWarn, "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) + providerLog(logger.LevelWarn, "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) + providerLog(logger.LevelWarn, "error preparing database query %#v: %v", q, err) return nil, err } defer stmt.Close() @@ -250,16 +250,3 @@ func getUserFromDbRow(row *sql.Row, rows *sql.Rows) (User, error) { } return user, err } - -func sqlCommonLog(level string, sender string, format string, v ...interface{}) { - switch level { - case "info": - logger.Info(sender, "", format, v...) - case "warn": - logger.Warn(sender, "", format, v...) - case "error": - logger.Error(sender, "", format, v...) - default: - logger.Debug(sender, "", format, v...) - } -} diff --git a/dataprovider/sqlite.go b/dataprovider/sqlite.go index a44be0ed..a72c9872 100644 --- a/dataprovider/sqlite.go +++ b/dataprovider/sqlite.go @@ -6,6 +6,8 @@ import ( "fmt" "os" "path/filepath" + + "github.com/drakkan/sftpgo/logger" ) // SQLiteProvider auth provider for SQLite database @@ -16,7 +18,7 @@ type SQLiteProvider struct { func initializeSQLiteProvider(basePath string) error { var err error var connectionString string - provider = SQLiteProvider{} + logSender = SQLiteDataProviderName if len(config.ConnectionString) == 0 { dbPath := config.Name if !filepath.IsAbs(dbPath) { @@ -24,7 +26,7 @@ func initializeSQLiteProvider(basePath string) error { } fi, err := os.Stat(dbPath) if err != nil { - provider.log(Warn, "sqlite database file does not exists, please be sure to create and initialize"+ + providerLog(logger.LevelWarn, "sqlite database file does not exists, please be sure to create and initialize"+ " a database before starting sftpgo") return err } @@ -38,11 +40,12 @@ func initializeSQLiteProvider(basePath string) error { } dbHandle, err := sql.Open("sqlite3", connectionString) if err == nil { - provider.log(Debug, "sqlite database handle created, connection string: %#v", connectionString) + providerLog(logger.LevelDebug, "sqlite database handle created, connection string: %#v", connectionString) dbHandle.SetMaxOpenConns(1) provider = SQLiteProvider{dbHandle: dbHandle} } else { - provider.log(Warn, "error creating sqlite database handler, connection string: %#v, error: %v", connectionString, err) + providerLog(logger.LevelWarn, "error creating sqlite database handler, connection string: %#v, error: %v", + connectionString, err) } return err } @@ -88,11 +91,3 @@ func (p SQLiteProvider) deleteUser(user User) error { func (p SQLiteProvider) getUsers(limit int, offset int, order string, username string) ([]User, error) { return sqlCommonGetUsers(limit, offset, order, username, p.dbHandle) } - -func (p SQLiteProvider) log(level string, format string, v ...interface{}) { - sqlCommonLog(level, p.providerName(), format, v...) -} - -func (p SQLiteProvider) providerName() string { - return SQLiteDataProviderName -} diff --git a/logger/logger.go b/logger/logger.go index f642f1d5..5cdb10e8 100644 --- a/logger/logger.go +++ b/logger/logger.go @@ -22,6 +22,17 @@ const ( dateFormat = "2006-01-02T15:04.05.000" // YYYY-MM-DDTHH:MM.SS.ZZZ ) +// LogLevel defines log levels. +type LogLevel uint8 + +// defines our own log level, just in case we'll change logger in future +const ( + LevelDebug LogLevel = iota + LevelInfo + LevelWarn + LevelError +) + var ( logger zerolog.Logger consoleLogger zerolog.Logger @@ -58,6 +69,21 @@ func InitLogger(logFilePath string, logMaxSize int, logMaxBackups int, logMaxAge logger = logger.With().Timestamp().Logger().Level(level) } +// Log logs at the specified level for the specified sender +func Log(level LogLevel, sender string, connectionID string, format string, v ...interface{}) { + switch level { + case LevelDebug: + Debug(sender, connectionID, format, v...) + case LevelInfo: + Info(sender, connectionID, format, v...) + case LevelWarn: + Warn(sender, connectionID, format, v...) + default: + Error(sender, connectionID, format, v...) + } + +} + // Debug logs at debug level for the specified sender func Debug(sender string, connectionID string, format string, v ...interface{}) { logger.Debug().Str("sender", sender).Str("connection_id", connectionID).Msg(fmt.Sprintf(format, v...)) diff --git a/sftpd/handler.go b/sftpd/handler.go index 35250721..bb4cab22 100644 --- a/sftpd/handler.go +++ b/sftpd/handler.go @@ -41,17 +41,8 @@ type Connection struct { } // Log outputs a log entry to the configured logger -func (c Connection) Log(level string, sender string, format string, v ...interface{}) { - switch level { - case "info": - logger.Info(sender, c.ID, format, v...) - case "warn": - logger.Warn(sender, c.ID, format, v...) - case "error": - logger.Error(sender, c.ID, format, v...) - default: - logger.Debug(sender, c.ID, format, v...) - } +func (c Connection) Log(level logger.LogLevel, sender string, format string, v ...interface{}) { + logger.Log(level, sender, c.ID, format, v...) } // Fileread creates a reader for a file on the system and returns the reader back. @@ -76,11 +67,11 @@ func (c Connection) Fileread(request *sftp.Request) (io.ReaderAt, error) { file, err := os.Open(p) if err != nil { - c.Log(Error, logSender, "could not open file %#v for reading: %v", p, err) + c.Log(logger.LevelError, logSender, "could not open file %#v for reading: %v", p, err) return nil, sftp.ErrSshFxFailure } - c.Log(Debug, logSender, "fileread requested for path: %#v", p) + c.Log(logger.LevelDebug, logSender, "fileread requested for path: %#v", p) transfer := Transfer{ file: file, @@ -127,13 +118,13 @@ func (c Connection) Filewrite(request *sftp.Request) (io.WriterAt, error) { } if statErr != nil { - c.Log(Error, logSender, "error performing file stat %#v: %v", p, statErr) + c.Log(logger.LevelError, logSender, "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() { - c.Log(Warn, logSender, "attempted to open a directory for writing to: %#v", p) + c.Log(logger.LevelWarn, logSender, "attempted to open a directory for writing to: %#v", p) return nil, sftp.ErrSshFxOpUnsupported } @@ -155,7 +146,7 @@ func (c Connection) Filecmd(request *sftp.Request) error { return sftp.ErrSshFxOpUnsupported } - c.Log(Debug, logSender, "new cmd, method: %v, sourcePath: %#v, targetPath: %#v", request.Method, + c.Log(logger.LevelDebug, logSender, "new cmd, method: %v, sourcePath: %#v, targetPath: %#v", request.Method, p, target) switch request.Method { @@ -218,11 +209,11 @@ func (c Connection) Filelist(request *sftp.Request) (sftp.ListerAt, error) { return nil, sftp.ErrSshFxPermissionDenied } - c.Log(Debug, logSender, "requested list file for dir: %#v", p) + c.Log(logger.LevelDebug, logSender, "requested list file for dir: %#v", p) files, err := ioutil.ReadDir(p) if err != nil { - c.Log(Error, logSender, "error listing directory: %#v", err) + c.Log(logger.LevelError, logSender, "error listing directory: %#v", err) return nil, sftp.ErrSshFxFailure } @@ -232,12 +223,12 @@ func (c Connection) Filelist(request *sftp.Request) (sftp.ListerAt, error) { return nil, sftp.ErrSshFxPermissionDenied } - c.Log(Debug, logSender, "requested stat for file: %#v", p) + c.Log(logger.LevelDebug, logSender, "requested stat for file: %#v", p) s, err := os.Stat(p) if os.IsNotExist(err) { return nil, sftp.ErrSshFxNoSuchFile } else if err != nil { - c.Log(Error, logSender, "error running STAT on file: %#v", err) + c.Log(logger.LevelError, logSender, "error running STAT on file: %#v", err) return nil, sftp.ErrSshFxFailure } @@ -267,7 +258,7 @@ func (c Connection) handleSFTPRename(sourcePath string, targetPath string) error return sftp.ErrSshFxPermissionDenied } if err := os.Rename(sourcePath, targetPath); err != nil { - c.Log(Error, logSender, "failed to rename file, source: %#v target: %#v: %v", sourcePath, targetPath, err) + c.Log(logger.LevelError, logSender, "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) @@ -282,11 +273,11 @@ func (c Connection) handleSFTPRmdir(path string) error { numFiles, size, fileList, err := utils.ScanDirContents(path) if err != nil { - c.Log(Error, logSender, "failed to remove directory %#v, scanning error: %v", path, err) + c.Log(logger.LevelError, logSender, "failed to remove directory %#v, scanning error: %v", path, err) return sftp.ErrSshFxFailure } if err := os.RemoveAll(path); err != nil { - c.Log(Error, logSender, "failed to remove directory %#v: %v", path, err) + c.Log(logger.LevelError, logSender, "failed to remove directory %#v: %v", path, err) return sftp.ErrSshFxFailure } @@ -303,7 +294,7 @@ func (c Connection) handleSFTPSymlink(sourcePath string, targetPath string) erro return sftp.ErrSshFxPermissionDenied } if err := os.Symlink(sourcePath, targetPath); err != nil { - c.Log(Warn, logSender, "failed to create symlink %#v -> %#v: %v", sourcePath, targetPath, err) + c.Log(logger.LevelWarn, logSender, "failed to create symlink %#v -> %#v: %v", sourcePath, targetPath, err) return sftp.ErrSshFxFailure } @@ -317,7 +308,7 @@ func (c Connection) handleSFTPMkdir(path string) error { } if err := c.createMissingDirs(filepath.Join(path, "testfile")); err != nil { - c.Log(Error, logSender, "error making missing dir for path %#v: %v", path, err) + c.Log(logger.LevelError, logSender, "error making missing dir for path %#v: %v", path, err) return sftp.ErrSshFxFailure } logger.CommandLog(mkdirLogSender, path, "", c.User.Username, c.ID, c.protocol) @@ -333,12 +324,12 @@ func (c Connection) handleSFTPRemove(path string) error { var fi os.FileInfo var err error if fi, err = os.Lstat(path); err != nil { - c.Log(Error, logSender, "failed to remove a file %#v: stat error: %v", path, err) + c.Log(logger.LevelError, logSender, "failed to remove a file %#v: stat error: %v", path, err) return sftp.ErrSshFxFailure } size = fi.Size() if err := os.Remove(path); err != nil { - c.Log(Error, logSender, "failed to remove a file/symlink %#v: %v", path, err) + c.Log(logger.LevelError, logSender, "failed to remove a file/symlink %#v: %v", path, err) return sftp.ErrSshFxFailure } @@ -353,7 +344,7 @@ func (c Connection) handleSFTPRemove(path string) error { func (c Connection) handleSFTPUploadToNewFile(requestPath, filePath string) (io.WriterAt, error) { if !c.hasSpace(true) { - c.Log(Info, logSender, "denying file write due to space limit") + c.Log(logger.LevelInfo, logSender, "denying file write due to space limit") return nil, sftp.ErrSshFxFailure } @@ -365,13 +356,13 @@ func (c Connection) handleSFTPUploadToNewFile(requestPath, filePath string) (io. err := c.createMissingDirs(requestPath) if err != nil { - c.Log(Error, logSender, "error making missing dir for path %#v: %v", requestPath, err) + c.Log(logger.LevelError, logSender, "error making missing dir for path %#v: %v", requestPath, err) return nil, sftp.ErrSshFxFailure } file, err := os.Create(filePath) if err != nil { - c.Log(Error, logSender, "error creating file %#v: %v", requestPath, err) + c.Log(logger.LevelError, logSender, "error creating file %#v: %v", requestPath, err) return nil, sftp.ErrSshFxFailure } @@ -398,7 +389,7 @@ func (c Connection) handleSFTPUploadToExistingFile(pflags sftp.FileOpenFlags, re fileSize int64) (io.WriterAt, error) { var err error if !c.hasSpace(false) { - c.Log(Info, logSender, "denying file write due to space limit") + c.Log(logger.LevelInfo, logSender, "denying file write due to space limit") return nil, sftp.ErrSshFxFailure } @@ -406,14 +397,14 @@ func (c Connection) handleSFTPUploadToExistingFile(pflags sftp.FileOpenFlags, re if osFlags&os.O_TRUNC == 0 { // see https://github.com/pkg/sftp/issues/295 - c.Log(Info, logSender, "upload resume is not supported, returning error for file: %#v", requestPath) + c.Log(logger.LevelInfo, logSender, "upload resume is not supported, returning error for file: %#v", requestPath) return nil, sftp.ErrSshFxOpUnsupported } if uploadMode == uploadModeAtomic { err = os.Rename(requestPath, filePath) if err != nil { - c.Log(Error, logSender, "error renaming existing file for atomic upload, source: %#v, dest: %#v, err: %v", + c.Log(logger.LevelError, logSender, "error renaming existing file for atomic upload, source: %#v, dest: %#v, err: %v", requestPath, filePath, err) return nil, sftp.ErrSshFxFailure } @@ -421,7 +412,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 { - c.Log(Error, logSender, "error opening existing file, flags: %v, source: %#v, err: %v", pflags, filePath, err) + c.Log(logger.LevelError, logSender, "error opening existing file, flags: %v, source: %#v, err: %v", pflags, filePath, err) return nil, sftp.ErrSshFxFailure } @@ -453,15 +444,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 { - c.Log(Warn, logSender, "quota enforcement not possible for user %v: %v", c.User.Username, err) + c.Log(logger.LevelWarn, logSender, "quota enforcement not possible for user %v: %v", c.User.Username, err) return true } - c.Log(Warn, logSender, "error getting used quota for %v: %v", c.User.Username, err) + c.Log(logger.LevelWarn, logSender, "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) { - c.Log(Debug, logSender, "quota exceed for user %v, num files: %v/%v, size: %v/%v check files: %v", + c.Log(logger.LevelDebug, logSender, "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 } @@ -482,14 +473,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 { - c.Log(Warn, logSender, "error resolving not existent path: %#v", err) + c.Log(logger.LevelWarn, logSender, "error resolving not existent path: %#v", err) } return r, err } err = c.isSubDir(p) if err != nil { - c.Log(Warn, logSender, "Invalid path resolution, dir: %#v outside user home: %#v err: %v", p, c.User.HomeDir, err) + c.Log(logger.LevelWarn, logSender, "Invalid path resolution, dir: %#v outside user home: %#v err: %v", p, c.User.HomeDir, err) } return r, err } @@ -516,7 +507,7 @@ func (c Connection) findNonexistentDirs(path string) ([]string, error) { } err = c.isSubDir(p) if err != nil { - c.Log(Warn, logSender, "Error finding non existing dir: %v", err) + c.Log(logger.LevelWarn, logSender, "Error finding non existing dir: %v", err) } return results, err } @@ -525,7 +516,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 { - c.Log(Warn, logSender, "unable to find non existent dirs: %v", err) + c.Log(logger.LevelWarn, logSender, "unable to find non existent dirs: %v", err) return "", err } var parent string @@ -556,11 +547,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 { - c.Log(Warn, logSender, "invalid home dir %#v: %v", c.User.HomeDir, err) + c.Log(logger.LevelWarn, logSender, "invalid home dir %#v: %v", c.User.HomeDir, err) return err } if !strings.HasPrefix(sub, parent) { - c.Log(Warn, logSender, "dir %#v is not inside: %#v ", sub, parent) + c.Log(logger.LevelWarn, logSender, "dir %#v is not inside: %#v ", sub, parent) return fmt.Errorf("dir %#v is not inside: %#v", sub, parent) } return nil @@ -575,7 +566,7 @@ func (c Connection) createMissingDirs(filePath string) error { for i := range dirsToCreate { d := dirsToCreate[last-i] if err := os.Mkdir(d, 0777); err != nil { - c.Log(Error, logSender, "error creating missing dir: %#v", d) + c.Log(logger.LevelError, logSender, "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 98162a0a..73814738 100644 --- a/sftpd/scp.go +++ b/sftpd/scp.go @@ -12,6 +12,7 @@ import ( "time" "github.com/drakkan/sftpgo/dataprovider" + "github.com/drakkan/sftpgo/logger" "github.com/drakkan/sftpgo/utils" "golang.org/x/crypto/ssh" ) @@ -43,7 +44,7 @@ func (c *scpCommand) handle() error { defer removeConnection(c.connection.ID) destPath := c.getDestPath() commandType := c.getCommandType() - c.connection.Log(Debug, logSenderSCP, "handle scp command, args: %v user: %v command type: %v, dest path: %#v", + c.connection.Log(logger.LevelDebug, logSenderSCP, "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 @@ -84,7 +85,7 @@ func (c *scpCommand) handleRecursiveUpload() error { } if strings.HasPrefix(command, "E") { numDirs-- - c.connection.Log(Debug, logSenderSCP, "received end dir command, num dirs: %v", numDirs) + c.connection.Log(logger.LevelDebug, logSenderSCP, "received end dir command, num dirs: %v", numDirs) if numDirs == 0 { // upload is now complete send confirmation message err = c.sendConfirmationMessage() @@ -107,7 +108,7 @@ func (c *scpCommand) handleRecursiveUpload() error { if err != nil { return err } - c.connection.Log(Debug, logSenderSCP, "received start dir command, num dirs: %v destPath: %#v", numDirs, destPath) + c.connection.Log(logger.LevelDebug, logSenderSCP, "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 { @@ -126,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") - c.connection.Log(Warn, logSenderSCP, "error creating dir: %#v, permission denied", dirPath) + c.connection.Log(logger.LevelWarn, logSenderSCP, "error creating dir: %#v, permission denied", dirPath) c.sendErrorMessage(err.Error()) return err } p, err := c.connection.buildPath(dirPath) if err != nil { - c.connection.Log(Warn, logSenderSCP, "error creating dir: %#v, invalid file path, err: %v", dirPath, err) + c.connection.Log(logger.LevelWarn, logSenderSCP, "error creating dir: %#v, invalid file path, err: %v", dirPath, err) c.sendErrorMessage(err.Error()) return err } @@ -142,7 +143,7 @@ func (c *scpCommand) handleCreateDir(dirPath string) error { if err != nil { return err } - c.connection.Log(Debug, mkdirLogSender, "created dir %#v", dirPath) + c.connection.Log(logger.LevelDebug, mkdirLogSender, "created dir %#v", dirPath) return nil } @@ -190,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") - c.connection.Log(Warn, logSenderSCP, "error uploading file: %#v, err: %v", filePath, err) + c.connection.Log(logger.LevelWarn, logSenderSCP, "error uploading file: %#v, err: %v", filePath, err) c.sendErrorMessage(err.Error()) return err } @@ -198,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") - c.connection.Log(Warn, logSenderSCP, "error uploading file: %#v, permission denied", requestPath) + c.connection.Log(logger.LevelWarn, logSenderSCP, "error uploading file: %#v, permission denied", requestPath) c.sendErrorMessage(err.Error()) return err } @@ -206,7 +207,7 @@ func (c *scpCommand) handleUploadFile(requestPath, filePath string, sizeToRead i file, err := os.Create(filePath) if err != nil { - c.connection.Log(Error, logSenderSCP, "error creating file %#v: %v", requestPath, err) + c.connection.Log(logger.LevelError, logSenderSCP, "error creating file %#v: %v", requestPath, err) c.sendErrorMessage(err.Error()) return err } @@ -237,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") - c.connection.Log(Warn, logSenderSCP, "error uploading file: %#v, permission denied", uploadFilePath) + c.connection.Log(logger.LevelWarn, logSenderSCP, "error uploading file: %#v, permission denied", uploadFilePath) c.sendErrorMessage(err.Error()) return err } p, err := c.connection.buildPath(uploadFilePath) if err != nil { - c.connection.Log(Warn, logSenderSCP, "error uploading file: %#v, err: %v", uploadFilePath, err) + c.connection.Log(logger.LevelWarn, logSenderSCP, "error uploading file: %#v, err: %v", uploadFilePath, err) c.sendErrorMessage(err.Error()) return err } @@ -258,13 +259,13 @@ func (c *scpCommand) handleUpload(uploadFilePath string, sizeToRead int64) error } if statErr != nil { - c.connection.Log(Error, logSenderSCP, "error performing file stat %#v: %v", p, statErr) + c.connection.Log(logger.LevelError, logSenderSCP, "error performing file stat %#v: %v", p, statErr) c.sendErrorMessage(err.Error()) return err } if stat.IsDir() { - c.connection.Log(Warn, logSenderSCP, "attempted to open a directory for writing to: %#v", p) + c.connection.Log(logger.LevelWarn, logSenderSCP, "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 @@ -273,7 +274,7 @@ func (c *scpCommand) handleUpload(uploadFilePath string, sizeToRead int64) error if uploadMode == uploadModeAtomic { err = os.Rename(p, filePath) if err != nil { - c.connection.Log(Error, logSenderSCP, "error renaming existing file for atomic upload, source: %#v, dest: %#v, err: %v", + c.connection.Log(logger.LevelError, logSenderSCP, "error renaming existing file for atomic upload, source: %#v, dest: %#v, err: %v", p, filePath, err) c.sendErrorMessage(err.Error()) return err @@ -314,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() { - c.connection.Log(Debug, logSenderSCP, "recursive download, dir path: %#v", dirPath) + c.connection.Log(logger.LevelDebug, logSenderSCP, "recursive download, dir path: %#v", dirPath) err = c.sendDownloadProtocolMessages(dirPath, stat) if err != nil { return err @@ -424,21 +425,21 @@ func (c *scpCommand) handleDownload(filePath string) error { if !c.connection.User.HasPerm(dataprovider.PermDownload) { err := fmt.Errorf("Permission denied") - c.connection.Log(Warn, logSenderSCP, "error downloading file: %#v, permission denied", filePath) + c.connection.Log(logger.LevelWarn, logSenderSCP, "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") - c.connection.Log(Warn, logSenderSCP, "error downloading file: %#v, invalid file path", filePath) + c.connection.Log(logger.LevelWarn, logSenderSCP, "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) { - c.connection.Log(Warn, logSenderSCP, "error downloading file: %#v, err: %v", p, err) + c.connection.Log(logger.LevelWarn, logSenderSCP, "error downloading file: %#v, err: %v", p, err) c.sendErrorMessage(err.Error()) return err } @@ -450,7 +451,7 @@ func (c *scpCommand) handleDownload(filePath string) error { file, err := os.Open(p) if err != nil { - c.connection.Log(Error, logSenderSCP, "could not open file %#v for reading: %v", p, err) + c.connection.Log(logger.LevelError, logSenderSCP, "could not open file %#v for reading: %v", p, err) c.sendErrorMessage(err.Error()) return err } @@ -525,7 +526,7 @@ func (c *scpCommand) readConfirmationMessage() error { msg.WriteString(string(readed)) } } - c.connection.Log(Info, logSenderSCP, "scp error message received: %v is error: %v", msg.String(), isError) + c.connection.Log(logger.LevelInfo, logSenderSCP, "scp error message received: %v is error: %v", msg.String(), isError) err = fmt.Errorf("%v", msg.String()) c.channel.Close() } @@ -578,7 +579,7 @@ func (c *scpCommand) sendConfirmationMessage() error { func (c *scpCommand) sendProtocolMessage(message string) error { _, err := c.channel.Write([]byte(message)) if err != nil { - c.connection.Log(Warn, logSenderSCP, "error sending protocol message: %v, err: %v", message, err) + c.connection.Log(logger.LevelWarn, logSenderSCP, "error sending protocol message: %v, err: %v", message, err) c.channel.Close() } return err @@ -593,7 +594,7 @@ func (c *scpCommand) sendExitStatus(err error) { ex := exitStatusMsg{ Status: status, } - c.connection.Log(Debug, logSenderSCP, "send exit status for command with args: %v user: %v err: %v", + c.connection.Log(logger.LevelDebug, logSenderSCP, "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() @@ -624,7 +625,7 @@ func (c *scpCommand) getNextUploadProtocolMessage() (string, error) { func (c *scpCommand) createDir(dirPath string) error { var err error if err = os.Mkdir(dirPath, 0777); err != nil { - c.connection.Log(Error, logSenderSCP, "error creating dir: %v", dirPath) + c.connection.Log(logger.LevelError, logSenderSCP, "error creating dir: %v", dirPath) c.sendErrorMessage(err.Error()) return err } @@ -644,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) - c.connection.Log(Warn, logSenderSCP, "error: %v", err) + c.connection.Log(logger.LevelWarn, logSenderSCP, "error: %v", err) c.sendErrorMessage(err.Error()) return size, name, err } @@ -652,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 { - c.connection.Log(Warn, logSenderSCP, "error getting size from upload message: %v", err) + c.connection.Log(logger.LevelWarn, logSenderSCP, "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") - c.connection.Log(Warn, logSenderSCP, "error: %v", err) + c.connection.Log(logger.LevelWarn, logSenderSCP, "error: %v", err) c.sendErrorMessage(err.Error()) return size, name, err } } else { err = fmt.Errorf("Error splitting upload message: %v", command) - c.connection.Log(Warn, logSenderSCP, "error: %v", err) + c.connection.Log(logger.LevelWarn, logSenderSCP, "error: %v", err) c.sendErrorMessage(err.Error()) return size, name, err } diff --git a/sftpd/server.go b/sftpd/server.go index 4b06339e..b71f3b0d 100644 --- a/sftpd/server.go +++ b/sftpd/server.go @@ -232,7 +232,7 @@ func (c Configuration) AcceptInboundConnection(conn net.Conn, config *ssh.Server lock: new(sync.Mutex), sshConn: sconn, } - connection.Log(Info, logSender, "User id: %d, logged in with: %#v, name: %#v, home_dir: %#v", + connection.Log(logger.LevelInfo, logSender, "User id: %d, logged in with: %#v, name: %#v, home_dir: %#v", user.ID, loginType, user.Username, user.HomeDir) go ssh.DiscardRequests(reqs) @@ -241,14 +241,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" { - connection.Log(Debug, logSender, "received an unknown channel type: %v", newChannel.ChannelType()) + connection.Log(logger.LevelDebug, logSender, "received an unknown channel type: %v", newChannel.ChannelType()) newChannel.Reject(ssh.UnknownChannelType, "unknown channel type") continue } channel, requests, err := newChannel.Accept() if err != nil { - connection.Log(Warn, logSender, "could not accept a channel: %v", err) + connection.Log(logger.LevelWarn, logSender, "could not accept a channel: %v", err) continue } @@ -270,7 +270,8 @@ 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) - connection.Log(Debug, logSender, "new exec command: %v args: %v user: %v, error: %v", name, scpArgs, + connection.Log(logger.LevelDebug, logSender, "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 @@ -300,10 +301,10 @@ func (c Configuration) handleSftpConnection(channel io.ReadWriteCloser, connecti server := sftp.NewRequestServer(channel, handler) if err := server.Serve(); err == io.EOF { - connection.Log(Debug, logSenderSCP, "connection closed") + connection.Log(logger.LevelDebug, logSenderSCP, "connection closed") server.Close() } else if err != nil { - connection.Log(Error, logSenderSCP, "sftp connection closed with error: %v", err) + connection.Log(logger.LevelError, logSenderSCP, "sftp connection closed with error: %v", err) } removeConnection(connection.ID) diff --git a/sftpd/sftpd.go b/sftpd/sftpd.go index 25090659..23f1b4c5 100644 --- a/sftpd/sftpd.go +++ b/sftpd/sftpd.go @@ -34,11 +34,6 @@ const ( operationRename = "rename" protocolSFTP = "SFTP" protocolSCP = "SCP" - - Debug = "debug" - Info = "info" - Warn = "warn" - Error = "error" ) var ( @@ -178,7 +173,7 @@ func CloseActiveConnection(connectionID string) bool { defer mutex.RUnlock() for _, c := range openConnections { if c.ID == connectionID { - c.Log(Debug, logSender, "closing connection") + c.Log(logger.LevelDebug, logSender, "closing connection") c.sshConn.Close() result = true break @@ -252,17 +247,17 @@ func CheckIdleConnections() { if t.connectionID == c.ID { transferIdleTime := time.Since(t.lastActivity) if transferIdleTime < idleTime { - c.Log(Debug, logSender, "idle time: %v setted to transfer idle time: %v", + c.Log(logger.LevelDebug, logSender, "idle time: %v setted to transfer idle time: %v", idleTime, transferIdleTime) idleTime = transferIdleTime } } } if idleTime > idleTimeout { - c.Log(Info, logSender, "close idle connection, idle time: %v", idleTime) + c.Log(logger.LevelInfo, logSender, "close idle connection, idle time: %v", idleTime) err := c.sshConn.Close() if err != nil { - c.Log(Warn, logSender, "idle connection close failed: %v", err) + c.Log(logger.LevelWarn, logSender, "idle connection close failed: %v", err) } } } @@ -273,7 +268,7 @@ func addConnection(id string, c Connection) { mutex.Lock() defer mutex.Unlock() openConnections[id] = c - c.Log(Debug, logSender, "connection added, num open connections: %v", len(openConnections)) + c.Log(logger.LevelDebug, logSender, "connection added, num open connections: %v", len(openConnections)) } func removeConnection(id string) { @@ -281,7 +276,7 @@ func removeConnection(id string) { defer mutex.Unlock() c := openConnections[id] delete(openConnections, id) - c.Log(Debug, logSender, "connection removed, num open connections: %v", len(openConnections)) + c.Log(logger.LevelDebug, logSender, "connection removed, num open connections: %v", len(openConnections)) } func addTransfer(transfer *Transfer) {