From 006c67a5db76af46503f1e0abdbbfea1bdff119d Mon Sep 17 00:00:00 2001
From: Michael Barz <mbarz@owncloud.com>
Date: Fri, 19 Jul 2024 11:02:33 +0200
Subject: [PATCH] feat: add more logging to the collaboration service

---
 changelog/unreleased/collaboration-logging.md            | 5 +++++
 services/collaboration/pkg/connector/contentconnector.go | 7 ++++++-
 services/collaboration/pkg/connector/fileconnector.go    | 7 ++++++-
 services/collaboration/pkg/middleware/accesslog.go       | 1 +
 4 files changed, 18 insertions(+), 2 deletions(-)
 create mode 100644 changelog/unreleased/collaboration-logging.md

diff --git a/changelog/unreleased/collaboration-logging.md b/changelog/unreleased/collaboration-logging.md
new file mode 100644
index 0000000000..dd7470cdcc
--- /dev/null
+++ b/changelog/unreleased/collaboration-logging.md
@@ -0,0 +1,5 @@
+Enhancement: Improve the collaboration service logging
+
+We added more debug log information to the collaboration service. This is vital for scenarios when we need to debug in remote setups.
+
+https://github.com/owncloud/ocis/pull/9653
diff --git a/services/collaboration/pkg/connector/contentconnector.go b/services/collaboration/pkg/connector/contentconnector.go
index f450ef5c47..a292442141 100644
--- a/services/collaboration/pkg/connector/contentconnector.go
+++ b/services/collaboration/pkg/connector/contentconnector.go
@@ -67,7 +67,10 @@ func (c *ContentConnector) GetFile(ctx context.Context, writer io.Writer) error
 		return err
 	}
 
-	logger := zerolog.Ctx(ctx)
+	logger := zerolog.Ctx(ctx).With().
+		Interface("FileReference", wopiContext.FileReference).
+		Logger()
+	logger.Debug().Msg("GetFile: start")
 
 	// Initiate download request
 	req := &providerv1beta1.InitiateFileDownloadRequest{
@@ -201,7 +204,9 @@ func (c *ContentConnector) PutFile(ctx context.Context, stream io.Reader, stream
 	logger := zerolog.Ctx(ctx).With().
 		Str("RequestedLockID", lockID).
 		Int64("UploadLength", streamLength).
+		Interface("FileReference", wopiContext.FileReference).
 		Logger()
+	logger.Debug().Msg("PutFile: start")
 
 	// We need a stat call on the target file in order to get both the lock
 	// (if any) and the current size of the file
diff --git a/services/collaboration/pkg/connector/fileconnector.go b/services/collaboration/pkg/connector/fileconnector.go
index 59689286c9..39993a2efe 100644
--- a/services/collaboration/pkg/connector/fileconnector.go
+++ b/services/collaboration/pkg/connector/fileconnector.go
@@ -148,6 +148,7 @@ func (f *FileConnector) Lock(ctx context.Context, lockID, oldLockID string) (str
 		Str("RequestedLockID", lockID).
 		Str("RequestedOldLockID", oldLockID).
 		Logger()
+	logger.Debug().Msg("Lock: start")
 
 	if lockID == "" {
 		logger.Error().Msg("Lock failed due to empty lockID")
@@ -157,6 +158,7 @@ func (f *FileConnector) Lock(ctx context.Context, lockID, oldLockID string) (str
 	var setOrRefreshStatus *rpcv1beta1.Status
 	if oldLockID == "" {
 		// If the oldLockID is empty, this is a "LOCK" request
+		logger.Debug().Msg("Lock: this is a SetLock request")
 		req := &providerv1beta1.SetLockRequest{
 			Ref: wopiContext.FileReference,
 			Lock: &providerv1beta1.Lock{
@@ -178,6 +180,7 @@ func (f *FileConnector) Lock(ctx context.Context, lockID, oldLockID string) (str
 	} else {
 		// If the oldLockID isn't empty, this is a "UnlockAndRelock" request. We'll
 		// do a "RefreshLock" in reva and provide the old lock
+		logger.Debug().Msg("Lock: this is a RefreshLock request")
 		req := &providerv1beta1.RefreshLockRequest{
 			Ref: wopiContext.FileReference,
 			Lock: &providerv1beta1.Lock{
@@ -285,6 +288,7 @@ func (f *FileConnector) RefreshLock(ctx context.Context, lockID string) (string,
 	logger := zerolog.Ctx(ctx).With().
 		Str("RequestedLockID", lockID).
 		Logger()
+	logger.Debug().Msg("RefreshLock: start")
 
 	if lockID == "" {
 		logger.Error().Msg("RefreshLock failed due to empty lockID")
@@ -393,6 +397,7 @@ func (f *FileConnector) UnLock(ctx context.Context, lockID string) (string, erro
 	logger := zerolog.Ctx(ctx).With().
 		Str("RequestedLockID", lockID).
 		Logger()
+	logger.Debug().Msg("UnLock: start")
 
 	if lockID == "" {
 		logger.Error().Msg("Unlock failed due to empty lockID")
@@ -579,7 +584,7 @@ func (f *FileConnector) CheckFileInfo(ctx context.Context) (fileinfo.FileInfo, e
 
 	info.SetProperties(infoMap)
 
-	logger.Debug().Msg("CheckFileInfo: success")
+	logger.Debug().Interface("FileInfo", info).Msg("CheckFileInfo: success")
 	return info, nil
 }
 
diff --git a/services/collaboration/pkg/middleware/accesslog.go b/services/collaboration/pkg/middleware/accesslog.go
index e51faeb4bb..ea990e4f5a 100644
--- a/services/collaboration/pkg/middleware/accesslog.go
+++ b/services/collaboration/pkg/middleware/accesslog.go
@@ -27,6 +27,7 @@ func AccessLog(logger log.Logger) func(http.Handler) http.Handler {
 				Str("traceid", spanContext.TraceID().String()).
 				Str("remote-addr", r.RemoteAddr).
 				Str("method", r.Method).
+				Str("wopi-action", r.Header.Get("X-WOPI-Override")).
 				Int("status", wrap.Status()).
 				Str("path", r.URL.Path).
 				Dur("duration", time.Since(start)).