Mirrors/sftpgo
1
0
Fork 0
mirror of https://github.com/drakkan/sftpgo.git synced 2025-12-07 06:40:54 +03:00
Code Issues Packages Projects Releases Wiki Activity

improve logging

Browse Source 
this partially revert #45
This commit is contained in:
Nicola Murino
2019-09-06 15:19:01 +02:00
parent abbb7f272b
commit 4f1c2c094f
11 changed files with 155 additions and 181 deletions
Download Patch File Download Diff File Expand all files Collapse all files

25
dataprovider/bolt.go
View File

@@ -8,6 +8,7 @@ import (
"path/filepath" "path/filepath"
"time" "time"
"github.com/drakkan/sftpgo/logger"
"github.com/drakkan/sftpgo/utils" "github.com/drakkan/sftpgo/utils"
bolt "go.etcd.io/bbolt" bolt "go.etcd.io/bbolt"
) )
@@ -24,7 +25,7 @@ type BoltProvider struct {
func initializeBoltProvider(basePath string) error { func initializeBoltProvider(basePath string) error {
var err error var err error
provider = BoltProvider{} logSender = BoltDataProviderName
dbPath := config.Name dbPath := config.Name
if !filepath.IsAbs(dbPath) { if !filepath.IsAbs(dbPath) {
dbPath = filepath.Join(basePath, dbPath) dbPath = filepath.Join(basePath, dbPath)
@@ -34,13 +35,13 @@ func initializeBoltProvider(basePath string) error {
FreelistType: bolt.FreelistArrayType, FreelistType: bolt.FreelistArrayType,
Timeout: 5 * time.Second}) Timeout: 5 * time.Second})
if err == nil { 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 { err = dbHandle.Update(func(tx *bolt.Tx) error {
_, e := tx.CreateBucketIfNotExists(usersBucket) _, e := tx.CreateBucketIfNotExists(usersBucket)
return e return e
}) })
if err != nil { if err != nil {
provider.log(Warn, "error creating users bucket: %v", err) providerLog(logger.LevelWarn, "error creating users bucket: %v", err)
return err return err
} }
err = dbHandle.Update(func(tx *bolt.Tx) error { err = dbHandle.Update(func(tx *bolt.Tx) error {
@@ -48,12 +49,12 @@ func initializeBoltProvider(basePath string) error {
return e return e
}) })
if err != nil { 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 return err
} }
provider = BoltProvider{dbHandle: dbHandle} provider = BoltProvider{dbHandle: dbHandle}
} else { } 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 return err
} }
@@ -65,7 +66,7 @@ func (p BoltProvider) validateUserAndPass(username string, password string) (Use
} }
user, err := p.userExists(username) user, err := p.userExists(username)
if err != nil { 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 user, err
} }
return checkUserAndPass(user, password) return checkUserAndPass(user, password)
@@ -78,7 +79,7 @@ func (p BoltProvider) validateUserAndPubKey(username string, pubKey string) (Use
} }
user, err := p.userExists(username) user, err := p.userExists(username)
if err != nil { 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 user, "", err
} }
return checkUserAndPubKey(user, pubKey) 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) { func (p BoltProvider) getUsedQuota(username string) (int, int64, error) {
user, err := p.userExists(username) user, err := p.userExists(username)
if err != nil { 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 0, 0, err
} }
return user.UsedQuotaFiles, user.UsedQuotaSize, 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 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
}

21
dataprovider/dataprovider.go
View File

@@ -35,7 +35,6 @@ const (
// BoltDataProviderName name for bbolt key/value store provider // BoltDataProviderName name for bbolt key/value store provider
BoltDataProviderName = "bolt" BoltDataProviderName = "bolt"
logSender = "dataProvider"
argonPwdPrefix = "$argon2id$" argonPwdPrefix = "$argon2id$"
bcryptPwdPrefix = "$2a$" bcryptPwdPrefix = "$2a$"
pbkdf2SHA1Prefix = "$pbkdf2-sha1$" pbkdf2SHA1Prefix = "$pbkdf2-sha1$"
@@ -43,11 +42,6 @@ const (
pbkdf2SHA512Prefix = "$pbkdf2-sha512$" pbkdf2SHA512Prefix = "$pbkdf2-sha512$"
manageUsersDisabledError = "please set manage_users to 1 in sftpgo.conf to enable this method" 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" trackQuotaDisabledError = "please enable track_quota in sftpgo.conf to use this method"
Debug = "debug"
Info = "info"
Warn = "warn"
Error = "error"
) )
var ( var (
@@ -60,6 +54,7 @@ var (
PermCreateDirs, PermCreateSymlinks} PermCreateDirs, PermCreateSymlinks}
hashPwdPrefixes = []string{argonPwdPrefix, bcryptPwdPrefix, pbkdf2SHA1Prefix, pbkdf2SHA256Prefix, pbkdf2SHA512Prefix} hashPwdPrefixes = []string{argonPwdPrefix, bcryptPwdPrefix, pbkdf2SHA1Prefix, pbkdf2SHA256Prefix, pbkdf2SHA512Prefix}
pbkdfPwdPrefixes = []string{pbkdf2SHA1Prefix, pbkdf2SHA256Prefix, pbkdf2SHA512Prefix} pbkdfPwdPrefixes = []string{pbkdf2SHA1Prefix, pbkdf2SHA256Prefix, pbkdf2SHA512Prefix}
logSender = "dataProvider"
) )
// Config provider configuration // Config provider configuration
@@ -146,8 +141,6 @@ type Provider interface {
deleteUser(user User) error deleteUser(user User) error
getUsers(limit int, offset int, order string, username string) ([]User, error) getUsers(limit int, offset int, order string, username string) ([]User, error)
getUserByID(ID int64) (User, error) getUserByID(ID int64) (User, error)
log(level string, format string, v ...interface{})
providerName() string
} }
// Initialize the data provider. // Initialize the data provider.
@@ -282,19 +275,19 @@ func checkUserAndPass(user User, password string) (User, error) {
if strings.HasPrefix(user.Password, argonPwdPrefix) { if strings.HasPrefix(user.Password, argonPwdPrefix) {
match, err = argon2id.ComparePasswordAndHash(password, user.Password) match, err = argon2id.ComparePasswordAndHash(password, user.Password)
if err != nil { 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 return user, err
} }
} else if strings.HasPrefix(user.Password, bcryptPwdPrefix) { } else if strings.HasPrefix(user.Password, bcryptPwdPrefix) {
if err = bcrypt.CompareHashAndPassword([]byte(user.Password), []byte(password)); err != nil { 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 return user, err
} }
match = true match = true
} else if utils.IsStringPrefixInSlice(user.Password, pbkdfPwdPrefixes) { } else if utils.IsStringPrefixInSlice(user.Password, pbkdfPwdPrefixes) {
match, err = comparePbkdf2PasswordAndHash(password, user.Password) match, err = comparePbkdf2PasswordAndHash(password, user.Password)
if err != nil { 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 return user, err
} }
} }
@@ -311,7 +304,7 @@ func checkUserAndPubKey(user User, pubKey string) (User, string, error) {
for i, k := range user.PublicKeys { for i, k := range user.PublicKeys {
storedPubKey, comment, _, _, err := ssh.ParseAuthorizedKey([]byte(k)) storedPubKey, comment, _, _, err := ssh.ParseAuthorizedKey([]byte(k))
if err != nil { 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 return user, "", err
} }
if string(storedPubKey.Marshal()) == pubKey { if string(storedPubKey.Marshal()) == pubKey {
@@ -377,3 +370,7 @@ func getSSLMode() string {
} }
return "" return ""
} }
func providerLog(level logger.LogLevel, format string, v ...interface{}) {
logger.Log(level, logSender, "", format, v...)
}

20
dataprovider/mysql.go
View File

@@ -5,6 +5,8 @@ import (
"fmt" "fmt"
"runtime" "runtime"
"time" "time"
"github.com/drakkan/sftpgo/logger"
) )
// MySQLProvider auth provider for MySQL/MariaDB database // MySQLProvider auth provider for MySQL/MariaDB database
@@ -15,7 +17,7 @@ type MySQLProvider struct {
func initializeMySQLProvider() error { func initializeMySQLProvider() error {
var err error var err error
var connectionString string var connectionString string
provider = MySQLProvider{} logSender = MySQLDataProviderName
if len(config.ConnectionString) == 0 { if len(config.ConnectionString) == 0 {
connectionString = fmt.Sprintf("%v:%v@tcp([%v]:%v)/%v?charset=utf8&interpolateParams=true&timeout=10s&tls=%v", 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()) config.Username, config.Password, config.Host, config.Port, config.Name, getSSLMode())
@@ -25,13 +27,13 @@ func initializeMySQLProvider() error {
dbHandle, err := sql.Open("mysql", connectionString) dbHandle, err := sql.Open("mysql", connectionString)
if err == nil { if err == nil {
numCPU := runtime.NumCPU() 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.SetMaxIdleConns(numCPU)
dbHandle.SetMaxOpenConns(numCPU) dbHandle.SetMaxOpenConns(numCPU)
dbHandle.SetConnMaxLifetime(1800 * time.Second) dbHandle.SetConnMaxLifetime(1800 * time.Second)
provider = MySQLProvider{dbHandle: dbHandle} provider = MySQLProvider{dbHandle: dbHandle}
} else { } 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 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 { func (p MySQLProvider) updateQuota(username string, filesAdd int, sizeAdd int64, reset bool) error {
tx, err := p.dbHandle.Begin() tx, err := p.dbHandle.Begin()
if err != nil { 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 return err
} }
err = sqlCommonUpdateQuota(username, filesAdd, sizeAdd, reset, p.dbHandle) 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() err = tx.Rollback()
} }
if err != nil { 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 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) { func (p MySQLProvider) getUsers(limit int, offset int, order string, username string) ([]User, error) {
return sqlCommonGetUsers(limit, offset, order, username, p.dbHandle) 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
}

20
dataprovider/pgsql.go
View File

@@ -4,6 +4,8 @@ import (
"database/sql" "database/sql"
"fmt" "fmt"
"runtime" "runtime"
"github.com/drakkan/sftpgo/logger"
) )
// PGSQLProvider auth provider for PostgreSQL database // PGSQLProvider auth provider for PostgreSQL database
@@ -14,7 +16,7 @@ type PGSQLProvider struct {
func initializePGSQLProvider() error { func initializePGSQLProvider() error {
var err error var err error
var connectionString string var connectionString string
provider = PGSQLProvider{} logSender = PGSQLDataProviderName
if len(config.ConnectionString) == 0 { if len(config.ConnectionString) == 0 {
connectionString = fmt.Sprintf("host='%v' port=%v dbname='%v' user='%v' password='%v' sslmode=%v connect_timeout=10", 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()) config.Host, config.Port, config.Name, config.Username, config.Password, getSSLMode())
@@ -24,12 +26,12 @@ func initializePGSQLProvider() error {
dbHandle, err := sql.Open("postgres", connectionString) dbHandle, err := sql.Open("postgres", connectionString)
if err == nil { if err == nil {
numCPU := runtime.NumCPU() 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.SetMaxIdleConns(numCPU)
dbHandle.SetMaxOpenConns(numCPU) dbHandle.SetMaxOpenConns(numCPU)
provider = PGSQLProvider{dbHandle: dbHandle} provider = PGSQLProvider{dbHandle: dbHandle}
} else { } 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 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 { func (p PGSQLProvider) updateQuota(username string, filesAdd int, sizeAdd int64, reset bool) error {
tx, err := p.dbHandle.Begin() tx, err := p.dbHandle.Begin()
if err != nil { 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 return err
} }
err = sqlCommonUpdateQuota(username, filesAdd, sizeAdd, reset, p.dbHandle) 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() err = tx.Rollback()
} }
if err != nil { 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 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) { func (p PGSQLProvider) getUsers(limit int, offset int, order string, username string) ([]User, error) {
return sqlCommonGetUsers(limit, offset, order, username, p.dbHandle) 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
}

41
dataprovider/sqlcommon.go
View File

@@ -15,7 +15,7 @@ func getUserByUsername(username string, dbHandle *sql.DB) (User, error) {
q := getUserByUsernameQuery() q := getUserByUsernameQuery()
stmt, err := dbHandle.Prepare(q) stmt, err := dbHandle.Prepare(q)
if err != nil { 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 return user, err
} }
defer stmt.Close() defer stmt.Close()
@@ -31,7 +31,7 @@ func sqlCommonValidateUserAndPass(username string, password string, dbHandle *sq
} }
user, err := getUserByUsername(username, dbHandle) user, err := getUserByUsername(username, dbHandle)
if err != nil { 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 user, err
} }
return checkUserAndPass(user, password) return checkUserAndPass(user, password)
@@ -44,7 +44,7 @@ func sqlCommonValidateUserAndPubKey(username string, pubKey string, dbHandle *sq
} }
user, err := getUserByUsername(username, dbHandle) user, err := getUserByUsername(username, dbHandle)
if err != nil { 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 user, "", err
} }
return checkUserAndPubKey(user, pubKey) return checkUserAndPubKey(user, pubKey)
@@ -55,7 +55,7 @@ func sqlCommonGetUserByID(ID int64, dbHandle *sql.DB) (User, error) {
q := getUserByIDQuery() q := getUserByIDQuery()
stmt, err := dbHandle.Prepare(q) stmt, err := dbHandle.Prepare(q)
if err != nil { 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 return user, err
} }
defer stmt.Close() defer stmt.Close()
@@ -68,16 +68,16 @@ func sqlCommonUpdateQuota(username string, filesAdd int, sizeAdd int64, reset bo
q := getUpdateQuotaQuery(reset) q := getUpdateQuotaQuery(reset)
stmt, err := dbHandle.Prepare(q) stmt, err := dbHandle.Prepare(q)
if err != nil { 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 return err
} }
defer stmt.Close() defer stmt.Close()
_, err = stmt.Exec(sizeAdd, filesAdd, utils.GetTimeAsMsSinceEpoch(time.Now()), username) _, err = stmt.Exec(sizeAdd, filesAdd, utils.GetTimeAsMsSinceEpoch(time.Now()), username)
if err == nil { 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) username, filesAdd, sizeAdd, reset)
} else { } 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 return err
} }
@@ -86,7 +86,7 @@ func sqlCommonGetUsedQuota(username string, dbHandle *sql.DB) (int, int64, error
q := getQuotaQuery() q := getQuotaQuery()
stmt, err := dbHandle.Prepare(q) stmt, err := dbHandle.Prepare(q)
if err != nil { 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 return 0, 0, err
} }
defer stmt.Close() defer stmt.Close()
@@ -95,7 +95,7 @@ func sqlCommonGetUsedQuota(username string, dbHandle *sql.DB) (int, int64, error
var usedSize int64 var usedSize int64
err = stmt.QueryRow(username).Scan(&usedSize, &usedFiles) err = stmt.QueryRow(username).Scan(&usedSize, &usedFiles)
if err != nil { 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 0, 0, err
} }
return usedFiles, usedSize, err return usedFiles, usedSize, err
@@ -106,7 +106,7 @@ func sqlCommonCheckUserExists(username string, dbHandle *sql.DB) (User, error) {
q := getUserByUsernameQuery() q := getUserByUsernameQuery()
stmt, err := dbHandle.Prepare(q) stmt, err := dbHandle.Prepare(q)
if err != nil { 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 return user, err
} }
defer stmt.Close() defer stmt.Close()
@@ -122,7 +122,7 @@ func sqlCommonAddUser(user User, dbHandle *sql.DB) error {
q := getAddUserQuery() q := getAddUserQuery()
stmt, err := dbHandle.Prepare(q) stmt, err := dbHandle.Prepare(q)
if err != nil { 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 return err
} }
defer stmt.Close() defer stmt.Close()
@@ -147,7 +147,7 @@ func sqlCommonUpdateUser(user User, dbHandle *sql.DB) error {
q := getUpdateUserQuery() q := getUpdateUserQuery()
stmt, err := dbHandle.Prepare(q) stmt, err := dbHandle.Prepare(q)
if err != nil { 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 return err
} }
defer stmt.Close() defer stmt.Close()
@@ -168,7 +168,7 @@ func sqlCommonDeleteUser(user User, dbHandle *sql.DB) error {
q := getDeleteUserQuery() q := getDeleteUserQuery()
stmt, err := dbHandle.Prepare(q) stmt, err := dbHandle.Prepare(q)
if err != nil { 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 return err
} }
defer stmt.Close() defer stmt.Close()
@@ -181,7 +181,7 @@ func sqlCommonGetUsers(limit int, offset int, order string, username string, dbH
q := getUsersQuery(order, username) q := getUsersQuery(order, username)
stmt, err := dbHandle.Prepare(q) stmt, err := dbHandle.Prepare(q)
if err != nil { 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 return nil, err
} }
defer stmt.Close() defer stmt.Close()
@@ -250,16 +250,3 @@ func getUserFromDbRow(row *sql.Row, rows *sql.Rows) (User, error) {
} }
return user, err 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...)
}
}

19
dataprovider/sqlite.go
View File

@@ -6,6 +6,8 @@ import (
"fmt" "fmt"
"os" "os"
"path/filepath" "path/filepath"
"github.com/drakkan/sftpgo/logger"
) )
// SQLiteProvider auth provider for SQLite database // SQLiteProvider auth provider for SQLite database
@@ -16,7 +18,7 @@ type SQLiteProvider struct {
func initializeSQLiteProvider(basePath string) error { func initializeSQLiteProvider(basePath string) error {
var err error var err error
var connectionString string var connectionString string
provider = SQLiteProvider{} logSender = SQLiteDataProviderName
if len(config.ConnectionString) == 0 { if len(config.ConnectionString) == 0 {
dbPath := config.Name dbPath := config.Name
if !filepath.IsAbs(dbPath) { if !filepath.IsAbs(dbPath) {
@@ -24,7 +26,7 @@ func initializeSQLiteProvider(basePath string) error {
} }
fi, err := os.Stat(dbPath) fi, err := os.Stat(dbPath)
if err != nil { 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") " a database before starting sftpgo")
return err return err
} }
@@ -38,11 +40,12 @@ func initializeSQLiteProvider(basePath string) error {
} }
dbHandle, err := sql.Open("sqlite3", connectionString) dbHandle, err := sql.Open("sqlite3", connectionString)
if err == nil { 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) dbHandle.SetMaxOpenConns(1)
provider = SQLiteProvider{dbHandle: dbHandle} provider = SQLiteProvider{dbHandle: dbHandle}
} else { } 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 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) { func (p SQLiteProvider) getUsers(limit int, offset int, order string, username string) ([]User, error) {
return sqlCommonGetUsers(limit, offset, order, username, p.dbHandle) 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
}

26
logger/logger.go
View File

@@ -22,6 +22,17 @@ const (
dateFormat = "2006-01-02T15:04.05.000" // YYYY-MM-DDTHH:MM.SS.ZZZ 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 ( var (
logger zerolog.Logger logger zerolog.Logger
consoleLogger 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) 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 // Debug logs at debug level for the specified sender
func Debug(sender string, connectionID string, format string, v ...interface{}) { func Debug(sender string, connectionID string, format string, v ...interface{}) {
logger.Debug().Str("sender", sender).Str("connection_id", connectionID).Msg(fmt.Sprintf(format, v...)) logger.Debug().Str("sender", sender).Str("connection_id", connectionID).Msg(fmt.Sprintf(format, v...))

79
sftpd/handler.go
View File

@@ -41,17 +41,8 @@ type Connection struct {
} }
// Log outputs a log entry to the configured logger // Log outputs a log entry to the configured logger
func (c Connection) Log(level string, sender string, format string, v ...interface{}) { func (c Connection) Log(level logger.LogLevel, sender string, format string, v ...interface{}) {
switch level { logger.Log(level, sender, c.ID, format, v...)
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. // 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) file, err := os.Open(p)
if err != nil { 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 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{ transfer := Transfer{
file: file, file: file,
@@ -127,13 +118,13 @@ func (c Connection) Filewrite(request *sftp.Request) (io.WriterAt, error) {
} }
if statErr != nil { 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 return nil, sftp.ErrSshFxFailure
} }
// This happen if we upload a file that has the same name of an existing directory // This happen if we upload a file that has the same name of an existing directory
if stat.IsDir() { 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 return nil, sftp.ErrSshFxOpUnsupported
} }
@@ -155,7 +146,7 @@ func (c Connection) Filecmd(request *sftp.Request) error {
return sftp.ErrSshFxOpUnsupported 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) p, target)
switch request.Method { switch request.Method {
@@ -218,11 +209,11 @@ func (c Connection) Filelist(request *sftp.Request) (sftp.ListerAt, error) {
return nil, sftp.ErrSshFxPermissionDenied 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) files, err := ioutil.ReadDir(p)
if err != nil { 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 return nil, sftp.ErrSshFxFailure
} }
@@ -232,12 +223,12 @@ func (c Connection) Filelist(request *sftp.Request) (sftp.ListerAt, error) {
return nil, sftp.ErrSshFxPermissionDenied 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) s, err := os.Stat(p)
if os.IsNotExist(err) { if os.IsNotExist(err) {
return nil, sftp.ErrSshFxNoSuchFile return nil, sftp.ErrSshFxNoSuchFile
} else if err != nil { } 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 return nil, sftp.ErrSshFxFailure
} }
@@ -267,7 +258,7 @@ func (c Connection) handleSFTPRename(sourcePath string, targetPath string) error
return sftp.ErrSshFxPermissionDenied return sftp.ErrSshFxPermissionDenied
} }
if err := os.Rename(sourcePath, targetPath); err != nil { 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 return sftp.ErrSshFxFailure
} }
logger.CommandLog(renameLogSender, sourcePath, targetPath, c.User.Username, c.ID, c.protocol) 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) numFiles, size, fileList, err := utils.ScanDirContents(path)
if err != nil { 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 return sftp.ErrSshFxFailure
} }
if err := os.RemoveAll(path); err != nil { 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 return sftp.ErrSshFxFailure
} }
@@ -303,7 +294,7 @@ func (c Connection) handleSFTPSymlink(sourcePath string, targetPath string) erro
return sftp.ErrSshFxPermissionDenied return sftp.ErrSshFxPermissionDenied
} }
if err := os.Symlink(sourcePath, targetPath); err != nil { 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 return sftp.ErrSshFxFailure
} }
@@ -317,7 +308,7 @@ func (c Connection) handleSFTPMkdir(path string) error {
} }
if err := c.createMissingDirs(filepath.Join(path, "testfile")); err != nil { 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 return sftp.ErrSshFxFailure
} }
logger.CommandLog(mkdirLogSender, path, "", c.User.Username, c.ID, c.protocol) 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 fi os.FileInfo
var err error var err error
if fi, err = os.Lstat(path); err != nil { 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 return sftp.ErrSshFxFailure
} }
size = fi.Size() size = fi.Size()
if err := os.Remove(path); err != nil { 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 return sftp.ErrSshFxFailure
} }
@@ -353,7 +344,7 @@ func (c Connection) handleSFTPRemove(path string) error {
func (c Connection) handleSFTPUploadToNewFile(requestPath, filePath string) (io.WriterAt, error) { func (c Connection) handleSFTPUploadToNewFile(requestPath, filePath string) (io.WriterAt, error) {
if !c.hasSpace(true) { 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 return nil, sftp.ErrSshFxFailure
} }
@@ -365,13 +356,13 @@ func (c Connection) handleSFTPUploadToNewFile(requestPath, filePath string) (io.
err := c.createMissingDirs(requestPath) err := c.createMissingDirs(requestPath)
if err != nil { 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 return nil, sftp.ErrSshFxFailure
} }
file, err := os.Create(filePath) file, err := os.Create(filePath)
if err != nil { 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 return nil, sftp.ErrSshFxFailure
} }
@@ -398,7 +389,7 @@ func (c Connection) handleSFTPUploadToExistingFile(pflags sftp.FileOpenFlags, re
fileSize int64) (io.WriterAt, error) { fileSize int64) (io.WriterAt, error) {
var err error var err error
if !c.hasSpace(false) { 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 return nil, sftp.ErrSshFxFailure
} }
@@ -406,14 +397,14 @@ func (c Connection) handleSFTPUploadToExistingFile(pflags sftp.FileOpenFlags, re
if osFlags&os.O_TRUNC == 0 { if osFlags&os.O_TRUNC == 0 {
// see https://github.com/pkg/sftp/issues/295 // 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 return nil, sftp.ErrSshFxOpUnsupported
} }
if uploadMode == uploadModeAtomic { if uploadMode == uploadModeAtomic {
err = os.Rename(requestPath, filePath) err = os.Rename(requestPath, filePath)
if err != nil { 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) requestPath, filePath, err)
return nil, sftp.ErrSshFxFailure return nil, sftp.ErrSshFxFailure
} }
@@ -421,7 +412,7 @@ func (c Connection) handleSFTPUploadToExistingFile(pflags sftp.FileOpenFlags, re
// we use 0666 so the umask is applied // we use 0666 so the umask is applied
file, err := os.OpenFile(filePath, osFlags, 0666) file, err := os.OpenFile(filePath, osFlags, 0666)
if err != nil { 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 return nil, sftp.ErrSshFxFailure
} }
@@ -453,15 +444,15 @@ func (c Connection) hasSpace(checkFiles bool) bool {
numFile, size, err := dataprovider.GetUsedQuota(dataProvider, c.User.Username) numFile, size, err := dataprovider.GetUsedQuota(dataProvider, c.User.Username)
if err != nil { if err != nil {
if _, ok := err.(*dataprovider.MethodDisabledError); ok { 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 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 return false
} }
if (checkFiles && c.User.QuotaFiles > 0 && numFile >= c.User.QuotaFiles) || if (checkFiles && c.User.QuotaFiles > 0 && numFile >= c.User.QuotaFiles) ||
(c.User.QuotaSize > 0 && size >= c.User.QuotaSize) { (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) c.User.Username, numFile, c.User.QuotaFiles, size, c.User.QuotaSize, checkFiles)
return false 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. // path chain until we hit a directory that _does_ exist and can be validated.
_, err = c.findFirstExistingDir(r) _, err = c.findFirstExistingDir(r)
if err != nil { 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 return r, err
} }
err = c.isSubDir(p) err = c.isSubDir(p)
if err != nil { 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 return r, err
} }
@@ -516,7 +507,7 @@ func (c Connection) findNonexistentDirs(path string) ([]string, error) {
} }
err = c.isSubDir(p) err = c.isSubDir(p)
if err != nil { 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 return results, err
} }
@@ -525,7 +516,7 @@ func (c Connection) findNonexistentDirs(path string) ([]string, error) {
func (c Connection) findFirstExistingDir(path string) (string, error) { func (c Connection) findFirstExistingDir(path string) (string, error) {
results, err := c.findNonexistentDirs(path) results, err := c.findNonexistentDirs(path)
if err != nil { 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 return "", err
} }
var parent string 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 // home dir must exist and it is already a validated absolute path
parent, err := filepath.EvalSymlinks(c.User.HomeDir) parent, err := filepath.EvalSymlinks(c.User.HomeDir)
if err != nil { 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 return err
} }
if !strings.HasPrefix(sub, parent) { 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 fmt.Errorf("dir %#v is not inside: %#v", sub, parent)
} }
return nil return nil
@@ -575,7 +566,7 @@ func (c Connection) createMissingDirs(filePath string) error {
for i := range dirsToCreate { for i := range dirsToCreate {
d := dirsToCreate[last-i] d := dirsToCreate[last-i]
if err := os.Mkdir(d, 0777); err != nil { 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 return err
} }
utils.SetPathPermissions(d, c.User.GetUID(), c.User.GetGID()) utils.SetPathPermissions(d, c.User.GetUID(), c.User.GetGID())

55
sftpd/scp.go
View File

@@ -12,6 +12,7 @@ import (
"time" "time"
"github.com/drakkan/sftpgo/dataprovider" "github.com/drakkan/sftpgo/dataprovider"
"github.com/drakkan/sftpgo/logger"
"github.com/drakkan/sftpgo/utils" "github.com/drakkan/sftpgo/utils"
"golang.org/x/crypto/ssh" "golang.org/x/crypto/ssh"
) )
@@ -43,7 +44,7 @@ func (c *scpCommand) handle() error {
defer removeConnection(c.connection.ID) defer removeConnection(c.connection.ID)
destPath := c.getDestPath() destPath := c.getDestPath()
commandType := c.getCommandType() 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) c.args, c.connection.User.Username, commandType, destPath)
if commandType == "-t" { if commandType == "-t" {
// -t means "to", so upload // -t means "to", so upload
@@ -84,7 +85,7 @@ func (c *scpCommand) handleRecursiveUpload() error {
} }
if strings.HasPrefix(command, "E") { if strings.HasPrefix(command, "E") {
numDirs-- 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 { if numDirs == 0 {
// upload is now complete send confirmation message // upload is now complete send confirmation message
err = c.sendConfirmationMessage() err = c.sendConfirmationMessage()
@@ -107,7 +108,7 @@ func (c *scpCommand) handleRecursiveUpload() error {
if err != nil { if err != nil {
return err 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") { } else if strings.HasPrefix(command, "C") {
err = c.handleUpload(c.getFileUploadDestPath(destPath, name), sizeToRead) err = c.handleUpload(c.getFileUploadDestPath(destPath, name), sizeToRead)
if err != nil { if err != nil {
@@ -126,14 +127,14 @@ func (c *scpCommand) handleCreateDir(dirPath string) error {
updateConnectionActivity(c.connection.ID) updateConnectionActivity(c.connection.ID)
if !c.connection.User.HasPerm(dataprovider.PermCreateDirs) { if !c.connection.User.HasPerm(dataprovider.PermCreateDirs) {
err := fmt.Errorf("Permission denied") 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()) c.sendErrorMessage(err.Error())
return err return err
} }
p, err := c.connection.buildPath(dirPath) p, err := c.connection.buildPath(dirPath)
if err != nil { 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()) c.sendErrorMessage(err.Error())
return err return err
} }
@@ -142,7 +143,7 @@ func (c *scpCommand) handleCreateDir(dirPath string) error {
if err != nil { if err != nil {
return err return err
} }
c.connection.Log(Debug, mkdirLogSender, "created dir %#v", dirPath) c.connection.Log(logger.LevelDebug, mkdirLogSender, "created dir %#v", dirPath)
return nil 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 { func (c *scpCommand) handleUploadFile(requestPath, filePath string, sizeToRead int64, isNewFile bool) error {
if !c.connection.hasSpace(true) { if !c.connection.hasSpace(true) {
err := fmt.Errorf("denying file write due to space limit") 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()) c.sendErrorMessage(err.Error())
return err 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 _, err := os.Stat(filepath.Dir(requestPath)); os.IsNotExist(err) {
if !c.connection.User.HasPerm(dataprovider.PermCreateDirs) { if !c.connection.User.HasPerm(dataprovider.PermCreateDirs) {
err := fmt.Errorf("Permission denied") 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()) c.sendErrorMessage(err.Error())
return err return err
} }
@@ -206,7 +207,7 @@ func (c *scpCommand) handleUploadFile(requestPath, filePath string, sizeToRead i
file, err := os.Create(filePath) file, err := os.Create(filePath)
if err != nil { 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()) c.sendErrorMessage(err.Error())
return err return err
} }
@@ -237,14 +238,14 @@ func (c *scpCommand) handleUpload(uploadFilePath string, sizeToRead int64) error
updateConnectionActivity(c.connection.ID) updateConnectionActivity(c.connection.ID)
if !c.connection.User.HasPerm(dataprovider.PermUpload) { if !c.connection.User.HasPerm(dataprovider.PermUpload) {
err := fmt.Errorf("Permission denied") 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()) c.sendErrorMessage(err.Error())
return err return err
} }
p, err := c.connection.buildPath(uploadFilePath) p, err := c.connection.buildPath(uploadFilePath)
if err != nil { 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()) c.sendErrorMessage(err.Error())
return err return err
} }
@@ -258,13 +259,13 @@ func (c *scpCommand) handleUpload(uploadFilePath string, sizeToRead int64) error
} }
if statErr != nil { 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()) c.sendErrorMessage(err.Error())
return err return err
} }
if stat.IsDir() { 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) err = fmt.Errorf("Attempted to open a directory for writing: %#v", p)
c.sendErrorMessage(err.Error()) c.sendErrorMessage(err.Error())
return err return err
@@ -273,7 +274,7 @@ func (c *scpCommand) handleUpload(uploadFilePath string, sizeToRead int64) error
if uploadMode == uploadModeAtomic { if uploadMode == uploadModeAtomic {
err = os.Rename(p, filePath) err = os.Rename(p, filePath)
if err != nil { 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) p, filePath, err)
c.sendErrorMessage(err.Error()) c.sendErrorMessage(err.Error())
return err 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 { func (c *scpCommand) handleRecursiveDownload(dirPath string, stat os.FileInfo) error {
var err error var err error
if c.isRecursive() { 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) err = c.sendDownloadProtocolMessages(dirPath, stat)
if err != nil { if err != nil {
return err return err
@@ -424,21 +425,21 @@ func (c *scpCommand) handleDownload(filePath string) error {
if !c.connection.User.HasPerm(dataprovider.PermDownload) { if !c.connection.User.HasPerm(dataprovider.PermDownload) {
err := fmt.Errorf("Permission denied") 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()) c.sendErrorMessage(err.Error())
return err return err
} }
p, err := c.connection.buildPath(filePath) p, err := c.connection.buildPath(filePath)
if err != nil { if err != nil {
err := fmt.Errorf("Invalid file path") 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()) c.sendErrorMessage(err.Error())
return err return err
} }
var stat os.FileInfo var stat os.FileInfo
if stat, err = os.Stat(p); os.IsNotExist(err) { 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()) c.sendErrorMessage(err.Error())
return err return err
} }
@@ -450,7 +451,7 @@ func (c *scpCommand) handleDownload(filePath string) error {
file, err := os.Open(p) file, err := os.Open(p)
if err != nil { 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()) c.sendErrorMessage(err.Error())
return err return err
} }
@@ -525,7 +526,7 @@ func (c *scpCommand) readConfirmationMessage() error {
msg.WriteString(string(readed)) 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()) err = fmt.Errorf("%v", msg.String())
c.channel.Close() c.channel.Close()
} }
@@ -578,7 +579,7 @@ func (c *scpCommand) sendConfirmationMessage() error {
func (c *scpCommand) sendProtocolMessage(message string) error { func (c *scpCommand) sendProtocolMessage(message string) error {
_, err := c.channel.Write([]byte(message)) _, err := c.channel.Write([]byte(message))
if err != nil { 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() c.channel.Close()
} }
return err return err
@@ -593,7 +594,7 @@ func (c *scpCommand) sendExitStatus(err error) {
ex := exitStatusMsg{ ex := exitStatusMsg{
Status: status, 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.args, c.connection.User.Username, err)
c.channel.SendRequest("exit-status", false, ssh.Marshal(&ex)) c.channel.SendRequest("exit-status", false, ssh.Marshal(&ex))
c.channel.Close() c.channel.Close()
@@ -624,7 +625,7 @@ func (c *scpCommand) getNextUploadProtocolMessage() (string, error) {
func (c *scpCommand) createDir(dirPath string) error { func (c *scpCommand) createDir(dirPath string) error {
var err error var err error
if err = os.Mkdir(dirPath, 0777); err != nil { 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()) c.sendErrorMessage(err.Error())
return err return err
} }
@@ -644,7 +645,7 @@ func (c *scpCommand) parseUploadMessage(command string) (int64, string, error) {
if !strings.HasPrefix(command, "C") && !strings.HasPrefix(command, "D") { if !strings.HasPrefix(command, "C") && !strings.HasPrefix(command, "D") {
err = fmt.Errorf("unknown or invalid upload message: %v args: %v user: %v", err = fmt.Errorf("unknown or invalid upload message: %v args: %v user: %v",
command, c.args, c.connection.User.Username) 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()) c.sendErrorMessage(err.Error())
return size, name, err return size, name, err
} }
@@ -652,20 +653,20 @@ func (c *scpCommand) parseUploadMessage(command string) (int64, string, error) {
if len(parts) == 3 { if len(parts) == 3 {
size, err = strconv.ParseInt(parts[1], 10, 64) size, err = strconv.ParseInt(parts[1], 10, 64)
if err != nil { 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)) c.sendErrorMessage(fmt.Sprintf("Error getting size: %v", err))
return size, name, err return size, name, err
} }
name = parts[2] name = parts[2]
if len(name) == 0 { if len(name) == 0 {
err = fmt.Errorf("error getting name from upload message, cannot be empty") 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()) c.sendErrorMessage(err.Error())
return size, name, err return size, name, err
} }
} else { } else {
err = fmt.Errorf("Error splitting upload message: %v", command) 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()) c.sendErrorMessage(err.Error())
return size, name, err return size, name, err
} }

13
sftpd/server.go
View File

@@ -232,7 +232,7 @@ func (c Configuration) AcceptInboundConnection(conn net.Conn, config *ssh.Server
lock: new(sync.Mutex), lock: new(sync.Mutex),
sshConn: sconn, 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) user.ID, loginType, user.Username, user.HomeDir)
go ssh.DiscardRequests(reqs) 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 // If its not a session channel we just move on because its not something we
// know how to handle at this point. // know how to handle at this point.
if newChannel.ChannelType() != "session" { 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") newChannel.Reject(ssh.UnknownChannelType, "unknown channel type")
continue continue
} }
channel, requests, err := newChannel.Accept() channel, requests, err := newChannel.Accept()
if err != nil { 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 continue
} }
@@ -270,7 +270,8 @@ func (c Configuration) AcceptInboundConnection(conn net.Conn, config *ssh.Server
var msg execMsg var msg execMsg
if err := ssh.Unmarshal(req.Payload, &msg); err == nil { if err := ssh.Unmarshal(req.Payload, &msg); err == nil {
name, scpArgs, err := parseCommandPayload(msg.Command) 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) connection.User.Username, err)
if err == nil && name == "scp" && len(scpArgs) >= 2 { if err == nil && name == "scp" && len(scpArgs) >= 2 {
ok = true ok = true
@@ -300,10 +301,10 @@ func (c Configuration) handleSftpConnection(channel io.ReadWriteCloser, connecti
server := sftp.NewRequestServer(channel, handler) server := sftp.NewRequestServer(channel, handler)
if err := server.Serve(); err == io.EOF { if err := server.Serve(); err == io.EOF {
connection.Log(Debug, logSenderSCP, "connection closed") connection.Log(logger.LevelDebug, logSenderSCP, "connection closed")
server.Close() server.Close()
} else if err != nil { } 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) removeConnection(connection.ID)

17
sftpd/sftpd.go
View File

@@ -34,11 +34,6 @@ const (
operationRename = "rename" operationRename = "rename"
protocolSFTP = "SFTP" protocolSFTP = "SFTP"
protocolSCP = "SCP" protocolSCP = "SCP"
Debug = "debug"
Info = "info"
Warn = "warn"
Error = "error"
) )
var ( var (
@@ -178,7 +173,7 @@ func CloseActiveConnection(connectionID string) bool {
defer mutex.RUnlock() defer mutex.RUnlock()
for _, c := range openConnections { for _, c := range openConnections {
if c.ID == connectionID { if c.ID == connectionID {
c.Log(Debug, logSender, "closing connection") c.Log(logger.LevelDebug, logSender, "closing connection")
c.sshConn.Close() c.sshConn.Close()
result = true result = true
break break
@@ -252,17 +247,17 @@ func CheckIdleConnections() {
if t.connectionID == c.ID { if t.connectionID == c.ID {
transferIdleTime := time.Since(t.lastActivity) transferIdleTime := time.Since(t.lastActivity)
if transferIdleTime < idleTime { 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)
idleTime = transferIdleTime idleTime = transferIdleTime
} }
} }
} }
if idleTime > idleTimeout { 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() err := c.sshConn.Close()
if err != nil { 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() mutex.Lock()
defer mutex.Unlock() defer mutex.Unlock()
openConnections[id] = c 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) { func removeConnection(id string) {
@@ -281,7 +276,7 @@ func removeConnection(id string) {
defer mutex.Unlock() defer mutex.Unlock()
c := openConnections[id] c := openConnections[id]
delete(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) { func addTransfer(transfer *Transfer) {