Sync behaviour - possible bug?

[krisnoble]

My logs show very frequent sync events despite my sync interval in the music controller settings being 180? It seems like a sync is running every 5-10 seconds based on my logs. I assume this is a bug unless there is some distinction between a full sync which happens every sync interval, and some smaller more regular sync operation?

Possibly related: I'm also having issues with transferring music over to my SMB share, I wonder if the sync process is trying to work with partially-transferred files causing them to be locked and the transfers to fail? I do also see errors in my logs that the tracks couldn't be parsed correctly for the same tracks that could not be transferred.

Example sync logs over a 2-minute period:

2023-08-08 09:29:05.454 INFO (MainThread) [music_assistant.music] Sync task for URL completed
2023-08-08 09:29:05.833 INFO (MainThread) [music_assistant.music] Sync task for Filesystem (remote share) completed
2023-08-08 09:29:15.455 INFO (MainThread) [music_assistant.music] Sync task for URL completed
2023-08-08 09:29:15.868 INFO (MainThread) [music_assistant.music] Sync task for Filesystem (remote share) completed
2023-08-08 09:29:21.008 INFO (MainThread) [music_assistant.music] Sync task for URL completed
2023-08-08 09:29:21.363 INFO (MainThread) [music_assistant.music] Sync task for Filesystem (remote share) completed
2023-08-08 09:29:21.831 INFO (MainThread) [music_assistant.music] Sync task for URL completed
2023-08-08 09:29:22.163 INFO (MainThread) [music_assistant.music] Sync task for Filesystem (remote share) completed
2023-08-08 09:29:25.462 INFO (MainThread) [music_assistant.music] Sync task for URL completed
2023-08-08 09:29:25.891 INFO (MainThread) [music_assistant.music] Sync task for Filesystem (remote share) completed
2023-08-08 09:29:35.457 INFO (MainThread) [music_assistant.music] Sync task for URL completed
2023-08-08 09:29:35.846 INFO (MainThread) [music_assistant.music] Sync task for Filesystem (remote share) completed
2023-08-08 09:29:45.459 INFO (MainThread) [music_assistant.music] Sync task for URL completed
2023-08-08 09:29:46.272 INFO (MainThread) [music_assistant.music] Sync task for Filesystem (remote share) completed
2023-08-08 09:29:55.466 INFO (MainThread) [music_assistant.music] Sync task for URL completed
2023-08-08 09:29:55.823 INFO (MainThread) [music_assistant.music] Sync task for Filesystem (remote share) completed
2023-08-08 09:30:05.461 INFO (MainThread) [music_assistant.music] Sync task for URL completed
2023-08-08 09:30:05.866 INFO (MainThread) [music_assistant.music] Sync task for Filesystem (remote share) completed
2023-08-08 09:30:15.465 INFO (MainThread) [music_assistant.music] Sync task for URL completed
2023-08-08 09:30:15.870 INFO (MainThread) [music_assistant.music] Sync task for Filesystem (remote share) completed
2023-08-08 09:30:21.011 INFO (MainThread) [music_assistant.music] Sync task for URL completed
2023-08-08 09:30:21.342 INFO (MainThread) [music_assistant.music] Sync task for Filesystem (remote share) completed
2023-08-08 09:30:21.832 INFO (MainThread) [music_assistant.music] Sync task for URL completed
2023-08-08 09:30:22.252 INFO (MainThread) [music_assistant.music] Sync task for Filesystem (remote share) completed
2023-08-08 09:30:25.464 INFO (MainThread) [music_assistant.music] Sync task for URL completed
2023-08-08 09:30:25.882 INFO (MainThread) [music_assistant.music] Sync task for Filesystem (remote share) completed
2023-08-08 09:30:35.465 INFO (MainThread) [music_assistant.music] Sync task for URL completed
2023-08-08 09:30:35.842 INFO (MainThread) [music_assistant.music] Sync task for Filesystem (remote share) completed
2023-08-08 09:30:35.843 INFO (MainThread) [music_assistant.music] Sync task for URL completed
2023-08-08 09:30:45.469 INFO (MainThread) [music_assistant.music] Sync task for URL completed
2023-08-08 09:30:46.261 INFO (MainThread) [music_assistant.music] Sync task for Filesystem (remote share) completed
2023-08-08 09:30:55.470 INFO (MainThread) [music_assistant.music] Sync task for URL completed
2023-08-08 09:30:55.882 INFO (MainThread) [music_assistant.music] Sync task for Filesystem (remote share) completed

and an example of a file error for an incomplete track:

2023-08-08 09:02:55.934 ERROR (MainThread) [music_assistant.providers.filesystem_smb] Error processing Chillsynth/HOME - Odyssey/HOME - Odyssey - 12 On The Way Out.mp3 - Unable to retrieve info for /tmp/filesystem_smb/Chillsynth/HOME - Odyssey/HOME - Odyssey - 12 On The Way Out.mp3: Invalid argument
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/music_assistant/server/helpers/tags.py", line 346, in parse_tags
    raise InvalidDataError(error["string"])
music_assistant.common.models.errors.InvalidDataError: Invalid argument

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/music_assistant/server/providers/filesystem_local/base.py", line 325, in sync_library
    track = await self._parse_track(item)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/music_assistant/server/providers/filesystem_local/base.py", line 619, in _parse_track
    tags = await parse_tags(input_file, file_item.file_size)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/music_assistant/server/helpers/tags.py", line 357, in parse_tags
    raise InvalidDataError(f"Unable to retrieve info for {file_path}: {str(err)}") from err
music_assistant.common.models.errors.InvalidDataError: Unable to retrieve info for /tmp/filesystem_smb/Chillsynth/HOME - Odyssey/HOME - Odyssey - 12 On The Way Out.mp3: Invalid argument

[krisnoble]

Following up: I did a docker restart on a hunch and it seems to have solved the problem. But if I set the sync interval to 10 minutes, it starts again. Perhaps setting the sync interval too low gets the system into some sort of error state?

Additionally: If I docker restart the container with the interval set to 10 minutes, then set it to 60 minutes, the sync seems to run every 60 seconds. Maybe somewhere there's a bug that sets the interval in seconds rather than minutes?

Relevant logs:

2023-08-08 15:02:18.309 INFO (MainThread) [music_assistant] Starting Music Assistant Server (263be3735bc342c4b87ec21636bbe3c0) version 2.0.0b70 - uvloop: False
...
2023-08-08 15:02:18.454 INFO (MainThread) [music_assistant.music] Setting up the sync interval to 10 minutes.
...
2023-08-08 15:02:19.621 INFO (MainThread) [music_assistant] Loaded music provider Filesystem (remote share)
2023-08-08 15:02:58.753 INFO (MainThread) [music_assistant.music] Setting up the sync interval to 60 minutes.
2023-08-08 15:02:58.757 INFO (MainThread) [music_assistant.music] Sync task for URL completed
2023-08-08 15:02:59.095 INFO (MainThread) [music_assistant.music] Sync task for Filesystem (remote share) completed
2023-08-08 15:03:58.759 INFO (MainThread) [music_assistant.music] Sync task for URL completed
2023-08-08 15:03:59.083 INFO (MainThread) [music_assistant.music] Sync task for Filesystem (remote share) completed
2023-08-08 15:04:58.760 INFO (MainThread) [music_assistant.music] Sync task for URL completed
2023-08-08 15:04:59.095 INFO (MainThread) [music_assistant.music] Sync task for Filesystem (remote share) completed
2023-08-08 15:05:58.761 INFO (MainThread) [music_assistant.music] Sync task for URL completed
2023-08-08 15:05:59.121 INFO (MainThread) [music_assistant.music] Sync task for Filesystem (remote share) completed

[OzGav]

How is this going? If it is still a problem I will move this to the issues so we can have a look more closely.

[krisnoble]

Seems like it's still an issue - I did switch from SMB to local but if I set the sync interval down to 5 it seems to trigger the same behaviour.

[OzGav]

OK I'll move this to an issue to see what Marcel thinks. I don't see this at all though so I'm not sure....

[krisnoble]

Thanks - I've done some more tests on a fresh install and there's definitely something going on, I'll post in the issue so everything's in one place for Marcel