owncloud / owncloud/ocis

async propagation logs errors

Open
#10,522 0 comments 0 reactions 0 assignees View on GitHub
Type:Bug
Dominant language
Go
Stars
2.1k
Forks
274
Avg merge
2d 1h
Merged PRs (30d)
103

Description

when the async propagation tries to propagate to a node that was deleted it might log sth like this:
```
2024-11-07 15: 06: 03.980
{
"level": "error",
"pid": 1,
"pid": 1,
"method": "async.Propagate",
"spaceid": "535c46b8-aeac-4868-976e-09dd1ad10798",
"nodeid": "435c16a0-4d70-4a99-b3ce-e2d20c04ad7c",
"parentid": "",
"sizediff": 0,
"error": "node.XattrsWithReader /var/lib/ocis/storage/users/spaces/53/5c46b8-aeac-4868-976e-09dd1ad10798/nodes: no data available",
"time": "2024-11-07t14:06:03Z",
"caller": "runtime/asm_amd64.s:1700",
"message": "Propagation failed. Could not read node."
}


2024-11-07 15: 06: 00.041
{
"level": "error",
"pid": 1,
"pid": 1,
"request-id": "c04e0583a154d766ebf8466f483fdc0e",
"method": "async.Propagate",
"spaceid": "535c46b8-aeac-4868-976e-09dd1ad10798",
"nodeid": "3353ccfd-5605-47c5-843d-74fe881bc442",
"parentid": "435c16a0-4d70-4a99-b3ce-e2d20c04ad7c",
"sizediff": 20000000,
"error": "internal error: Missing parent ID on node",
"time": "2024-11-07t14:06:00Z",
"caller": "runtime/asm_amd64.s:1700",
"message": "Propagation failed. Could not read node."
}


2024-11-07 15: 06: 00.041
{
"level": "error",
"pid": 1,
"pid": 1,
"request-id": "c04e0583a154d766ebf8466f483fdc0e",
"path": "/var/lib/ocis/storage/users/spaces/53/5c46b8-aeac-4868-976e-09dd1ad10798/nodes/43/5c/16/a0/-4d70-4a99-b3ce-e2d20c04ad7c",
"nodeid": "435c16a0-4d70-4a99-b3ce-e2d20c04ad7c",
"attrs": {
"user.ocis.tmtime": "MjAyNC0xMS0wN1QxNDowNTo1OC43MDk5MjkwNDJa"
},
"messagepack": "\ufffd\ufffduser.ocis.tmtime\ufffd\u001e2024-11-07t14:05:58.709929042Z",
"time": "2024-11-07t14:06:00Z",
"caller": "github.com/cs3org/reva/v2@v2.26.3/pkg/storage/utils/decomposedfs/tree/propagator/async.go:219",
"message": "missing parent id"
}


2024-11-07 15: 05: 57.255
{
"level": "info",
"service": "storage-users",
"pkg": "rgrpc",
"traceid": "7aeae87a766637febdaf515cd3bc07a5",
"method": "async.Propagate",
"spaceid": "535c46b8-aeac-4868-976e-09dd1ad10798",
"nodeid": "435c16a0-4d70-4a99-b3ce-e2d20c04ad7c",
"parentid": "535c46b8-aeac-4868-976e-09dd1ad10798",
"sizediff": 0,
"time": "2024-11-07t14:05:57Z",
"line": "github.com/cs3org/reva/v2@v2.26.3/pkg/storage/utils/decomposedfs/tree/propagator/async.go:414",
"message": "Propagation done. cleaning up"
}
```

It will also write an mpk file that only contains the tmtime:
```
storageusers-85989ddf75-5kmhm:~$ strings /var/lib/ocis/storage/users/spaces/53/5c46b8-aeac-4868-976e-09dd1ad10798/nodes/43/5c/16/a0/-4d70-4a99-b3ce-e2d20c04ad7c.mpk
user.ocis.tmtime
2024-11-07T14:05:58.709929042Z
```

We do lock the node metadata when propagationg, but the delete codepath does not seem to care and just deletes the node. This causes the SetMultiple() implementation to just recreate the file:
```
msgBytes, err = os.ReadFile(metaPath)
subspan.End()
attribs := map[string][]byte{}
switch {
case err != nil:
if !errors.Is(err, fs.ErrNotExist) {
return err
}
case len(msgBytes) == 0:
// ugh. an empty file? bail out
return errors.New("encountered empty metadata file")
default:
// only unmarshal if we read data
err = msgpack.Unmarshal(msgBytes, &attribs)
if err != nil {
return err
}
}
```

we need to find a way to either not delete the mpk file if it is locked, or detect that tha file was deleted in the propagation...

The filesystem metadata is not corrupt, but we leave unused data, that accumulates.

cc @aduffeck

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.