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".