diff --git a/changelog/unreleased/align-logs.md b/changelog/unreleased/align-logs.md new file mode 100644 index 00000000000..94ab219f540 --- /dev/null +++ b/changelog/unreleased/align-logs.md @@ -0,0 +1,5 @@ +Bugfix: consistently use spaceid and nodeid in logs + +Sometimes we tried to log a node which led to a JSON recursion error because it contains a reference to the space root, which references itself. We now always log `spaceid` and `nodeid`. + +https://github.com/cs3org/reva/pull/4623 diff --git a/internal/http/services/owncloud/ocs/handlers/apps/sharing/shares/shares.go b/internal/http/services/owncloud/ocs/handlers/apps/sharing/shares/shares.go index 4a46ebaa139..ef88c9acb87 100644 --- a/internal/http/services/owncloud/ocs/handlers/apps/sharing/shares/shares.go +++ b/internal/http/services/owncloud/ocs/handlers/apps/sharing/shares/shares.go @@ -1147,7 +1147,7 @@ func (h *Handler) listSharesWithOthers(w http.ResponseWriter, r *http.Request) { s := r.URL.Query().Get("space") spaceRef := r.URL.Query().Get("space_ref") ctx := r.Context() - sublog := appctx.GetLogger(ctx).With().Str("path", p).Str("space", s).Str("space_ref", spaceRef).Logger() + sublog := appctx.GetLogger(ctx).With().Str("path", p).Str("spaceid", s).Str("space_ref", spaceRef).Logger() if p != "" || s != "" || spaceRef != "" { ref, err := h.extractReference(r) if err != nil { diff --git a/pkg/rhttp/datatx/manager/spaces/spaces.go b/pkg/rhttp/datatx/manager/spaces/spaces.go index ce585ab5426..1e06a2fedc2 100644 --- a/pkg/rhttp/datatx/manager/spaces/spaces.go +++ b/pkg/rhttp/datatx/manager/spaces/spaces.go @@ -80,7 +80,7 @@ func (m *manager) Handler(fs storage.FS) (http.Handler, error) { var spaceID string spaceID, r.URL.Path = router.ShiftPath(r.URL.Path) - sublog := appctx.GetLogger(ctx).With().Str("datatx", "spaces").Str("space", spaceID).Logger() + sublog := appctx.GetLogger(ctx).With().Str("datatx", "spaces").Str("spaceid", spaceID).Logger() switch r.Method { case "GET", "HEAD": diff --git a/pkg/storage/fs/posix/lookup/lookup.go b/pkg/storage/fs/posix/lookup/lookup.go index d64223f7d49..d08d94fd5f3 100644 --- a/pkg/storage/fs/posix/lookup/lookup.go +++ b/pkg/storage/fs/posix/lookup/lookup.go @@ -199,7 +199,8 @@ func (lu *Lookup) Path(ctx context.Context, n *node.Node, hasPermission node.Per appctx.GetLogger(ctx). Error().Err(err). Str("path", p). - Interface("node", n). + Str("spaceid", n.SpaceID). + Str("nodeid", n.ID). Msg("Path()") return } diff --git a/pkg/storage/utils/decomposedfs/decomposedfs.go b/pkg/storage/utils/decomposedfs/decomposedfs.go index d1ebb61e2f8..9af86b4c437 100644 --- a/pkg/storage/utils/decomposedfs/decomposedfs.go +++ b/pkg/storage/utils/decomposedfs/decomposedfs.go @@ -246,9 +246,10 @@ func (fs *Decomposedfs) Postprocessing(ch <-chan events.Event) { for event := range ch { switch ev := event.Event.(type) { case events.PostprocessingFinished: + sublog := log.With().Str("event", "PostprocessingFinished").Str("uploadid", ev.UploadID).Logger() session, err := fs.sessionStore.Get(ctx, ev.UploadID) if err != nil { - log.Error().Err(err).Str("uploadID", ev.UploadID).Msg("Failed to get upload") + sublog.Error().Err(err).Msg("Failed to get upload") continue // NOTE: since we can't get the upload, we can't delete the blob } @@ -256,11 +257,12 @@ func (fs *Decomposedfs) Postprocessing(ch <-chan events.Event) { n, err := session.Node(ctx) if err != nil { - log.Error().Err(err).Str("uploadID", ev.UploadID).Msg("could not read node") + sublog.Error().Err(err).Msg("could not read node") continue } + sublog = log.With().Str("spaceid", session.SpaceID()).Str("nodeid", session.NodeID()).Logger() if !n.Exists { - log.Debug().Str("uploadID", ev.UploadID).Str("nodeID", session.NodeID()).Msg("node no longer exists") + sublog.Debug().Msg("node no longer exists") fs.sessionStore.Cleanup(ctx, session, false, false, false) continue } @@ -274,7 +276,7 @@ func (fs *Decomposedfs) Postprocessing(ch <-chan events.Event) { switch ev.Outcome { default: - log.Error().Str("outcome", string(ev.Outcome)).Str("uploadID", ev.UploadID).Msg("unknown postprocessing outcome - aborting") + sublog.Error().Str("outcome", string(ev.Outcome)).Msg("unknown postprocessing outcome - aborting") fallthrough case events.PPOutcomeAbort: failed = true @@ -283,7 +285,7 @@ func (fs *Decomposedfs) Postprocessing(ch <-chan events.Event) { metrics.UploadSessionsAborted.Inc() case events.PPOutcomeContinue: if err := session.Finalize(); err != nil { - log.Error().Err(err).Str("uploadID", ev.UploadID).Msg("could not finalize upload") + sublog.Error().Err(err).Msg("could not finalize upload") failed = true revertNodeMetadata = false keepUpload = true @@ -301,7 +303,7 @@ func (fs *Decomposedfs) Postprocessing(ch <-chan events.Event) { getParent := func() *node.Node { p, err := n.Parent(ctx) if err != nil { - log.Error().Err(err).Str("uploadID", ev.UploadID).Msg("could not read parent") + sublog.Error().Err(err).Msg("could not read parent") return nil } return p @@ -312,19 +314,19 @@ func (fs *Decomposedfs) Postprocessing(ch <-chan events.Event) { // if no other upload session is in progress (processing id != session id) or has finished (processing id == "") latestSession, err := n.ProcessingID(ctx) if err != nil { - log.Error().Err(err).Str("node", n.ID).Str("uploadID", ev.UploadID).Msg("reading node for session failed") + sublog.Error().Err(err).Msg("reading node for session failed") } if latestSession == session.ID() { // propagate reverted sizeDiff after failed postprocessing if err := fs.tp.Propagate(ctx, n, -session.SizeDiff()); err != nil { - log.Error().Err(err).Str("uploadID", ev.UploadID).Msg("could not propagate tree size change") + sublog.Error().Err(err).Msg("could not propagate tree size change") } } } else if p := getParent(); p != nil { // update parent tmtime to propagate etag change after successful postprocessing _ = p.SetTMTime(ctx, &now) if err := fs.tp.Propagate(ctx, p, 0); err != nil { - log.Error().Err(err).Str("uploadID", ev.UploadID).Msg("could not propagate etag change") + sublog.Error().Err(err).Msg("could not propagate etag change") } } @@ -350,22 +352,24 @@ func (fs *Decomposedfs) Postprocessing(ch <-chan events.Event) { SpaceOwner: n.SpaceOwnerOrManager(ctx), }, ); err != nil { - log.Error().Err(err).Str("uploadID", ev.UploadID).Msg("Failed to publish UploadReady event") + sublog.Error().Err(err).Msg("Failed to publish UploadReady event") } case events.RestartPostprocessing: + sublog := log.With().Str("event", "RestartPostprocessing").Str("uploadid", ev.UploadID).Logger() session, err := fs.sessionStore.Get(ctx, ev.UploadID) if err != nil { - log.Error().Err(err).Str("uploadID", ev.UploadID).Msg("Failed to get upload") + sublog.Error().Err(err).Msg("Failed to get upload") continue } n, err := session.Node(ctx) if err != nil { - log.Error().Err(err).Str("uploadID", ev.UploadID).Msg("could not read node") + sublog.Error().Err(err).Msg("could not read node") continue } + sublog = log.With().Str("spaceid", session.SpaceID()).Str("nodeid", session.NodeID()).Logger() s, err := session.URL(ctx) if err != nil { - log.Error().Err(err).Str("uploadID", ev.UploadID).Msg("could not create url") + sublog.Error().Err(err).Msg("could not create url") continue } @@ -381,9 +385,10 @@ func (fs *Decomposedfs) Postprocessing(ch <-chan events.Event) { Filename: session.Filename(), Filesize: uint64(session.Size()), }); err != nil { - log.Error().Err(err).Str("uploadID", ev.UploadID).Msg("Failed to publish BytesReceived event") + sublog.Error().Err(err).Msg("Failed to publish BytesReceived event") } case events.PostprocessingStepFinished: + sublog := log.With().Str("event", "PostprocessingStepFinished").Str("uploadid", ev.UploadID).Logger() if ev.FinishedStep != events.PPStepAntivirus { // atm we are only interested in antivirus results continue @@ -395,6 +400,7 @@ func (fs *Decomposedfs) Postprocessing(ch <-chan events.Event) { // Should we handle this here? continue } + sublog = log.With().Str("scan_description", res.Description).Bool("infected", res.Infected).Logger() var n *node.Node switch ev.UploadID { @@ -480,19 +486,20 @@ func (fs *Decomposedfs) Postprocessing(ch <-chan events.Event) { // uploadid is not empty -> this is an async upload session, err := fs.sessionStore.Get(ctx, ev.UploadID) if err != nil { - log.Error().Err(err).Str("uploadID", ev.UploadID).Msg("Failed to get upload") + sublog.Error().Err(err).Msg("Failed to get upload") continue } n, err = session.Node(ctx) if err != nil { - log.Error().Err(err).Interface("uploadID", ev.UploadID).Msg("Failed to get node after scan") + sublog.Error().Err(err).Msg("Failed to get node after scan") continue } + sublog = log.With().Str("spaceid", session.SpaceID()).Str("nodeid", session.NodeID()).Logger() } if err := n.SetScanData(ctx, res.Description, res.Scandate); err != nil { - log.Error().Err(err).Str("uploadID", ev.UploadID).Interface("resourceID", res.ResourceID).Msg("Failed to set scan results") + sublog.Error().Err(err).Msg("Failed to set scan results") continue } diff --git a/pkg/storage/utils/decomposedfs/lookup/lookup.go b/pkg/storage/utils/decomposedfs/lookup/lookup.go index bd432c5fd3a..e7a81398395 100644 --- a/pkg/storage/utils/decomposedfs/lookup/lookup.go +++ b/pkg/storage/utils/decomposedfs/lookup/lookup.go @@ -211,7 +211,8 @@ func (lu *Lookup) Path(ctx context.Context, n *node.Node, hasPermission node.Per appctx.GetLogger(ctx). Error().Err(err). Str("path", p). - Interface("node", n). + Str("spaceid", n.SpaceID). + Str("nodeid", n.ID). Msg("Path()") return } diff --git a/pkg/storage/utils/decomposedfs/metadata.go b/pkg/storage/utils/decomposedfs/metadata.go index ec5fed27cb2..41a44a75f1d 100644 --- a/pkg/storage/utils/decomposedfs/metadata.go +++ b/pkg/storage/utils/decomposedfs/metadata.go @@ -42,7 +42,7 @@ func (fs *Decomposedfs) SetArbitraryMetadata(ctx context.Context, ref *provider. if err != nil { return errors.Wrap(err, "Decomposedfs: error resolving ref") } - sublog := appctx.GetLogger(ctx).With().Interface("node", n).Logger() + sublog := appctx.GetLogger(ctx).With().Str("spaceid", n.SpaceID).Str("nodeid", n.ID).Logger() if !n.Exists { err = errtypes.NotFound(filepath.Join(n.ParentID, n.Name)) @@ -135,7 +135,7 @@ func (fs *Decomposedfs) UnsetArbitraryMetadata(ctx context.Context, ref *provide if err != nil { return errors.Wrap(err, "Decomposedfs: error resolving ref") } - sublog := appctx.GetLogger(ctx).With().Interface("node", n).Logger() + sublog := appctx.GetLogger(ctx).With().Str("spaceid", n.SpaceID).Str("nodeid", n.ID).Logger() if !n.Exists { err = errtypes.NotFound(filepath.Join(n.ParentID, n.Name)) diff --git a/pkg/storage/utils/decomposedfs/node/node.go b/pkg/storage/utils/decomposedfs/node/node.go index db22961fd29..d5413402321 100644 --- a/pkg/storage/utils/decomposedfs/node/node.go +++ b/pkg/storage/utils/decomposedfs/node/node.go @@ -513,7 +513,7 @@ func (n *Node) readOwner(ctx context.Context) (*userpb.UserId, error) { func (n *Node) PermissionSet(ctx context.Context) (provider.ResourcePermissions, bool) { u, ok := ctxpkg.ContextGetUser(ctx) if !ok { - appctx.GetLogger(ctx).Debug().Interface("node", n).Msg("no user in context, returning default permissions") + appctx.GetLogger(ctx).Debug().Str("spaceid", n.SpaceID).Str("nodeid", n.ID).Msg("no user in context, returning default permissions") return NoPermissions(), false } if utils.UserEqual(u.Id, n.SpaceRoot.Owner()) { @@ -582,7 +582,7 @@ func (n *Node) SetMtime(ctx context.Context, t *time.Time) (err error) { // SetEtag sets the temporary etag of a node if it differs from the current etag func (n *Node) SetEtag(ctx context.Context, val string) (err error) { - sublog := appctx.GetLogger(ctx).With().Interface("node", n).Logger() + sublog := appctx.GetLogger(ctx).With().Str("spaceid", n.SpaceID).Str("nodeid", n.ID).Logger() var tmTime time.Time if tmTime, err = n.GetTMTime(ctx); err != nil { return @@ -1014,7 +1014,7 @@ func isGrantExpired(g *provider.Grant) bool { func (n *Node) ReadUserPermissions(ctx context.Context, u *userpb.User) (ap provider.ResourcePermissions, accessDenied bool, err error) { // check if the current user is the owner if utils.UserEqual(u.Id, n.Owner()) { - appctx.GetLogger(ctx).Debug().Str("node", n.ID).Msg("user is owner, returning owner permissions") + appctx.GetLogger(ctx).Debug().Str("spaceid", n.SpaceID).Str("nodeid", n.ID).Msg("user is owner, returning owner permissions") return OwnerPermissions(), false, nil } @@ -1032,7 +1032,7 @@ func (n *Node) ReadUserPermissions(ctx context.Context, u *userpb.User) (ap prov // we read all grantees from the node var grantees []string if grantees, err = n.ListGrantees(ctx); err != nil { - appctx.GetLogger(ctx).Error().Err(err).Interface("node", n).Msg("error listing grantees") + appctx.GetLogger(ctx).Error().Err(err).Str("spaceid", n.SpaceID).Str("nodeid", n.ID).Msg("error listing grantees") return NoPermissions(), true, err } @@ -1073,15 +1073,15 @@ func (n *Node) ReadUserPermissions(ctx context.Context, u *userpb.User) (ap prov } AddPermissions(&ap, g.GetPermissions()) case metadata.IsAttrUnset(err): - appctx.GetLogger(ctx).Error().Interface("node", n).Str("grant", grantees[i]).Interface("grantees", grantees).Msg("grant vanished from node after listing") + appctx.GetLogger(ctx).Error().Str("spaceid", n.SpaceID).Str("nodeid", n.ID).Str("grant", grantees[i]).Interface("grantees", grantees).Msg("grant vanished from node after listing") // continue with next segment default: - appctx.GetLogger(ctx).Error().Err(err).Interface("node", n).Str("grant", grantees[i]).Msg("error reading permissions") + appctx.GetLogger(ctx).Error().Err(err).Str("spaceid", n.SpaceID).Str("nodeid", n.ID).Str("grant", grantees[i]).Msg("error reading permissions") // continue with next segment } } - appctx.GetLogger(ctx).Debug().Interface("permissions", ap).Interface("node", n).Interface("user", u).Msg("returning aggregated permissions") + appctx.GetLogger(ctx).Debug().Interface("permissions", ap).Str("spaceid", n.SpaceID).Str("nodeid", n.ID).Interface("user", u).Msg("returning aggregated permissions") return ap, false, nil } @@ -1135,7 +1135,7 @@ func (n *Node) IsDenied(ctx context.Context) bool { func (n *Node) ListGrantees(ctx context.Context) (grantees []string, err error) { attrs, err := n.Xattrs(ctx) if err != nil { - appctx.GetLogger(ctx).Error().Err(err).Str("node", n.ID).Msg("error listing attributes") + appctx.GetLogger(ctx).Error().Err(err).Str("spaceid", n.SpaceID).Str("nodeid", n.ID).Msg("error listing attributes") return nil, err } for name := range attrs { @@ -1202,7 +1202,8 @@ func (n *Node) ListGrants(ctx context.Context) ([]*provider.Grant, error) { appctx.GetLogger(ctx). Error(). Err(err). - Str("node", n.ID). + Str("spaceid", n.SpaceID). + Str("nodeid", n.ID). Str("grantee", g). Msg("error reading grant") continue diff --git a/pkg/storage/utils/decomposedfs/recycle.go b/pkg/storage/utils/decomposedfs/recycle.go index 72c2b226403..aa0ead067b0 100644 --- a/pkg/storage/utils/decomposedfs/recycle.go +++ b/pkg/storage/utils/decomposedfs/recycle.go @@ -57,7 +57,7 @@ func (fs *Decomposedfs) ListRecycle(ctx context.Context, ref *provider.Reference } spaceID := ref.ResourceId.OpaqueId - sublog := appctx.GetLogger(ctx).With().Str("space", spaceID).Str("key", key).Str("relative_path", relativePath).Logger() + sublog := appctx.GetLogger(ctx).With().Str("spaceid", spaceID).Str("key", key).Str("relative_path", relativePath).Logger() // check permissions trashnode, err := fs.lu.NodeFromSpaceID(ctx, spaceID) @@ -98,7 +98,7 @@ func (fs *Decomposedfs) ListRecycle(ctx context.Context, ref *provider.Reference if attrBytes, ok := attrs[prefixes.TrashOriginAttr]; ok { origin = string(attrBytes) } else { - sublog.Error().Err(err).Str("space", spaceID).Msg("could not read origin path, skipping") + sublog.Error().Err(err).Str("spaceid", spaceID).Msg("could not read origin path, skipping") return nil, err } @@ -291,14 +291,14 @@ func (fs *Decomposedfs) listTrashRoot(ctx context.Context, spaceID string) ([]*p // TODO nanos } } else { - log.Error().Err(err).Str("trashRoot", trashRoot).Str("item", itemPath).Str("node", nodeID).Str("dtime", timeSuffix).Msg("could not parse time format, ignoring") + log.Error().Err(err).Str("trashRoot", trashRoot).Str("item", itemPath).Str("spaceid", spaceID).Str("nodeid", nodeID).Str("dtime", timeSuffix).Msg("could not parse time format, ignoring") } // lookup origin path in extended attributes if attr, ok := attrs[prefixes.TrashOriginAttr]; ok { item.Ref = &provider.Reference{Path: string(attr)} } else { - log.Error().Str("trashRoot", trashRoot).Str("item", itemPath).Str("node", nodeID).Str("dtime", timeSuffix).Msg("could not read origin path") + log.Error().Str("trashRoot", trashRoot).Str("item", itemPath).Str("spaceid", spaceID).Str("nodeid", nodeID).Str("dtime", timeSuffix).Msg("could not read origin path") } select { case results <- item: diff --git a/pkg/storage/utils/decomposedfs/spaces.go b/pkg/storage/utils/decomposedfs/spaces.go index 0c1f541f8b1..6a555ea12f6 100644 --- a/pkg/storage/utils/decomposedfs/spaces.go +++ b/pkg/storage/utils/decomposedfs/spaces.go @@ -808,7 +808,7 @@ func (fs *Decomposedfs) storageSpaceFromNode(ctx context.Context, n *node.Node, } } - sublog := appctx.GetLogger(ctx).With().Str("space", n.SpaceRoot.ID).Logger() + sublog := appctx.GetLogger(ctx).With().Str("spaceid", n.SpaceID).Logger() var err error // TODO apply more filters diff --git a/pkg/storage/utils/decomposedfs/upload.go b/pkg/storage/utils/decomposedfs/upload.go index 02f74ce2622..03c757b9882 100644 --- a/pkg/storage/utils/decomposedfs/upload.go +++ b/pkg/storage/utils/decomposedfs/upload.go @@ -223,7 +223,7 @@ func (fs *Decomposedfs) InitiateUpload(ctx context.Context, ref *provider.Refere } } - log.Debug().Interface("session", session).Interface("node", n).Interface("metadata", metadata).Msg("Decomposedfs: resolved filename") + log.Debug().Str("uploadid", session.ID()).Str("spaceid", n.SpaceID).Str("nodeid", n.ID).Interface("metadata", metadata).Msg("Decomposedfs: resolved filename") _, err = node.CheckQuota(ctx, n.SpaceRoot, n.Exists, uint64(n.Blobsize), uint64(session.Size())) if err != nil { diff --git a/pkg/storage/utils/decomposedfs/upload/store.go b/pkg/storage/utils/decomposedfs/upload/store.go index aeab235de17..b880b39baa3 100644 --- a/pkg/storage/utils/decomposedfs/upload/store.go +++ b/pkg/storage/utils/decomposedfs/upload/store.go @@ -216,12 +216,12 @@ func (store OcisStore) CreateNodeForUpload(session *OcisSession, initAttrs node. f, err = store.updateExistingNode(ctx, session, n, session.SpaceID(), uint64(session.Size())) if f != nil { - appctx.GetLogger(ctx).Info().Str("lockfile", f.Name()).Interface("err", err).Msg("got lock file from updateExistingNode") + appctx.GetLogger(ctx).Debug().Str("lockfile", f.Name()).Interface("err", err).Msg("got lock file from updateExistingNode") } } else { f, err = store.initNewNode(ctx, session, n, uint64(session.Size())) if f != nil { - appctx.GetLogger(ctx).Info().Str("lockfile", f.Name()).Interface("err", err).Msg("got lock file from initNewNode") + appctx.GetLogger(ctx).Debug().Str("lockfile", f.Name()).Interface("err", err).Msg("got lock file from initNewNode") } } defer func() { diff --git a/pkg/storage/utils/decomposedfs/upload/upload.go b/pkg/storage/utils/decomposedfs/upload/upload.go index 45f48ec8446..fe2861e5562 100644 --- a/pkg/storage/utils/decomposedfs/upload/upload.go +++ b/pkg/storage/utils/decomposedfs/upload/upload.go @@ -318,7 +318,7 @@ func (session *OcisSession) Cleanup(revertNodeMetadata, cleanBin, cleanInfo bool if revertNodeMetadata { n, err := session.Node(ctx) if err != nil { - appctx.GetLogger(ctx).Error().Err(err).Str("node", n.ID).Str("sessionid", session.ID()).Msg("reading node for session failed") + appctx.GetLogger(ctx).Error().Err(err).Str("spaceid", n.SpaceID).Str("nodeid", n.ID).Str("uploadid", session.ID()).Msg("reading node for session failed") } if session.NodeExists() { p := session.info.MetaData["versionsPath"] @@ -340,7 +340,7 @@ func (session *OcisSession) Cleanup(revertNodeMetadata, cleanBin, cleanInfo bool // if no other upload session is in progress (processing id != session id) or has finished (processing id == "") latestSession, err := n.ProcessingID(ctx) if err != nil { - appctx.GetLogger(ctx).Error().Err(err).Str("node", n.ID).Str("sessionid", session.ID()).Msg("reading processingid for session failed") + appctx.GetLogger(ctx).Error().Err(err).Str("spaceid", n.SpaceID).Str("nodeid", n.ID).Str("uploadid", session.ID()).Msg("reading processingid for session failed") } if latestSession == session.ID() { // actually delete the node