etag propagation API tests are intermittent

[phil-davis]

Currently most (or all) of the new etag propagation tests are failing and are in the expected-failures list for OCIS test runs. We know that the etag propagation does not currently work all the way up the tree for elements inside sub-folders...

But when running CI for owncloud/ocis#660 , one of the test scenarios unexpectedly passed:
https://drone.owncloud.com/owncloud/ocis/387/23/7

Feature: propagation of etags when moving files or folders

  Background:                                                                              # /srv/app/testrunner/tests/acceptance/features/apiWebdavEtagPropagation1/moveFileFolder.feature:4
    Given user "Alice" has been created with default attributes and without skeleton files # FeatureContext::userHasBeenCreatedWithDefaultAttributesAndWithoutSkeletonFiles()

  Scenario Outline: renaming a file inside a folder changes its etag                              # /srv/app/testrunner/tests/acceptance/features/apiWebdavEtagPropagation1/moveFileFolder.feature:7
    Given using <dav_version> DAV path                                                            # FeatureContext::usingOldOrNewDavPath()
    And user "Alice" has created folder "/upload"                                                 # FeatureContext::userHasCreatedFolder()
    And user "Alice" has uploaded file with content "uploaded content" to "/upload/file.txt"      # FeatureContext::userHasUploadedAFileWithContentTo()
    And user "Alice" has stored etag of element "/"                                               # WebDavPropertiesContext::userHasStoredEtagOfElement()
    And user "Alice" has stored etag of element "/upload"                                         # WebDavPropertiesContext::userHasStoredEtagOfElement()
    When user "Alice" moves file "/upload/file.txt" to "/upload/renamed.txt" using the WebDAV API # FeatureContext::userMovesFileUsingTheAPI()
    Then these etags should have changed:                                                         # WebDavPropertiesContext::theseEtagsShouldHaveChanged()
      | user  | path    |
      | Alice | /       |
      | Alice | /upload |

    Examples:
      | dav_version |
      | old         |
        WebDavPropertiesContext::theseEtagsShouldHaveChanged
        The etag '09f19497badfd2f49051cbbd10716c78' of element '/' of user 'Alice' did not change.
        The etag 'cc3b25809ed831fac67f21e42c351fb9' of element '/upload' of user 'Alice' did not change.
        Failed asserting that 2 matches expected 0.
      | new         |

...

runsh: There were no unexpected failures.
runsh: Total unexpected passed scenarios throughout the test run:
apiWebdavEtagPropagation1/moveFileFolder.feature:21
make: *** [test-acceptance-api] Error 1
Makefile:207: recipe for target 'test-acceptance-api' failed

The example for old DAV path failed as expected, but the example for new DAV path passed unexpectedly - it seems that the etags of /upload and / did change.

After restarting drone CI, the CI passed (i.e. the scenario moveFileFolder.feature:21 failed as expected)

Under some conditions the etags do get updated. Maybe there are other etag scenarios that might sometimes pass. Needs investigation.

[phil-davis]

@individual-it has done some local test runs and confirmed that the test scenario sometimes passes (maybe 1 in 20 times). He will add information here...

[individual-it]

how to reproduce:

1. start OCIS with OCIS-Storage-driver: REVA_STORAGE_HOME_DRIVER=ocis REVA_STORAGE_HOME_DATA_DRIVER=ocis REVA_STORAGE_OC_DRIVER=ocis REVA_STORAGE_OC_DATA_DRIVER=ocis bin/ocis server
2. run tests till they pass: result=1; count=0; while [ $result -ne 0 ]; do make test-acceptance-api DELETE_USER_DATA_CMD='rm -rf /var/tmp/ocis/root/nodes/root/*' TEST_SERVER_URL=https://localhost:9200 TEST_OCIS=true OCIS_REVA_DATA_ROOT=/var/tmp/reva/ SKELETON_DIR=apps/testing/data/apiSkeleton BEHAT_FILTER_TAGS='~@notToImplementOnOCIS' BEHAT_FEATURE=tests/acceptance/features/apiWebdavEtagPropagation1/moveFileFolder.feature:21; result=$?; let count=count+1; echo $count; done

[individual-it]

it seems to have to do something with the tmtime:
usually we end up in this code path: https://github.com/cs3org/reva/blob/bccddc4b5a486c456309179967f132ec3a784340/pkg/storage/fs/ocis/tree.go#L364
every-time the test passes it lands in this code path: https://github.com/cs3org/reva/blob/bccddc4b5a486c456309179967f132ec3a784340/pkg/storage/fs/ocis/tree.go#L361

[individual-it]

I guess when a file is renamed the modification time of all parent folders are changed to the same timestamp only sometimes its gets late and the etag is updated

[butonic]

When manually debugging this we saw the tmtime was indeed not before mtime when executing a MOVE. Specifically renaming a file in the same folder, which caused the change not to be propagated further.

@C0rby and I noticed that a stat would show a change as well as a modify time. But only the change time would update ... Which is correct for renaming a folder ... The question is if that translates to the os.Stat mtime .... Hm I doubt it...

[butonic]

No the filings.modtime only reads the mtime. We would need to read the crime using syscall... Platform specific code... See https://stackoverflow.com/a/20877193

[dpakach]

The tests mentioned here seem to have been fixed and both are passing now locally. So I think this issue can be closed now.
@phil-davis can we close this now?

[phil-davis]

yes, this is no longer intermittent. expected-failures lists the remaining scenarios that consistently fail.