From 157d1db0b10ced70c62df8f6fc4767360c636aa5 Mon Sep 17 00:00:00 2001 From: Nicola Murino Date: Sun, 12 Feb 2023 18:56:53 +0100 Subject: [PATCH] fs events: add elapsed field to notifications Signed-off-by: Nicola Murino --- docs/custom-actions.md | 2 ++ docs/eventmanager.md | 1 + docs/logs.md | 1 + go.mod | 2 +- go.sum | 2 ++ internal/common/actions.go | 11 ++++--- internal/common/actions_test.go | 28 ++++++++-------- internal/common/connection.go | 51 ++++++++++++++++++++--------- internal/common/eventmanager.go | 16 +++++---- internal/common/transfer.go | 16 ++++----- internal/logger/logger.go | 3 +- internal/sftpd/ssh_cmd.go | 9 +++-- pkgs/build.sh | 2 +- templates/webadmin/eventaction.html | 3 ++ 14 files changed, 94 insertions(+), 53 deletions(-) diff --git a/docs/custom-actions.md b/docs/custom-actions.md index 2592f049..e3dbb597 100644 --- a/docs/custom-actions.md +++ b/docs/custom-actions.md @@ -40,6 +40,7 @@ If the `hook` defines a path to an external program, then this program can read - `SFTPGO_ACTION_VIRTUAL_TARGET`, virtual target path, seen by SFTPGo users - `SFTPGO_ACTION_SSH_CMD`, non-empty for `ssh_cmd` `SFTPGO_ACTION` - `SFTPGO_ACTION_FILE_SIZE`, non-zero for `pre-upload`, `upload`, `download`, `delete`, and `copy` actions if the file size is greater than `0` +- `SFTPGO_ACTION_ELAPSED`, elapsed time as milliseconds - `SFTPGO_ACTION_FS_PROVIDER`, `0` for local filesystem, `1` for S3 backend, `2` for Google Cloud Storage (GCS) backend, `3` for Azure Blob Storage backend, `4` for local encrypted backend, `5` for SFTP backend - `SFTPGO_ACTION_BUCKET`, non-empty for S3, GCS and Azure backends - `SFTPGO_ACTION_ENDPOINT`, non-empty for S3, SFTP and Azure backend if configured @@ -64,6 +65,7 @@ If the `hook` defines an HTTP URL then this URL will be invoked as HTTP POST. Th - `virtual_target_path`, string, virtual target path, seen by SFTPGo users - `ssh_cmd`, string, included for `ssh_cmd` action - `file_size`, int64, included for `pre-upload`, `upload`, `download`, `delete` and `copy` actions if the file size is greater than `0` +- `elapsed`, int64, elapsed size as milliseconds - `fs_provider`, integer, `0` for local filesystem, `1` for S3 backend, `2` for Google Cloud Storage (GCS) backend, `3` for Azure Blob Storage backend, `4` for local encrypted backend, `5` for SFTP backend, `6` for HTTPFs backend - `bucket`, string, included for S3, GCS and Azure backends - `endpoint`, string, included for S3, SFTP and Azure backend if configured diff --git a/docs/eventmanager.md b/docs/eventmanager.md index 4aa9fbf4..fdd5e5ec 100644 --- a/docs/eventmanager.md +++ b/docs/eventmanager.md @@ -39,6 +39,7 @@ The following placeholders are supported: - `{{TargetName}}`. Target object name for renames. - `{{FsTargetPath}}`. Full filesystem target path for renames. - `{{FileSize}}`. File size. +- `{{Elapsed}}`. Elapsed time as milliseconds for filesystem events. - `{{Protocol}}`. Used protocol, for example `SFTP`, `FTP`. - `{{IP}}`. Client IP address. - `{{Role}}`. User or admin role. diff --git a/docs/logs.md b/docs/logs.md index 03d0f3e0..136c3620 100644 --- a/docs/logs.md +++ b/docs/logs.md @@ -36,6 +36,7 @@ The logs can be divided into the following categories: - `access_time` datetime as YYYY-MM-DDTHH:MM:SS. Valid for sender `Chtimes` otherwise empty - `modification_time` datetime as YYYY-MM-DDTHH:MM:SS. Valid for sender `Chtimes` otherwise empty - `size` int64. Valid for sender `Truncate` otherwise -1 + - `elapsed`, int64. Elapsed time, as milliseconds - `ssh_command`, string. Valid for sender `SSHCommand` otherwise empty - `connection_id` string. Unique connection identifier - `protocol` string. `SFTP`, `SCP`, `SSH`, `FTP`, `HTTP`, `DAV`, `DataRetention`, `EventAction` diff --git a/go.mod b/go.mod index f8921074..5d098de2 100644 --- a/go.mod +++ b/go.mod @@ -52,7 +52,7 @@ require ( github.com/rs/cors v1.8.3 github.com/rs/xid v1.4.0 github.com/rs/zerolog v1.29.0 - github.com/sftpgo/sdk v0.1.3-0.20221217110036-383c1bb50fa0 + github.com/sftpgo/sdk v0.1.3-0.20230212154322-556375985d8c github.com/shirou/gopsutil/v3 v3.23.1 github.com/spf13/afero v1.9.3 github.com/spf13/cobra v1.6.1 diff --git a/go.sum b/go.sum index df60c31b..a38dd25a 100644 --- a/go.sum +++ b/go.sum @@ -1802,6 +1802,8 @@ github.com/seccomp/libseccomp-golang v0.9.2-0.20210429002308-3879420cc921/go.mod github.com/secsy/goftp v0.0.0-20200609142545-aa2de14babf4 h1:PT+ElG/UUFMfqy5HrxJxNzj3QBOf7dZwupeVC+mG1Lo= github.com/sftpgo/sdk v0.1.3-0.20221217110036-383c1bb50fa0 h1:e1OQroqX8SWV06Z270CxG2/v//Wx1026iXKTDRn5J1E= github.com/sftpgo/sdk v0.1.3-0.20221217110036-383c1bb50fa0/go.mod h1:3GpW3Qy8IHH6kex0ny+Y6ayeYb9OJxz8Pxh3IZgAs2E= +github.com/sftpgo/sdk v0.1.3-0.20230212154322-556375985d8c h1:SiWQZe99SZ/O4QSIsxzL91NgwFJNoo4IJ31cazUrYh4= +github.com/sftpgo/sdk v0.1.3-0.20230212154322-556375985d8c/go.mod h1:B1lPGb05WtvvrX5IuhHrSjWdRT867qBaoxlS2Q9+1bA= github.com/shirou/gopsutil/v3 v3.23.1 h1:a9KKO+kGLKEvcPIs4W62v0nu3sciVDOOOPUD0Hz7z/4= github.com/shirou/gopsutil/v3 v3.23.1/go.mod h1:NN6mnm5/0k8jw4cBfCnJtr5L7ErOTg18tMNpgFkn0hA= github.com/shoenig/test v0.4.3/go.mod h1:xYtyGBC5Q3kzCNyJg/SjgNpfAa2kvmgA0i5+lQso8x0= diff --git a/internal/common/actions.go b/internal/common/actions.go index 11157bef..b508be01 100644 --- a/internal/common/actions.go +++ b/internal/common/actions.go @@ -92,7 +92,7 @@ func ExecutePreAction(conn *BaseConnection, operation, filePath, virtualPath str return 0, nil } event = newActionNotification(&conn.User, operation, filePath, virtualPath, "", "", "", - conn.protocol, conn.GetRemoteIP(), conn.ID, fileSize, openFlags, conn.getNotificationStatus(nil)) + conn.protocol, conn.GetRemoteIP(), conn.ID, fileSize, openFlags, conn.getNotificationStatus(nil), 0) if hasNotifiersPlugin { plugin.Handler.NotifyFsEvent(event) } @@ -127,7 +127,7 @@ func ExecutePreAction(conn *BaseConnection, operation, filePath, virtualPath str // ExecuteActionNotification executes the defined hook, if any, for the specified action func ExecuteActionNotification(conn *BaseConnection, operation, filePath, virtualPath, target, virtualTarget, sshCmd string, - fileSize int64, err error, + fileSize int64, err error, elapsed int64, ) error { hasNotifiersPlugin := plugin.Handler.HasNotifiers() hasHook := util.Contains(Config.Actions.ExecuteOn, operation) @@ -136,7 +136,7 @@ func ExecuteActionNotification(conn *BaseConnection, operation, filePath, virtua return nil } notification := newActionNotification(&conn.User, operation, filePath, virtualPath, target, virtualTarget, sshCmd, - conn.protocol, conn.GetRemoteIP(), conn.ID, fileSize, 0, conn.getNotificationStatus(err)) + conn.protocol, conn.GetRemoteIP(), conn.ID, fileSize, 0, conn.getNotificationStatus(err), elapsed) if hasNotifiersPlugin { plugin.Handler.NotifyFsEvent(notification) } @@ -152,6 +152,7 @@ func ExecuteActionNotification(conn *BaseConnection, operation, filePath, virtua FsTargetPath: notification.TargetPath, ObjectName: path.Base(notification.VirtualPath), FileSize: notification.FileSize, + Elapsed: notification.Elapsed, Protocol: notification.Protocol, IP: notification.IP, Role: notification.Role, @@ -190,7 +191,7 @@ func newActionNotification( user *dataprovider.User, operation, filePath, virtualPath, target, virtualTarget, sshCmd, protocol, ip, sessionID string, fileSize int64, - openFlags, status int, + openFlags, status int, elapsed int64, ) *notifier.FsEvent { var bucket, endpoint string @@ -232,6 +233,7 @@ func newActionNotification( OpenFlags: openFlags, Role: user.Role, Timestamp: time.Now().UnixNano(), + Elapsed: elapsed, } } @@ -321,6 +323,7 @@ func notificationAsEnvVars(event *notifier.FsEvent) []string { fmt.Sprintf("SFTPGO_ACTION_VIRTUAL_TARGET=%s", event.VirtualTargetPath), fmt.Sprintf("SFTPGO_ACTION_SSH_CMD=%s", event.SSHCmd), fmt.Sprintf("SFTPGO_ACTION_FILE_SIZE=%d", event.FileSize), + fmt.Sprintf("SFTPGO_ACTION_ELAPSED=%d", event.Elapsed), fmt.Sprintf("SFTPGO_ACTION_FS_PROVIDER=%d", event.FsProvider), fmt.Sprintf("SFTPGO_ACTION_BUCKET=%s", event.Bucket), fmt.Sprintf("SFTPGO_ACTION_ENDPOINT=%s", event.Endpoint), diff --git a/internal/common/actions_test.go b/internal/common/actions_test.go index d45e5a5a..7a3a404d 100644 --- a/internal/common/actions_test.go +++ b/internal/common/actions_test.go @@ -71,7 +71,7 @@ func TestNewActionNotification(t *testing.T) { c := NewBaseConnection("id", ProtocolSSH, "", "", user) sessionID := xid.New().String() a := newActionNotification(&user, operationDownload, "path", "vpath", "target", "", "", ProtocolSFTP, "", sessionID, - 123, 0, c.getNotificationStatus(errors.New("fake error"))) + 123, 0, c.getNotificationStatus(errors.New("fake error")), 0) assert.Equal(t, user.Username, a.Username) assert.Equal(t, 0, len(a.Bucket)) assert.Equal(t, 0, len(a.Endpoint)) @@ -79,38 +79,38 @@ func TestNewActionNotification(t *testing.T) { user.FsConfig.Provider = sdk.S3FilesystemProvider a = newActionNotification(&user, operationDownload, "path", "vpath", "target", "", "", ProtocolSSH, "", sessionID, - 123, 0, c.getNotificationStatus(nil)) + 123, 0, c.getNotificationStatus(nil), 0) assert.Equal(t, "s3bucket", a.Bucket) assert.Equal(t, "endpoint", a.Endpoint) assert.Equal(t, 1, a.Status) user.FsConfig.Provider = sdk.GCSFilesystemProvider a = newActionNotification(&user, operationDownload, "path", "vpath", "target", "", "", ProtocolSCP, "", sessionID, - 123, 0, c.getNotificationStatus(ErrQuotaExceeded)) + 123, 0, c.getNotificationStatus(ErrQuotaExceeded), 0) assert.Equal(t, "gcsbucket", a.Bucket) assert.Equal(t, 0, len(a.Endpoint)) assert.Equal(t, 3, a.Status) a = newActionNotification(&user, operationDownload, "path", "vpath", "target", "", "", ProtocolSCP, "", sessionID, - 123, 0, c.getNotificationStatus(fmt.Errorf("wrapper quota error: %w", ErrQuotaExceeded))) + 123, 0, c.getNotificationStatus(fmt.Errorf("wrapper quota error: %w", ErrQuotaExceeded)), 0) assert.Equal(t, "gcsbucket", a.Bucket) assert.Equal(t, 0, len(a.Endpoint)) assert.Equal(t, 3, a.Status) user.FsConfig.Provider = sdk.HTTPFilesystemProvider a = newActionNotification(&user, operationDownload, "path", "vpath", "target", "", "", ProtocolSSH, "", sessionID, - 123, 0, c.getNotificationStatus(nil)) + 123, 0, c.getNotificationStatus(nil), 0) assert.Equal(t, "httpendpoint", a.Endpoint) assert.Equal(t, 1, a.Status) user.FsConfig.Provider = sdk.AzureBlobFilesystemProvider a = newActionNotification(&user, operationDownload, "path", "vpath", "target", "", "", ProtocolSCP, "", sessionID, - 123, 0, c.getNotificationStatus(nil)) + 123, 0, c.getNotificationStatus(nil), 0) assert.Equal(t, "azcontainer", a.Bucket) assert.Equal(t, "azendpoint", a.Endpoint) assert.Equal(t, 1, a.Status) a = newActionNotification(&user, operationDownload, "path", "vpath", "target", "", "", ProtocolSCP, "", sessionID, - 123, os.O_APPEND, c.getNotificationStatus(nil)) + 123, os.O_APPEND, c.getNotificationStatus(nil), 0) assert.Equal(t, "azcontainer", a.Bucket) assert.Equal(t, "azendpoint", a.Endpoint) assert.Equal(t, 1, a.Status) @@ -118,7 +118,7 @@ func TestNewActionNotification(t *testing.T) { user.FsConfig.Provider = sdk.SFTPFilesystemProvider a = newActionNotification(&user, operationDownload, "path", "vpath", "target", "", "", ProtocolSFTP, "", sessionID, - 123, 0, c.getNotificationStatus(nil)) + 123, 0, c.getNotificationStatus(nil), 0) assert.Equal(t, "sftpendpoint", a.Endpoint) } @@ -135,7 +135,7 @@ func TestActionHTTP(t *testing.T) { }, } a := newActionNotification(user, operationDownload, "path", "vpath", "target", "", "", ProtocolSFTP, "", - xid.New().String(), 123, 0, 1) + xid.New().String(), 123, 0, 1, 0) status, err := actionHandler.Handle(a) assert.NoError(t, err) assert.Equal(t, 1, status) @@ -175,16 +175,16 @@ func TestActionCMD(t *testing.T) { } sessionID := shortuuid.New() a := newActionNotification(user, operationDownload, "path", "vpath", "target", "", "", ProtocolSFTP, "", sessionID, - 123, 0, 1) + 123, 0, 1, 0) status, err := actionHandler.Handle(a) assert.NoError(t, err) assert.Equal(t, 1, status) c := NewBaseConnection("id", ProtocolSFTP, "", "", *user) - err = ExecuteActionNotification(c, OperationSSHCmd, "path", "vpath", "target", "vtarget", "sha1sum", 0, nil) + err = ExecuteActionNotification(c, OperationSSHCmd, "path", "vpath", "target", "vtarget", "sha1sum", 0, nil, 0) assert.NoError(t, err) - err = ExecuteActionNotification(c, operationDownload, "path", "vpath", "", "", "", 0, nil) + err = ExecuteActionNotification(c, operationDownload, "path", "vpath", "", "", "", 0, nil, 0) assert.NoError(t, err) Config.Actions = actionsCopy @@ -208,7 +208,7 @@ func TestWrongActions(t *testing.T) { } a := newActionNotification(user, operationUpload, "", "", "", "", "", ProtocolSFTP, "", xid.New().String(), - 123, 0, 1) + 123, 0, 1, 0) status, err := actionHandler.Handle(a) assert.Error(t, err, "action with bad command must fail") assert.Equal(t, 1, status) @@ -307,7 +307,7 @@ func TestUnconfiguredHook(t *testing.T) { assert.NoError(t, err) assert.Equal(t, status, 0) - err = ExecuteActionNotification(c, operationDownload, "", "", "", "", "", 0, nil) + err = ExecuteActionNotification(c, operationDownload, "", "", "", "", "", 0, nil, 0) assert.NoError(t, err) err = plugin.Initialize(nil, "debug") diff --git a/internal/common/connection.go b/internal/common/connection.go index 9795289c..9e7b93f2 100644 --- a/internal/common/connection.go +++ b/internal/common/connection.go @@ -360,15 +360,17 @@ func (c *BaseConnection) CreateDir(virtualPath string, checkFilePatterns bool) e if err != nil { return err } + startTime := time.Now() if err := fs.Mkdir(fsPath); err != nil { c.Log(logger.LevelError, "error creating dir: %#v error: %+v", fsPath, err) return c.GetFsError(fs, err) } vfs.SetPathPermissions(fs, fsPath, c.User.GetUID(), c.User.GetGID()) + elapsed := time.Since(startTime).Nanoseconds() / 1000000 logger.CommandLog(mkdirLogSender, fsPath, "", c.User.Username, "", c.ID, c.protocol, -1, -1, "", "", "", -1, - c.localAddr, c.remoteAddr) - ExecuteActionNotification(c, operationMkdir, fsPath, virtualPath, "", "", "", 0, nil) //nolint:errcheck + c.localAddr, c.remoteAddr, elapsed) + ExecuteActionNotification(c, operationMkdir, fsPath, virtualPath, "", "", "", 0, nil, elapsed) //nolint:errcheck return nil } @@ -397,6 +399,7 @@ func (c *BaseConnection) RemoveFile(fs vfs.Fs, fsPath, virtualPath string, info return c.GetPermissionDeniedError() } updateQuota := true + startTime := time.Now() if err := fs.Remove(fsPath, false); err != nil { if status > 0 && fs.IsNotExist(err) { // file removed in the pre-action, if the file was deleted from the EventManager the quota is already updated @@ -407,9 +410,10 @@ func (c *BaseConnection) RemoveFile(fs vfs.Fs, fsPath, virtualPath string, info return c.GetFsError(fs, err) } } + elapsed := time.Since(startTime).Nanoseconds() / 1000000 logger.CommandLog(removeLogSender, fsPath, "", c.User.Username, "", c.ID, c.protocol, -1, -1, "", "", "", -1, - c.localAddr, c.remoteAddr) + c.localAddr, c.remoteAddr, elapsed) if updateQuota && info.Mode()&os.ModeSymlink == 0 { vfolder, err := c.User.GetVirtualFolderForPath(path.Dir(virtualPath)) if err == nil { @@ -421,7 +425,7 @@ func (c *BaseConnection) RemoveFile(fs vfs.Fs, fsPath, virtualPath string, info dataprovider.UpdateUserQuota(&c.User, -1, -size, false) //nolint:errcheck } } - ExecuteActionNotification(c, operationDelete, fsPath, virtualPath, "", "", "", size, nil) //nolint:errcheck + ExecuteActionNotification(c, operationDelete, fsPath, virtualPath, "", "", "", size, nil, elapsed) //nolint:errcheck return nil } @@ -478,14 +482,16 @@ func (c *BaseConnection) RemoveDir(virtualPath string) error { return c.GetGenericError(nil) } + startTime := time.Now() if err := fs.Remove(fsPath, true); err != nil { c.Log(logger.LevelError, "failed to remove directory %#v: %+v", fsPath, err) return c.GetFsError(fs, err) } + elapsed := time.Since(startTime).Nanoseconds() / 1000000 logger.CommandLog(rmdirLogSender, fsPath, "", c.User.Username, "", c.ID, c.protocol, -1, -1, "", "", "", -1, - c.localAddr, c.remoteAddr) - ExecuteActionNotification(c, operationRmdir, fsPath, virtualPath, "", "", "", 0, nil) //nolint:errcheck + c.localAddr, c.remoteAddr, elapsed) + ExecuteActionNotification(c, operationRmdir, fsPath, virtualPath, "", "", "", 0, nil, elapsed) //nolint:errcheck return nil } @@ -597,8 +603,10 @@ func (c *BaseConnection) copyFile(virtualSourcePath, virtualTargetPath string, s } defer wCancelFn() + startTime := time.Now() _, err = io.Copy(writer, reader) - return closeWriterAndUpdateQuota(writer, c, virtualSourcePath, virtualTargetPath, numFiles, truncatedSize, err, operationCopy) + return closeWriterAndUpdateQuota(writer, c, virtualSourcePath, virtualTargetPath, numFiles, truncatedSize, + err, operationCopy, startTime) } func (c *BaseConnection) doRecursiveCopy(virtualSourcePath, virtualTargetPath string, srcInfo os.FileInfo, @@ -709,6 +717,7 @@ func (c *BaseConnection) renameInternal(virtualSourcePath, virtualTargetPath str if err != nil { return err } + startTime := time.Now() srcInfo, err := fsSrc.Lstat(fsSourcePath) if err != nil { return c.GetFsError(fsSrc, err) @@ -756,11 +765,12 @@ func (c *BaseConnection) renameInternal(virtualSourcePath, virtualTargetPath str return c.GetFsError(fsSrc, err) } vfs.SetPathPermissions(fsDst, fsTargetPath, c.User.GetUID(), c.User.GetGID()) + elapsed := time.Since(startTime).Nanoseconds() / 1000000 c.updateQuotaAfterRename(fsDst, virtualSourcePath, virtualTargetPath, fsTargetPath, initialSize, files, size) //nolint:errcheck logger.CommandLog(renameLogSender, fsSourcePath, fsTargetPath, c.User.Username, "", c.ID, c.protocol, -1, -1, - "", "", "", -1, c.localAddr, c.remoteAddr) + "", "", "", -1, c.localAddr, c.remoteAddr, elapsed) ExecuteActionNotification(c, operationRename, fsSourcePath, virtualSourcePath, fsTargetPath, //nolint:errcheck - virtualTargetPath, "", 0, nil) + virtualTargetPath, "", 0, nil, elapsed) return nil } @@ -810,12 +820,14 @@ func (c *BaseConnection) CreateSymlink(virtualSourcePath, virtualTargetPath stri if relativePath != "" { fsSourcePath = relativePath } + startTime := time.Now() if err := fs.Symlink(fsSourcePath, fsTargetPath); err != nil { - c.Log(logger.LevelError, "failed to create symlink %#v -> %#v: %+v", fsSourcePath, fsTargetPath, err) + c.Log(logger.LevelError, "failed to create symlink %q -> %q: %+v", fsSourcePath, fsTargetPath, err) return c.GetFsError(fs, err) } + elapsed := time.Since(startTime).Nanoseconds() / 1000000 logger.CommandLog(symlinkLogSender, fsSourcePath, fsTargetPath, c.User.Username, "", c.ID, c.protocol, -1, -1, "", - "", "", -1, c.localAddr, c.remoteAddr) + "", "", -1, c.localAddr, c.remoteAddr, elapsed) return nil } @@ -899,12 +911,14 @@ func (c *BaseConnection) handleChmod(fs vfs.Fs, fsPath, pathForPerms string, att if c.ignoreSetStat(fs) { return nil } + startTime := time.Now() if err := fs.Chmod(c.getRealFsPath(fsPath), attributes.Mode); err != nil { c.Log(logger.LevelError, "failed to chmod path %#v, mode: %v, err: %+v", fsPath, attributes.Mode.String(), err) return c.GetFsError(fs, err) } + elapsed := time.Since(startTime).Nanoseconds() / 1000000 logger.CommandLog(chmodLogSender, fsPath, "", c.User.Username, attributes.Mode.String(), c.ID, c.protocol, - -1, -1, "", "", "", -1, c.localAddr, c.remoteAddr) + -1, -1, "", "", "", -1, c.localAddr, c.remoteAddr, elapsed) return nil } @@ -915,13 +929,15 @@ func (c *BaseConnection) handleChown(fs vfs.Fs, fsPath, pathForPerms string, att if c.ignoreSetStat(fs) { return nil } + startTime := time.Now() if err := fs.Chown(c.getRealFsPath(fsPath), attributes.UID, attributes.GID); err != nil { c.Log(logger.LevelError, "failed to chown path %#v, uid: %v, gid: %v, err: %+v", fsPath, attributes.UID, attributes.GID, err) return c.GetFsError(fs, err) } + elapsed := time.Since(startTime).Nanoseconds() / 1000000 logger.CommandLog(chownLogSender, fsPath, "", c.User.Username, "", c.ID, c.protocol, attributes.UID, attributes.GID, - "", "", "", -1, c.localAddr, c.remoteAddr) + "", "", "", -1, c.localAddr, c.remoteAddr, elapsed) return nil } @@ -932,6 +948,7 @@ func (c *BaseConnection) handleChtimes(fs vfs.Fs, fsPath, pathForPerms string, a if Config.SetstatMode == 1 { return nil } + startTime := time.Now() isUploading := c.setTimes(fsPath, attributes.Atime, attributes.Mtime) if err := fs.Chtimes(c.getRealFsPath(fsPath), attributes.Atime, attributes.Mtime, isUploading); err != nil { c.setTimes(fsPath, time.Time{}, time.Time{}) @@ -942,10 +959,11 @@ func (c *BaseConnection) handleChtimes(fs vfs.Fs, fsPath, pathForPerms string, a fsPath, attributes.Atime, attributes.Mtime, err) return c.GetFsError(fs, err) } + elapsed := time.Since(startTime).Nanoseconds() / 1000000 accessTimeString := attributes.Atime.Format(chtimesFormat) modificationTimeString := attributes.Mtime.Format(chtimesFormat) logger.CommandLog(chtimesLogSender, fsPath, "", c.User.Username, "", c.ID, c.protocol, -1, -1, - accessTimeString, modificationTimeString, "", -1, c.localAddr, c.remoteAddr) + accessTimeString, modificationTimeString, "", -1, c.localAddr, c.remoteAddr, elapsed) return nil } @@ -982,13 +1000,14 @@ func (c *BaseConnection) SetStat(virtualPath string, attributes *StatAttributes) if !c.User.HasPerm(dataprovider.PermOverwrite, pathForPerms) { return c.GetPermissionDeniedError() } - + startTime := time.Now() if err = c.truncateFile(fs, fsPath, virtualPath, attributes.Size); err != nil { c.Log(logger.LevelError, "failed to truncate path %#v, size: %v, err: %+v", fsPath, attributes.Size, err) return c.GetFsError(fs, err) } + elapsed := time.Since(startTime).Nanoseconds() / 1000000 logger.CommandLog(truncateLogSender, fsPath, "", c.User.Username, "", c.ID, c.protocol, -1, -1, "", "", - "", attributes.Size, c.localAddr, c.remoteAddr) + "", attributes.Size, c.localAddr, c.remoteAddr, elapsed) } return nil diff --git a/internal/common/eventmanager.go b/internal/common/eventmanager.go index 7e67cde0..fda6cce0 100644 --- a/internal/common/eventmanager.go +++ b/internal/common/eventmanager.go @@ -447,6 +447,7 @@ type EventParams struct { ObjectName string ObjectType string FileSize int64 + Elapsed int64 Protocol string IP string Role string @@ -633,6 +634,7 @@ func (p *EventParams) getStringReplacements(addObjectData bool) []string { "{{ObjectName}}", p.ObjectName, "{{ObjectType}}", p.ObjectType, "{{FileSize}}", fmt.Sprintf("%d", p.FileSize), + "{{Elapsed}}", fmt.Sprintf("%d", p.Elapsed), "{{Protocol}}", p.Protocol, "{{IP}}", p.IP, "{{Role}}", p.Role, @@ -685,7 +687,7 @@ func getCSVRetentionReport(results []folderRetentionCheckResult) ([]byte, error) } func closeWriterAndUpdateQuota(w io.WriteCloser, conn *BaseConnection, virtualSourcePath, virtualTargetPath string, - numFiles int, truncatedSize int64, errTransfer error, operation string, + numFiles int, truncatedSize int64, errTransfer error, operation string, startTime time.Time, ) error { errWrite := w.Close() targetPath := virtualSourcePath @@ -704,14 +706,15 @@ func closeWriterAndUpdateQuota(w io.WriteCloser, conn *BaseConnection, virtualSo _, fsDstPath, errDstFs = conn.GetFsAndResolvedPath(virtualTargetPath) } if errSrcFs == nil && errDstFs == nil { + elapsed := time.Since(startTime).Nanoseconds() / 1000000 if errTransfer == nil { errTransfer = errWrite } if operation == operationCopy { logger.CommandLog(copyLogSender, fsSrcPath, fsDstPath, conn.User.Username, "", conn.ID, conn.protocol, -1, -1, - "", "", "", info.Size(), conn.localAddr, conn.remoteAddr) + "", "", "", info.Size(), conn.localAddr, conn.remoteAddr, elapsed) } - ExecuteActionNotification(conn, operation, fsSrcPath, virtualSourcePath, fsDstPath, virtualTargetPath, "", info.Size(), errTransfer) //nolint:errcheck + ExecuteActionNotification(conn, operation, fsSrcPath, virtualSourcePath, fsDstPath, virtualTargetPath, "", info.Size(), errTransfer, elapsed) //nolint:errcheck } } else { eventManagerLog(logger.LevelWarn, "unable to update quota after writing %q: %v", targetPath, err) @@ -1735,18 +1738,19 @@ func executeCompressFsActionForUser(c dataprovider.EventActionFsCompress, replac Writer: zip.NewWriter(writer), Entries: make(map[string]bool), } + startTime := time.Now() for _, item := range paths { if err := addZipEntry(zipWriter, conn, item, baseDir); err != nil { - closeWriterAndUpdateQuota(writer, conn, name, "", numFiles, truncatedSize, err, operationUpload) //nolint:errcheck + closeWriterAndUpdateQuota(writer, conn, name, "", numFiles, truncatedSize, err, operationUpload, startTime) //nolint:errcheck return err } } if err := zipWriter.Writer.Close(); err != nil { eventManagerLog(logger.LevelError, "unable to close zip file %q: %v", name, err) - closeWriterAndUpdateQuota(writer, conn, name, "", numFiles, truncatedSize, err, operationUpload) //nolint:errcheck + closeWriterAndUpdateQuota(writer, conn, name, "", numFiles, truncatedSize, err, operationUpload, startTime) //nolint:errcheck return fmt.Errorf("unable to close zip file %q: %w", name, err) } - return closeWriterAndUpdateQuota(writer, conn, name, "", numFiles, truncatedSize, err, operationUpload) + return closeWriterAndUpdateQuota(writer, conn, name, "", numFiles, truncatedSize, err, operationUpload, startTime) } func executeExistFsRuleAction(exist []string, replacer *strings.Replacer, conditions dataprovider.ConditionOptions, diff --git a/internal/common/transfer.go b/internal/common/transfer.go index 5ea544ed..d8dbb6fc 100644 --- a/internal/common/transfer.go +++ b/internal/common/transfer.go @@ -393,7 +393,7 @@ func (t *BaseTransfer) Close() error { logger.TransferLog(downloadLogSender, t.fsPath, elapsed, t.BytesSent.Load(), t.Connection.User.Username, t.Connection.ID, t.Connection.protocol, t.Connection.localAddr, t.Connection.remoteAddr, t.ftpMode) ExecuteActionNotification(t.Connection, operationDownload, t.fsPath, t.requestPath, "", "", "", //nolint:errcheck - t.BytesSent.Load(), t.ErrTransfer) + t.BytesSent.Load(), t.ErrTransfer, elapsed) } else { statSize, deletedFiles, errStat := t.getUploadFileSize() if errStat == nil { @@ -408,7 +408,7 @@ func (t *BaseTransfer) Close() error { numFiles -= deletedFiles t.Connection.Log(logger.LevelDebug, "upload file size %d, num files %d, deleted files %d, fs path %q", uploadFileSize, numFiles, deletedFiles, t.fsPath) - numFiles, uploadFileSize = t.executeUploadHook(numFiles, uploadFileSize) + numFiles, uploadFileSize = t.executeUploadHook(numFiles, uploadFileSize, elapsed) t.updateQuota(numFiles, uploadFileSize) t.updateTimes() logger.TransferLog(uploadLogSender, t.fsPath, elapsed, t.BytesReceived.Load(), t.Connection.User.Username, @@ -420,11 +420,11 @@ func (t *BaseTransfer) Close() error { err = t.ErrTransfer } } - t.updateTransferTimestamps(uploadFileSize) + t.updateTransferTimestamps(uploadFileSize, elapsed) return err } -func (t *BaseTransfer) updateTransferTimestamps(uploadFileSize int64) { +func (t *BaseTransfer) updateTransferTimestamps(uploadFileSize, elapsed int64) { if t.ErrTransfer != nil { return } @@ -433,7 +433,7 @@ func (t *BaseTransfer) updateTransferTimestamps(uploadFileSize int64) { if err := dataprovider.UpdateUserTransferTimestamps(t.Connection.User.Username, true); err == nil { t.Connection.uploadDone.Store(true) ExecuteActionNotification(t.Connection, operationFirstUpload, t.fsPath, t.requestPath, "", //nolint:errcheck - "", "", uploadFileSize, t.ErrTransfer) + "", "", uploadFileSize, t.ErrTransfer, elapsed) } } return @@ -442,14 +442,14 @@ func (t *BaseTransfer) updateTransferTimestamps(uploadFileSize int64) { if err := dataprovider.UpdateUserTransferTimestamps(t.Connection.User.Username, false); err == nil { t.Connection.downloadDone.Store(true) ExecuteActionNotification(t.Connection, operationFirstDownload, t.fsPath, t.requestPath, "", //nolint:errcheck - "", "", t.BytesSent.Load(), t.ErrTransfer) + "", "", t.BytesSent.Load(), t.ErrTransfer, elapsed) } } } -func (t *BaseTransfer) executeUploadHook(numFiles int, fileSize int64) (int, int64) { +func (t *BaseTransfer) executeUploadHook(numFiles int, fileSize, elapsed int64) (int, int64) { err := ExecuteActionNotification(t.Connection, operationUpload, t.fsPath, t.requestPath, "", "", "", - fileSize, t.ErrTransfer) + fileSize, t.ErrTransfer, elapsed) if err != nil { if t.ErrTransfer == nil { t.ErrTransfer = err diff --git a/internal/logger/logger.go b/internal/logger/logger.go index 35cc34e5..e933229d 100644 --- a/internal/logger/logger.go +++ b/internal/logger/logger.go @@ -223,7 +223,7 @@ func TransferLog(operation, path string, elapsed int64, size int64, user, connec // CommandLog logs an SFTP/SCP/SSH command func CommandLog(command, path, target, user, fileMode, connectionID, protocol string, uid, gid int, atime, mtime, - sshCommand string, size int64, localAddr, remoteAddr string) { + sshCommand string, size int64, localAddr, remoteAddr string, elapsed int64) { logger.Info(). Timestamp(). Str("sender", command). @@ -238,6 +238,7 @@ func CommandLog(command, path, target, user, fileMode, connectionID, protocol st Str("access_time", atime). Str("modification_time", mtime). Int64("size", size). + Int64("elapsed", elapsed). Str("ssh_command", sshCommand). Str("connection_id", connectionID). Str("protocol", protocol). diff --git a/internal/sftpd/ssh_cmd.go b/internal/sftpd/ssh_cmd.go index 8c6325b4..fd8d1936 100644 --- a/internal/sftpd/ssh_cmd.go +++ b/internal/sftpd/ssh_cmd.go @@ -29,6 +29,7 @@ import ( "runtime/debug" "strings" "sync" + "time" "github.com/google/shlex" "github.com/sftpgo/sdk" @@ -55,6 +56,7 @@ type sshCommand struct { command string args []string connection *Connection + startTime time.Time } type systemCommand struct { @@ -97,6 +99,7 @@ func processSSHCommand(payload []byte, connection *Connection, enabledSSHCommand sshCommand: sshCommand{ command: name, connection: connection, + startTime: time.Now(), args: args}, } go scpCommand.handle() //nolint:errcheck @@ -107,6 +110,7 @@ func processSSHCommand(payload []byte, connection *Connection, enabledSSHCommand sshCommand := sshCommand{ command: name, connection: connection, + startTime: time.Now(), args: args, } go sshCommand.handle() //nolint:errcheck @@ -549,6 +553,7 @@ func (c *sshCommand) sendExitStatus(err error) { c.connection.channel.Close() // for scp we notify single uploads/downloads if c.command != scpCmdName { + elapsed := time.Since(c.startTime).Nanoseconds() / 1000000 metric.SSHCommandCompleted(err) if vCmdPath != "" { _, p, errFs := c.connection.GetFsAndResolvedPath(vCmdPath) @@ -563,11 +568,11 @@ func (c *sshCommand) sendExitStatus(err error) { } } common.ExecuteActionNotification(c.connection.BaseConnection, common.OperationSSHCmd, cmdPath, vCmdPath, //nolint:errcheck - targetPath, vTargetPath, c.command, 0, err) + targetPath, vTargetPath, c.command, 0, err, elapsed) if err == nil { logger.CommandLog(sshCommandLogSender, cmdPath, targetPath, c.connection.User.Username, "", c.connection.ID, common.ProtocolSSH, -1, -1, "", "", c.connection.command, -1, c.connection.GetLocalAddress(), - c.connection.GetRemoteAddress()) + c.connection.GetRemoteAddress(), elapsed) } } } diff --git a/pkgs/build.sh b/pkgs/build.sh index 50e70001..b0dc031b 100755 --- a/pkgs/build.sh +++ b/pkgs/build.sh @@ -1,6 +1,6 @@ #!/bin/bash -NFPM_VERSION=2.25.0 +NFPM_VERSION=2.26.0 NFPM_ARCH=${NFPM_ARCH:-amd64} if [ -z ${SFTPGO_VERSION} ] then diff --git a/templates/webadmin/eventaction.html b/templates/webadmin/eventaction.html index afcc7018..d3d15034 100644 --- a/templates/webadmin/eventaction.html +++ b/templates/webadmin/eventaction.html @@ -760,6 +760,9 @@ along with this program. If not, see .

{{`{{FileSize}}`}} => File size.

+

+ {{`{{Elapsed}}`}} => Elapsed time as milliseconds for filesystem events. +

{{`{{Protocol}}`}} => Protocol, for example "SFTP", "FTP".