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

bug: WRITE events are missed on Mac OS arm64 #6

Closed
saurori opened this issue Oct 14, 2022 · 8 comments · Fixed by #7
Closed

bug: WRITE events are missed on Mac OS arm64 #6

saurori opened this issue Oct 14, 2022 · 8 comments · Fixed by #7
Assignees
Labels
bug Something isn't working s: fixed was fixed or solution offered
Milestone

Comments

@saurori
Copy link

saurori commented Oct 14, 2022

Description

Description

On Mac OS arm64 (14" 2021 Macbook Pro, M1 Pro), fsnotify sends two events when a file changes: CHMOD and WRITE. When the first event CHMOD comes in, w.Remove(event.Name) and w.Add(event.Name) are called here. This causes the second WRITE event to sometimes not trigger a build (possibly some race condition). I am not sure what is causing this, and it is not clear why the Remove and Add is necessary on each event. If the Remove() and Add() lines are commented out, the build refreshes and works as expected when a file changes, every time.

Expected Behavior

build() is called every time a file changes.

Actual Behavior

When a file changes, only some times a build will trigger.

To Reproduce

  1. Create a new buffalo project with buffalo new
  2. Run buffalo dev
  3. Edit and save a file in actions/ multiple times and watch for rebuilds of the app.

Additional Context

Details

-> Go: Checking installation
✓ The `go` executable was found on your system at: /usr/local/go/bin/go

-> Go: Checking minimum version requirements
✓ Your version of Go, 1.18.7, meets the minimum requirements.

-> Go: Checking Package Management
✓ You are using Go Modules (`go`) for package management.

-> Go: Checking PATH
✓ Your PATH contains /Users/saurori/Documents/dev/bin.

-> Node: Checking installation
✓ The `node` executable was found on your system at: /opt/homebrew/bin/node

-> Node: Checking minimum version requirements
✓ Your version of Node, v18.10.0, meets the minimum requirements.

-> NPM: Checking installation
✓ The `npm` executable was found on your system at: /opt/homebrew/bin/npm

-> NPM: Checking minimum version requirements
✓ Your version of NPM, 8.19.2, meets the minimum requirements.

-> Yarn: Checking installation
✓ The `yarnpkg` executable was found on your system at: /opt/homebrew/bin/yarnpkg

-> Yarn: Checking minimum version requirements
✘ Your version of Yarn, 4.0.0-rc.25, does not meet the minimum requirements.

Minimum versions of Yarn are:

* >=1.12

For help setting up your Yarn environment please follow the instructions for you platform at:

https://yarnpkg.com/en/docs/install

-> PostgreSQL: Checking installation
✓ The `postgres` executable was found on your system at: /opt/homebrew/bin/postgres

-> PostgreSQL: Checking minimum version requirements
✓ Your version of PostgreSQL, 14.5.0, meets the minimum requirements.

-> MySQL: Checking installation
✘ The `mysql` executable could not be found on your system.
For help setting up your MySQL environment please follow the instructions for you platform at:

https://www.mysql.com/downloads/

-> SQLite3: Checking installation
✓ The `sqlite3` executable was found on your system at: /usr/bin/sqlite3

-> SQLite3: Checking minimum version requirements
✓ Your version of SQLite3, 3.37.0, meets the minimum requirements.

-> Cockroach: Checking installation
✘ The `cockroach` executable could not be found on your system.
For help setting up your Cockroach environment please follow the instructions for you platform at:

https://www.cockroachlabs.com/docs/stable/

-> Buffalo (CLI): Checking installation
✓ The `buffalo` executable was found on your system at: /Users/saurori/Documents/dev/bin/buffalo

-> Buffalo (CLI): Checking minimum version requirements
✓ Your version of Buffalo (CLI), v0.18.7, meets the minimum requirements.

-> Buffalo: Application Details
Pwd         /Users/saurori/Documents/dev/src/github.com/saurori/gobuffalo/coke
Root        /Users/saurori/Documents/dev/src/github.com/saurori/gobuffalo/coke
GoPath      /Users/saurori/Documents/dev
PackagePkg  coke
ActionsPkg  coke/actions
ModelsPkg   coke/models
GriftsPkg   coke/grifts
WithModules true
Name        coke
Bin         bin/coke
VCS         git
WithPop     true
WithSQLite  false
WithDep     false
WithWebpack true
WithNodeJs  true
WithYarn    true
WithDocker  true
WithGrifts  true
AsWeb       true
AsAPI       false
InApp       true
PackageJSON {map[build:webpack --mode production --progress dev:webpack --watch]}

-> Buffalo: config/buffalo-app.toml
name = "coke"
bin = "bin/coke"
vcs = "git"
with_pop = true
with_sqlite = false
with_dep = false
with_webpack = true
with_nodejs = true
with_yarn = true
with_docker = true
with_grifts = true
as_web = true
as_api = false

-> Buffalo: config/buffalo-plugins.toml
[[plugin]]
  binary = "buffalo-pop"
  go_get = "github.com/gobuffalo/buffalo-pop/v3@latest"

-> Buffalo: go.mod
module coke

go 1.17

require (
        github.com/gobuffalo/buffalo v1.0.1
        github.com/gobuffalo/buffalo-pop/v3 v3.0.6
        github.com/gobuffalo/envy v1.10.2
        github.com/gobuffalo/grift v1.5.2
        github.com/gobuffalo/mw-csrf v1.0.1
        github.com/gobuffalo/mw-forcessl v1.0.1
        github.com/gobuffalo/mw-i18n/v2 v2.0.2
        github.com/gobuffalo/mw-paramlogger v1.0.1
        github.com/gobuffalo/pop/v6 v6.0.8
        github.com/gobuffalo/suite/v4 v4.0.3
        github.com/unrolled/secure v1.13.0
)

require (
        github.com/BurntSushi/toml v1.2.0 // indirect
        github.com/Masterminds/semver/v3 v3.1.1 // indirect
        github.com/aymerick/douceur v0.2.0 // indirect
        github.com/davecgh/go-spew v1.1.1 // indirect
        github.com/dustin/go-humanize v1.0.0 // indirect
        github.com/fatih/color v1.13.0 // indirect
        github.com/fatih/structs v1.1.0 // indirect
        github.com/felixge/httpsnoop v1.0.3 // indirect
        github.com/fsnotify/fsnotify v1.6.0 // indirect
        github.com/go-sql-driver/mysql v1.6.0 // indirect
        github.com/gobuffalo/events v1.4.3 // indirect
        github.com/gobuffalo/fizz v1.14.4 // indirect
        github.com/gobuffalo/flect v0.3.0 // indirect
        github.com/gobuffalo/github_flavored_markdown v1.1.3 // indirect
        github.com/gobuffalo/helpers v0.6.7 // indirect
        github.com/gobuffalo/httptest v1.5.2 // indirect
        github.com/gobuffalo/logger v1.0.7 // indirect
        github.com/gobuffalo/meta v0.3.3 // indirect
        github.com/gobuffalo/nulls v0.4.2 // indirect
        github.com/gobuffalo/plush/v4 v4.1.16 // indirect
        github.com/gobuffalo/refresh v1.13.2 // indirect
        github.com/gobuffalo/tags/v3 v3.1.4 // indirect
        github.com/gobuffalo/validate/v3 v3.3.3 // indirect
        github.com/gofrs/uuid v4.3.0+incompatible // indirect
        github.com/gorilla/css v1.0.0 // indirect
        github.com/gorilla/handlers v1.5.1 // indirect
        github.com/gorilla/mux v1.8.0 // indirect
        github.com/gorilla/securecookie v1.1.1 // indirect
        github.com/gorilla/sessions v1.2.1 // indirect
        github.com/inconshreveable/mousetrap v1.0.1 // indirect
        github.com/jackc/chunkreader/v2 v2.0.1 // indirect
        github.com/jackc/pgconn v1.13.0 // indirect
        github.com/jackc/pgio v1.0.0 // indirect
        github.com/jackc/pgpassfile v1.0.0 // indirect
        github.com/jackc/pgproto3/v2 v2.3.1 // indirect
        github.com/jackc/pgservicefile v0.0.0-20200714003250-2b9c44734f2b // indirect
        github.com/jackc/pgtype v1.12.0 // indirect
        github.com/jackc/pgx/v4 v4.17.2 // indirect
        github.com/jmoiron/sqlx v1.3.5 // indirect
        github.com/joho/godotenv v1.4.0 // indirect
        github.com/kballard/go-shellquote v0.0.0-20180428030007-95032a82bc51 // indirect
        github.com/luna-duclos/instrumentedsql v1.1.3 // indirect
        github.com/mattn/go-colorable v0.1.13 // indirect
        github.com/mattn/go-isatty v0.0.16 // indirect
        github.com/mattn/go-sqlite3 v1.14.15 // indirect
        github.com/microcosm-cc/bluemonday v1.0.21 // indirect
        github.com/mitchellh/go-homedir v1.1.0 // indirect
        github.com/monoculum/formam v3.5.5+incompatible // indirect
        github.com/nicksnyder/go-i18n v1.10.1 // indirect
        github.com/pelletier/go-toml v1.9.5 // indirect
        github.com/pkg/errors v0.9.1 // indirect
        github.com/pmezard/go-difflib v1.0.0 // indirect
        github.com/rogpeppe/go-internal v1.9.0 // indirect
        github.com/sergi/go-diff v1.2.0 // indirect
        github.com/sirupsen/logrus v1.9.0 // indirect
        github.com/sourcegraph/annotate v0.0.0-20160123013949-f4cad6c6324d // indirect
        github.com/sourcegraph/syntaxhighlight v0.0.0-20170531221838-bd320f5d308e // indirect
        github.com/spf13/cobra v1.6.0 // indirect
        github.com/spf13/pflag v1.0.5 // indirect
        github.com/stretchr/testify v1.8.0 // indirect
        golang.org/x/crypto v0.0.0-20221012134737-56aed061732a // indirect
        golang.org/x/net v0.0.0-20221014081412-f15817d10f9b // indirect
        golang.org/x/sync v0.0.0-20220929204114-8fcdb60fdcc0 // indirect
        golang.org/x/sys v0.0.0-20221013171732-95e765b1cc43 // indirect
        golang.org/x/term v0.0.0-20220919170432-7a66f970e087 // indirect
        golang.org/x/text v0.3.8 // indirect
        gopkg.in/yaml.v2 v2.4.0 // indirect
        gopkg.in/yaml.v3 v3.0.1 // indirect
)
@sio4 sio4 self-assigned this Oct 15, 2022
@sio4 sio4 added the bug Something isn't working label Oct 15, 2022
@sio4
Copy link
Member

sio4 commented Oct 15, 2022

Actually, I can't confirm the behavior since I have no that machine but just tested it with my Linux box. With the current code, the event sequence is as the following:

When :w from vi, :wq from vi, and removed a file:

XXX watcher event: "actions/app.go": RENAME
buffalo: 2022/10/15 14:27:39 === Rebuild on: actions/app.go ===

XXX watcher event: "actions/app.go": RENAME
buffalo: 2022/10/15 14:27:51 === Rebuild on: actions/app.go ===
XXX watcher event: "actions/app.go": CHMOD
XXX watcher event: "actions/app.go": CHMOD

XXX watcher event: "actions/tester.go": REMOVE
buffalo: 2022/10/15 14:29:21 === Rebuild on: actions/tester.go ===

The sequence is mostly fine except why the event is not WRITE but RENAME. For the second test with :wq command, the additional CHMOD happens twice and was ignored.

When I removed those two lines (Remove() and Add()), the sequences are changed as the following:

When :w and :wq from vi, and removed a file:

XXX watcher event: "actions/app.go": RENAME
buffalo: 2022/10/15 14:22:47 === Rebuild on: actions/app.go ===
XXX watcher event: "actions/app.go": CHMOD
XXX watcher event: "actions/app.go": REMOVE

XXX watcher event: "actions/tester.go": REMOVE
buffalo: 2022/10/15 14:25:34 === Rebuild on: actions/tester.go ===

For some reason, an additional REMOVE event happened for all writing operations. I didn't check the details (about why RENAME instead of WRITE and why additional REMOVE happens) but currently it could be fine since the build() method has Once protection and it prevents additional build.

With this test, I guess the Remove() and Add() was added to prevent these additional events but not 100% sure since there is no commit history in the log. (However, as explained above, Once protection works properly so I think we can ignore those extra events even though they happen)

For the behavior on MacOS arm64, it seems like CHMOD comes before WRITE and some of them were missed by the timing of Remove and Add. I think it could be better we just remove these calls and just lean into the Once protection for now. (Or just prevent them for CHMOD cases)

Still, this is not a perfect solution but could be fine. Open for any opinions!

@sio4
Copy link
Member

sio4 commented Oct 15, 2022

Hi @saurori,

What do you think about this patch? Since we cannot be 100% sure of the side effects of Remove() and Add() even though it could be fine to remove them, I think this is better since we really ignore CHMOD for all actions on the event.

Once you confirm this approach on your OS and architecture, I will apply it to the next release soon.

--- a/refresh/manager.go
+++ b/refresh/manager.go
@@ -53,9 +53,9 @@ func (r *Manager) Start() error {
                                case event := <-w.Events():
                                        if event.Op != fsnotify.Chmod {
                                                go r.build(event)
+                                               w.Remove(event.Name)
+                                               w.Add(event.Name)
                                        }
-                                       w.Remove(event.Name)
-                                       w.Add(event.Name)
                                case <-r.context.Done():
                                        break LoopRebuilder
                                }

@sio4
Copy link
Member

sio4 commented Oct 15, 2022

Tested with vscode again. With vscode, the save operation made two WRITE events (could be affected by the other tools on save event). It seems like RENAME followed by CHMOD and REMOVE is the behavior of vim. Also, the test also shows a timing issue:

Mostly the second WRITE happens after build started but sometimes before that. However, it is the observation of logs so the real sequence could be different. Also even though I removed Remove() and Add(), it does not fully prevent the second WRITE. I think we can safely remove the Remove() and Add() calls.

XXX watcher event: "actions/app.go": WRITE true
buffalo: 2022/10/15 15:27:05 === Rebuild on: actions/app.go ===
XXX watcher event: "actions/app.go": WRITE true

XXX watcher event: "actions/app.go": WRITE true
XXX watcher event: "actions/app.go": WRITE true
buffalo: 2022/10/15 15:26:55 === Rebuild on: actions/app.go ===

The patch will be simply:

--- a/refresh/manager.go
+++ b/refresh/manager.go
@@ -54,8 +54,6 @@ func (r *Manager) Start() error {
                                        if event.Op != fsnotify.Chmod {
                                                go r.build(event)
                                        }
-                                       w.Remove(event.Name)
-                                       w.Add(event.Name)
                                case <-r.context.Done():
                                        break LoopRebuilder
                                }

@sio4
Copy link
Member

sio4 commented Oct 15, 2022

@saurori could you please check if #7 looks good?

@saurori
Copy link
Author

saurori commented Oct 15, 2022

@sio4 Looks good. I know it's difficult to test this since fsnotify has different implementations (kqueue, inotify, etc) across different OSs and architectures. Hopefully this works across all.

@saurori
Copy link
Author

saurori commented Nov 3, 2022

@sio4 Do you plan on releasing an updated cli version with this fix (updated go.mod dependency)? Otherwise the fix is not in the latest cli for use in buffalo dev.

@sio4
Copy link
Member

sio4 commented Nov 3, 2022

@sio4 Do you plan on releasing an updated cli version with this fix (updated go.mod dependency)? Otherwise the fix is not in the latest cli for use in buffalo dev.

Hi @saurori, I was not able to make enough time recently but just (partially) resumed working on releasing Pop, Core, and CLI one by one due to their dependency chain.
I guess it could be done within a week or slightly more. Thanks for your understanding.

@sio4
Copy link
Member

sio4 commented Jan 29, 2023

(It was applied and released as CLI v0.18.13)

@sio4 sio4 added the s: fixed was fixed or solution offered label Jan 29, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working s: fixed was fixed or solution offered
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants