async propagation logs errors
- 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
Assessment
This issue has not been assessed yet.