Repository: Canop/bacon (language: rust)

Issue:
Race condition in config reloading
When reloading the config file, it is possible that `bacon` exits with `Error: job not found: "<current_job>"`.

Reproduction:
```console
$ cat bacon.toml
default_job = "echo"

[jobs.echo]
command = ["echo", "1"]
need_stdout = true
$ bacon echo
[...]
```
When saving the config file in e. g. vim, neovim or helix (but not when using `touch` or saving in gedit) there is a chance that bacon will exit with
```
Error: job not found: "echo"
```
This usually happens within a few tries, but usually takes longer when `BACON_LOG=debug` is specified.

I found this while trying to reproduce a hang on config reload similar to #306 with a small config file. With a normal sized config file, I have never seen this.

Given that this is editor-dependent, behaves differently on a `tmpfs` filesystem, and happens somewhat randomly and more likely on smaller config files, I think this issue is caused by the same editor behaviour as #222.

bacon version: a66fa35d8d619d3c7bf38455301a7d3b244ef788
OS: Linux
No `~/.config/bacon/prefs.toml` file.


Discussion / hints:
Can you have a look at the Watcher struct and see the sequence of "change" events ?
I’m not sure I understand what you’re asking. When I run with `BACON_LOG=trace` I get this log output when saving `bacon.toml`:
```
16:10:53.207 [TRACE] notify::inotify: inotify event: Event { wd: WatchDescriptor { id: 1, fd: (Weak) }, mask: MOVE_SELF, cookie: 0, name: None }
16:10:53.208 [INFO] bacon::watcher: notify event: Event { kind: Modify(Name(From)), paths: ["/tmp/t/bacon.toml"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None }
16:10:53.208 [INFO] bacon::watcher: ignorer.excludes_all_pathbufs(&we.paths) took 312ns
16:10:53.208 [DEBUG] bacon::watcher: at least one is included
16:10:53.208 [INFO] bacon::app: config watch event received
16:10:53.208 [DEBUG] bacon::app: requested action: Internal(ReloadConfig)
16:10:53.208 [DEBUG] bacon::exec::executor: failed to send 'die' signal: sending on a disconnected channel
16:10:53.208 [INFO] bacon::conf::settings: config loaded from "/tmp/t/bacon.toml"
16:10:53.208 [INFO] bacon::conf::settings: settings: Settings {
[Settings elided...]
}
16:10:53.210 [DEBUG] bacon::jobs::job_stack: picking job Initial
16:10:53.210 [DEBUG] bacon::context: watches: ["Cargo.toml", "src", "tests", "benches", "examples", "build.rs"]
16:10:53.210 [DEBUG] bacon::mission: Failed to initialise git ignorer: Could not find a git repository in '/tmp/t' or in any of its parents within device limits below '/'
16:10:53.210 [INFO] bacon::app: mission.ignorer() took 40.335µs
16:10:53.210 [INFO] bacon::watcher: watcher on []
16:10:53.210 [TRACE] mio::poll: registering event source with poller: token=Token(0), interests=READABLE
16:10:53.210 [INFO] bacon::watcher: watcher on [
    "/tmp/t/bacon.toml",
]
16:10:53.210 [TRACE] mio::poll: registering event source with poller: token=Token(0), interests=READABLE
16:10:53.211 [DEBUG] bacon::watcher: add watch file "/tmp/t/bacon.toml"
16:10:53.211 [TRACE] notify::inotify: adding inotify watch: /tmp/t/bacon.toml
16:10:53.211 [DEBUG] bacon::mission: command builder: CommandBuilder {
    exe: "echo",
    current_dir: Some(
        "/tmp/t",
    ),
    args: [
        "1",
    ],
    with_stdout: true,
    envs: {
        "CARGO_TERM_COLOR": "always",
    },
}
16:10:53.211 [INFO] bacon::exec::executor: start task Task { backtrace: None, grace_period: Period { duration: 5ms } }
16:10:53.217 [INFO] bacon::app: execution finished with status: Some(ExitStatus(unix_wait_status(0)))
16:10:53.218 [DEBUG] bacon::analysis::standard::standard_report_building: stats: Stats {
    warnings: 0,
    errors: 0,
    test_fails: 0,
    passed_tests: 0,
    location_lines: 0,
    normal_lines: 0,
}
16:10:53.218 [DEBUG] bacon::result::command_result: report stats: Stats { warnings: 0, errors: 0, test_fails: 0, passed_tests: 0, location_lines: 0, normal_lines: 0 }
16:10:53.218 [DEBUG] bacon::state: Got report
16:10:53.218 [INFO] bacon::state: Stats: Stats {
    warnings: 0,
    errors: 0,
    test_fails: 0,
    passed_tests: 0,
    location_lines: 0,
    normal_lines: 0,
}

```

This start of the sequence is the same regardless of whether bacon quits or continues. [^1] When bacon quits, the log ends after the line
```
16:10:53.210 [DEBUG] bacon::jobs::job_stack: picking job Initial
```
without any further output.

This is what helix does when I save:
```console
$ inotifywait --monitor .
Setting up watches.
Watches established.
./ MOVED_FROM bacon.toml
./ MOVED_TO bacon.tomlRVgcK0.bck
./ CREATE bacon.toml
./ OPEN bacon.toml
./ MODIFY bacon.toml
./ CLOSE_WRITE,CLOSE bacon.toml
./ ATTRIB bacon.toml
./ DELETE bacon.tomlRVgcK0.bck
```

If I understand correctly, bacon reacts to the `MOVED_FROM` event and immediately reloads the config file, but the config file is only complete at the `CLOSE_WRITE` event.

[^1]: I also once saw this (with bacon continuing):
    ```
    16:10:54.534 [TRACE] notify::inotify: inotify event: Event { wd: WatchDescriptor { id: 1, fd: (Weak) }, mask: MOVE_SELF, cookie: 0, name: None }
    16:10:54.534 [INFO] bacon::watcher: notify event: Event { kind: Modify(Name(From)), paths: ["/tmp/t/bacon.toml"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None }
    16:10:54.534 [INFO] bacon::watcher: ignorer.excludes_all_pathbufs(&we.paths) took 260ns
    16:10:54.534 [DEBUG] bacon::watcher: at least one is included
    16:10:54.534 [INFO] bacon::app: config watch event received
    16:10:54.534 [DEBUG] bacon::app: requested action: Internal(ReloadConfig)
    16:10:54.534 [DEBUG] bacon::exec::executor: failed to send 'die' signal: sending on a disconnected channel
    16:10:54.534 [TRACE] notify::inotify: inotify event: Event { wd: WatchDescriptor { id: 1, fd: (Weak) }, mask: ATTRIB, cookie: 0, name: None }
    16:10:54.534 [DEBUG] bacon::watcher: ignoring metadata change
    16:10:54.534 [TRACE] notify::inotify: inotify event: Event { wd: WatchDescriptor { id: 1, fd: (Weak) }, mask: DELETE_SELF, cookie: 0, name: None }
    16:10:54.534 [INFO] bacon::watcher: notify event: Event { kind: Remove(File), paths: ["/tmp/t/bacon.toml"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None }
    16:10:54.535 [INFO] bacon::watcher: ignorer.excludes_all_pathbufs(&we.paths) took 66ns
    16:10:54.535 [DEBUG] bacon::watcher: at least one is included
    16:10:54.535 [DEBUG] bacon::watcher: error when notifying on notify event: sending on a disconnected channel
    16:10:54.535 [TRACE] notify::inotify: inotify event: Event { wd: WatchDescriptor { id: 1, fd: (Weak) }, mask: IGNORED, cookie: 0, name: None }
    16:10:54.535 [TRACE] notify::inotify: removing inotify watch: /tmp/t/bacon.toml
    16:10:54.535 [INFO] bacon::conf::settings: config loaded from "/tmp/t/bacon.toml"
    16:10:54.535 [INFO] bacon::conf::settings: settings: Settings {
    [...]
    ```
> If I understand correctly, bacon reacts to the MOVED_FROM event and immediately reloads the config file, but the config file is only complete at the CLOSE_WRITE event.

That's what I seem to read too.

Can you try adding this line 44 of watcher.rs ?

                        EventKind::Modify(ModifyKind::Name(RenameMode::From)) => {
                            debug!("rename from event: {we:?}");
                            return; // maybe a move to a backup file
                        }

If it's a problem, I'll try to see whether I can reproduce with helix.

A problem with always ignoring this event is that there are cases where a file is removed and bacon should react.
@narpfel In fact there's something in bacon which should already work.

Please try adding this to your prefs:

    grace_period = "10ms"

> Can you try adding this line 44 of watcher.rs ?

This seems to work:
```
20:14:04.777 [DEBUG] bacon::watcher: rename from event: Event { kind: Modify(Name(From)), paths: ["/tmp/t/bacon.toml"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None }
20:14:04.778 [DEBUG] bacon::watcher: ignoring metadata change
20:14:04.778 [INFO] bacon::watcher: notify event: Event { kind: Remove(File), paths: ["/tmp/t/bacon.toml"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None }
```
The `MOVED_FROM` is ignored and the next event on the original config file is `DELETE`ing it (at which point it is the tempfile and the new config file has already been written).

`grace_period` doesn’t work because the reload-config code doesn’t check for it: https://github.com/Canop/bacon/blob/a66fa35d8d619d3c7bf38455301a7d3b244ef788/src/app.rs#L166-L169 and https://github.com/Canop/bacon/blob/a66fa35d8d619d3c7bf38455301a7d3b244ef788/src/app.rs#L284-L287
> grace_period doesn’t work because the reload-config code doesn’t check for it

Ok, this I should fix, then.

Fix patch:
diff --git a/defaults/default-prefs.toml b/defaults/default-prefs.toml
index c54cf44..f2cd0dc 100644
--- a/defaults/default-prefs.toml
+++ b/defaults/default-prefs.toml
@@ -22,8 +22,9 @@
 
 # The grace period is a delay after a file event before the real
 # task is launched and during which other events will be ignored.
-# This is useful if several events are often sent quasi-simultaneously
-# (eg your editor backups before saving, then renames).
+# This is mostly useful when your editor does several operations
+# when saving a file and the state is temporarly wrong (eg it
+# moves the file to a backup name before recreating the right one)
 # You can set it to "none" if it's useless for you.
 #
 # grace_period = "5ms"
diff --git a/src/app.rs b/src/app.rs
index d943d9e..5b5021b 100644
--- a/src/app.rs
+++ b/src/app.rs
@@ -102,6 +102,7 @@ fn run_mission(
     headless: bool,
 ) -> Result<DoAfterMission> {
     let keybindings = mission.settings.keybindings.clone();
+    let grace_period = mission.settings.grace_period;
 
     // build the watcher detecting and transmitting mission file changes
     let ignorer = time!(Info, mission.ignorer());
@@ -165,6 +166,7 @@ fn run_mission(
             }
             recv(config_watcher.receiver) -> _ => {
                 info!("config watch event received");
+                grace_period.sleep(); // Fix #310
                 action = Some(&Action::Internal(Internal::ReloadConfig));
             }
             recv(executor.line_receiver) -> info => {
diff --git a/src/exec/period.rs b/src/exec/period.rs
index 918b67c..8b408cd 100644
--- a/src/exec/period.rs
+++ b/src/exec/period.rs
@@ -24,6 +24,9 @@ impl Period {
     pub const fn is_zero(&self) -> bool {
         self.duration.is_zero()
     }
+    pub fn sleep(&self) {
+        std::thread::sleep(self.duration);
+    }
 }
 
 impl From<Duration> for Period {


Test patch: