syncthing destroyed (at least) two photos

Last week, I took two selfies. I remember it well because I had this cool Torproject.org swag and wanted to thank the person who sent them to me. Then I forgot about it, then I remembered I needed to send those pics, so I looked on my phone again, and the photos were gone.

Strange. I could have sworn I took those pictures! And I remember I did because I took two photos: the first was blurry…

And then I remembered the syncthing-gtk desktop client notified me that it “deleted two files to reflect remote changes” or something like that. I didn’t quite pay attention to it at the time, because I keep getting those notifications when I login and I got alert fatigue. But now I can’t help but think that syncthing tried to sync the folders and decided the files should be removed.

Is that possible? Did Syncthing destroy my precious photos? How does it decide to copy files from device A to device B instead of deleting files on device A when they’re not present on device B? Could this be a timing issue?

One idea I had was that maybe the phone’s hardware clock is set to UTC but the desktop client’s hardware clock is set to local time, and that Syncthing gets confused by that?

Or maybe it’s a bug in syncthing-gtk? I’d be surprised because it really uses the same syncthing underneath, right?

I have since then set the folder as “send-only” on the phone, and enabled revisions, but that’s really worrisome, I must say. I use Syncthing quite a bit and the idea that it would delete files like this is kind of terrifying.

Those are the different software versions:

  • Phone: Android 11, Syncthing from F-Droid (probably n 1.12.1)
  • Desktop: Debian GNU/Linux “stable” 10 (buster), syncthing 1.0.0~ds1-1+b11, syncthing-gtk 0.9.4.3-1

Thanks!

Not that this is the culprit (which it is probably not), but your Syncthing version on Debian is more than 2 years old now. I would suggest checking https://apt.syncthing.net to have access to the current releases.

If a file is present and accounted for on disk at one point in time, and then is no longer there when we look next time, then we consider it deleted and tell the other side to delete it as well.

1 Like

that makes sense, thanks for clarifying that. so i guess that’s probably not what happened.

i really do wonder, then…

I am aware that Debian stable is now over two years old. And I did use that APT archive back when syncthing wasn’t in Debian – i’ve been using Syncthing for a while now – it’s just way more practical to use whatever is in Debian for me.

And if the version in Debian destroys content, it should be fixed or removed, but at least it should definitely be known that older versions of Syncthing have a data loss bug. As a Debian developer, it’s kind of my job to make sure to eat our own dogfood and make sure it’s not… poisonous, so to speak. :slight_smile:

Not that this is confirmed, of course. It’s kind of hard to figure out what happened here. It would definitely help if there would be logs of that kind of behavior… I looked at the syncthing logs (from syncthing-gtk) to figure out what was deleted and I couldn’t figure it out: there was just a lot of output about discovery and so on. In fact, I just started syncthing-gtk just now and it told me it deleted 6 files from various folders, and I can’t find a trace of that in the “daemon output”.

So I don’t know, it’s kind of really mysterious, why syncthing does what it does sometimes. It would really help to have a log of file transfers, for example. Is that a thing?

1 Like

It is, with -audit and maybe some trace options. There’s been literally a thousand bugs over the years, but I don’t think spontaneous deletes were ever one of them.

2 Likes

so help me out here, I add -audit to the commandline arguments to syncthing? anything else?

Just that commandline flag: Syncthing — Syncthing v1 documentation

Revisions of an item (identified by a path) are tracked internally by counting. That is not dependent on the hardware clock. Modification time and hardware clock is only involved in detecting if a local file has changed since we last looked at it.
And for a new file it isn’t an issue at all. Because then there is a record of the file on the originating device, and no record at all on any connected remote device - which is distinct from a record that is marked as deleted.

You probably did it the right way around, but it’s not entirely clear here: Syncthing can’t preserve files that were already changed/deleted. The versioning applies to files changed on remotes only. So here you have to enable versioning (revisions) on your desktop.

Edit: One thing you can still do is to query the api for info of that file. It won’t show us what happened, it should show the final version vector. Which will have info on which side deleted the file and some limited info on it’s history (did the desktop also modify the file at any point): GET /rest/db/file — Syncthing v1 documentation

1 Like

that says:

Write events to timestamped file audit-YYYYMMDD-HHMMSS.log.

Yet it’s not clear, just looking at that documentation, where that file will end up… Turns out it’s in ~/.config/syncthing/ which I would argue is counter-intuitive (it’s not configuration, it’s logs, so it would be better in ~/.cache or ~/.local). In any case, docs would need help here. :wink:

Also, it’s not clear to me what I am looking for in that file. There’s a lot of things in there, like:

{"id":78,"globalID":78,"time":"2021-01-24T13:55:29.77501108-05:00","type":"StateChanged","data":{"duration":0.023681757,"folder":"9mevi-pulmi","from":"scanning","to":"idle"}}

What would a delete event look like?

Yeah, I figured as much. My working theory right now is that something deleted the file, somewhere, and I can’t imagine it was the phone, so it must have been on the other end. So enabling the trash should help with future problems like those…

One problem here as I don’t even know what I’m looking for: I don’t even have the filename…

answering my own question, here’s an example:

{"id":16821,"globalID":16821,"time":"2021-01-25T11:07:37.271580077-05:00","type":"ItemStarted","data":{"action":"delete","folder":"lk9vs-206k6","item":"signal-2021-01-22-20-58-09.backup","typ
e":"file"}}
{"id":16822,"globalID":16822,"time":"2021-01-25T11:07:37.272158896-05:00","type":"StateChanged","data":{"folder":"fujjv-addqw","from":"idle","to":"scan-waiting"}}
{"id":16823,"globalID":16823,"time":"2021-01-25T11:07:37.27217929-05:00","type":"StateChanged","data":{"duration":0.000020036,"folder":"fujjv-addqw","from":"scan-waiting","to":"scanning"}}
{"id":16824,"globalID":16824,"time":"2021-01-25T11:07:37.273827323-05:00","type":"ItemFinished","data":{"action":"delete","error":null,"folder":"lk9vs-206k6","item":"signal-2021-01-22-20-58-0
9.backup","type":"file"}}
{"id":16825,"globalID":16825,"time":"2021-01-25T11:07:37.27663737-05:00","type":"LocalIndexUpdated","data":{"filenames":["signal-2021-01-22-20-58-09.backup"],"folder":"lk9vs-206k6","items":1,
"version":9}}
{"id":16826,"globalID":16826,"time":"2021-01-25T11:07:37.276648229-05:00","type":"RemoteChangeDetected","data":{"action":"deleted","folder":"lk9vs-206k6","folderID":"lk9vs-206k6","label":"signal-backups","modifiedBy":"CVJZX7H","path":"signal-2021-01-22-20-58-09.backup","type":"file"}}

key piece here seems to be:

{
  "id": 16824,
  "globalID": 16824,
  "time": "2021-01-25T11:07:37.273827323-05:00",
  "type": "ItemFinished",
  "data": {
    "action": "delete",
    "error": null,
    "folder": "lk9vs-206k6",
    "item": "signal-2021-01-22-20-58-09.backup",
    "type": "file"
  }
}

and it seems this jq commandline will show me all the deletes in the audit log, which is kind of useful:

jq '. | select(.type=="ItemFinished") | select(.data.action == "delete")' < audit-20210124-135459.log

obviously, I now have only one delete, but at least I have a way to debug this in the future, thanks. :slight_smile:

1 Like

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