Refactor the logging system

* created a "Log" function for type "Connection"
* created a "log" function for type "Provider"
* replace logger calls to Log/log where possible

I also renamed PGSSQL to PGSQL, as this seemed to be a typo

Signed-off-by: Jo Vandeginste <Jo.Vandeginste@kuleuven.be>
This commit is contained in:
Jo Vandeginste
2019-09-06 11:23:06 +02:00
committed by drakkan
parent a7363a16be
commit abbb7f272b
11 changed files with 176 additions and 106 deletions

View File

@@ -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
}

View File

@@ -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 {

View File

@@ -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
}

View File

@@ -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
}

View File

@@ -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...)
}
}

View File

@@ -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
}

View File

@@ -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, "?")

View File

@@ -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())

View File

@@ -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
}

View File

@@ -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)

View File

@@ -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) {