SFTP Synchronization Failures
I have my private music collection stored on an SFTP server. I am running a synchronization right now that is showing failures with no explanation of the issue. Here are a couple:
2024-07-13T15:38:38 FAILED /sftp/Music/DeadLife/2018, Variations On The Resolve/08-Pathos Station.flac 2024-07-13T15:38:38 ERROR This file was not downloaded to /opt/astiga/tmp/libIwa5XM.fla 2024-07-13T15:39:01 F_ERR 2024-07-13T15:39:01 FAILED /sftp/Music/DeadLife/2019, Orphan/10-Never Saw Another Day.flac 2024-07-13T15:39:01 ERROR This file was not downloaded to /opt/astiga/tmp/libHgXfOv.flac 2024-07-13T15:39:01 F_ERR 2024-07-13T15:39:01 FAILED /sftp/Music/DeadLife/2019, Orphan/11-She Closed Her Eyes.flac 2024-07-13T15:39:01 ERROR This file was not downloaded to /opt/astiga/tmp/libRcXth4.flac 2024-07-13T15:39:02 ADD /sftp/Music/DeadLife/2018, Variations On The Resolve/11-The Deepest Ocean.flac 2024-07-13T15:39:02 F_ERR 2024-07-13T15:39:02 FAILED /sftp/Music/DeadLife/2019, Rebel Nights/02-Summer Mist.flac 2024-07-13T15:39:02 ERROR This file was not downloaded to /opt/astiga/tmp/libkRknYE.flac 2024-07-13T15:39:06 ADD /sftp/Music/DeadLife/2019, Orphan/09-Severed All Ties.flac 2024-07-13T15:39:07 ADD /sftp/Music/DeadLife/2019, Orphan/02-A Vast Darkness Beyond.flac 2024-07-13T15:39:07 F_ERR 2024-07-13T15:39:07 FAILED /sftp/Music/DeadLife/2019, Rebel Nights/03-Blue Gum.flac 2024-07-13T15:39:07 ERROR This file was not downloaded to /opt/astiga/tmp/libm0Riqq.flac 2024-07-13T15:39:07 F_ERR
I have command-line FLAC installed on the server, and all of these files above test OK.
Comments
I can see over 10,000 files were added and 43 failed. It might be these just had failures this time around, so that's a failure rate of under 0.5%. Can you see if it works next time?
The sync is not even finished yet. It is still running as of now.
I requested that the log be sent, but it was not. Instead, a link to the log was emailed. However, the log is now lost forever.
I ran the sync a second time, and this time it was significantly faster. It also emailed a text file log as an attachment.
The initial sync load needs retry logic for the failures.
I'll look into what happened, thanks.
My daily sync is now also showing failures:
```
2024-07-22T05:09:57 F_ERR2024-07-22T05:09:57 FAILED /sftp/Music/Terence Blanchard/1993, The Malcolm X Jazz Suite/01-The Opening.flac2024-07-22T05:09:57 ERROR This file was not downloaded to /opt/astiga/tmp/libR278bA.flac2024-07-22T05:10:19 F_ERR2024-07-22T05:10:19 FAILED /sftp/Music/Terence Blanchard/1993, The Malcolm X Jazz Suite/07-Betty's Theme.flac2024-07-22T05:10:19 ERROR This file was not downloaded to /opt/astiga/tmp/libMcO38z.flac2024-07-22T08:15:43 F_ERR2024-07-22T08:15:44 F_ERR2024-07-22T08:15:44 ADD /sftp/Music/Youthopian/2023, Arcade Girl/02-Cyber Rapture.flac2024-07-22T08:15:44 ADD /sftp/Music/Youthopian/2023, Arcade Girl/03-The Runner.flac2024-07-22T08:15:55 F_ERR2024-07-22T08:15:55 FAILED /sftp/Music/Youthopian/2023, Arcade Girl/09-Late City Nights.flac2024-07-22T08:15:55 ERROR This file was not downloaded to /opt/astiga/tmp/libacPFCu.flac2024-07-22T08:15:56 F_ERR2024-07-22T08:15:57 ADD /sftp/Music/Youthopian/2023, Arcade Girl/06-Simone.flac2024-07-22T08:15:57 F_ERR2024-07-22T08:15:57 FAILED /sftp/Music/Youthopian/2023, Arcade Girl/08-Stargazing.flac2024-07-22T08:15:57 ERROR This file was not downloaded to /opt/astiga/tmp/libYXRSiT.flac```
Synchronization is too random for SFTP. It is not reliable. These files were also successfully downloaded in the past and unchanged on the server.
I guess I'll have to look into the failures to understand the underlying reasons why they are working sporadically. But before it was only 0.5% failure rate - is that higher now?
I'm on holiday so won't be able to look at this until Friday.
I would expect a 0% chance of failure over a secure connection. The daily sync also appears to have taken over eight hours. The encrypted connection may explain the additional time required. Eight hours seems like an excessive amount of time for a daily sync. There were a small number of new files. I am constantly adding new music, but the majority of files are unchanged.
It looks like the time stamp at the end of the sync shows:
minutes:seconds:milliseconds
The sync took over eight minutes and not eight hours.
I am seeing weird results for added files. I executed another sync after the failures to see the following added at the end:
2024-07-22T10:33:04 ADD /sftp/Music/Terence Blanchard/1993, The Malcolm X Jazz Suite/07-Betty's Theme.flac2024-07-22T10:33:05 ADD /sftp/Music/Terence Blanchard/1993, The Malcolm X Jazz Suite/01-The Opening.flac2024-07-22T10:33:06 ADD /sftp/Music/Street Cleaner/2021, Edge/06-Terror Influx (feat. Aubrey Hodges).flac2024-07-22T10:33:08 ADD /sftp/Music/Youthopian/2023, Arcade Girl/09-Late City Nights.flac2024-07-22T10:33:10 ADD /sftp/Music/Youthopian/2023, Arcade Girl/08-Stargazing.flacall five files above should have already existed in the library. They are sync'd daily and are not new files.
I just played from my mobile phone to my dash via Bluetooth minutes ago. I hear a file playing correctly, but all tag info is missing:
This file exist on the server, and mediainfo shows that it includes all tag data:
There two of the same song at different bitrates. Both files have all tag info. Astiga is only playing one of them.
Sorry - I'll have to check all of these items when I get back.
0% failure would be nice but the nature of networked applications and large amounts of data are such that something, sometime will go wrong.
I do not understand this statement. The SFTP protocol by design ensures data integrity. A successful transfer ensures that the file is correct. There should be zero failures. Any failures are the result of either:
a buggy SFTP library component
or
a buggy implementation.
Today daily sync executed then executed all by itself a second time.
I do not understand the logic behind it. It runs one pass of all directories after which it then adds all files. During the second execution for pass #2, it is completely adding every single file. Also, it has been running for hours.
The logic is to run one pass of directories, looking for updated and new music files. Then it goes through all of the music files, adding them.
You're correct - it looks like all of your files were re-added. Looking at the job before this, the SFTP server responded with an unexpected reply (a reply the library we use couldn't handle) but then we didn't handle this well - we treat this as an empty result in our synchronisation code and interpret that as the files we expect to see being deleted. Thus, the library was deleted from Astiga on that pass but then recreated on the next.
This only affects SFTP servers.
We'll fix it so we don't interpret such a failure to be a non-existence of the file. Instead, we'll log the failure.
I requested that the log be sent, but it was not. Instead, a link to the log was emailed. However, the log is now lost forever.
I looked into this. We send a link if the log is over 2MB. However, the link only goes to the most recent log, so this might be overwritten.
To fix this we'll have to look into retaining logs, at least for a period. Right now this wouldn't be a priority to do, but we can definitely look at it if it keeps coming up.
Since the log is 100% text, it is highly compressible. Consider zipping the log prior to email.
Nice idea. Does require more dependencies, but I'll look into it. 👍️
This same issue happened again today during automatic daily scan. I have turned off automatic scan until it is confirmed this has been resolved.
Thanks for your patience. I hope we'll be able to get to this soon.
@Dryst We have some fixes for this in the next build in the next day or two. If you could keep an eye out for this it would be great - the errors seem sporadic so we want to make sure we've covered all paths.
We've deployed that fix now: https://community.asti.ga/discussion/comment/3399/#Comment_3399
Thank you.
This is greatly improved, and all issues I described above are resolved.
Great to hear, thanks, but do let us know if something else happens!