improve more logs

dataprovider/bolt.go

@@ -140,7 +140,7 @@ func (p BoltProvider) updateQuota(username string, filesAdd int, sizeAdd int64,
 func (p BoltProvider) getUsedQuota(username string) (int, int64, error) {
 	user, err := p.userExists(username)
 	if err != nil {
-		logger.Warn(logSender, "", "unable to get quota for user '%v' error: %v", username, err)
+		logger.Warn(logSender, "", "unable to get quota for user %v error: %v", username, err)
 		return 0, 0, err
 	}
 	return user.UsedQuotaFiles, user.UsedQuotaSize, err
@@ -173,7 +173,7 @@ func (p BoltProvider) addUser(user User) error {
 			return err
 		}
 		if u := bucket.Get([]byte(user.Username)); u != nil {
-			return fmt.Errorf("username '%v' already exists", user.Username)
+			return fmt.Errorf("username %v already exists", user.Username)
 		}
 		id, err := bucket.NextSequence()
 		if err != nil {
@@ -204,7 +204,7 @@ func (p BoltProvider) updateUser(user User) error {
 			return err
 		}
 		if u := bucket.Get([]byte(user.Username)); u == nil {
-			return &RecordNotFoundError{err: fmt.Sprintf("username '%v' does not exist", user.Username)}
+			return &RecordNotFoundError{err: fmt.Sprintf("username %v does not exist", user.Username)}
 		}
 		buf, err := json.Marshal(user)
 		if err != nil {

dataprovider/mysql.go

@@ -26,13 +26,13 @@ func initializeMySQLProvider() error {
 	dbHandle, err := sql.Open("mysql", connectionString)
 	if err == nil {
 		numCPU := runtime.NumCPU()
-		logger.Debug(logSender, "", "mysql database handle created, connection string: '%v', pool size: %v", connectionString, numCPU)
+		logger.Debug(logSender, "", "mysql database handle created, connection string: %#v, pool size: %v", connectionString, numCPU)
 		dbHandle.SetMaxIdleConns(numCPU)
 		dbHandle.SetMaxOpenConns(numCPU)
 		dbHandle.SetConnMaxLifetime(1800 * time.Second)
 		provider = MySQLProvider{dbHandle: dbHandle}
 	} else {
-		logger.Warn(logSender, "", "error creating mysql database handler, connection string: '%v', error: %v", connectionString, err)
+		logger.Warn(logSender, "", "error creating mysql database handler, connection string: %#v, error: %v", connectionString, err)
 	}
 	return err
 }

dataprovider/pgsql.go

@@ -25,12 +25,12 @@ func initializePGSQLProvider() error {
 	dbHandle, err := sql.Open("postgres", connectionString)
 	if err == nil {
 		numCPU := runtime.NumCPU()
-		logger.Debug(logSender, "", "postgres database handle created, connection string: '%v', pool size: %v", connectionString, numCPU)
+		logger.Debug(logSender, "", "postgres database handle created, connection string: %#v, pool size: %v", connectionString, numCPU)
 		dbHandle.SetMaxIdleConns(numCPU)
 		dbHandle.SetMaxOpenConns(numCPU)
 		provider = PGSQLProvider{dbHandle: dbHandle}
 	} else {
-		logger.Warn(logSender, "", "error creating postgres database handler, connection string: '%v', error: %v", connectionString, err)
+		logger.Warn(logSender, "", "error creating postgres database handler, connection string: %#v, error: %v", connectionString, err)
 	}
 	return err
 }

dataprovider/sqlcommon.go

@@ -15,7 +15,7 @@ func getUserByUsername(username string, dbHandle *sql.DB) (User, error) {
 	q := getUserByUsernameQuery()
 	stmt, err := dbHandle.Prepare(q)
 	if err != nil {
-		logger.Debug(logSender, "", "error preparing database query %v: %v", q, err)
+		logger.Warn(logSender, "", "error preparing database query %#v: %v", q, err)
 		return user, err
 	}
 	defer stmt.Close()
@@ -55,7 +55,7 @@ func sqlCommonGetUserByID(ID int64, dbHandle *sql.DB) (User, error) {
 	q := getUserByIDQuery()
 	stmt, err := dbHandle.Prepare(q)
 	if err != nil {
-		logger.Debug(logSender, "", "error preparing database query %v: %v", q, err)
+		logger.Debug(logSender, "", "error preparing database query %#v: %v", q, err)
 		return user, err
 	}
 	defer stmt.Close()
@@ -68,7 +68,7 @@ func sqlCommonUpdateQuota(username string, filesAdd int, sizeAdd int64, reset bo
 	q := getUpdateQuotaQuery(reset)
 	stmt, err := dbHandle.Prepare(q)
 	if err != nil {
-		logger.Debug(logSender, "", "error preparing database query %v: %v", q, err)
+		logger.Debug(logSender, "", "error preparing database query %#v: %v", q, err)
 		return err
 	}
 	defer stmt.Close()
@@ -86,7 +86,7 @@ func sqlCommonGetUsedQuota(username string, dbHandle *sql.DB) (int, int64, error
 	q := getQuotaQuery()
 	stmt, err := dbHandle.Prepare(q)
 	if err != nil {
-		logger.Warn(logSender, "", "error preparing database query %v: %v", q, err)
+		logger.Warn(logSender, "", "error preparing database query %#v: %v", q, err)
 		return 0, 0, err
 	}
 	defer stmt.Close()
@@ -95,7 +95,7 @@ func sqlCommonGetUsedQuota(username string, dbHandle *sql.DB) (int, int64, error
 	var usedSize int64
 	err = stmt.QueryRow(username).Scan(&usedSize, &usedFiles)
 	if err != nil {
-		logger.Warn(logSender, "", "error getting user quota: %v, error: %v", username, err)
+		logger.Warn(logSender, "", "error getting quota for user: %v, error: %v", username, err)
 		return 0, 0, err
 	}
 	return usedFiles, usedSize, err
@@ -106,7 +106,7 @@ func sqlCommonCheckUserExists(username string, dbHandle *sql.DB) (User, error) {
 	q := getUserByUsernameQuery()
 	stmt, err := dbHandle.Prepare(q)
 	if err != nil {
-		logger.Warn(logSender, "", "error preparing database query %v: %v", q, err)
+		logger.Warn(logSender, "", "error preparing database query %#v: %v", q, err)
 		return user, err
 	}
 	defer stmt.Close()
@@ -122,7 +122,7 @@ func sqlCommonAddUser(user User, dbHandle *sql.DB) error {
 	q := getAddUserQuery()
 	stmt, err := dbHandle.Prepare(q)
 	if err != nil {
-		logger.Warn(logSender, "", "error preparing database query %v: %v", q, err)
+		logger.Warn(logSender, "", "error preparing database query %#v: %v", q, err)
 		return err
 	}
 	defer stmt.Close()
@@ -147,7 +147,7 @@ func sqlCommonUpdateUser(user User, dbHandle *sql.DB) error {
 	q := getUpdateUserQuery()
 	stmt, err := dbHandle.Prepare(q)
 	if err != nil {
-		logger.Warn(logSender, "", "error preparing database query %v: %v", q, err)
+		logger.Warn(logSender, "", "error preparing database query %#v: %v", q, err)
 		return err
 	}
 	defer stmt.Close()
@@ -168,7 +168,7 @@ func sqlCommonDeleteUser(user User, dbHandle *sql.DB) error {
 	q := getDeleteUserQuery()
 	stmt, err := dbHandle.Prepare(q)
 	if err != nil {
-		logger.Warn(logSender, "", "error preparing database query %v: %v", q, err)
+		logger.Warn(logSender, "", "error preparing database query %#v: %v", q, err)
 		return err
 	}
 	defer stmt.Close()
@@ -181,7 +181,7 @@ func sqlCommonGetUsers(limit int, offset int, order string, username string, dbH
 	q := getUsersQuery(order, username)
 	stmt, err := dbHandle.Prepare(q)
 	if err != nil {
-		logger.Warn(logSender, "", "error preparing database query %v: %v", q, err)
+		logger.Warn(logSender, "", "error preparing database query %#v: %v", q, err)
 		return nil, err
 	}
 	defer stmt.Close()

dataprovider/sqlite.go

@@ -39,11 +39,11 @@ func initializeSQLiteProvider(basePath string) error {
 	}
 	dbHandle, err := sql.Open("sqlite3", connectionString)
 	if err == nil {
-		logger.Debug(logSender, "", "sqlite database handle created, connection string: '%v'", connectionString)
+		logger.Debug(logSender, "", "sqlite database handle created, connection string: %#v", connectionString)
 		dbHandle.SetMaxOpenConns(1)
 		provider = SQLiteProvider{dbHandle: dbHandle}
 	} else {
-		logger.Warn(logSender, "", "error creating sqlite database handler, connection string: '%v', error: %v", connectionString, err)
+		logger.Warn(logSender, "", "error creating sqlite database handler, connection string: %#v, error: %v", connectionString, err)
 	}
 	return err
 }

sftpd/scp.go

@@ -108,7 +108,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)
+				logger.Debug(logSenderSCP, c.connection.ID, "received start dir command, num dirs: %v destPath: %#v", numDirs, destPath)
 			} else if strings.HasPrefix(command, "C") {
 				err = c.handleUpload(c.getFileUploadDestPath(destPath, name), sizeToRead)
 				if err != nil {
@@ -127,14 +127,14 @@ func (c *scpCommand) handleCreateDir(dirPath string) error {
 	updateConnectionActivity(c.connection.ID)
 	if !c.connection.User.HasPerm(dataprovider.PermCreateDirs) {
 		err := fmt.Errorf("Permission denied")
-		logger.Warn(logSenderSCP, c.connection.ID, "error creating dir: %v, permission denied", dirPath)
+		logger.Warn(logSenderSCP, c.connection.ID, "error creating dir: %#v, permission denied", dirPath)
 		c.sendErrorMessage(err.Error())
 		return err
 	}
 
 	p, err := c.connection.buildPath(dirPath)
 	if err != nil {
-		logger.Warn(logSenderSCP, c.connection.ID, "error creating dir: %v, invalid file path, err: %v", dirPath, err)
+		logger.Warn(logSenderSCP, c.connection.ID, "error creating dir: %#v, invalid file path, err: %v", dirPath, err)
 		c.sendErrorMessage(err.Error())
 		return err
 	}
@@ -191,7 +191,7 @@ func (c *scpCommand) getUploadFileData(sizeToRead int64, transfer *Transfer) err
 func (c *scpCommand) handleUploadFile(requestPath, filePath string, sizeToRead int64, isNewFile bool) error {
 	if !c.connection.hasSpace(true) {
 		err := fmt.Errorf("denying file write due to space limit")
-		logger.Warn(logSenderSCP, c.connection.ID, "error uploading file: %v, err: %v", filePath, err)
+		logger.Warn(logSenderSCP, c.connection.ID, "error uploading file: %#v, err: %v", filePath, err)
 		c.sendErrorMessage(err.Error())
 		return err
 	}
@@ -199,7 +199,7 @@ func (c *scpCommand) handleUploadFile(requestPath, filePath string, sizeToRead i
 	if _, err := os.Stat(filepath.Dir(requestPath)); os.IsNotExist(err) {
 		if !c.connection.User.HasPerm(dataprovider.PermCreateDirs) {
 			err := fmt.Errorf("Permission denied")
-			logger.Warn(logSenderSCP, c.connection.ID, "error uploading file: %v, permission denied", requestPath)
+			logger.Warn(logSenderSCP, c.connection.ID, "error uploading file: %#v, permission denied", requestPath)
 			c.sendErrorMessage(err.Error())
 			return err
 		}
@@ -207,7 +207,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)
+		logger.Error(logSenderSCP, "error creating file %#v: %v", requestPath, err)
 		c.sendErrorMessage(err.Error())
 		return err
 	}
@@ -238,14 +238,14 @@ func (c *scpCommand) handleUpload(uploadFilePath string, sizeToRead int64) error
 	updateConnectionActivity(c.connection.ID)
 	if !c.connection.User.HasPerm(dataprovider.PermUpload) {
 		err := fmt.Errorf("Permission denied")
-		logger.Warn(logSenderSCP, c.connection.ID, "error uploading file: %v, permission denied", uploadFilePath)
+		logger.Warn(logSenderSCP, c.connection.ID, "error uploading file: %#v, permission denied", uploadFilePath)
 		c.sendErrorMessage(err.Error())
 		return err
 	}
 
 	p, err := c.connection.buildPath(uploadFilePath)
 	if err != nil {
-		logger.Warn(logSenderSCP, c.connection.ID, "error uploading file: %v, err: %v", uploadFilePath, err)
+		logger.Warn(logSenderSCP, c.connection.ID, "error uploading file: %#v, err: %v", uploadFilePath, err)
 		c.sendErrorMessage(err.Error())
 		return err
 	}
@@ -259,14 +259,14 @@ func (c *scpCommand) handleUpload(uploadFilePath string, sizeToRead int64) error
 	}
 
 	if statErr != nil {
-		logger.Error(logSenderSCP, "error performing file stat %v: %v", p, statErr)
+		logger.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)
-		err = fmt.Errorf("Attempted to open a directory for writing: %v", p)
+		logger.Warn(logSenderSCP, c.connection.ID, "attempted to open a directory for writing to: %#v", p)
+		err = fmt.Errorf("Attempted to open a directory for writing: %#v", p)
 		c.sendErrorMessage(err.Error())
 		return err
 	}
@@ -274,7 +274,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",
+			logger.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 +315,7 @@ func (c *scpCommand) sendDownloadProtocolMessages(dirPath string, stat os.FileIn
 func (c *scpCommand) handleRecursiveDownload(dirPath string, stat os.FileInfo) error {
 	var err error
 	if c.isRecursive() {
-		logger.Debug(logSenderSCP, c.connection.ID, "recursive download, dir path: %v", dirPath)
+		logger.Debug(logSenderSCP, c.connection.ID, "recursive download, dir path: %#v", dirPath)
 		err = c.sendDownloadProtocolMessages(dirPath, stat)
 		if err != nil {
 			return err
@@ -425,21 +425,21 @@ func (c *scpCommand) handleDownload(filePath string) error {
 
 	if !c.connection.User.HasPerm(dataprovider.PermDownload) {
 		err := fmt.Errorf("Permission denied")
-		logger.Warn(logSenderSCP, c.connection.ID, "error downloading file: %v, permission denied", filePath)
+		logger.Warn(logSenderSCP, c.connection.ID, "error downloading file: %#v, permission denied", filePath)
 		c.sendErrorMessage(err.Error())
 		return err
 	}
 	p, err := c.connection.buildPath(filePath)
 	if err != nil {
 		err := fmt.Errorf("Invalid file path")
-		logger.Warn(logSenderSCP, c.connection.ID, "error downloading file: %v, invalid file path", filePath)
+		logger.Warn(logSenderSCP, c.connection.ID, "error downloading file: %#v, invalid file path", filePath)
 		c.sendErrorMessage(err.Error())
 		return err
 	}
 
 	var stat os.FileInfo
 	if stat, err = os.Stat(p); os.IsNotExist(err) {
-		logger.Warn(logSenderSCP, c.connection.ID, "error downloading file: %v, err: %v", p, err)
+		logger.Warn(logSenderSCP, c.connection.ID, "error downloading file: %#v, err: %v", p, err)
 		c.sendErrorMessage(err.Error())
 		return err
 	}
@@ -451,7 +451,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)
+		logger.Error(logSenderSCP, "could not open file %#v for reading: %v", p, err)
 		c.sendErrorMessage(err.Error())
 		return err
 	}

sftpd/server.go

@@ -321,12 +321,12 @@ func (c Configuration) createHandler(connection Connection) sftp.Handlers {
 
 func loginUser(user dataprovider.User, loginType string) (*ssh.Permissions, error) {
 	if !filepath.IsAbs(user.HomeDir) {
-		logger.Warn(logSender, "", "user %v has invalid home dir: %v. Home dir must be an absolute path, login not allowed",
+		logger.Warn(logSender, "", "user %v has invalid home dir: %#v. Home dir must be an absolute path, login not allowed",
 			user.Username, user.HomeDir)
 		return nil, fmt.Errorf("Cannot login user with invalid home dir: %v", user.HomeDir)
 	}
 	if _, err := os.Stat(user.HomeDir); os.IsNotExist(err) {
-		logger.Debug(logSender, "", "home directory \"%v\" for user %v does not exist, try to create", user.HomeDir, user.Username)
+		logger.Debug(logSender, "", "home directory %#v for user %v does not exist, try to create", user.HomeDir, user.Username)
 		err := os.MkdirAll(user.HomeDir, 0777)
 		if err == nil {
 			utils.SetPathPermissions(user.HomeDir, user.GetUID(), user.GetGID())

sftpd/sftpd.go

@@ -173,7 +173,7 @@ func CloseActiveConnection(connectionID string) bool {
 	defer mutex.RUnlock()
 	for _, c := range openConnections {
 		if c.ID == connectionID {
-			logger.Debug(logSender, "", "closing connection with id: %v", connectionID)
+			logger.Debug(logSender, connectionID, "closing connection")
 			c.sshConn.Close()
 			result = true
 			break
@@ -247,16 +247,16 @@ func CheckIdleConnections() {
 			if t.connectionID == c.ID {
 				transferIdleTime := time.Since(t.lastActivity)
 				if transferIdleTime < idleTime {
-					logger.Debug(logSender, "", "idle time: %v setted to transfer idle time: %v connection id: %v",
-						idleTime, transferIdleTime, c.ID)
+					logger.Debug(logSender, c.ID, "idle time: %v setted to transfer idle time: %v",
+						idleTime, transferIdleTime)
 					idleTime = transferIdleTime
 				}
 			}
 		}
 		if idleTime > idleTimeout {
-			logger.Debug(logSender, "", "close idle connection id: %v idle time: %v", c.ID, idleTime)
+			logger.Debug(logSender, c.ID, "close idle connection, idle time: %v", idleTime)
 			err := c.sshConn.Close()
-			logger.Debug(logSender, "", "idle connection closed id: %v, err: %v", c.ID, err)
+			logger.Debug(logSender, c.ID, "idle connection closed, err: %v", err)
 		}
 	}
 	logger.Debug(logSender, "", "check idle connections ended")
@@ -297,7 +297,7 @@ func removeTransfer(transfer *Transfer) error {
 		activeTransfers[indexToRemove] = activeTransfers[len(activeTransfers)-1]
 		activeTransfers = activeTransfers[:len(activeTransfers)-1]
 	} else {
-		logger.Warn(logSender, "", "transfer to remove not found!")
+		logger.Warn(logSender, transfer.connectionID, "transfer to remove not found!")
 		err = fmt.Errorf("transfer to remove not found")
 	}
 	return err
@@ -321,13 +321,13 @@ func executeAction(operation string, username string, path string, target string
 		if _, err = os.Stat(actions.Command); err == nil {
 			command := exec.Command(actions.Command, operation, username, path, target)
 			err = command.Start()
-			logger.Debug(logSender, "", "start command \"%v\" with arguments: %v, %v, %v, %v, error: %v",
+			logger.Debug(logSender, "", "start command %#v with arguments: %v, %v, %v, %v, error: %v",
 				actions.Command, operation, username, path, target, err)
 			if err == nil {
 				go command.Wait()
 			}
 		} else {
-			logger.Warn(logSender, "", "Invalid action command \"%v\" : %v", actions.Command, err)
+			logger.Warn(logSender, "", "Invalid action command %#v : %v", actions.Command, err)
 		}
 	}
 	if len(actions.HTTPNotificationURL) > 0 {
@@ -357,7 +357,7 @@ func executeAction(operation string, username string, path string, target string
 					url.String(), respCode, time.Since(startTime), err)
 			}()
 		} else {
-			logger.Warn(logSender, "", "Invalid http_notification_url \"%v\" : %v", actions.HTTPNotificationURL, err)
+			logger.Warn(logSender, "", "Invalid http_notification_url %#v : %v", actions.HTTPNotificationURL, err)
 		}
 	}
 	return err

sftpd/transfer.go

@@ -60,7 +60,7 @@ func (t *Transfer) Close() error {
 	err := t.file.Close()
 	if t.transferType == transferUpload && t.file.Name() != t.path {
 		err = os.Rename(t.file.Name(), t.path)
-		logger.Debug(logSender, t.connectionID, "atomic upload completed, rename: \"%v\" -> \"%v\", error: %v",
+		logger.Debug(logSender, t.connectionID, "atomic upload completed, rename: %#v -> %#v, error: %v",
 			t.file.Name(), t.path, err)
 	}
 	elapsed := time.Since(t.start).Nanoseconds() / 1000000