[SOLVED] External Versioning failing with no errors in the GUI in v1.14.0

Support
1

This can be new (or not), but I did have errors in the GUI in this kind of a situation before (see https://github.com/syncthing/syncthing/issues/7354).

However, today I have experienced the GUI stuck like this:

1
1706Ă—404 31 KB

I thought that the file deletion was just taking some time, but after a while I checked the actual logs, and the errors are right there:

INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx"): syncing: delete file: external versioner: archive: file was not removed by external script

Is this expected or should this be qualified as a bug?

2

I think it’s saying that the script didn’t do what it was asked, so I suggest you verify the script does the right thing

3

Folder status in the screenshot is preparing to sync: Errors are always cleared at the start of a sync. The error being logged means it is accounted for and should appear in the UI again. I’d expect the failed items to appear again once the operation is through, don’t they?

1 Like
4

I tried to pause and unpause the folder multiple times, but it was always the same, i.e. stuck in “Preparing for Sync”, but no errors themselves reported in the GUI. The folder was in that state for 30+ minutes, and that was why I checked the logs in the first place. Basically, the GUI was showing “Preparing for Sync”, but the logs were reporting external versioner errors. There were no “Failed Items” reported whatsoever.

Of course, that was obvious. The errors got cleared after I fixed the script. The problem here is that there were no errors shown in the GUI, and I just thought that it really was taking a very long time just to sync the deletions.

Edit:

Just for the record, this is what I expected, and also what does actually happen if I try to reproduce the problem using the current main.

image
image707Ă—339 25.9 KB

I don’t know why the behaviour was different in my real installation though.

5

Sounds like a bug fixed a few months ago.

6

This is all in v1.14.0 :wink:.

The full logs looked like this:

15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1247.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1210.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1248.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx"): syncing: delete dir: directory has been deleted on a remote device but is not empty; the contents are probably ignored on that remote device, but not locally
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx"): syncing: delete dir: directory has been deleted on a remote device but is not empty; the contents are probably ignored on that remote device, but not locally
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1195.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1187.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1214.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1220.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1201.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1252.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1244.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1204.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1213.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1206.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1215.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1208.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1238.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1194.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1242.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1207.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1190.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1197.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1245.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1232.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1223.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1243.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1225.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1250.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1189.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1216.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx"): syncing: delete dir: directory has been deleted on a remote device but is not empty; the contents are probably ignored on that remote device, but not locally
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1191.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1231.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1235.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1251.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1233.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1209.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1192.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1234.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1203.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1226.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1230.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1239.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1219.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1205.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1249.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1236.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx"): syncing: delete dir: directory has been deleted on a remote device but is not empty; the contents are probably ignored on that remote device, but not locally
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx"): syncing: delete dir: directory has been deleted on a remote device but is not empty; the contents are probably ignored on that remote device, but not locally
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1224.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1222.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1196.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1188.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1228.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1241.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx"): syncing: delete dir: directory has been deleted on a remote device but is not empty; the contents are probably ignored on that remote device, but not locally
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1193.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1199.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1212.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1237.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1240.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1246.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1202.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1221.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1218.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1211.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1198.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1253.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1229.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1217.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1227.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: Puller (folder "xxx" (nduzw-sud32), item "xxx\\1200.jpg"): syncing: delete file: external versioner: archive: file was not removed by external script
15:52:48 INFO: "xxx" (nduzw-sud32): Failed to sync 73 items
15:52:48 INFO: Folder "xxx" (nduzw-sud32) isn't making sync progress - retrying in 24m53s.

and then it kept retrying every minute until I checked the logfile and fixed the versioning script afterwards.

7

IIRC we don’t send the errors to the GUI until the sync iteration completes, so a long preparing-to-sync phase won’t show errors while they are occurring. They should display once the sync failed, then clear again when it starts retrying? I mean, imsodin already said precisely this, but perhaps didn’t emphasize the short period the errors might in fact be visible?

8

I kept checking the GUI multiple times for quite a few minutes, and there was still nothing though. I tried to rescan and/or pause and unpause the folder, and I think that I even tried restarting Syncthing itself, but the situation didn’t change. Then I looked at the logfiles and realised the actual issue.

I cannot reproduce the problem in my test environment, so it is kind of difficult to find the cause. If I try doing the same there, I get failed items immediately.

The last thing that I can do is to reproduce this in the real environment, using the same files with the same broken versioning script, but now with debugging enabled. I may try doing some testing later on this week.

9

I think that I have a conclusion to this one.

I have encountered the same problem today on different machine, with a different folder, and this time the folder did change to “Out of Sync” for a moment before going back to the “Preparing…” state.

Basically, it seems that as long as the external versioner keeps failing, Syncthing will keep retrying to version those files on and on. As this continues, the GUI is seemingly stuck like that. It also seems to take quite a while to go through all the files, which prolongs the time even more. Once done, the folder gets marked as “Out of Sync”, but around 2 minutes later (judging by the logs), Syncthing repeats the whole process again. This seems to go on indefinitely.

10

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.