feat: atomic file saving

[anesthetice]

Split-off feature from #1578 with additional changes (the use of tempfile)

fixes #1128

[anesthetice]

@flxzt, @Doublonmousse,

I'd say this PR is ready for review, let me know what you think

[anesthetice]

@flxzt

I converted this PR to a draft as I was checking a couple of things:

• Immediately re-reading the file to verify the checksum is most likely not actually very useful (and quite expensive), so I removed the operation.
• File operations on UNIX systems are painful, it's apparently wise to also call fsync on the parent directory, which is now done. (For a real guarantee, one might actually then have to recursively call fsync on all of the parent directories.)

Also, the crate atomic-write-file seems pretty good, which we could just use instead of relying on tempfile.

[flxzt]

This looks pretty good, could be ready to get merged.

[Doublonmousse]

Seems like things don't always work on mac os.
Sometimes it is fine, but other time it seems like the operations are delayed or the notification comes later so the save both works (content saved) and fails at the same time (detected as the file being renamed or moved). In that case the log is

 277.598926292s DEBUG save_document_to_file: rnote::canvas::imexport: Saving file is now in progress path="Some(\"/Users/USER/Documents/New Document.rnote\")"
 277.614542667s DEBUG save_document_to_file: rnote::canvas::imexport: Saving file has finished successfully path="Some(\"/Users/USER/Documents/New Document.rnote\")"
 278.627569417s DEBUG rnote::canvas: event=DebouncedEvent { event: Event { kind: Create(File), paths: ["/Users/USER/Documents/.tmpMYNoqo"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None }, time: Instant { tv_sec: 3286, tv_nsec: 305733541 } } expect_write=true msg="output file parent directory watcher event received"
 278.627642292s DEBUG rnote::canvas: event=DebouncedEvent { event: Event { kind: Modify(Name(Any)), paths: ["/Users/USER/Documents/.tmpMYNoqo"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None }, time: Instant { tv_sec: 3286, tv_nsec: 305735708 } } expect_write=true msg="output file parent directory watcher event received"
 278.628077500s DEBUG rnote::canvas: event=DebouncedEvent { event: Event { kind: Modify(Name(Any)), paths: ["/Users/USER/Documents/New Document.rnote"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None }, time: Instant { tv_sec: 3286, tv_nsec: 305750750 } } expect_write=true msg="output file parent directory watcher event received"
 278.629639958s DEBUG rnote::canvas: event=DebouncedEvent { event: Event { kind: Modify(Data(Content)), paths: ["/Users/USER/Documents/New Document.rnote"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None }, time: Instant { tv_sec: 3286, tv_nsec: 305751208 } } expect_write=true msg="output file parent directory watcher event received"

where the temp file is clearly visible here.

In the app the "opened file was renamed or moved" popup shows before the "saved document successfully" (even if the final state is having modifications to save and needing to choose again a path for saving)

[anesthetice]

Seems like things don't always work on mac os. Sometimes it is fine, but other time it seems like the operations are delayed or the notification comes later so the save both works (content saved) and fails at the same time (detected as the file being renamed or moved). In that case the log is

 277.598926292s DEBUG save_document_to_file: rnote::canvas::imexport: Saving file is now in progress path="Some(\"/Users/USER/Documents/New Document.rnote\")"
 277.614542667s DEBUG save_document_to_file: rnote::canvas::imexport: Saving file has finished successfully path="Some(\"/Users/USER/Documents/New Document.rnote\")"
 278.627569417s DEBUG rnote::canvas: event=DebouncedEvent { event: Event { kind: Create(File), paths: ["/Users/USER/Documents/.tmpMYNoqo"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None }, time: Instant { tv_sec: 3286, tv_nsec: 305733541 } } expect_write=true msg="output file parent directory watcher event received"
 278.627642292s DEBUG rnote::canvas: event=DebouncedEvent { event: Event { kind: Modify(Name(Any)), paths: ["/Users/USER/Documents/.tmpMYNoqo"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None }, time: Instant { tv_sec: 3286, tv_nsec: 305735708 } } expect_write=true msg="output file parent directory watcher event received"
 278.628077500s DEBUG rnote::canvas: event=DebouncedEvent { event: Event { kind: Modify(Name(Any)), paths: ["/Users/USER/Documents/New Document.rnote"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None }, time: Instant { tv_sec: 3286, tv_nsec: 305750750 } } expect_write=true msg="output file parent directory watcher event received"
 278.629639958s DEBUG rnote::canvas: event=DebouncedEvent { event: Event { kind: Modify(Data(Content)), paths: ["/Users/USER/Documents/New Document.rnote"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None }, time: Instant { tv_sec: 3286, tv_nsec: 305751208 } } expect_write=true msg="output file parent directory watcher event received"

where the temp file is clearly visible here.

In the app the "opened file was renamed or moved" popup shows before the "saved document successfully" (even if the final state is having modifications to save and needing to choose again a path for saving)

Oh this is not going to be a very fun one to fix, multiple issues:

1 - Calling set_output_file every time

To fix an issue I was having, I added the following at the end of the save_document_to_file function:
https://github.com/anesthetice/rnote/blob/d83439914a7e7d9f5e3de7d51bd0faa48b498dc0/crates/rnote-ui/src/canvas/imexport.rs#L253-L261

But this changes the "output-file" property of the canvas, so a new file watcher is created:

rnote/crates/rnote-ui/src/canvas/mod.rs

Lines 1127 to 1142 in 55ce8c9

	let appwindow_output_file = self.connect_notify_local(
	Some("output-file"),
	clone!(
	#[weak]
	appwindow,
	move |canvas, _pspec| {
	if let Some(output_file) = canvas.output_file() {
	canvas.create_output_file_watcher(&output_file, &appwindow);
	} else {
	canvas.clear_output_file_watcher();
	canvas.dismiss_output_file_modified_toast();
	}
	appwindow.refresh_titles(canvas);
	}
	),
	);

At this point on my machine at least, I think the following is going on: the previous events have hit the old watcher, but since the timeout of 1 second has not yet passed they are not emitted, a new file watcher is created and replaces the old one (which is further stopped), this new file watcher has not received any of the events.

2 - Inconsistent reporting of events by notify

When forcing a single instance of the file watcher to always be active, and saving a file, I get the following instead:

  13.975508131s  INFO rnote::canvas: event=DebouncedEvent { event: Event { kind: Create(File), paths: ["/home/user/Downloads/b.rnote"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None }, time: Instant { tv_sec: 8960, tv_nsec: 613640912 } } expect_write=true msg="output file parent directory watcher event received"
  13.975567222s  INFO rnote::canvas: event=DebouncedEvent { event: Event { kind: Access(Open(Any)), paths: ["/home/user/Downloads/b.rnote"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None }, time: Instant { tv_sec: 8960, tv_nsec: 613648606 } } expect_write=true msg="output file parent directory watcher event received"
  13.975599132s  INFO rnote::canvas: event=DebouncedEvent { event: Event { kind: Access(Close(Write)), paths: ["/home/user/Downloads/b.rnote"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None }, time: Instant { tv_sec: 8960, tv_nsec: 622564915 } } expect_write=true msg="output file parent directory watcher event received"
  
// you can ignore this one, it stems from calling sync on the parent directory
  13.975632926s  INFO rnote::canvas: event=DebouncedEvent { event: Event { kind: Access(Open(Any)), paths: ["/home/user/Downloads"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None }, time: Instant { tv_sec: 8960, tv_nsec: 622584612 } } expect_write=false msg="output file parent directory watcher event received"

From reading notify-rs/notify#129, this is maybe seemingly intended? But doesn't match your events, maybe related to this notify-rs/notify#554?

Anyways, I'll try to fix issue n°1 first, will notify you when I'm done @Doublonmousse, to check if that fixes things.

[Doublonmousse]

Is this a mac-os specific thing ? (does it never happen/always work on everything else - aka linux with meson and flatpak, windows- no matter what ?)

From other issues (like #990) maybe notify isn't robust or timeouts aren't enough in our case (I'm wary of timeouts as well, maybe this kind of issue doesn't happen because events are generally fast enough. But it might not be 100 % true on all cases if some events are buffered, delayed, or take more time on slower drive. That would also explain why it'd appear more on cloud storage). The issue doesn't happen 100% of the time either.

Maybe waiting on the Modify(Data(Content)) to appear on our file when saving is more robust than doing timeouts (if this is consistently the last message and it not appearing == bug then this could be a workaround).

Maybe (for EventKind::Modify(ModifyKind::Data(_data_change)))

rnote/crates/rnote-ui/src/canvas/mod.rs

Lines 977 to 978 in 55ce8c9

	if canvas.output_file_expect_write() {
	// While writing is in progress, multiple modify events might occur.

is not true anymore (if it's really atomic we may have it once and setting the flag to false would work. Though not sure what happens for cloud storage)

Currently we reset the flag here for EventKind::Access(AccessKind::Close(AccessMode::Write))

rnote/crates/rnote-ui/src/canvas/mod.rs

Lines 1039 to 1041 in 55ce8c9

	if canvas.output_file_expect_write() {
	// Own file writing has finished
	canvas.set_output_file_expect_write(false);

(maybe this happen before the ModifyKind::Data event ?)

and here (but only if an error is found so probably not in my case)

rnote/crates/rnote-ui/src/canvas/imexport.rs

Lines 273 to 280 in 55ce8c9

	if let Err(e) = file_write_operation.await {
	self.set_save_in_progress(false);
	// If the file operations failed in any way, we make sure to clear the expect_write flag
	// because we can't know for sure if the output-file watcher will be able to.
	self.set_output_file_expect_write(false);
	return Err(e);
	}

[anesthetice]

Could you try again on macOS @Doublonmousse? Does the Access(Close(Write)) event really not occur?

edit, this could be useful, the events read from notify directly (no debouncer) and cleaned up for readability:

event: Create(File), paths: ["/home/user/Downloads/.tmpPNUrOT"]
event: Access(Open(Any)), paths: ["/home/user/Downloads/.tmpPNUrOT"]
event: Modify(Data(Any)), paths: ["/home/user/Downloads/.tmpPNUrOT"]

event: Modify(Name(From)), paths: ["/home/user/Downloads/.tmpPNUrOT"], attr:tracker: Some(6291)
event: Modify(Name(To)), paths: ["/home/user/Downloads/aa.rnote"], attr:tracker: Some(6291)
event: Modify(Name(Both)), paths: ["/home/user/Downloads/.tmpPNUrOT", "/home/user/Downloads/aa.rnote"], attr:tracker: Some(6291)

event: kind: Access(Close(Write)), paths: ["/home/user/Downloads/aa.rnote"]
event: kind: Access(Open(Any)), paths: ["/home/user/Downloads"]

[Doublonmousse]

Trying to add some traces (default debouncer config for now), going to redo with the latest commit shortly.
Doing

    pub(crate) fn set_output_file_expect_write(&self, expect_write: bool) {
        debug!("set_output_file_expect_write to {:?}", expect_write);
        self.imp().output_file_expect_write.set(expect_write);
    }

Shows that the value is never set back to false on mac os.

  22.759464292s DEBUG rnote::canvas: event=DebouncedEvent { event: Event { kind: Modify(Name(Any)), paths: ["/Users/user/Documents/GitHub/rnote/fresh_test.rnote"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None }, time: Instant { tv_sec: 1234, tv_nsec: 529910708 } } expect_write=true msg="output file parent directory watcher event received"

is the event that triggers the issue (in EventKind::Modify(ModifyKind::Name(_))). It is not EventKind::Modify(ModifyKind::Data(_data_change)) because the set_output_file_expect_write is never called to false so any such event is filtered out.

Edit: same thing with the commit. Removing the debouncer timeout shows that this can also happen on the first save as well.

[anesthetice]

Not the cleanest fix (if it even fixes the issue), but not the cleanest bug either...

Does it work now?

[Doublonmousse]

Does it work now?

Yes it does

[flxzt]

Thanks!