Track Metadata: Fix synchronization (import/export) of file tags #4628

uklotzde · 2022-01-16T13:28:14Z

Synchronization of file tags (import/export) is severely broken due to various reasons:

Using stale data from QFileInfo that reports outdated file modification time stamps
Not considering unknown synchronization time stamps appropriately that are created by the database migration from 2.3 to 2.4. The export is skipped then, although apparently not strictly probably due to the internal caching issues caused by QFileInfo.

Those 2 different causes made it difficult to discover the misbehavior. The new unit test ensures that this will never break again.

Tests the fixes from the preceding commits. Reverting each of those commits will cause test failures.

daschuer

Thank you. I have left some comments.

src/track/track.cpp

src/sources/metadatasource.cpp

daschuer · 2022-01-16T14:17:45Z

src/track/trackrecord.h

+
+        /// The status could not be determined for whatever reason,
+        /// e.g. inaccessible file, ...
+        Undefined,


The difference between Undefined/Unknown/Void is not obvious in the using code.
How about renaming these value to
NotImported/UnknownSyncronizedTime/UnknownFileTime

The synchronization status type should not mention files directly. It is independent of how the content of sources is stored. Files are just one kind of storage type.

As already mentioned synchronization time stamps should not be confused with raw file time stamps and we should not mix that up on this higher level of abstraction.

The names of the variants are abstract and do not need to leak implementation details from other parts of the code. Descriptions of possible use cases have deliberately been added as possible examples in the comments.

I also dislike composed terms that start with the same stem. Different kind of "unknowns" are confusing, too. It is easier to recognize distinct words.

Ok, so what about:
SourceSyncStatus = Unsynced
SourceSyncStatus = Syncronized
SourceSyncStatus = ImportPending
SourceSyncStatus = ExportPending

Please provide a mapping to the existing values.

Void = Unsynced
Syncronized = Syncronized
Outdated = ImportPending
Undefined = ExportPending
Unknown = Unknown

My proposal is this PR. I did not receive any alternative proposals yet that I consider as an improvement.

For my feeling my recent proposal follows your demand in #4628 (comment)
My demand is to have more descriptive names than the ambiguous Undefined/Unknown/Void.
What would be an alternative for you?

The variant names are recognizable and they were helpful while writing the different test cases.

They represent a state and are not directly related to any import/export activity as you suggested.

If you really insist to keep these empty and interchangeable words Undefined/Unknown/Void and like to rely on out of sight comments, I'll give up. It is a pity that we have not found a compromise.

Naming can be changed at any time. But I refuse to overload this PR with more unrelated changes.

src/sources/metadatasource.h

src/track/track.cpp

uklotzde · 2022-01-18T19:05:21Z

I hope that c72115f fixes the sporadic CI failures. One sleep might have been missing. The dependency on uncontrollable side effects is unfortunate.

Holzhaus · 2022-01-18T19:46:12Z

Now clang-tidy fails.

TrackDAO: Refactorings from debugging #4628

daschuer · 2022-01-18T20:56:51Z

rror: /home/runner/work/mixxx/mixxx/src/library/trackcollectionmanager.cpp:333:42: error: this statement may fall through [-Werror=implicit-fallthrough=]
  333 |             pTrack->markForMetadataExport();

uklotzde · 2022-01-19T20:25:55Z

Fore my feeling the new test class overshoots our goal by far. We have no interest in tests, testing file timing in a separate testing calls. The test should test the productive code. In the productive code we have a > operator for testing for outdated files. We have no case where we write a file and read it back immediately. So the implemented ms resolution is not required.

The only reason I can consider in real live where this is relevant is a concurrent write to the same file form Mixxx and another Tool. Here is the result undefined anyway.

It should be sufficient to test this with a reasonable old file. So you may consider to reintroduce the changing the file time directly and set it to a age of one hour or such. This way we can get rid of all the tests failures related to file time resolution and caching.

I also prefer to go back to a procedural test body that is closer to the implementations of other tests. This is way easier to read instead of your deeply nested test classes where the control flow is hard to track, especially because an implicit run time measurement is involved.

These extensive tests with all their combinatorics have revealed many issues.

uklotzde · 2022-01-19T21:13:28Z

We should restart the build jobs repeatedly to see if there are still timing issues on Ubuntu with the minimum delay of 1 ms between file modifications.

All timing code in Mixxx and the tests should only compare time stamps that have been generated by the file system as the single source of truth. I am not aware that we missed any occurrence that uses time stamps from a second, inconsistent source.

Be-ing · 2022-01-19T21:15:16Z

Manually restarting GitHub Actions jobs will cancel the old run. You can hack around this by repeatedly doing git commit --amend and force pushing to create jobs testing identical code with different commit hashes.

uklotzde · 2022-01-19T21:20:56Z

Manually restarting GitHub Actions jobs will cancel the old run. You can hack around this by repeatedly doing git commit --amend and force pushing to create jobs testing identical code with different commit hashes.

Restarting works as expected and the tests have been rerun as intended. We want them to fail, not to succeed.

This saves 1 sleep operation per test run.

uklotzde · 2022-01-20T10:01:48Z

ed15311 will hopefully fix the Ubuntu issues.

78ecbac saves 1 sleep operation per test case.

daschuer · 2022-01-20T11:33:48Z

It is still failing locally in rare cases:

info [0x55bd0389efd0] TrackCollectionManager - External collections are disabled in test mode
info [0x55bd0389efd0] TrackCollectionManager - Library scanner is disabled in test mode
info [0x55bd0389efd0] SeratoMarkers2 - Reading bpmlock state from 'Serato Markers2' tag data...
info [0x55bd0389efd0] SeratoMarkers2 - Reading track color from 'Serato Markers2' tag data...
warning [0x55bd0389efd0] Track - Exporting and overwriting metadata into file "/tmp/mixxx-test-NjCcZd/cover-test-jpg.mp3" even though the file has been modified at QDateTime(2022-01-20 11:29:18.314 UTC Qt::UTC) after the last library synchronization at QDateTime(2022-01-20 11:29:18.306 UTC Qt::UTC)
/home/sperry/workspace/2.3/src/test/libraryfilesynctest.cpp:253: Failure
Value of: !fileLastModifiedAfter.isValid() || fileLastModifiedAfter > fileLastModifiedBefore
  Actual: false
Expected: true
info [0x55bd0389efd0] TrackCollection - Disconnecting database
info [0x55bd0389efd0] GlobalTrackCache - Destroying instance
[  FAILED  ] LibraryFileWithMetadataSyncStatusOutdatedTest.saveTrackMetadataWithSyncEnabled (24 ms)
[----------] 1 test from LibraryFileWithMetadataSyncStatusOutdatedTest (24 ms total)

[----------] Global test environment tear-down
[==========] 1 test from 1 test suite ran. (24 ms total)
[  PASSED  ] 0 tests.
[  FAILED  ] 1 test, listed below:
[  FAILED  ] LibraryFileWithMetadataSyncStatusOutdatedTest.saveTrackMetadataWithSyncEnabled

 1 FAILED TEST

uklotzde · 2022-01-20T11:48:00Z

It is still failing locally in rare cases:

info [0x55bd0389efd0] TrackCollectionManager - External collections are disabled in test mode
info [0x55bd0389efd0] TrackCollectionManager - Library scanner is disabled in test mode
info [0x55bd0389efd0] SeratoMarkers2 - Reading bpmlock state from 'Serato Markers2' tag data...
info [0x55bd0389efd0] SeratoMarkers2 - Reading track color from 'Serato Markers2' tag data...
warning [0x55bd0389efd0] Track - Exporting and overwriting metadata into file "/tmp/mixxx-test-NjCcZd/cover-test-jpg.mp3" even though the file has been modified at QDateTime(2022-01-20 11:29:18.314 UTC Qt::UTC) after the last library synchronization at QDateTime(2022-01-20 11:29:18.306 UTC Qt::UTC)
/home/sperry/workspace/2.3/src/test/libraryfilesynctest.cpp:253: Failure
Value of: !fileLastModifiedAfter.isValid() || fileLastModifiedAfter > fileLastModifiedBefore
  Actual: false
Expected: true
info [0x55bd0389efd0] TrackCollection - Disconnecting database
info [0x55bd0389efd0] GlobalTrackCache - Destroying instance
[  FAILED  ] LibraryFileWithMetadataSyncStatusOutdatedTest.saveTrackMetadataWithSyncEnabled (24 ms)
[----------] 1 test from LibraryFileWithMetadataSyncStatusOutdatedTest (24 ms total)

[----------] Global test environment tear-down
[==========] 1 test from 1 test suite ran. (24 ms total)
[  PASSED  ] 0 tests.
[  FAILED  ] 1 test, listed below:
[  FAILED  ] LibraryFileWithMetadataSyncStatusOutdatedTest.saveTrackMetadataWithSyncEnabled

 1 FAILED TEST

Unfortunately we cannot loop our track saving code until a different time stamp for the file is generated when exporting metadata. Then we need to increase the sleep time until the tests succeed reliably.

I am running the tests on btrfs and tmpfs (used by QTemporaryDir). They succeed even if I comment out the sleep.

eb0c83f

src/test/libraryfilesynctest.cpp

daschuer · 2022-01-20T12:03:34Z

src/test/libraryfilesynctest.cpp

+        ASSERT_EQ(1, pTrack.use_count());
+        const auto trackId = pTrack->getId();
+        ASSERT_TRUE(trackId.isValid());
+        ASSERT_TRUE(pTrack->isDirty());


Is this the case? This does not match to the comment below.

What do you mean?

src/test/libraryfilesynctest.cpp

daschuer · 2022-01-20T12:18:41Z

The latest commit works here. However I would prefer a more robust solution by just setting the file time to an reasonable old value on creation.

uklotzde · 2022-01-20T12:59:40Z

The latest commit works here. However I would prefer a more robust solution by just setting the file time to an reasonable old value on creation.

That would be inconsistent with the implicit update of the modification time stamp when saving the file. We don't know anything about the relation of the different clocks and should rely on a single source of truth.

I have already burned my fingers and will not touch it again!!

daschuer · 2022-01-20T16:16:13Z

Original we had in one case a bussy loop that finds exactly the minimum difference that is considered as such. But you had no solution for setting the file to a newer value.

Now you have increased the sleep time to 2 ms, a wild guess that works on my device which makes the busy loop obsolete, because the 2 is used there as well.

This mean you original demand to test with them I um difference does no longer work anyway.

I think a much better solution is to creat the file, read the file time and sibstract 1 and write it back.

The same can be done when advancing the file time read it add one and write it back. This way it should be rock solid.

uklotzde · 2022-01-20T21:15:28Z

Original we had in one case a bussy loop that finds exactly the minimum difference that is considered as such. But you had no solution for setting the file to a newer value.

Now you have increased the sleep time to 2 ms, a wild guess that works on my device which makes the busy loop obsolete, because the 2 is used there as well.

This mean you original demand to test with them I um difference does no longer work anyway.

I think a much better solution is to creat the file, read the file time and sibstract 1 and write it back.

The same can be done when advancing the file time read it add one and write it back. This way it should be rock solid.

Thanks. That was actually a good idea. The current test design has proven to be solid as this change was easy to integrate. Though somehow also tricky, I added comments.

3a44c83

daschuer · 2022-01-23T10:00:43Z

Now it is working reliable. Thank you. I am sorry for you burned fingers.

uklotzde added 4 commits January 16, 2022 13:18

TrackDAO: Use correct function for reading preferences

5d92bd5

Fix synchronization of track metadata with file tags

0c8ae03

Prevent reading of stale file modification time stamps

e057b61

Add LibraryFileSyncTest

7a378a7

Tests the fixes from the preceding commits. Reverting each of those commits will cause test failures.

uklotzde added the major bug label Jan 16, 2022

github-actions bot added build code quality library labels Jan 16, 2022

daschuer requested changes Jan 16, 2022

View reviewed changes

uklotzde added 3 commits January 16, 2022 17:44

Add test for re-importing outdated metadata

eca81c2

Remove dependency on TrackDAO

8fd96ca

Reword log message

41f5ed8

daschuer reviewed Jan 16, 2022

View reviewed changes

src/sources/metadatasource.h Show resolved Hide resolved

Rename utility function and use an exhaustive switch/case statement

6e9b845

daschuer reviewed Jan 16, 2022

View reviewed changes

src/track/track.cpp Show resolved Hide resolved

Fix export of outdated metadata and add tests for many use cases

ab2df29

uklotzde mentioned this pull request Jan 17, 2022

Log re-import of track metadata from file tags with time stamps #4631

Merged

Only consider imported metadata if import succeeded

756b1c7

uklotzde changed the title ~~Track Metadata: Fix synchronization (import/export) of file tags~~ [WiP] Track Metadata: Fix synchronization (import/export) of file tags Jan 18, 2022

uklotzde marked this pull request as draft January 18, 2022 14:17

uklotzde changed the title ~~[WiP] Track Metadata: Fix synchronization (import/export) of file tags~~ Track Metadata: Fix synchronization (import/export) of file tags Jan 18, 2022

uklotzde marked this pull request as ready for review January 18, 2022 17:17

daschuer added a commit that referenced this pull request Jan 18, 2022

Merge pull request #4633 from uklotzde/trackdao

e6207b3

TrackDAO: Refactorings from debugging #4628

uklotzde added 4 commits January 18, 2022 22:57

Enable, fix, and test saving and metadata export of missing track

bfdf55d

LibraryFileSyncTest: Replace debug assertions with gtest macros

87ff85b

LibraryFileSyncTest: Set track property directly

0ebcabe

LibraryFileSyncTest: Sleep after updating files

18ec590

uklotzde added 3 commits January 20, 2022 10:45

Replace ASSERT with EXPECT and restore function signatures

a4f550b

Loop until a file is detected as modified

ed15311

Insert a sleep before and not after file modifications

78ecbac

This saves 1 sleep operation per test run.

Merge branch 'main' of git@github.com:mixxxdj/mixxx.git into trackrecord

e4a5d7d

Testing: Increase sleep time for file modification time stamps

eb0c83f

daschuer requested changes Jan 20, 2022

View reviewed changes

uklotzde added 3 commits January 20, 2022 13:38

Rename function in test code

23e623f

Prevent infinite loop in test code

082cc7e

LibraryFileSyncTest: Replace all ASSERT_ with EXPECT_ macros

186d9c1

Adjust file times instead of sleeping for metadata sync tests

3a44c83

uklotzde added 4 commits January 20, 2022 22:22

Rename enum class

872820e

Add comment about test execution

3ced935

Rename unit test

75920be

Merge branch 'main' of git@github.com:mixxxdj/mixxx.git into trackrecord

1efaa82

daschuer approved these changes Jan 23, 2022

View reviewed changes

daschuer merged commit cf88944 into mixxxdj:main Jan 23, 2022

uklotzde deleted the trackrecord branch January 23, 2022 10:36

ronso0 added this to the 2.4.0 milestone Aug 5, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Track Metadata: Fix synchronization (import/export) of file tags #4628

Track Metadata: Fix synchronization (import/export) of file tags #4628

uklotzde commented Jan 16, 2022 •

edited

Loading

daschuer left a comment

daschuer Jan 16, 2022

uklotzde Jan 16, 2022

daschuer Jan 16, 2022

uklotzde Jan 16, 2022

daschuer Jan 16, 2022 •

edited

Loading

uklotzde Jan 16, 2022 •

edited

Loading

daschuer Jan 16, 2022 •

edited

Loading

uklotzde Jan 17, 2022

daschuer Jan 18, 2022

uklotzde Jan 18, 2022

uklotzde commented Jan 18, 2022 •

edited

Loading

Holzhaus commented Jan 18, 2022

daschuer commented Jan 18, 2022

uklotzde commented Jan 19, 2022 •

edited

Loading

uklotzde commented Jan 19, 2022

Be-ing commented Jan 19, 2022

uklotzde commented Jan 19, 2022 •

edited

Loading

uklotzde commented Jan 20, 2022

daschuer commented Jan 20, 2022 •

edited

Loading

uklotzde commented Jan 20, 2022 •

edited

Loading

daschuer Jan 20, 2022

uklotzde Jan 20, 2022

daschuer commented Jan 20, 2022

uklotzde commented Jan 20, 2022 •

edited

Loading

daschuer commented Jan 20, 2022

uklotzde commented Jan 20, 2022 •

edited

Loading

daschuer commented Jan 23, 2022

Track Metadata: Fix synchronization (import/export) of file tags #4628

Track Metadata: Fix synchronization (import/export) of file tags #4628

Conversation

uklotzde commented Jan 16, 2022 • edited Loading

daschuer left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

daschuer Jan 16, 2022 • edited Loading

Choose a reason for hiding this comment

uklotzde Jan 16, 2022 • edited Loading

Choose a reason for hiding this comment

daschuer Jan 16, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

uklotzde commented Jan 18, 2022 • edited Loading

Holzhaus commented Jan 18, 2022

daschuer commented Jan 18, 2022

uklotzde commented Jan 19, 2022 • edited Loading

uklotzde commented Jan 19, 2022

Be-ing commented Jan 19, 2022

uklotzde commented Jan 19, 2022 • edited Loading

uklotzde commented Jan 20, 2022

daschuer commented Jan 20, 2022 • edited Loading

uklotzde commented Jan 20, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

daschuer commented Jan 20, 2022

uklotzde commented Jan 20, 2022 • edited Loading

daschuer commented Jan 20, 2022

uklotzde commented Jan 20, 2022 • edited Loading

daschuer commented Jan 23, 2022

uklotzde commented Jan 16, 2022 •

edited

Loading

daschuer Jan 16, 2022 •

edited

Loading

uklotzde Jan 16, 2022 •

edited

Loading

daschuer Jan 16, 2022 •

edited

Loading

uklotzde commented Jan 18, 2022 •

edited

Loading

uklotzde commented Jan 19, 2022 •

edited

Loading

uklotzde commented Jan 19, 2022 •

edited

Loading

daschuer commented Jan 20, 2022 •

edited

Loading

uklotzde commented Jan 20, 2022 •

edited

Loading

uklotzde commented Jan 20, 2022 •

edited

Loading

uklotzde commented Jan 20, 2022 •

edited

Loading