Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Stop duplicate messages being sent by tedge-log-plugin and tedge-configuration-plugin on file reload #2454

Merged

Conversation

Bravo555
Copy link
Contributor

Proposed changes

This fix consists of 2 parts:

  1. NotifyStream impl was changed to make use of a notify-debouncer-full crate to delay and debounce fs events. This should also impact other consumers of NotifyStream.
  2. Watch parameters of tedge-log-plugin were changed to only listen to Modified events, no longer listening to FileCreated events.

This fix was confirmed to produce only 1 reload when using following editors:

  • nano
  • vim
  • neovim

More details regarding both parts can be found in their respective commit messages.

Types of changes

  • Bugfix (non-breaking change which fixes an issue)
  • New feature (non-breaking change which adds functionality)
  • Improvement (general improvements like code refactoring that doesn't explicitly fix a bug or add any new functionality)
  • Documentation Update (if none of the other choices apply)
  • Breaking change (fix or feature that would cause existing functionality to not work as expected)

Paste Link to the issue

Checklist

  • I have read the CONTRIBUTING doc
  • I have signed the CLA (in all commits with git commit -s)
  • I ran cargo fmt as mentioned in CODING_GUIDELINES
  • I used cargo clippy as mentioned in CODING_GUIDELINES
  • I have added tests that prove my fix is effective or that my feature works
  • I have added necessary documentation (if appropriate)

Further comments

Copy link

codecov bot commented Nov 15, 2023

Codecov Report

Merging #2454 (351e8b8) into main (6fe2820) will increase coverage by 0.0%.
Report is 19 commits behind head on main.
The diff coverage is 90.8%.

Additional details and impacted files
Files Coverage Δ
...rates/extensions/tedge_config_manager/src/actor.rs 67.8% <0.0%> (ø)
crates/extensions/tedge_log_manager/src/actor.rs 66.8% <0.0%> (-0.5%) ⬇️
crates/common/tedge_utils/src/notify.rs 93.2% <92.9%> (+2.0%) ⬆️

... and 65 files with indirect coverage changes

Copy link
Contributor

github-actions bot commented Nov 15, 2023

Robot Results

✅ Passed ❌ Failed ⏭️ Skipped Total Pass % ⏱️ Duration
362 0 3 362 100 49m8.029999999s

@reubenmiller
Copy link
Contributor

  1. Watch parameters of tedge-log-plugin were changed to only listen to Modified events, no longer listening to FileCreated events.

Are we also sure that this change does not affect replacing existing files using mv and cp? We have some system test coverage for the configuration plugin, but none for the log manager. We should double check that we are not breaking any existing behaviour.

Also, shouldn't we also be doing the same handling for the configuration manager?

@Bravo555
Copy link
Contributor Author

Are we also sure that this change does not affect replacing existing files using mv and cp?

Moving files and creating files both also emit Modified event

We have some system test coverage for the configuration plugin, but none for the log manager. We should double check that we are not breaking any existing behaviour.

This is a good candidate for a Rust integration test, which I'll add for this PR.

Also, shouldn't we also be doing the same handling for the configuration manager?

We probably should. I'll update the configuration manager as well.

Comment on lines +77 to +95
let event = match notify_event.kind {
EventKind::Access(access_kind) => match access_kind {
AccessKind::Close(access_mode) => match access_mode {
AccessMode::Any | AccessMode::Other | AccessMode::Write => {
Some(FsEvent::Modified)
}
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is the branch that allows us to only listen to FsEvent::Modified. The actual sequence returned by lower-level notify-debouncer-full is:

[crates/common/tedge_utils/src/notify.rs:77] &notify_event = DebouncedEvent {
    event: Event {
        kind: Create(
            File,
        ),
        paths: [
            "/etc/tedge/plugins/tedge-log-plugin.toml",
        ],
        attr:tracker: None,
        attr:flag: None,
        attr:info: None,
        attr:source: None,
    },
    time: Instant {
        tv_sec: 23846,
        tv_nsec: 112231843,
    },
}
[crates/common/tedge_utils/src/notify.rs:77] &notify_event = DebouncedEvent {
    event: Event {
        kind: Access(
            Close(
                Write,
            ),
        ),
        paths: [
            "/etc/tedge/plugins/tedge-log-plugin.toml",
        ],
        attr:tracker: None,
        attr:flag: None,
        attr:info: None,
        attr:source: None,
    },
    time: Instant {
        tv_sec: 23846,
        tv_nsec: 112263954,
    },
}
[crates/common/tedge_utils/src/notify.rs:77] &notify_event = DebouncedEvent {
    event: Event {
        kind: Remove(
            File,
        ),
        paths: [
            "/etc/tedge/plugins/tedge-log-plugin.toml~",
        ],
        attr:tracker: None,
        attr:flag: None,
        attr:info: None,
        attr:source: None,
    },
    time: Instant {
        tv_sec: 23846,
        tv_nsec: 112322524,
    },
}

when saving the file with nvim, or:

[crates/common/tedge_utils/src/notify.rs:77] &notify_event = DebouncedEvent {
    event: Event {
        kind: Create(
            File,
        ),
        paths: [
            "/etc/tedge/plugins/tedge-log-plugin.toml",
        ],
        attr:tracker: None,
        attr:flag: None,
        attr:info: None,
        attr:source: None,
    },
    time: Instant {
        tv_sec: 23953,
        tv_nsec: 87955441,
    },
}
[crates/common/tedge_utils/src/notify.rs:77] &notify_event = DebouncedEvent {
    event: Event {
        kind: Access(
            Close(
                Write,
            ),
        ),
        paths: [
            "/etc/tedge/plugins/tedge-log-plugin.toml",
        ],
        attr:tracker: None,
        attr:flag: None,
        attr:info: None,
        attr:source: None,
    },
    time: Instant {
        tv_sec: 23953,
        tv_nsec: 87977201,
    },
}

when file is copied. Picking up AccessKind::Close(AccessMode::Write) allows us to reload appropriately.

Copy link
Contributor

@didier-wenzek didier-wenzek left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Approved. The code is clear and correct. Using notify-debouncer-full was a great idea!

crates/common/tedge_utils/src/notify.rs Outdated Show resolved Hide resolved
@didier-wenzek
Copy link
Contributor

Are we also sure that this change does not affect replacing existing files using mv and cp?

This is working as expected.

Copy link
Contributor

@albinsuresh albinsuresh left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM.

@Bravo555 Bravo555 changed the title Stop duplicate messages being sent by tedge-log-plugin on file reload Stop duplicate messages being sent by tedge-log-plugin and tedge-configuration-plugin on file reload Nov 16, 2023
@Bravo555 Bravo555 force-pushed the fix/2451/log-upload-metadata-duplicates branch from 4568fe4 to e6c2dca Compare November 16, 2023 12:36
@Bravo555 Bravo555 force-pushed the fix/2451/log-upload-metadata-duplicates branch from e6c2dca to 7b8a913 Compare November 16, 2023 15:25
@Bravo555
Copy link
Contributor Author

This is a good candidate for a Rust integration test, which I'll add for this PR.

Instead of doing integration tests for both tedge-log-plugin and tedge-configuration-plugin, I've decided to only add 1 unit test: notify::tests::modify_emitted_for_move_copy_create_delete that checks if FsEvent::Modified is emitted when the file is modified, deleted, created, or renamed.

To add relevant tests for both plugins, I'd need to rewrite the plugins themselves a little bit, and we're currently more pressed for other stuff, so that should be sufficient for now.

Copy link
Contributor

@albinsuresh albinsuresh left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Some queries to better understand the test logic.

crates/common/tedge_utils/src/notify.rs Show resolved Hide resolved
crates/common/tedge_utils/src/notify.rs Outdated Show resolved Hide resolved
crates/common/tedge_utils/src/notify.rs Show resolved Hide resolved
@Bravo555 Bravo555 force-pushed the fix/2451/log-upload-metadata-duplicates branch from 406031b to 7e339d9 Compare November 17, 2023 12:08
This commit adds debouncing of the `NotifyStream` events via the
`notify-debouncer-full` crate. The debouncing window is configured as
50ms, leading to sending of `FsEvent` messages being delayed by that
amount and duplicate events within that window being merged, which
should reduce the number of duplicate messages.

The tests had to be altered to delay deleting files, as if a file was
created and deleted within the debounce window, the `FileCreated` and
`FileRemoved` events would not fire. Other parts of the system which
rely on fs events and also create and delete files quickly, not
anticipating the delay, could also exhibit similar problems if we're not
careful. FsEvents should not be relied on too much, as they can be
unreliable[1].

A new test was added that checks if creating, modifying, deleting, or
renaming a file causes `FsEvent::Modified` to be emitted. This event is
emitted so that it can be used by consumers which need to respond to
changes of the content of the type regardless if it was modified,
deleted, moved, etc.

Also, `notify` crate itself was upgraded to the latest version.

[1]: https://docs.rs/notify/latest/notify/#known-problems
`tedge-log-plugin` and `tedge-configuration-plugin` no longer respond to
`FsEvent::FileCreated` and only listen to `FsEvent::Modified` which is
guaranteed to be emitted if the content of the file changed, regardless
of the kind of the operation which led to this change.

As described in the comment, different editors handle editing files
differently, but only listening for modifications leads to only 1 reload
taking place with following editors i tested:
- nano
- vim
- neovim

Listening for file changes could be made more simple by using
`notify-debouncer-mini` instead, which doesn't emit precise types of
events, but only `Any` events, which only describe that there was a
change to the watched file/dir, and then it is up to the application to
scan the filesystem and perform necessary steps in reaction to that
change. For relevant plugins, that would be perfect, as the only thing
we need to know is if the file was changed, and then we always read the
file and publish the message. However, to keep our own `FsEvent` layer
working, which is also used by other components, this was not done, but
can be considered in the future, if we determine file events to be too
unreliable.
@Bravo555 Bravo555 force-pushed the fix/2451/log-upload-metadata-duplicates branch from 7e339d9 to 351e8b8 Compare November 17, 2023 12:15
@Bravo555 Bravo555 merged commit e2c667b into thin-edge:main Nov 20, 2023
18 checks passed
@Bravo555 Bravo555 deleted the fix/2451/log-upload-metadata-duplicates branch November 20, 2023 08:36
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

4 participants