diff --git a/dataprovider/bolt.go b/dataprovider/bolt.go index 63e8fb6e..f745ae4c 100644 --- a/dataprovider/bolt.go +++ b/dataprovider/bolt.go @@ -8,7 +8,6 @@ import ( "path/filepath" "time" - "github.com/drakkan/sftpgo/logger" "github.com/drakkan/sftpgo/utils" bolt "go.etcd.io/bbolt" ) @@ -25,6 +24,7 @@ type BoltProvider struct { func initializeBoltProvider(basePath string) error { var err error + provider = BoltProvider{} dbPath := config.Name if !filepath.IsAbs(dbPath) { dbPath = filepath.Join(basePath, dbPath) @@ -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") + provider.log(Debug, "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) + provider.log(Warn, "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) + provider.log(Warn, "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) + provider.log(Warn, "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) + p.log(Warn, "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) + p.log(Warn, "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) + p.log(Warn, "unable to get quota for user %v error: %v", username, err) return 0, 0, err } return user.UsedQuotaFiles, user.UsedQuotaSize, err @@ -313,3 +313,11 @@ 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 0f4a021a..caaab55b 100644 --- a/dataprovider/dataprovider.go +++ b/dataprovider/dataprovider.go @@ -28,8 +28,8 @@ import ( const ( // SQLiteDataProviderName name for SQLite database provider SQLiteDataProviderName = "sqlite" - // PGSSQLDataProviderName name for PostgreSQL database provider - PGSSQLDataProviderName = "postgresql" + // PGSQLDataProviderName name for PostgreSQL database provider + PGSQLDataProviderName = "postgresql" // MySQLDataProviderName name for MySQL database provider MySQLDataProviderName = "mysql" // BoltDataProviderName name for bbolt key/value store provider @@ -43,11 +43,16 @@ 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 ( // SupportedProviders data provider configured in the sftpgo.conf file must match of these strings - SupportedProviders = []string{SQLiteDataProviderName, PGSSQLDataProviderName, MySQLDataProviderName, BoltDataProviderName} + SupportedProviders = []string{SQLiteDataProviderName, PGSQLDataProviderName, MySQLDataProviderName, BoltDataProviderName} config Config provider Provider sqlPlaceholders []string @@ -141,6 +146,8 @@ 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. @@ -150,7 +157,7 @@ func Initialize(cnf Config, basePath string) error { sqlPlaceholders = getSQLPlaceholders() if config.Driver == SQLiteDataProviderName { return initializeSQLiteProvider(basePath) - } else if config.Driver == PGSSQLDataProviderName { + } else if config.Driver == PGSQLDataProviderName { return initializePGSQLProvider() } else if config.Driver == MySQLDataProviderName { return initializeMySQLProvider() @@ -347,7 +354,7 @@ func comparePbkdf2PasswordAndHash(password, hashedPassword string) (bool, error) } func getSSLMode() string { - if config.Driver == PGSSQLDataProviderName { + if config.Driver == PGSQLDataProviderName { if config.SSLMode == 0 { return "disable" } else if config.SSLMode == 1 { diff --git a/dataprovider/mysql.go b/dataprovider/mysql.go index 689c9059..94a77dc1 100644 --- a/dataprovider/mysql.go +++ b/dataprovider/mysql.go @@ -5,8 +5,6 @@ import ( "fmt" "runtime" "time" - - "github.com/drakkan/sftpgo/logger" ) // MySQLProvider auth provider for MySQL/MariaDB database @@ -17,6 +15,7 @@ type MySQLProvider struct { func initializeMySQLProvider() error { var err error var connectionString string + provider = MySQLProvider{} 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()) @@ -26,13 +25,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) + provider.log(Debug, "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) + provider.log(Warn, "error creating mysql database handler, connection string: %#v, error: %v", connectionString, err) } return err } @@ -52,7 +51,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) + p.log(Warn, "error starting transaction to update quota for user %v: %v", username, err) return err } err = sqlCommonUpdateQuota(username, filesAdd, sizeAdd, reset, p.dbHandle) @@ -62,7 +61,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) + p.log(Warn, "error closing transaction to update quota for user %v: %v", username, err) } return err } @@ -90,3 +89,11 @@ 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 274f39d2..49a729b3 100644 --- a/dataprovider/pgsql.go +++ b/dataprovider/pgsql.go @@ -4,8 +4,6 @@ import ( "database/sql" "fmt" "runtime" - - "github.com/drakkan/sftpgo/logger" ) // PGSQLProvider auth provider for PostgreSQL database @@ -16,6 +14,7 @@ type PGSQLProvider struct { func initializePGSQLProvider() error { var err error var connectionString string + provider = PGSQLProvider{} 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()) @@ -25,12 +24,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) + provider.log(Debug, "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) + provider.log(Warn, "error creating postgres database handler, connection string: %#v, error: %v", connectionString, err) } return err } @@ -50,7 +49,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) + p.log(Warn, "error starting transaction to update quota for user %v: %v", username, err) return err } err = sqlCommonUpdateQuota(username, filesAdd, sizeAdd, reset, p.dbHandle) @@ -60,7 +59,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) + p.log(Warn, "error closing transaction to update quota for user %v: %v", username, err) } return err } @@ -88,3 +87,11 @@ 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 8239d410..5af7c824 100644 --- a/dataprovider/sqlcommon.go +++ b/dataprovider/sqlcommon.go @@ -250,3 +250,16 @@ 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 fe8f2902..a44be0ed 100644 --- a/dataprovider/sqlite.go +++ b/dataprovider/sqlite.go @@ -6,8 +6,6 @@ import ( "fmt" "os" "path/filepath" - - "github.com/drakkan/sftpgo/logger" ) // SQLiteProvider auth provider for SQLite database @@ -18,6 +16,7 @@ type SQLiteProvider struct { func initializeSQLiteProvider(basePath string) error { var err error var connectionString string + provider = SQLiteProvider{} if len(config.ConnectionString) == 0 { dbPath := config.Name if !filepath.IsAbs(dbPath) { @@ -25,7 +24,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"+ + provider.log(Warn, "sqlite database file does not exists, please be sure to create and initialize"+ " a database before starting sftpgo") return err } @@ -39,11 +38,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) + provider.log(Debug, "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) + provider.log(Warn, "error creating sqlite database handler, connection string: %#v, error: %v", connectionString, err) } return err } @@ -89,3 +88,11 @@ 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/dataprovider/sqlqueries.go b/dataprovider/sqlqueries.go index aceaf018..f5f40a71 100644 --- a/dataprovider/sqlqueries.go +++ b/dataprovider/sqlqueries.go @@ -10,7 +10,7 @@ const ( func getSQLPlaceholders() []string { var placeholders []string for i := 1; i <= 20; i++ { - if config.Driver == PGSSQLDataProviderName { + if config.Driver == PGSQLDataProviderName { placeholders = append(placeholders, fmt.Sprintf("$%v", i)) } else { placeholders = append(placeholders, "?") diff --git a/sftpd/handler.go b/sftpd/handler.go index f0dc01ec..35250721 100644 --- a/sftpd/handler.go +++ b/sftpd/handler.go @@ -40,6 +40,20 @@ type Connection struct { sshConn *ssh.ServerConn } +// 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...) + } +} + // Fileread creates a reader for a file on the system and returns the reader back. func (c Connection) Fileread(request *sftp.Request) (io.ReaderAt, error) { updateConnectionActivity(c.ID) @@ -62,11 +76,11 @@ func (c Connection) Fileread(request *sftp.Request) (io.ReaderAt, error) { file, err := os.Open(p) if err != nil { - logger.Error(logSender, c.ID, "could not open file %#v for reading: %v", p, err) + c.Log(Error, logSender, "could not open file %#v for reading: %v", p, err) return nil, sftp.ErrSshFxFailure } - logger.Debug(logSender, c.ID, "fileread requested for path: %#v", p) + c.Log(Debug, logSender, "fileread requested for path: %#v", p) transfer := Transfer{ file: file, @@ -113,13 +127,13 @@ func (c Connection) Filewrite(request *sftp.Request) (io.WriterAt, error) { } if statErr != nil { - logger.Error(logSender, c.ID, "error performing file stat %#v: %v", p, statErr) + c.Log(Error, 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() { - logger.Warn(logSender, c.ID, "attempted to open a directory for writing to: %#v", p) + c.Log(Warn, logSender, "attempted to open a directory for writing to: %#v", p) return nil, sftp.ErrSshFxOpUnsupported } @@ -141,7 +155,7 @@ func (c Connection) Filecmd(request *sftp.Request) error { return sftp.ErrSshFxOpUnsupported } - logger.Debug(logSender, c.ID, "new cmd, method: %v, sourcePath: %#v, targetPath: %#v", request.Method, + c.Log(Debug, logSender, "new cmd, method: %v, sourcePath: %#v, targetPath: %#v", request.Method, p, target) switch request.Method { @@ -204,11 +218,11 @@ func (c Connection) Filelist(request *sftp.Request) (sftp.ListerAt, error) { return nil, sftp.ErrSshFxPermissionDenied } - logger.Debug(logSender, c.ID, "requested list file for dir: %#v", p) + c.Log(Debug, logSender, "requested list file for dir: %#v", p) files, err := ioutil.ReadDir(p) if err != nil { - logger.Error(logSender, c.ID, "error listing directory: %#v", err) + c.Log(Error, logSender, "error listing directory: %#v", err) return nil, sftp.ErrSshFxFailure } @@ -218,12 +232,12 @@ func (c Connection) Filelist(request *sftp.Request) (sftp.ListerAt, error) { return nil, sftp.ErrSshFxPermissionDenied } - logger.Debug(logSender, c.ID, "requested stat for file: %#v", p) + c.Log(Debug, logSender, "requested stat for file: %#v", p) s, err := os.Stat(p) if os.IsNotExist(err) { return nil, sftp.ErrSshFxNoSuchFile } else if err != nil { - logger.Error(logSender, c.ID, "error running STAT on file: %#v", err) + c.Log(Error, logSender, "error running STAT on file: %#v", err) return nil, sftp.ErrSshFxFailure } @@ -253,7 +267,7 @@ func (c Connection) handleSFTPRename(sourcePath string, targetPath string) error return sftp.ErrSshFxPermissionDenied } if err := os.Rename(sourcePath, targetPath); err != nil { - logger.Error(logSender, c.ID, "failed to rename file, source: %#v target: %#v: %v", sourcePath, targetPath, err) + c.Log(Error, 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) @@ -268,11 +282,11 @@ func (c Connection) handleSFTPRmdir(path string) error { numFiles, size, fileList, err := utils.ScanDirContents(path) if err != nil { - logger.Error(logSender, c.ID, "failed to remove directory %#v, scanning error: %v", path, err) + c.Log(Error, logSender, "failed to remove directory %#v, scanning error: %v", path, err) return sftp.ErrSshFxFailure } if err := os.RemoveAll(path); err != nil { - logger.Error(logSender, c.ID, "failed to remove directory %#v: %v", path, err) + c.Log(Error, logSender, "failed to remove directory %#v: %v", path, err) return sftp.ErrSshFxFailure } @@ -289,7 +303,7 @@ func (c Connection) handleSFTPSymlink(sourcePath string, targetPath string) erro return sftp.ErrSshFxPermissionDenied } if err := os.Symlink(sourcePath, targetPath); err != nil { - logger.Warn(logSender, c.ID, "failed to create symlink %#v -> %#v: %v", sourcePath, targetPath, err) + c.Log(Warn, logSender, "failed to create symlink %#v -> %#v: %v", sourcePath, targetPath, err) return sftp.ErrSshFxFailure } @@ -303,7 +317,7 @@ func (c Connection) handleSFTPMkdir(path string) error { } if err := c.createMissingDirs(filepath.Join(path, "testfile")); err != nil { - logger.Error(logSender, c.ID, "error making missing dir for path %#v: %v", path, err) + c.Log(Error, 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) @@ -319,12 +333,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, c.ID, "failed to remove a file %#v: stat error: %v", path, err) + c.Log(Error, 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 { - logger.Error(logSender, c.ID, "failed to remove a file/symlink %#v: %v", path, err) + c.Log(Error, logSender, "failed to remove a file/symlink %#v: %v", path, err) return sftp.ErrSshFxFailure } @@ -339,7 +353,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, c.ID, "denying file write due to space limit") + c.Log(Info, logSender, "denying file write due to space limit") return nil, sftp.ErrSshFxFailure } @@ -351,13 +365,13 @@ func (c Connection) handleSFTPUploadToNewFile(requestPath, filePath string) (io. err := c.createMissingDirs(requestPath) if err != nil { - logger.Error(logSender, c.ID, "error making missing dir for path %#v: %v", requestPath, err) + c.Log(Error, logSender, "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, c.ID, "error creating file %#v: %v", requestPath, err) + c.Log(Error, logSender, "error creating file %#v: %v", requestPath, err) return nil, sftp.ErrSshFxFailure } @@ -384,7 +398,7 @@ func (c Connection) handleSFTPUploadToExistingFile(pflags sftp.FileOpenFlags, re fileSize int64) (io.WriterAt, error) { var err error if !c.hasSpace(false) { - logger.Info(logSender, c.ID, "denying file write due to space limit") + c.Log(Info, logSender, "denying file write due to space limit") return nil, sftp.ErrSshFxFailure } @@ -392,14 +406,14 @@ 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, c.ID, "upload resume is not supported, returning error for file: %#v", requestPath) + c.Log(Info, 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 { - logger.Error(logSender, c.ID, "error renaming existing file for atomic upload, source: %#v, dest: %#v, err: %v", + c.Log(Error, logSender, "error renaming existing file for atomic upload, source: %#v, dest: %#v, err: %v", requestPath, filePath, err) return nil, sftp.ErrSshFxFailure } @@ -407,7 +421,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, c.ID, "error opening existing file, flags: %v, source: %#v, err: %v", pflags, filePath, err) + c.Log(Error, logSender, "error opening existing file, flags: %v, source: %#v, err: %v", pflags, filePath, err) return nil, sftp.ErrSshFxFailure } @@ -439,15 +453,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, c.ID, "quota enforcement not possible for user %v: %v", c.User.Username, err) + c.Log(Warn, logSender, "quota enforcement not possible for user %v: %v", c.User.Username, err) return true } - logger.Warn(logSender, c.ID, "error getting used quota for %v: %v", c.User.Username, err) + c.Log(Warn, 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) { - logger.Debug(logSender, c.ID, "quota exceed for user %v, num files: %v/%v, size: %v/%v check files: %v", + c.Log(Debug, 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 } @@ -468,14 +482,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, c.ID, "error resolving not existent path: %#v", err) + c.Log(Warn, logSender, "error resolving not existent path: %#v", err) } return r, err } err = c.isSubDir(p) if err != nil { - logger.Warn(logSender, c.ID, "Invalid path resolution, dir: %#v outside user home: %#v err: %v", p, c.User.HomeDir, err) + c.Log(Warn, logSender, "Invalid path resolution, dir: %#v outside user home: %#v err: %v", p, c.User.HomeDir, err) } return r, err } @@ -502,7 +516,7 @@ func (c Connection) findNonexistentDirs(path string) ([]string, error) { } err = c.isSubDir(p) if err != nil { - logger.Warn(logSender, c.ID, "Error finding non existing dir: %v", err) + c.Log(Warn, logSender, "Error finding non existing dir: %v", err) } return results, err } @@ -511,7 +525,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, c.ID, "unable to find non existent dirs: %v", err) + c.Log(Warn, logSender, "unable to find non existent dirs: %v", err) return "", err } var parent string @@ -542,11 +556,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, c.ID, "invalid home dir %#v: %v", c.User.HomeDir, err) + c.Log(Warn, logSender, "invalid home dir %#v: %v", c.User.HomeDir, err) return err } if !strings.HasPrefix(sub, parent) { - logger.Warn(logSender, c.ID, "dir %#v is not inside: %#v ", sub, parent) + c.Log(Warn, logSender, "dir %#v is not inside: %#v ", sub, parent) return fmt.Errorf("dir %#v is not inside: %#v", sub, parent) } return nil @@ -561,7 +575,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, c.ID, "error creating missing dir: %#v", d) + c.Log(Error, 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 da97437f..98162a0a 100644 --- a/sftpd/scp.go +++ b/sftpd/scp.go @@ -12,7 +12,6 @@ import ( "time" "github.com/drakkan/sftpgo/dataprovider" - "github.com/drakkan/sftpgo/logger" "github.com/drakkan/sftpgo/utils" "golang.org/x/crypto/ssh" ) @@ -44,7 +43,7 @@ func (c *scpCommand) handle() error { defer removeConnection(c.connection.ID) destPath := c.getDestPath() commandType := c.getCommandType() - logger.Debug(logSenderSCP, c.connection.ID, "handle scp command, args: %v user: %v command type: %v, dest path: %#v", + c.connection.Log(Debug, 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 @@ -85,7 +84,7 @@ func (c *scpCommand) handleRecursiveUpload() error { } if strings.HasPrefix(command, "E") { numDirs-- - logger.Debug(logSenderSCP, c.connection.ID, "received end dir command, num dirs: %v", numDirs) + c.connection.Log(Debug, logSenderSCP, "received end dir command, num dirs: %v", numDirs) if numDirs == 0 { // upload is now complete send confirmation message err = c.sendConfirmationMessage() @@ -108,7 +107,7 @@ func (c *scpCommand) handleRecursiveUpload() error { if err != nil { return err } - logger.Debug(logSenderSCP, c.connection.ID, "received start dir command, num dirs: %v destPath: %#v", numDirs, destPath) + c.connection.Log(Debug, 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 { @@ -127,14 +126,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, c.connection.ID, "error creating dir: %#v, permission denied", dirPath) + c.connection.Log(Warn, logSenderSCP, "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, c.connection.ID, "error creating dir: %#v, invalid file path, err: %v", dirPath, err) + c.connection.Log(Warn, logSenderSCP, "error creating dir: %#v, invalid file path, err: %v", dirPath, err) c.sendErrorMessage(err.Error()) return err } @@ -143,7 +142,7 @@ func (c *scpCommand) handleCreateDir(dirPath string) error { if err != nil { return err } - logger.CommandLog(mkdirLogSender, dirPath, "", c.connection.User.Username, c.connection.ID, c.connection.protocol) + c.connection.Log(Debug, mkdirLogSender, "created dir %#v", dirPath) return nil } @@ -191,7 +190,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, c.connection.ID, "error uploading file: %#v, err: %v", filePath, err) + c.connection.Log(Warn, logSenderSCP, "error uploading file: %#v, err: %v", filePath, err) c.sendErrorMessage(err.Error()) return err } @@ -199,7 +198,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, c.connection.ID, "error uploading file: %#v, permission denied", requestPath) + c.connection.Log(Warn, logSenderSCP, "error uploading file: %#v, permission denied", requestPath) c.sendErrorMessage(err.Error()) return err } @@ -207,7 +206,7 @@ func (c *scpCommand) handleUploadFile(requestPath, filePath string, sizeToRead i file, err := os.Create(filePath) if err != nil { - logger.Error(logSenderSCP, "error creating file %#v: %v", requestPath, err) + c.connection.Log(Error, logSenderSCP, "error creating file %#v: %v", requestPath, err) c.sendErrorMessage(err.Error()) return err } @@ -238,14 +237,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, c.connection.ID, "error uploading file: %#v, permission denied", uploadFilePath) + c.connection.Log(Warn, logSenderSCP, "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, c.connection.ID, "error uploading file: %#v, err: %v", uploadFilePath, err) + c.connection.Log(Warn, logSenderSCP, "error uploading file: %#v, err: %v", uploadFilePath, err) c.sendErrorMessage(err.Error()) return err } @@ -259,13 +258,13 @@ func (c *scpCommand) handleUpload(uploadFilePath string, sizeToRead int64) error } if statErr != nil { - logger.Error(logSenderSCP, "error performing file stat %#v: %v", p, statErr) + c.connection.Log(Error, logSenderSCP, "error performing file stat %#v: %v", p, statErr) c.sendErrorMessage(err.Error()) return err } if stat.IsDir() { - logger.Warn(logSenderSCP, c.connection.ID, "attempted to open a directory for writing to: %#v", p) + c.connection.Log(Warn, 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 @@ -274,7 +273,7 @@ func (c *scpCommand) handleUpload(uploadFilePath string, sizeToRead int64) error if uploadMode == uploadModeAtomic { err = os.Rename(p, filePath) if err != nil { - logger.Error(logSenderSCP, "error renaming existing file for atomic upload, source: %#v, dest: %#v, err: %v", + c.connection.Log(Error, logSenderSCP, "error renaming existing file for atomic upload, source: %#v, dest: %#v, err: %v", p, filePath, err) c.sendErrorMessage(err.Error()) return err @@ -315,7 +314,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, c.connection.ID, "recursive download, dir path: %#v", dirPath) + c.connection.Log(Debug, logSenderSCP, "recursive download, dir path: %#v", dirPath) err = c.sendDownloadProtocolMessages(dirPath, stat) if err != nil { return err @@ -425,21 +424,21 @@ func (c *scpCommand) handleDownload(filePath string) error { if !c.connection.User.HasPerm(dataprovider.PermDownload) { err := fmt.Errorf("Permission denied") - logger.Warn(logSenderSCP, c.connection.ID, "error downloading file: %#v, permission denied", filePath) + c.connection.Log(Warn, 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") - logger.Warn(logSenderSCP, c.connection.ID, "error downloading file: %#v, invalid file path", filePath) + c.connection.Log(Warn, 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) { - logger.Warn(logSenderSCP, c.connection.ID, "error downloading file: %#v, err: %v", p, err) + c.connection.Log(Warn, logSenderSCP, "error downloading file: %#v, err: %v", p, err) c.sendErrorMessage(err.Error()) return err } @@ -451,7 +450,7 @@ func (c *scpCommand) handleDownload(filePath string) error { file, err := os.Open(p) if err != nil { - logger.Error(logSenderSCP, "could not open file %#v for reading: %v", p, err) + c.connection.Log(Error, logSenderSCP, "could not open file %#v for reading: %v", p, err) c.sendErrorMessage(err.Error()) return err } @@ -526,7 +525,7 @@ func (c *scpCommand) readConfirmationMessage() error { msg.WriteString(string(readed)) } } - logger.Info(logSenderSCP, "scp error message received: %v is error: %v", msg.String(), isError) + c.connection.Log(Info, logSenderSCP, "scp error message received: %v is error: %v", msg.String(), isError) err = fmt.Errorf("%v", msg.String()) c.channel.Close() } @@ -579,7 +578,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, c.connection.ID, "error sending protocol message: %v, err: %v", message, err) + c.connection.Log(Warn, logSenderSCP, "error sending protocol message: %v, err: %v", message, err) c.channel.Close() } return err @@ -594,7 +593,7 @@ func (c *scpCommand) sendExitStatus(err error) { ex := exitStatusMsg{ Status: status, } - logger.Debug(logSenderSCP, c.connection.ID, "send exit status for command with args: %v user: %v err: %v", + c.connection.Log(Debug, 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() @@ -625,7 +624,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 { - logger.Error(logSenderSCP, "error creating dir: %v", dirPath) + c.connection.Log(Error, logSenderSCP, "error creating dir: %v", dirPath) c.sendErrorMessage(err.Error()) return err } @@ -645,7 +644,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, c.connection.ID, "error: %v", err) + c.connection.Log(Warn, logSenderSCP, "error: %v", err) c.sendErrorMessage(err.Error()) return size, name, err } @@ -653,20 +652,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, c.connection.ID, "error getting size from upload message: %v", err) + c.connection.Log(Warn, 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") - logger.Warn(logSenderSCP, c.connection.ID, "error: %v", err) + c.connection.Log(Warn, logSenderSCP, "error: %v", err) c.sendErrorMessage(err.Error()) return size, name, err } } else { err = fmt.Errorf("Error splitting upload message: %v", command) - logger.Warn(logSenderSCP, c.connection.ID, "error: %v", err) + c.connection.Log(Warn, logSenderSCP, "error: %v", err) c.sendErrorMessage(err.Error()) return size, name, err } diff --git a/sftpd/server.go b/sftpd/server.go index fe120292..4b06339e 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, } - logger.Info(logSender, connectionID, "User id: %d, logged in with: %#v, name: %#v, home_dir: %#v", + connection.Log(Info, 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" { - logger.Debug(logSender, connectionID, "received an unknown channel type: %v", newChannel.ChannelType()) + connection.Log(Debug, 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 { - logger.Warn(logSender, connectionID, "could not accept a channel: %v", err) + connection.Log(Warn, logSender, "could not accept a channel: %v", err) continue } @@ -270,7 +270,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, connectionID, "new exec command: %v args: %v user: %v, error: %v", name, scpArgs, + connection.Log(Debug, 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 +300,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.ID, "connection closed") + connection.Log(Debug, logSenderSCP, "connection closed") server.Close() } else if err != nil { - logger.Error(logSender, connection.ID, "sftp connection closed with error: %v", err) + connection.Log(Error, logSenderSCP, "sftp connection closed with error: %v", err) } removeConnection(connection.ID) diff --git a/sftpd/sftpd.go b/sftpd/sftpd.go index fd52711c..25090659 100644 --- a/sftpd/sftpd.go +++ b/sftpd/sftpd.go @@ -34,6 +34,11 @@ const ( operationRename = "rename" protocolSFTP = "SFTP" protocolSCP = "SCP" + + Debug = "debug" + Info = "info" + Warn = "warn" + Error = "error" ) var ( @@ -173,7 +178,7 @@ func CloseActiveConnection(connectionID string) bool { defer mutex.RUnlock() for _, c := range openConnections { if c.ID == connectionID { - logger.Debug(logSender, connectionID, "closing connection") + c.Log(Debug, logSender, "closing connection") c.sshConn.Close() result = true break @@ -247,33 +252,36 @@ func CheckIdleConnections() { if t.connectionID == c.ID { transferIdleTime := time.Since(t.lastActivity) if transferIdleTime < idleTime { - logger.Debug(logSender, c.ID, "idle time: %v setted to transfer idle time: %v", + c.Log(Debug, logSender, "idle time: %v setted to transfer idle time: %v", idleTime, transferIdleTime) idleTime = transferIdleTime } } } if idleTime > idleTimeout { - logger.Debug(logSender, c.ID, "close idle connection, idle time: %v", idleTime) + c.Log(Info, logSender, "close idle connection, idle time: %v", idleTime) err := c.sshConn.Close() - logger.Debug(logSender, c.ID, "idle connection closed, err: %v", err) + if err != nil { + c.Log(Warn, logSender, "idle connection close failed: %v", err) + } } } logger.Debug(logSender, "", "check idle connections ended") } -func addConnection(id string, conn Connection) { +func addConnection(id string, c Connection) { mutex.Lock() defer mutex.Unlock() - openConnections[id] = conn - logger.Debug(logSender, id, "connection added, num open connections: %v", len(openConnections)) + openConnections[id] = c + c.Log(Debug, logSender, "connection added, num open connections: %v", len(openConnections)) } func removeConnection(id string) { mutex.Lock() defer mutex.Unlock() + c := openConnections[id] delete(openConnections, id) - logger.Debug(logSender, id, "connection removed, num open connections: %v", len(openConnections)) + c.Log(Debug, logSender, "connection removed, num open connections: %v", len(openConnections)) } func addTransfer(transfer *Transfer) {