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.

Sign up for GitHub

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

Jump to bottom

cmd/govim: watcher tests fails on macOS #759

Closed
leitzler opened this issue Feb 6, 2020 · 7 comments · Fixed by #760
Closed

cmd/govim: watcher tests fails on macOS #759

leitzler opened this issue Feb 6, 2020 · 7 comments · Fixed by #760
Labels
bug Something isn't working testing Testing

Comments

@leitzler
Copy link
Member

leitzler commented Feb 6, 2020

What version of Vim/Gvim are you using?

Vim/Gvim version
$ vim --version
VIM - Vi IMproved 8.2 (2019 Dec 12, compiled Jan 12 2020 10:35:50)
macOS version
Included patches: 1-111
Compiled by pontus@MacBook-Pro.localdomain

What version of Go are you using (go version)?

$ go version
go version go1.13.5 darwin/amd64

What operating system and processor architecture are you using (go env)?

go env Output
$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/pontus/Library/Caches/go-build"
GOENV="/Users/pontus/Library/Application Support/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/pontus/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/darwin_amd64"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/Users/pontus/proj/govim/master/go.mod"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/xm/ls208xd174v95pgd20rn_qbh0000gn/T/go-build360468964=/tmp/go-build -gno-record-gcc-switches -fno-common"

What version/commit of govim are you using?

Current master, 897d5a4

What did you do?

VIM_FLAVOR=vim go test . in cmd/govim

What did you expect to see?

No failures

What did you see instead?

--- FAIL: TestScripts (10.46s)
    main_test.go:77: using gopls at "/var/folders/xm/ls208xd174v95pgd20rn_qbh0000gn/T/gobin-gopls-installdir034342552/gopls"
    --- FAIL: TestScripts/scenario_default (0.00s)
        --- FAIL: TestScripts/scenario_default/watcher (30.96s)
            testscript.go:348:
                # Test that the file watcher picks up file changes that occurs outside the editor
                # New file in the same package (29.583s)
                > vim ex 'e main.go'
                > cp const.go.orig const.go
                > errlogmatch '&protocol\.DidChangeWatchedFilesParams\{\n\S+:\s+Changes: \{\n\S+:\s+\{URI:"file://'$WORK/const.go'", Type:1\}'
                FAIL: testdata/scenario_default/watcher.txt:6: errlogmatch failed to find match

        --- FAIL: TestScripts/scenario_default/complete_watched (30.56s)
            testscript.go:348:
                # Test that ominfunc complete works where the completion is made
                # available in a file that is not loaded via the editor. (29.616s)
                > vim ex 'e main.go'
                > cp const.go.orig const.go
                > errlogmatch '&protocol\.DidChangeWatchedFilesParams\{\n\S+:\s+Changes: \{\n\S+:\s+\{URI:"file://'$WORK/const.go'", Type:1\}'
                FAIL: testdata/scenario_default/complete_watched.txt:6: errlogmatch failed to find match
@leitzler
Copy link
Member Author

leitzler commented Feb 6, 2020

TestScripts/scenario_default/watcher log:

2020-02-06T06:51:24.390516_#1: vim start =======================
2020-02-06T06:51:24.390516_#1: sendJSONMsg: [0,[49,"ex","e main.go"]]
2020-02-06T06:51:24.390516_#1: vim end =======================
2020-02-06T06:51:24.391941_#1: vim start =======================
2020-02-06T06:51:24.391941_#1: recvJSONMsg: [50] ["function","autocommand:0",[1]]
2020-02-06T06:51:24.391941_#1: vim end =======================
2020-02-06T06:51:24.392046_#1: run: waiting to read a JSON message
2020-02-06T06:51:24.392144_#1: vim start =======================
2020-02-06T06:51:24.392144_#1: sendJSONMsg: [50,["",null]]
2020-02-06T06:51:24.392144_#1: vim end =======================
2020-02-06T06:51:24.401106_#1: vim start =======================
2020-02-06T06:51:24.401106_#1: recvJSONMsg: [51] ["function","autocommand:1",[{"Num":1,"Name":"/private/var/folders/xm/ls208xd174v95pgd20rn_qbh0000gn/T/go-test-script543995856/script-watcher/main.go","Loaded":1,"Contents":"package main\n\nimport \"fmt\"\n\nfunc main() {\n\tfmt.Println()\n}\n"}]]
2020-02-06T06:51:24.401106_#1: vim end =======================
2020-02-06T06:51:24.401228_#1: run: waiting to read a JSON message
2020-02-06T06:51:24.401436_#1: vim start =======================
2020-02-06T06:51:24.401436_#1: sendJSONMsg: [0,[50,"call","listener_add","GOVIM_internal_EnrichDelta",1]]
2020-02-06T06:51:24.401436_#1: vim end =======================
2020-02-06T06:51:24.401918_#1: vim start =======================
2020-02-06T06:51:24.401918_#1: recvJSONMsg: [52] ["callback",50,["",1]]
2020-02-06T06:51:24.401918_#1: vim end =======================
2020-02-06T06:51:24.401975_#1: run: waiting to read a JSON message
2020-02-06T06:51:24.402037_#1: vim start =======================
2020-02-06T06:51:24.402037_#1: sendJSONMsg: [0,[51,"call","s:batchCall",[["call","s:mustBeZero","sign_unplace","govim"]]]]
2020-02-06T06:51:24.402037_#1: vim end =======================
2020-02-06T06:51:24.402590_#1: vim start =======================
2020-02-06T06:51:24.402590_#1: recvJSONMsg: [53] ["callback",51,["",[0]]]
2020-02-06T06:51:24.402590_#1: vim end =======================
2020-02-06T06:51:24.402638_#1: run: waiting to read a JSON message
2020-02-06T06:51:24.402782_#1: vim start =======================
2020-02-06T06:51:24.402782_#1: sendJSONMsg: [0,[52,"call","s:batchCall",[["call","s:mustNothing","prop_remove",{"id":0,"bufnr":1,"all":1}]]]]
2020-02-06T06:51:24.402782_#1: vim end =======================
2020-02-06T06:51:24.403278_#1: vim start =======================
2020-02-06T06:51:24.403278_#1: recvJSONMsg: [54] ["callback",52,["",[0]]]
2020-02-06T06:51:24.403278_#1: vim end =======================
2020-02-06T06:51:24.403316_#1: run: waiting to read a JSON message
2020-02-06T06:51:24.403561_#1: gopls server start =======================
2020-02-06T06:51:24.403561_#1: gopls.DidOpen() call; params:
2020-02-06T06:51:24.403561_#1: &protocol.DidOpenTextDocumentParams{
2020-02-06T06:51:24.403561_#1:     TextDocument: protocol.TextDocumentItem{URI:"file:///private/var/folders/xm/ls208xd174v95pgd20rn_qbh0000gn/T/go-test-script543995856/script-watcher/main.go", LanguageID:"go", Version:1, Text:"package main\n\nimport \"fmt\"\n\nfunc main() {\n\tfmt.Println()\n}\n"},
2020-02-06T06:51:24.403561_#1: }
2020-02-06T06:51:24.403561_#1: gopls server end =======================
2020-02-06T06:51:24.403693_#1: gopls server start =======================
2020-02-06T06:51:24.403693_#1: gopls.DidOpen() return; err: <nil>
2020-02-06T06:51:24.403693_#1: gopls server end =======================
2020-02-06T06:51:24.403721_#1: vim start =======================
2020-02-06T06:51:24.403721_#1: sendJSONMsg: [51,["",null]]
2020-02-06T06:51:24.403721_#1: vim end =======================
2020-02-06T06:51:24.411113_#1: vim start =======================
2020-02-06T06:51:24.411113_#1: recvJSONMsg: [55] ["callback",49,[""]]
2020-02-06T06:51:24.411113_#1: vim end =======================
2020-02-06T06:51:24.411172_#1: run: waiting to read a JSON message
2020-02-06T06:51:24.411259_#1: vim start =======================
2020-02-06T06:51:24.411259_#1: sendJSONMsg: [49,["",""]]
2020-02-06T06:51:24.411259_#1: vim end =======================
2020-02-06T06:51:24.411598_#1: vim start =======================
2020-02-06T06:51:24.411598_#1: recvJSONMsg: [56] ["callback",48,["",0]]
2020-02-06T06:51:24.411598_#1: vim end =======================
2020-02-06T06:51:24.411739_#1: run: waiting to read a JSON message
2020-02-06T06:51:24.571545_#1: gopls server start =======================
2020-02-06T06:51:24.571545_#1: gopls.DidChangeWatchedFiles() call; params:
2020-02-06T06:51:24.571545_#1: &protocol.DidChangeWatchedFilesParams{
2020-02-06T06:51:24.571545_#1:     Changes: {
2020-02-06T06:51:24.571545_#1:         {URI:"file:///private/var/folders/xm/ls208xd174v95pgd20rn_qbh0000gn/T/go-test-script543995856/script-watcher/const.go", Type:2},
2020-02-06T06:51:24.571545_#1:     },
2020-02-06T06:51:24.571545_#1: }
2020-02-06T06:51:24.571545_#1: gopls server end =======================
2020-02-06T06:51:24.571752_#1: gopls server start =======================
2020-02-06T06:51:24.571752_#1: gopls.DidChangeWatchedFiles() return; err: <nil>
2020-02-06T06:51:24.571752_#1: gopls server end =======================
2020-02-06T06:51:24.571789_#1: handleEvent: handled {/private/var/folders/xm/ls208xd174v95pgd20rn_qbh0000gn/T/go-test-script543995856/script-watcher/const.go changed}
2020-02-06T06:51:24.696139_#1: gopls client start =======================
2020-02-06T06:51:24.696139_#1: LogMessage callback: &protocol.LogMessageParams{Type:3, Message:"2020/02/06 06:51:24 go/packages.Load\n\tsnapshot = 0\n\tquery = [./... builtin]\n\tpackages = 2"}
2020-02-06T06:51:24.696139_#1: gopls client end =======================
TestScripts/scenario_default/complete_watched log: 
2020-02-06T07:04:47.405168_#1: vim start =======================
2020-02-06T07:04:47.405168_#1: sendJSONMsg: [0,[49,"ex","e main.go"]]
2020-02-06T07:04:47.405168_#1: vim end =======================
2020-02-06T07:04:47.405972_#1: vim start =======================
2020-02-06T07:04:47.405972_#1: recvJSONMsg: [50] ["function","autocommand:0",[1]]
2020-02-06T07:04:47.405972_#1: vim end =======================
2020-02-06T07:04:47.406029_#1: run: waiting to read a JSON message
2020-02-06T07:04:47.406110_#1: vim start =======================
2020-02-06T07:04:47.406110_#1: sendJSONMsg: [50,["",null]]
2020-02-06T07:04:47.406110_#1: vim end =======================
2020-02-06T07:04:47.412608_#1: vim start =======================
2020-02-06T07:04:47.412608_#1: recvJSONMsg: [51] ["function","autocommand:1",[{"Num":1,"Name":"/private/var/folders/xm/ls208xd174v95pgd20rn_qbh0000gn/T/go-test-script271676516/script-complete_watched/main.go","Loaded":1,"Contents":"package main\n\nimport \"fmt\"\n\nfunc main() {\n\tfmt.Println()\n}\n"}]]
2020-02-06T07:04:47.412608_#1: vim end =======================
2020-02-06T07:04:47.412664_#1: run: waiting to read a JSON message
2020-02-06T07:04:47.412864_#1: vim start =======================
2020-02-06T07:04:47.412864_#1: sendJSONMsg: [0,[50,"call","listener_add","GOVIM_internal_EnrichDelta",1]]
2020-02-06T07:04:47.412864_#1: vim end =======================
2020-02-06T07:04:47.413196_#1: vim start =======================
2020-02-06T07:04:47.413196_#1: recvJSONMsg: [52] ["callback",50,["",1]]
2020-02-06T07:04:47.413196_#1: vim end =======================
2020-02-06T07:04:47.413244_#1: run: waiting to read a JSON message
2020-02-06T07:04:47.413298_#1: vim start =======================
2020-02-06T07:04:47.413298_#1: sendJSONMsg: [0,[51,"call","s:batchCall",[["call","s:mustBeZero","sign_unplace","govim"]]]]
2020-02-06T07:04:47.413298_#1: vim end =======================
2020-02-06T07:04:47.413711_#1: vim start =======================
2020-02-06T07:04:47.413711_#1: recvJSONMsg: [53] ["callback",51,["",[0]]]
2020-02-06T07:04:47.413711_#1: vim end =======================
2020-02-06T07:04:47.413758_#1: run: waiting to read a JSON message
2020-02-06T07:04:47.413875_#1: vim start =======================
2020-02-06T07:04:47.413875_#1: sendJSONMsg: [0,[52,"call","s:batchCall",[["call","s:mustNothing","prop_remove",{"id":0,"bufnr":1,"all":1}]]]]
2020-02-06T07:04:47.413875_#1: vim end =======================
2020-02-06T07:04:47.414349_#1: vim start =======================
2020-02-06T07:04:47.414349_#1: recvJSONMsg: [54] ["callback",52,["",[0]]]
2020-02-06T07:04:47.414349_#1: vim end =======================
2020-02-06T07:04:47.414402_#1: run: waiting to read a JSON message
2020-02-06T07:04:47.414528_#1: gopls server start =======================
2020-02-06T07:04:47.414528_#1: gopls.DidOpen() call; params:
2020-02-06T07:04:47.414528_#1: &protocol.DidOpenTextDocumentParams{
2020-02-06T07:04:47.414528_#1:     TextDocument: protocol.TextDocumentItem{URI:"file:///private/var/folders/xm/ls208xd174v95pgd20rn_qbh0000gn/T/go-test-script271676516/script-complete_watched/main.go", LanguageID:"go", Version:1, Text:"package main\n\nimport \"fmt\"\n\nfunc main() {\n\tfmt.Println()\n}\n"},
2020-02-06T07:04:47.414528_#1: }
2020-02-06T07:04:47.414528_#1: gopls server end =======================
2020-02-06T07:04:47.414632_#1: gopls server start =======================
2020-02-06T07:04:47.414632_#1: gopls.DidOpen() return; err: <nil>
2020-02-06T07:04:47.414632_#1: gopls server end =======================
2020-02-06T07:04:47.414651_#1: vim start =======================
2020-02-06T07:04:47.414651_#1: sendJSONMsg: [51,["",null]]
2020-02-06T07:04:47.414651_#1: vim end =======================
2020-02-06T07:04:47.418746_#1: vim start =======================
2020-02-06T07:04:47.418746_#1: recvJSONMsg: [55] ["callback",49,[""]]
2020-02-06T07:04:47.418746_#1: vim end =======================
2020-02-06T07:04:47.418800_#1: run: waiting to read a JSON message
2020-02-06T07:04:47.418836_#1: vim start =======================
2020-02-06T07:04:47.418836_#1: sendJSONMsg: [49,["",""]]
2020-02-06T07:04:47.418836_#1: vim end =======================
2020-02-06T07:04:47.419058_#1: vim start =======================
2020-02-06T07:04:47.419058_#1: recvJSONMsg: [56] ["callback",48,["",0]]
2020-02-06T07:04:47.419058_#1: vim end =======================
2020-02-06T07:04:47.419092_#1: run: waiting to read a JSON message
2020-02-06T07:04:47.593264_#1: gopls server start =======================
2020-02-06T07:04:47.593264_#1: gopls.DidChangeWatchedFiles() call; params:
2020-02-06T07:04:47.593264_#1: &protocol.DidChangeWatchedFilesParams{
2020-02-06T07:04:47.593264_#1:     Changes: {
2020-02-06T07:04:47.593264_#1:         {URI:"file:///private/var/folders/xm/ls208xd174v95pgd20rn_qbh0000gn/T/go-test-script271676516/script-complete_watched/const.go", Type:2},
2020-02-06T07:04:47.593264_#1:     },
2020-02-06T07:04:47.593264_#1: }
2020-02-06T07:04:47.593264_#1: gopls server end =======================
2020-02-06T07:04:47.593444_#1: gopls server start =======================
2020-02-06T07:04:47.593444_#1: gopls.DidChangeWatchedFiles() return; err: <nil>
2020-02-06T07:04:47.593444_#1: gopls server end =======================
2020-02-06T07:04:47.593477_#1: handleEvent: handled {/private/var/folders/xm/ls208xd174v95pgd20rn_qbh0000gn/T/go-test-script271676516/script-complete_watched/const.go changed}
2020-02-06T07:04:47.714970_#1: gopls client start =======================
2020-02-06T07:04:47.714970_#1: LogMessage callback: &protocol.LogMessageParams{Type:3, Message:"2020/02/06 07:04:47 go/packages.Load\n\tsnapshot = 0\n\tquery = [./... builtin]\n\tpackages = 2"}
2020-02-06T07:04:47.714970_#1: gopls client end =======================

@leitzler leitzler added bug Something isn't working testing Testing labels Feb 6, 2020
@findleyr
Copy link
Contributor

findleyr commented Feb 6, 2020

In case it's not clear, the bug is that the const.go event is 'Changed', not 'Created'.

I don't have access to a Mac at the moment, so this is a shot in the dark: is it possible that the fsevent matches BOTH fChanged and fCreated, here?
https://github.com/govim/govim/blob/master/cmd/govim/internal/fswatcher/os_darwin.go#L75

@findleyr
Copy link
Contributor

findleyr commented Feb 6, 2020

FWIW, I just checked and the event type doesn't currently matter to gopls, so at least for now I believe this bug to be only affecting testing.

@leitzler
Copy link
Member Author

leitzler commented Feb 6, 2020

I don't have access to a Mac at the moment, so this is a shot in the dark: is it possible that the fsevent matches BOTH fChanged and fCreated, here?

Thanks for taking a look!
I just ran a quick test and it do indeed have both flags set.

I'll create a PR later tonight unless someone else beats me to it.

leitzler added a commit that referenced this issue Feb 6, 2020
@leitzler
cmd/govim: fix darwin file system watcher event check
5168d27 
Darwin has a separate file system watcher, and it might emit events
that includes both "Created" and "Changed" flag in the same event.

Since the flag "checked" is checked before "created", the darwin
implementation will skip to report "created" if both files exist.
It looks like it only affects tests at the moment (see comments
in #759).

This fix alters order so that only "created" is reported if both
flags exist.

Fixes #759
@leitzler leitzler mentioned this issue Feb 6, 2020
Merged
@leitzler
Copy link
Member Author

leitzler commented Feb 6, 2020

@findleyr If I understand it correctly, the correct way would be to report created instead of changed if both is set, right? Since a creation is a change implicitly, and the file can't change between those "events" anyway.

@findleyr
Copy link
Contributor

findleyr commented Feb 6, 2020

@leitzler I'm not that familiar with fsevents, but yes in this case I think we should just be sending created. That's consistent with the behavior on other operating systems.

I'd be curious to know whether it is the fsevents.ItemModified or fsevents.ItemChangeOwner bit that is causing us to match the fChanged mask.

@leitzler
Copy link
Member Author

leitzler commented Feb 6, 2020

Had the flag in my scroll back from the quick test, and it looks like it was ItemCreated, ItemModified & ItemIsFile.

leitzler added a commit that referenced this issue Feb 7, 2020
@leitzler
cmd/govim: fix darwin file system watcher event check (#760)
5cfafa0 
Darwin has a separate file system watcher, and it might emit events
that includes both "Created" and "Changed" flag in the same event.

Since the flag "checked" is checked before "created", the darwin
implementation will skip to report "created" if both files exist.
It looks like it only affects tests at the moment (see comments
in #759).

This fix alters order so that only "created" is reported if both
flags exist.

Fixes #759
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working testing Testing
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

cmd/govim: fix darwin file system watcher event check govim/govim
2 participants
@leitzler @findleyr