PROPFIND returns wrong folder size

[JammingBen]

Steps to reproduce

1. Upload a folder including 5 One-Byte text files
2. Do a PROPFIND request on the folder and check oc:size in the response

Expected behavior

The size should be 5. At least I think so. Or is there any reason the folder should compresses the size?

Actual behavior

The size is 3.

[butonic]

I can confirm ... for me size sometimes is 4 or 5 ... 😞

[phil-davis]

@SagarGi @saw-jan please get someone to have a look at what API acceptance test scenarios we have that check the size in a PROPFIND request for a folder, and report here. Hopefully there are tests cases for when the folder has multiple files. (And maybe there is some backend caching issue that results in different answers sometimes, and we haven't noticed the tests being flaky or...)

[butonic]

grepping log for tree/tree.go gives:

2023-05-04T08:08:50+02:00 DBG propagating line=/home/jfd/Repositories/reva/pkg/storage/utils/decomposedfs/tree/tree.go:708 nodeid=9a5e982c-482a-41a2-96e6-d0f9a702c44d pkg=rgrpc service=storage-users spaceid=534bb038-6f9d-4093-946f-133be61fa4e7 traceid=5e011c4459705e02b375a485fa3ab106
2023-05-04T08:08:50+02:00 DBG parent tmtime is older than node mtime, updating line=/home/jfd/Repositories/reva/pkg/storage/utils/decomposedfs/tree/tree.go:764 nodeid=534bb038-6f9d-4093-946f-133be61fa4e7 pkg=rgrpc service=storage-users spaceid=534bb038-6f9d-4093-946f-133be61fa4e7 stime=2023-05-04T06:08:50.453565243Z tmtime=2023-05-04T06:08:19.683519142Z traceid=5e011c4459705e02b375a485fa3ab106
2023-05-04 08:08:52.65 DBG ../../../../reva/pkg/storage/utils/decomposedfs/tree/tree.go:708 > propagating nodeid=13e96501-ffe4-4b97-a0c4-aedd096f6ffc pid=3913504 spaceid=534bb038-6f9d-4093-946f-133be61fa4e7
2023-05-04 08:08:52.651 DBG ../../../../reva/pkg/storage/utils/decomposedfs/tree/tree.go:764 > parent tmtime is older than node mtime, updating nodeid=9a5e982c-482a-41a2-96e6-d0f9a702c44d pid=3913504 spaceid=534bb038-6f9d-4093-946f-133be61fa4e7 stime=2023-05-04T06:08:52.650840122Z tmtime=2023-05-04T08:08:52.644666487+02:00
2023-05-04 08:08:52.651 DBG ../../../../reva/pkg/storage/utils/decomposedfs/tree/tree.go:807 > updated treesize of parent node newSize=1 nodeid=9a5e982c-482a-41a2-96e6-d0f9a702c44d pid=3913504 spaceid=534bb038-6f9d-4093-946f-133be61fa4e7
2023-05-04 08:08:52.651 DBG ../../../../reva/pkg/storage/utils/decomposedfs/tree/tree.go:708 > propagating nodeid=9a5e982c-482a-41a2-96e6-d0f9a702c44d pid=3913504 spaceid=534bb038-6f9d-4093-946f-133be61fa4e7
2023-05-04 08:08:52.651 DBG ../../../../reva/pkg/storage/utils/decomposedfs/tree/tree.go:764 > parent tmtime is older than node mtime, updating nodeid=534bb038-6f9d-4093-946f-133be61fa4e7 pid=3913504 spaceid=534bb038-6f9d-4093-946f-133be61fa4e7 stime=2023-05-04T06:08:52.650840122Z tmtime=2023-05-04T06:08:50.453565243Z
2023-05-04 08:08:52.652 DBG ../../../../reva/pkg/storage/utils/decomposedfs/tree/tree.go:807 > updated treesize of parent node newSize=541591 nodeid=534bb038-6f9d-4093-946f-133be61fa4e7 pid=3913504 spaceid=534bb038-6f9d-4093-946f-133be61fa4e7
2023-05-04 08:08:52.843 DBG ../../../../reva/pkg/storage/utils/decomposedfs/tree/tree.go:708 > propagating nodeid=0b7243d8-da5b-4691-994a-7e59bf2658de pid=3913504 spaceid=534bb038-6f9d-4093-946f-133be61fa4e7
2023-05-04 08:08:52.843 DBG ../../../../reva/pkg/storage/utils/decomposedfs/tree/tree.go:764 > parent tmtime is older than node mtime, updating nodeid=9a5e982c-482a-41a2-96e6-d0f9a702c44d pid=3913504 spaceid=534bb038-6f9d-4093-946f-133be61fa4e7 stime=2023-05-04T06:08:52.84362842Z tmtime=2023-05-04T06:08:52.654996003Z
2023-05-04 08:08:52.843 DBG ../../../../reva/pkg/storage/utils/decomposedfs/tree/tree.go:807 > updated treesize of parent node newSize=2 nodeid=9a5e982c-482a-41a2-96e6-d0f9a702c44d pid=3913504 spaceid=534bb038-6f9d-4093-946f-133be61fa4e7
2023-05-04 08:08:52.844 DBG ../../../../reva/pkg/storage/utils/decomposedfs/tree/tree.go:708 > propagating nodeid=9a5e982c-482a-41a2-96e6-d0f9a702c44d pid=3913504 spaceid=534bb038-6f9d-4093-946f-133be61fa4e7
2023-05-04 08:08:52.844 DBG ../../../../reva/pkg/storage/utils/decomposedfs/tree/tree.go:764 > parent tmtime is older than node mtime, updating nodeid=534bb038-6f9d-4093-946f-133be61fa4e7 pid=3913504 spaceid=534bb038-6f9d-4093-946f-133be61fa4e7 stime=2023-05-04T06:08:52.84362842Z tmtime=2023-05-04T06:08:52.655296371Z
2023-05-04 08:08:52.844 DBG ../../../../reva/pkg/storage/utils/decomposedfs/tree/tree.go:807 > updated treesize of parent node newSize=541592 nodeid=534bb038-6f9d-4093-946f-133be61fa4e7 pid=3913504 spaceid=534bb038-6f9d-4093-946f-133be61fa4e7
2023-05-04 08:08:52.846 DBG ../../../../reva/pkg/storage/utils/decomposedfs/tree/tree.go:708 > propagating nodeid=f8a42c8c-74b0-4d3c-ba9c-257e19a46e84 pid=3913504 spaceid=534bb038-6f9d-4093-946f-133be61fa4e7
2023-05-04 08:08:52.846 DBG ../../../../reva/pkg/storage/utils/decomposedfs/tree/tree.go:764 > parent tmtime is older than node mtime, updating nodeid=9a5e982c-482a-41a2-96e6-d0f9a702c44d pid=3913504 spaceid=534bb038-6f9d-4093-946f-133be61fa4e7 stime=2023-05-04T06:08:52.846487154Z tmtime=2023-05-04T06:08:52.84610198Z
2023-05-04 08:08:52.846 DBG ../../../../reva/pkg/storage/utils/decomposedfs/tree/tree.go:807 > updated treesize of parent node newSize=3 nodeid=9a5e982c-482a-41a2-96e6-d0f9a702c44d pid=3913504 spaceid=534bb038-6f9d-4093-946f-133be61fa4e7
2023-05-04 08:08:52.847 DBG ../../../../reva/pkg/storage/utils/decomposedfs/tree/tree.go:708 > propagating nodeid=9a5e982c-482a-41a2-96e6-d0f9a702c44d pid=3913504 spaceid=534bb038-6f9d-4093-946f-133be61fa4e7
2023-05-04 08:08:52.847 DBG ../../../../reva/pkg/storage/utils/decomposedfs/tree/tree.go:764 > parent tmtime is older than node mtime, updating nodeid=534bb038-6f9d-4093-946f-133be61fa4e7 pid=3913504 spaceid=534bb038-6f9d-4093-946f-133be61fa4e7 stime=2023-05-04T06:08:52.846487154Z tmtime=2023-05-04T06:08:52.846364109Z
2023-05-04 08:08:52.847 DBG ../../../../reva/pkg/storage/utils/decomposedfs/tree/tree.go:807 > updated treesize of parent node newSize=541593 nodeid=534bb038-6f9d-4093-946f-133be61fa4e7 pid=3913504 spaceid=534bb038-6f9d-4093-946f-133be61fa4e7
2023-05-04 08:08:52.852 DBG ../../../../reva/pkg/storage/utils/decomposedfs/tree/tree.go:708 > propagating nodeid=23c7659b-a293-4c80-9302-4d014d5c4852 pid=3913504 spaceid=534bb038-6f9d-4093-946f-133be61fa4e7
2023-05-04 08:08:52.852 DBG ../../../../reva/pkg/storage/utils/decomposedfs/tree/tree.go:708 > propagating nodeid=723ec1c7-b8cc-43e6-b557-d79a30816549 pid=3913504 spaceid=534bb038-6f9d-4093-946f-133be61fa4e7
2023-05-04 08:08:52.852 DBG ../../../../reva/pkg/storage/utils/decomposedfs/tree/tree.go:764 > parent tmtime is older than node mtime, updating nodeid=9a5e982c-482a-41a2-96e6-d0f9a702c44d pid=3913504 spaceid=534bb038-6f9d-4093-946f-133be61fa4e7 stime=2023-05-04T06:08:52.852698489Z tmtime=2023-05-04T06:08:52.848897723Z
2023-05-04 08:08:52.852 DBG ../../../../reva/pkg/storage/utils/decomposedfs/tree/tree.go:807 > updated treesize of parent node newSize=4 nodeid=9a5e982c-482a-41a2-96e6-d0f9a702c44d pid=3913504 spaceid=534bb038-6f9d-4093-946f-133be61fa4e7
2023-05-04 08:08:52.853 DBG ../../../../reva/pkg/storage/utils/decomposedfs/tree/tree.go:708 > propagating nodeid=9a5e982c-482a-41a2-96e6-d0f9a702c44d pid=3913504 spaceid=534bb038-6f9d-4093-946f-133be61fa4e7
2023-05-04 08:08:52.853 DBG ../../../../reva/pkg/storage/utils/decomposedfs/tree/tree.go:764 > parent tmtime is older than node mtime, updating nodeid=534bb038-6f9d-4093-946f-133be61fa4e7 pid=3913504 spaceid=534bb038-6f9d-4093-946f-133be61fa4e7 stime=2023-05-04T06:08:52.852698489Z tmtime=2023-05-04T06:08:52.849173368Z
2023-05-04 08:08:52.853 DBG ../../../../reva/pkg/storage/utils/decomposedfs/tree/tree.go:807 > updated treesize of parent node newSize=541594 nodeid=534bb038-6f9d-4093-946f-133be61fa4e7 pid=3913504 spaceid=534bb038-6f9d-4093-946f-133be61fa4e7
2023-05-04 08:08:52.853 DBG ../../../../reva/pkg/storage/utils/decomposedfs/tree/tree.go:764 > parent tmtime is older than node mtime, updating nodeid=9a5e982c-482a-41a2-96e6-d0f9a702c44d pid=3913504 spaceid=534bb038-6f9d-4093-946f-133be61fa4e7 stime=2023-05-04T06:08:52.852745169Z tmtime=2023-05-04T06:08:52.848897723Z
2023-05-04 08:08:52.853 DBG ../../../../reva/pkg/storage/utils/decomposedfs/tree/tree.go:807 > updated treesize of parent node newSize=4 nodeid=9a5e982c-482a-41a2-96e6-d0f9a702c44d pid=3913504 spaceid=534bb038-6f9d-4093-946f-133be61fa4e7
2023-05-04 08:08:52.854 DBG ../../../../reva/pkg/storage/utils/decomposedfs/tree/tree.go:708 > propagating nodeid=9a5e982c-482a-41a2-96e6-d0f9a702c44d pid=3913504 spaceid=534bb038-6f9d-4093-946f-133be61fa4e7
2023-05-04 08:08:52.854 DBG ../../../../reva/pkg/storage/utils/decomposedfs/tree/tree.go:764 > parent tmtime is older than node mtime, updating nodeid=534bb038-6f9d-4093-946f-133be61fa4e7 pid=3913504 spaceid=534bb038-6f9d-4093-946f-133be61fa4e7 stime=2023-05-04T06:08:52.852745169Z tmtime=2023-05-04T06:08:52.852698489Z
2023-05-04 08:08:52.854 DBG ../../../../reva/pkg/storage/utils/decomposedfs/tree/tree.go:807 > updated treesize of parent node newSize=541595 nodeid=534bb038-6f9d-4093-946f-133be61fa4e7 pid=3913504 spaceid=534bb038-6f9d-4093-946f-133be61fa4e7

I fear we are not locking correctly. the folder containing the files is updated to size=4 twice ... but the root is correctly updated to 541594 and 541595. I need to check the code ...

[micbar]

we need unit tests ;-)

[aduffeck]

Looking at the code this seems to be a problem with locking and the file metadata node cache. Will discuss in person.

[SwikritiT]

Some of the tests related to PROPFIND request are
https://github.com/owncloud/ocis/blob/master/tests/acceptance/features/apiContract/propfind.feature
https://github.com/owncloud/ocis/blob/master/tests/acceptance/features/coreApiWebdavOperations/propfind.feature
https://github.com/owncloud/ocis/blob/master/tests/acceptance/features/coreApiWebdavOperations/listFiles.feature

But we are not really checking the size especially not with folders with other resources on them

Here's one that Propfinds a size of an empty folder

ocis/tests/acceptance/features/coreApiWebdavProperties2/getFileProperties.feature

Line 500 in 52ddba3

Scenario Outline: Propfind the size of a folder using webdav api

I cannot find tests covering this issue. I'll look around more if I missed something otherwise I'll add a new one

[SwikritiT]

Added api test here: #6235 they're passing

[phil-davis]

Tests added in #6235 and pass.

The problem is expected to have been fixed by cs3org/reva#3845

Please re-open if the problem comes back.