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

Don't initialize plugins and user settings in tests #3220

Merged
merged 4 commits into from
Apr 5, 2024

Conversation

dmaluka
Copy link
Collaborator

@dmaluka dmaluka commented Mar 26, 2024

Adding InitRuntimeFiles() and InitPlugins() to buffer_test.go in PR #3062 (instead of just initializing runtime vars with empty values, as it was before) seems to cause sporadic failures of MacOS build tests on github, with crashes in various places but all beginning with lots of plugin failures:

2024/03/23 15:14:30 Plugin does not exist: autoclose at autoclose : &{autoclose autoclose <nil> [runtime/plugins/autoclose/autoclose.lua] false true}
2024/03/23 15:14:30 Plugin does not exist: comment at comment : &{comment comment <nil> [runtime/plugins/comment/comment.lua] false true}
2024/03/23 15:14:30 Plugin does not exist: diff at diff : &{diff diff <nil> [runtime/plugins/diff/diff.lua] false true}
2024/03/23 15:14:30 Plugin does not exist: ftoptions at ftoptions : &{ftoptions ftoptions <nil> [runtime/plugins/ftoptions/ftoptions.lua] false true}
...

I suppose tests should not rely on plugins, and more importantly, should not be affected by the contents of ~/.config/micro/ on the host.

@dmaluka
Copy link
Collaborator Author

dmaluka commented Mar 26, 2024

My bad that I suggested removing init() from rtfiles.go in #3062.

@JoeKar
Copy link
Collaborator

JoeKar commented Mar 26, 2024

I had already a bad feeling with the removal of init(), but tests have passed in the moment I changed it and also at the server.

I suppose tests should not rely on plugins, and more importantly, should not be affected by the contents of ~/.config/micro/ on the host.

But these are all internal/default plugins and I suppose it fails to load/initialize them.
From my perspective it shouldn't cause issues touching all the default plugins no matter if Linux, MacOS or Windows as test host is used. I'm afraid that we hide an issue in the productive or test code, which bites us in the future again.
Right now it would say that the tests are closer to the reality in the moment the buffer manipulations are done while the default plugins are loaded and active.

All logs end somehow with:

2024/03/26 19:04:44 Plugin does not exist: diff at diff : &{diff diff <nil> [runtime/plugins/diff/diff.lua] false true}
panic: runtime error: index out of range [3] with length 3

goroutine 60 [running]:
github.com/zyedidia/micro/v2/internal/buffer.(*LineArray).SetMatch(0xc000502d40?, 0x13ae900?, 0x0?)
	/Users/runner/work/micro/micro/internal/buffer/line_array.go:353 +0x13f
github.com/zyedidia/micro/v2/pkg/highlight.(*Highlighter).HighlightMatches(0xc00050feda?, {0x1595bd8, 0xc000234230}, 0xc000497f90?, 0x4)
	/Users/runner/work/micro/micro/pkg/highlight/highlighter.go:341 +0x66
github.com/zyedidia/micro/v2/internal/buffer.(*Buffer).UpdateRules.func1()
	/Users/runner/work/micro/micro/internal/buffer/buffer.go:920 +0x95
created by github.com/zyedidia/micro/v2/internal/buffer.(*Buffer).UpdateRules
	/Users/runner/work/micro/micro/internal/buffer/buffer.go:918 +0x57c
FAIL	github.com/zyedidia/micro/v2/internal/buffer	0.069s

The amount of goroutine is different like the test runtime, but every time it tells that the highlighter was invoked by UpdateRules(), which is most probably called by NewBufferFromString() from the testing code.
How does this fit together? 🤔

  • the runtime plugins can't be found
  • we've random and massive buffer creation (different buffer length) and destruction
  • async highlighting

The out of bounds access was equal with the same index. Unfortunately it doesn't exactly tell were...if it was the line count which changed in the meantime or what ever.

The MacOS build differs in the build arguments and one additional library loaded...

$ GOOS=darwin make build
GOOS=linux GOARCH=amd64 go generate ./runtime
go build -trimpath -ldflags "-s -w -X github.com/zyedidia/micro/v2/internal/util.Version=2.0.14-dev.111 -X github.com/zyedidia/micro/v2/internal/util.CommitHash=9eb93fc7 -X 'github.com/zyedidia/micro/v2/internal/util.CompileDate=March 26, 2024' " ./cmd/micro
go: downloading github.com/zyedidia/poller v1.0.1

...which is needed by the tcell fork (tscreen_darwin.go#L19-L36).

@dmaluka
Copy link
Collaborator Author

dmaluka commented Mar 27, 2024

Yeah, you are right, it would be good to find the root cause.

And yeah, internal plugins shouldn't cause issues. So it's probably a good idea to test with plugins loaded, at least in some tests...

All logs end somehow with:

2024/03/26 19:04:44 Plugin does not exist: diff at diff : &{diff diff <nil> [runtime/plugins/diff/diff.lua] false true}
panic: runtime error: index out of range [3] with length 3

FWIW, at least once I had a different runtime error (not an out-of-range access but an unlock of a not-locked mutex), but also somewhere in the highlighter accessing the line array:

fatal error: sync: unlock of unlocked mutex

goroutine 51 [running]:
sync.fatal({0x1478169?, 0x30?})
	/Users/runner/hostedtoolcache/go/1.19.13/x64/src/runtime/panic.go:1031 +0x1e
sync.(*Mutex).unlockSlow(0xc0004ea06c, 0xffffffff)
	/Users/runner/hostedtoolcache/go/1.19.13/x64/src/sync/mutex.go:229 +0x3c
sync.(*Mutex).Unlock(0xc00044a480?)
	/Users/runner/hostedtoolcache/go/1.19.13/x64/src/sync/mutex.go:223 +0x29
github.com/zyedidia/micro/v2/internal/buffer.(*LineArray).State(0xc000205f40?, 0x13aea00?)
	/Users/runner/work/micro/micro/internal/buffer/line_array.go:341 +0xfe
github.com/zyedidia/micro/v2/pkg/highlight.(*Highlighter).HighlightMatches(0xc0000358ca?, {0x1592118, 0xc0004e7e30}, 0xc00004cf90?, 0x4)
	/Users/runner/work/micro/micro/pkg/highlight/highlighter.go:335 +0x10e
github.com/zyedidia/micro/v2/internal/buffer.(*Buffer).UpdateRules.func1()
	/Users/runner/work/micro/micro/internal/buffer/buffer.go:920 +0x95
created by github.com/zyedidia/micro/v2/internal/buffer.(*Buffer).UpdateRules
	/Users/runner/work/micro/micro/internal/buffer/buffer.go:918 +0x57c

@dmaluka
Copy link
Collaborator Author

dmaluka commented Mar 27, 2024

Ok, the good news is that we can reproduce this locally. Just enter internal/buffer/ directory and run go test. You will see those Plugin does not exist errors (but the test result will be PASS). But if you run go test multiple times, after 10-20 attempts you will also reproduce those crashes with "index out of range" or "unlock of unlocked mutex".

And as I've found, these 2 problems (Plugin does not exist errors and crashes) are separate issues, not directly related to each other.

  • Plugin does not exist errors are triggered by your #3062 , specifically by adding config.InitPlugins() to buffer_test.go (as we've already been assuming), and are caused simply by the fact that plugins are initialized but not loaded. Adding config.LoadAllPlugins() to buffer_test.go "fixes" this problem.

However, it seems to me it's not a good idea to load plugins in buffer_test.go, because in buffer_test.go we don't properly initialize Lua. We only do ulua.L = lua.NewState() but we don't do the other stuff that init() in cmd/micro/initlua.go does. As a result, I guess, plugins will not be able to do anything correctly.

In order to initialize Lua correctly, it seems, we need to be inside cmd/micro/, so we cannot do it in buffer_test.go (or other tests, except micro_test.go), it seems.

So my current conclusion is that it's a good idea to do config.InitPlugins() in micro_test.go, but not in other tests.

  • The crashes ("index out of range" or "unlock of unlocked mutex"), on the other hand, are triggered by a combination of your #3062 (specifically by config.InitRuntimeFiles(), specifically RTSyntax* files) and my #3208. These crashes are observed independently of "Plugin does not exist" errors, and they are not observed before #3208. Apparently something's wrong with my implementation of header matches, I don't know what yet.

@JoeKar
Copy link
Collaborator

JoeKar commented Mar 27, 2024

However, it seems to me it's not a good idea to load plugins in buffer_test.go, because in buffer_test.go we don't properly initialize Lua. We only do ulua.L = lua.NewState() but we don't do the other stuff that init() in cmd/micro/initlua.go does. As a result, I guess, plugins will not be able to do anything correctly.

Ok, that is a good argument against using it there.
Unfortunately we don't do heavy buffer testing in micro_test.go, but that is probably bearable for the time being.

So my current conclusion is that it's a good idea to do config.InitPlugins() in micro_test.go, but not in other tests.

ACK

[...] are triggered by a combination of your #3062 (specifically by config.InitRuntimeFiles(), specifically RTSyntax* files) and my #3208.

I'll have a look at this too.

@JoeKar
Copy link
Collaborator

JoeKar commented Mar 27, 2024

Could it be possible that the current buffer under test is closed while to go routine at the end of UpdateRules() is still active?
-> a WaitQueue didn't solve that, so I assume it's unlikely.

Maybe it's much more trivial...
The LineArray isn't locked at modifications (deletions) and the async highlighter accesses lines while they're modified/deleted:

  • the plugin bug while testing increase the reproduction rate (at least for me, since it has impact at the runtime...maybe due to printing)
  • I added a mutex to the LineArray and performed 1k test runs in a row (with plugin bug present) without crash so far
    • I'll increase the amount and try again, while I'm AFK
    • unfortunately following test runs failed below 1k 😞

@dmaluka
Copy link
Collaborator Author

dmaluka commented Mar 27, 2024

The LineArray isn't locked at modifications (deletions) and the async highlighter accesses lines while they're modified/deleted

Yeah, and in particular, the problems that we are seeing are probably caused by deletion of lines: the number of lines changes (decreases), so lineNo in e.g. SetMatch() is bigger than the number of lines, so we get an index out of range error. Or in some cases, we get an unlock of unlocked mutex error instead, likely because the line has been deleted from the line array, but Go's bound checker hasn't detected that (since, AFAIK, Go doesn't really guarantee successful bounds checking when the array is being accessed simultaneously by different goroutines), so we try to unlock the deleted line's la.lines[lineN].lock mutex which is in an undefined state.

@dmaluka
Copy link
Collaborator Author

dmaluka commented Mar 28, 2024

BTW now it looks like #3208 per se is ok, it just (in combination with config.InitRuntimeFiles()) revealed the long existing race problem with highlighting, by enabling highlighting (namely, JSON highlighting) for lots of test buffers in buffer_generated_test.go, since those buffers match that infamous json header pattern ^\{$.

@JoeKar
Copy link
Collaborator

JoeKar commented Mar 28, 2024

Yeah, and in particular, the problems that we are seeing are probably caused by deletion of lines:

That's exactly what I meant. 😉
Unfortunately adding one more sync.Mutex to the whole LineArray and locking deleteLine()/deleteLines(), while the highlighting functions do the same (+ additional index boundary checks) doesn't seem to solve the problem.
Two times it failed in 9xx/1000, 2xx/1000...but one time it even completed 10k. 🤔
That is why I'm a bit puzzled right now.

Sadly I've no backtrace of these two failing tests, since I forwarded the test output to /dev/null in these runs. So it isn't excluded that we've to hunt at least one more race condition, independent of the line deletion.
I give it one more shot with 10k.

Performed:
for i in {1..10000}; do go test; if [[ $? != 0 ]]; then echo "FAILED: $i"; break; fi; done

Result:

fatal error: sync: unlock of unlocked mutex

goroutine 73 [running]:
sync.fatal({0x85dabe?, 0xc000584120?})
	/usr/lib/go-1.22/src/runtime/panic.go:1007 +0x18
sync.(*Mutex).unlockSlow(0xc0000e00ac, 0xffffffff)
	/usr/lib/go-1.22/src/sync/mutex.go:229 +0x35
sync.(*Mutex).Unlock(...)
	/usr/lib/go-1.22/src/sync/mutex.go:223
github.com/zyedidia/micro/v2/internal/buffer.(*LineArray).State(0xc0003a3b60, 0x2)
	/home/joeran/Tools/GitHub/micro/internal/buffer/line_array.go:351 +0x162
github.com/zyedidia/micro/v2/pkg/highlight.(*Highlighter).HighlightMatches(0xc000584120, {0x973b60, 0xc000002540}, 0x0?, 0x3)
	/home/joeran/Tools/GitHub/micro/pkg/highlight/highlighter.go:335 +0x104
github.com/zyedidia/micro/v2/internal/buffer.(*Buffer).UpdateRules.func1()
	/home/joeran/Tools/GitHub/micro/internal/buffer/buffer.go:920 +0x8d
created by github.com/zyedidia/micro/v2/internal/buffer.(*Buffer).UpdateRules in goroutine 43
	/home/joeran/Tools/GitHub/micro/internal/buffer/buffer.go:918 +0x15a5

goroutine 43 [sync.Mutex.Lock]:
sync.runtime_SemacquireMutex(0x74f875?, 0xa0?, 0x0?)
	/usr/lib/go-1.22/src/runtime/sema.go:77 +0x25
sync.(*Mutex).lockSlow(0xc0003a3b88)
	/usr/lib/go-1.22/src/sync/mutex.go:171 +0x15d
sync.(*Mutex).Lock(...)
	/usr/lib/go-1.22/src/sync/mutex.go:90
github.com/zyedidia/micro/v2/internal/buffer.(*LineArray).State(0xc0003a3b60, 0x0)
	/home/joeran/Tools/GitHub/micro/internal/buffer/line_array.go:344 +0x59
github.com/zyedidia/micro/v2/pkg/highlight.(*Highlighter).ReHighlightStates(0xc000584120, {0x973ba0, 0xc000281e00}, 0x6?)
	/home/joeran/Tools/GitHub/micro/pkg/highlight/highlighter.go:366 +0x18d
github.com/zyedidia/micro/v2/internal/buffer.(*SharedBuffer).MarkModified(0xc000281e00, 0x16?, 0x30?)
	/home/joeran/Tools/GitHub/micro/internal/buffer/buffer.go:155 +0x1b2
github.com/zyedidia/micro/v2/internal/buffer.(*SharedBuffer).insert(0xc000281e00, {0xc000585f80?, 0x10?}, {0xc000482650, 0x2, 0x8})
	/home/joeran/Tools/GitHub/micro/internal/buffer/buffer.go:135 +0x85
github.com/zyedidia/micro/v2/internal/buffer.ExecuteTextEvent(0x0?, 0xc000281e00)
	/home/joeran/Tools/GitHub/micro/internal/buffer/eventhandler.go:119 +0xfb
github.com/zyedidia/micro/v2/internal/buffer.(*EventHandler).Execute(0xc000523580, 0xc0003800b0)
	/home/joeran/Tools/GitHub/micro/internal/buffer/eventhandler.go:253 +0x1c6
github.com/zyedidia/micro/v2/internal/buffer.(*EventHandler).DoTextEvent(0xc000523580, 0xc0003800b0, 0x1)
	/home/joeran/Tools/GitHub/micro/internal/buffer/eventhandler.go:49 +0x4c
github.com/zyedidia/micro/v2/internal/buffer.(*EventHandler).InsertBytes(0xc000523580, {0xc000482648?, 0x2?}, {0xc000482650, 0x2, 0x8})
	/home/joeran/Tools/GitHub/micro/internal/buffer/eventhandler.go:201 +0x1d8
github.com/zyedidia/micro/v2/internal/buffer.(*EventHandler).Insert(...)
	/home/joeran/Tools/GitHub/micro/internal/buffer/eventhandler.go:186
github.com/zyedidia/micro/v2/internal/buffer.(*Buffer).Insert(0xc000002540, {0x7ceaa0?, 0x2?}, {0xc000482648?, 0x1?})
	/home/joeran/Tools/GitHub/micro/internal/buffer/buffer.go:496 +0xa6
github.com/zyedidia/micro/v2/internal/buffer.check(0xbd3060?, {0xc00042bf10, 0x5, 0x5}, {0xc00042be60, 0x2, 0xb57bd8?}, {0xc00042be20, 0x4, 0x4})
	/home/joeran/Tools/GitHub/micro/internal/buffer/buffer_test.go:67 +0x614
github.com/zyedidia/micro/v2/internal/buffer.TestReplacingNewlines1(0xc0001481a0?)
	/home/joeran/Tools/GitHub/micro/internal/buffer/buffer_generated_test.go:917 +0x266
testing.tRunner(0xc0001481a0, 0x8fbc60)
	/usr/lib/go-1.22/src/testing/testing.go:1689 +0xfb
created by testing.(*T).Run in goroutine 1
	/usr/lib/go-1.22/src/testing/testing.go:1742 +0x390
exit status 2
FAIL	github.com/zyedidia/micro/v2/internal/buffer	0.057s
FAILED: 1275

So now slightly different, it's the insert triggering the MarkModified(), triggering the ReHighlightStates(), while in parallel UpdateRules() triggered HighlightMatches().
Oh man, the whole LineArray manipulation approach needs (more) sync, otherwise there is no guarantee that the async highlighter will work at valid/existing lines.

It's a wonder, that it wasn't found so far.

@dmaluka
Copy link
Collaborator Author

dmaluka commented Mar 28, 2024

So now slightly different, it's the insert triggering the MarkModified()

Yeah, that explains it. The number of lines does not decrease, so lineNo is still valid, however lines are moved around within the line array, so what what we are thinking of as one line is now suddenly a different line, and its mutex is not locked.

So perhaps if you lock your per-buffer mutex during line insertions as well, perhaps you will not see a problem even after 100k runs...

However I think that still would not be enough. I think we should synchronize any operations that modify the buffer, i.e. even those that only modify the contents of a single line, without changing the number of lines or their order. If one goroutine reads a byte array which is being modified by another goroutine without synchronization, I think there is no guarantee that it will work correctly.

@dmaluka
Copy link
Collaborator Author

dmaluka commented Mar 28, 2024

BTW a couple of times I saw this test not crashing but just hanging. It was just stuck somewhere, without printing any errors.

@dmaluka
Copy link
Collaborator Author

dmaluka commented Mar 28, 2024

Oh man, the whole LineArray manipulation approach needs (more) sync, otherwise there is no guarantee that the async highlighter will work at valid/existing lines.

Yeah... Unless we wanna change the entire approach to highlighting (i.e. unless we wanna speed up highlighting not by running it in a background goroutine but in some other way), it seems we do need such a per-buffer mutex, and we should hold this mutex:

  • during any write access to the line array
  • during any read access to the line array done by a code running not in the main goroutine (at least it is the highlighter code, but maybe also something else, e.g. the asynchronous diffgutter code; need to look closer)

@dmaluka
Copy link
Collaborator Author

dmaluka commented Mar 28, 2024

But we should consider performance implications of such coarse-grained locking. Luckily, buffer_test.go already appears to include some benchmarks, so we can just try to use them to estimate the performance impact.

@dmaluka
Copy link
Collaborator Author

dmaluka commented Mar 28, 2024

And for the future, all this suggests that doing InitRuntimeFiles() in buffer_test.go is a good idea, to catch such issues earlier. But it should probably be done in a safer way, like it is done in micro_test.go: use a custom ConfigDir which is guaranteed be empty, instead of using whatever is in ~/.config/micro/ on the test machine.

EDIT: or alternatively, instead of creating a temporary empty config dir, just add a parameter to InitRuntimeFiles() to skip user's custom files.

@JoeKar
Copy link
Collaborator

JoeKar commented Mar 28, 2024

I prepared something to start with the lock on per buffer level:

diff --git a/internal/buffer/buffer.go b/internal/buffer/buffer.go
index 35e650fd..2e43dcd0 100644
--- a/internal/buffer/buffer.go
+++ b/internal/buffer/buffer.go
@@ -74,6 +74,8 @@ var (
 // that have the same file open
 type SharedBuffer struct {
 	*LineArray
+	lock sync.Mutex
+
 	// Stores the last modification time of the file the buffer is pointing to
 	ModTime time.Time
 	// Type of the buffer (e.g. help, raw, scratch etc..)
@@ -127,6 +129,8 @@ type SharedBuffer struct {
 }
 
 func (b *SharedBuffer) insert(pos Loc, value []byte) {
+	b.lock.Lock()
+	defer b.lock.Unlock()
 	b.isModified = true
 	b.HasSuggestions = false
 	b.LineArray.insert(pos, value)
@@ -135,6 +139,8 @@ func (b *SharedBuffer) insert(pos Loc, value []byte) {
 	b.MarkModified(pos.Y, pos.Y+inslines)
 }
 func (b *SharedBuffer) remove(start, end Loc) []byte {
+	b.lock.Lock()
+	defer b.lock.Unlock()
 	b.isModified = true
 	b.HasSuggestions = false
 	defer b.MarkModified(start.Y, end.Y)
@@ -618,6 +624,8 @@ func (b *Buffer) WordAt(loc Loc) []byte {
 // Modified returns if this buffer has been modified since
 // being opened
 func (b *Buffer) Modified() bool {
+	b.lock.Lock()
+	defer b.lock.Unlock()
 	if b.Type.Scratch {
 		return false
 	}
@@ -634,6 +642,8 @@ func (b *Buffer) Modified() bool {
 
 // Size returns the number of bytes in the current buffer
 func (b *Buffer) Size() int {
+	b.lock.Lock()
+	defer b.lock.Unlock()
 	nb := 0
 	for i := 0; i < b.LinesNum(); i++ {
 		nb += len(b.LineBytes(i))
@@ -916,8 +926,10 @@ func (b *Buffer) UpdateRules() {
 		b.Highlighter = highlight.NewHighlighter(b.SyntaxDef)
 		if b.Settings["syntax"].(bool) {
 			go func() {
+				b.lock.Lock()
 				b.Highlighter.HighlightStates(b)
 				b.Highlighter.HighlightMatches(b, 0, b.End().Y)
+				b.lock.Unlock()
 				screen.Redraw()
 			}()
 		}
@@ -926,6 +938,8 @@ func (b *Buffer) UpdateRules() {
 
 // ClearMatches clears all of the syntax highlighting for the buffer
 func (b *Buffer) ClearMatches() {
+	b.lock.Lock()
+	defer b.lock.Unlock()
 	for i := range b.lines {
 		b.SetMatch(i, nil)
 		b.SetState(i, nil)
@@ -1041,6 +1055,8 @@ func (b *Buffer) ClearCursors() {
 
 // MoveLinesUp moves the range of lines up one row
 func (b *Buffer) MoveLinesUp(start int, end int) {
+	b.lock.Lock()
+	defer b.lock.Unlock()
 	if start < 1 || start >= end || end > len(b.lines) {
 		return
 	}
@@ -1066,6 +1082,8 @@ func (b *Buffer) MoveLinesUp(start int, end int) {
 
 // MoveLinesDown moves the range of lines down one row
 func (b *Buffer) MoveLinesDown(start int, end int) {
+	b.lock.Lock()
+	defer b.lock.Unlock()
 	if start < 0 || start >= end || end >= len(b.lines) {
 		return
 	}
@@ -1095,6 +1113,8 @@ var BracePairs = [][2]rune{
 // if the boolean returned is true then the original matching brace is one character left
 // of the starting location
 func (b *Buffer) FindMatchingBrace(braceType [2]rune, start Loc) (Loc, bool, bool) {
+	b.lock.Lock()
+	defer b.lock.Unlock()
 	curLine := []rune(string(b.LineBytes(start.Y)))
 	startChar := ' '
 	if start.X >= 0 && start.X < len(curLine) {
@@ -1163,6 +1183,8 @@ func (b *Buffer) FindMatchingBrace(braceType [2]rune, start Loc) (Loc, bool, boo
 
 // Retab changes all tabs to spaces or vice versa
 func (b *Buffer) Retab() {
+	b.lock.Lock()
+	defer b.lock.Unlock()
 	toSpaces := b.Settings["tabstospaces"].(bool)
 	tabsize := util.IntOpt(b.Settings["tabsize"])
 	dirty := false
@@ -1215,10 +1237,14 @@ func ParseCursorLocation(cursorPositions []string) (Loc, error) {
 
 // Line returns the string representation of the given line number
 func (b *Buffer) Line(i int) string {
+	b.lock.Lock()
+	defer b.lock.Unlock()
 	return string(b.LineBytes(i))
 }
 
 func (b *Buffer) Write(bytes []byte) (n int, err error) {
+	b.lock.Lock()
+	defer b.lock.Unlock()
 	b.EventHandler.InsertBytes(b.End(), bytes)
 	return len(bytes), nil
 }
@@ -1356,6 +1382,8 @@ func (b *Buffer) FindNextDiffLine(startLine int, forward bool) (int, error) {
 // SearchMatch returns true if the given location is within a match of the last search.
 // It is used for search highlighting
 func (b *Buffer) SearchMatch(pos Loc) bool {
+	b.lock.Lock()
+	defer b.lock.Unlock()
 	return b.LineArray.SearchMatch(b, pos)
 }
 

From my point of view the per line locks in the line_array.go aren't needed any longer and I currently test with their removal.
Maybe I've overseen something, especially calls like w.Buf.Match(bloc.Y)[bloc.X] from within the bufwindow.go, which maybe should be wrapped like SearchMatch(), to properly lock.

PS:
Crap, that these code blocks don't receive a scrollbar in the moment the length exceeds a certain limit.

@JoeKar
Copy link
Collaborator

JoeKar commented Mar 28, 2024

So, 10k now passed.

In the moment you wrote about the per-buffer lock did you mean the line_array itself, or the buffer managing the line_array?
The downside of my current approach is that it superfluous the highlighter go routine, since no modifications are possible as long as the routine holds the lock and it doesn't even display the content. I suppose it's then better to be done in the line_array.

@dmaluka
Copy link
Collaborator Author

dmaluka commented Mar 28, 2024

In the moment you wrote about the per-buffer lock did you mean the line_array itself, or the buffer managing the line_array? The downside of my current approach is that it superfluous the highlighter go routine, since no modifications are possible as long as the routine holds the lock and it doesn't even display the content. I suppose it's then better to be done in the line_array.

Yes, that's exactly what I was going to say in a reply to your previous comment. I said "per-buffer lock" as a figure of speech (to contrast it with a per-line lock), I actually meant a per-linearray lock. There are quite a few reasons why this lock should be in LineArray, and probably no reason why it should be in (Shared)Buffer.

From my point of view the per line locks in the line_array.go aren't needed any longer and I currently test with their removal.

Yep, I also think so.

@JoeKar
Copy link
Collaborator

JoeKar commented Mar 28, 2024

I said "per-buffer lock" as a figure of speech (to contrast it with a per-line lock), I actually meant a per-linearray lock.

I wasn't asking for the per-line lock, just the layer of "per-buffer", but it's clear now.

There are quite a few reasons why this lock should be in LineArray, and probably no reason why it should be in (Shared)Buffer.

Just try it with a lock inside insert(), open micro an press Enter for a new line. I suppose it will stop responding and internally waits for an lock (deadlock?).

@dmaluka
Copy link
Collaborator Author

dmaluka commented Mar 28, 2024

I wasn't asking for the per-line lock, just the layer of "per-buffer", but it's clear now.

I didn't say you were asking for it. :)

Just try it with a lock inside insert(), open micro an press Enter for a new line. I suppose it will stop responding and internally waits for an lock (deadlock?).

Hmm, good luck debugging.

@dmaluka
Copy link
Collaborator Author

dmaluka commented Mar 29, 2024

Maybe you already found it, but just in case, the deadlock is simply due to trying to lock the same mutex twice (in the same goroutine). Turns out that insert() is recursive:

runtime/debug.Stack()
	runtime/debug/stack.go:24 +0x65
github.com/zyedidia/micro/v2/internal/buffer.(*LineArray).insert(0xc0005b5fb0, {0xecbf60, 0xc0000c1258}, {0xf24668, 0x0, 0xc6b})
	github.com/zyedidia/micro/v2/internal/buffer/line_array.go:212 +0x65
github.com/zyedidia/micro/v2/internal/buffer.(*LineArray).split(0xc0005b5fb0, {0xf24668, 0xc56})
	github.com/zyedidia/micro/v2/internal/buffer/line_array.go:249 +0x332
github.com/zyedidia/micro/v2/internal/buffer.(*LineArray).insert(0xc0005b5fb0, {0x7e5e18, 0xc0001266e0}, {0xc000949e00, 0x1, 0x99f9d8})
	github.com/zyedidia/micro/v2/internal/buffer/line_array.go:218 +0x398

@dmaluka
Copy link
Collaborator Author

dmaluka commented Mar 29, 2024

...So, a (hopefully correct) fix for this deadlock:

diff --git a/internal/buffer/line_array.go b/internal/buffer/line_array.go
index a906b1f4..fabed390 100644
--- a/internal/buffer/line_array.go
+++ b/internal/buffer/line_array.go
@@ -240,7 +240,7 @@ func (la *LineArray) joinLines(a, b int) {
 // split splits a line at a given position
 func (la *LineArray) split(pos Loc) {
 	la.newlineBelow(pos.Y)
-	la.insert(Loc{0, pos.Y + 1}, la.lines[pos.Y].data[pos.X:])
+	la.lines[pos.Y+1].data = append(la.lines[pos.Y+1].data, la.lines[pos.Y].data[pos.X:]...)
 	la.lines[pos.Y+1].state = la.lines[pos.Y].state
 	la.lines[pos.Y].state = nil
 	la.lines[pos.Y].match = nil

Then there is another similar deadlock in deletion, so a (hopefully correct) fix for it:

diff --git a/internal/buffer/line_array.go b/internal/buffer/line_array.go
index a906b1f4..bd6fc999 100644
--- a/internal/buffer/line_array.go
+++ b/internal/buffer/line_array.go
@@ -233,7 +233,7 @@ func (la *LineArray) insertByte(pos Loc, value byte) {
 
 // joinLines joins the two lines a and b
 func (la *LineArray) joinLines(a, b int) {
-	la.insert(Loc{len(la.lines[a].data), a}, la.lines[b].data)
+	la.lines[a].data = append(la.lines[a].data, la.lines[b].data...)
 	la.deleteLine(b)
 }
 

Then it works, but the buffer test still fails:

panic: runtime error: index out of range [3] with length 3

goroutine 53 [running]:
github.com/zyedidia/micro/v2/internal/buffer.(*LineArray).SetMatch(0xc00045f7d0, 0xc000178ac0, 0xc00009cf00)
	/home/mitya/src/micro-upstream/internal/buffer/line_array.go:360 +0xe5

so need to address that:

diff --git a/internal/buffer/line_array.go b/internal/buffer/line_array.go
index 8464c5d7..8772dd3b 100644
--- a/internal/buffer/line_array.go
+++ b/internal/buffer/line_array.go
@@ -357,6 +357,10 @@ func (la *LineArray) SetState(lineN int, s highlight.State) {
 func (la *LineArray) SetMatch(lineN int, m highlight.LineMatch) {
 	la.lock.Lock()
 	defer la.lock.Unlock()
+
+	if lineN >= len(la.lines) {
+		return
+	}
 	la.lines[lineN].match = m
 }
 

and similarly in other functions used by the highlighter.

This last point makes me think: so while this should (hopefully) guarantee correct and safe access to the line array, it does not guarantee that the highlighter itself will produce correct results (i.e. highlight correct pieces of text with correct colors), since the lines it operates on may be outdated. But HOPEFULLY such highlighting errors will be always immediately corrected by rehighlighting in MarkModified() (right? I'm not fully convinced of that myself).

@JoeKar
Copy link
Collaborator

JoeKar commented Mar 29, 2024

Maybe you already found it, but just in case, [...]

No, because I was going to bed. 😉
But thanks, this now explains, that Go doesn't allow recursive locks, even they are possible with PTHREAD_MUTEX_RECURSIVE as simple counting semaphore (at least in POSIX compliant OS). My bad...

so need to address that: [...] and similarly in other functions used by the highlighter.

I already had all of them in an intermediate version.

But HOPEFULLY such highlighting errors will be always immediately corrected by rehighlighting in MarkModified() (right? I'm not fully convinced of that myself).

I've doubts too, since MarkModified() and his re-highlighting is done in the same caller context, while the async context started by UpdateRules() possibly could finish later. 🤔

@dmaluka
Copy link
Collaborator Author

dmaluka commented Mar 29, 2024

I've doubts too, since MarkModified() and his re-highlighting is done in the same caller context, while the async context started by UpdateRules() possibly could finish later. 🤔

Yeah... For example, in HighlightStates() or HighlightMatches() called from the async goroutine, line := input.LineBytes(i) could be called even before the insertion/deletion done by the main goroutine, while SetState() or SetMatch() could be called later than the rehighlighting done by the main goroutine. Essentially, there is a race between background highlighting and the main goroutine's rehighlighting as a whole.

Hmm... BTW what about LineBytes() and the fact that it is used by the async highlighting? Even if we add the LineArray mutex locking to LineBytes() as well, it still returns data as a slice, i.e. "by reference". So this is still racy not just in terms of possible wrong highlight colors: for example, the async highlight goroutine may try to access a line's data slice (returned by LineArray()) that no longer exists, since this line had been deleted? (EDIT: well, the garbage collector should ensure that it still exists. But still, we access an object that may be modified by another goroutine, without synchronization...)

@JoeKar
Copy link
Collaborator

JoeKar commented Apr 2, 2024

And for the future, all this suggests that doing InitRuntimeFiles() in buffer_test.go is a good idea [...]
use a custom ConfigDir which is guaranteed be empty, instead of using whatever is in ~/.config/micro/ on the test machine.

The last one is tricky in case the test environment is out of your control.

EDIT: or alternatively, instead of creating a temporary empty config dir, just add a parameter to InitRuntimeFiles() to skip user's custom files.

This would prevent to mess around with the (current) three test environments. Sounds like the better choice, to force the intended set of features.
Maybe add a special initialization routine for tests only or split it up once again, to give the user full control over the initialized feature set?

Last but not least:
Will you take care of it and update your PR accordingly?

I currently prepare a (hopefully) possible approach to get rid of our race condition.

dmaluka added 4 commits April 3, 2024 03:04
Adding InitPlugins() to tests has caused noisy error logs when running
the buffer_test.go test (although the test result is still PASS):

2024/03/23 15:14:30 Plugin does not exist: autoclose at autoclose : &{autoclose autoclose <nil> [runtime/plugins/autoclose/autoclose.lua] false true}
2024/03/23 15:14:30 Plugin does not exist: comment at comment : &{comment comment <nil> [runtime/plugins/comment/comment.lua] false true}
2024/03/23 15:14:30 Plugin does not exist: diff at diff : &{diff diff <nil> [runtime/plugins/diff/diff.lua] false true}
2024/03/23 15:14:30 Plugin does not exist: ftoptions at ftoptions : &{ftoptions ftoptions <nil> [runtime/plugins/ftoptions/ftoptions.lua] false true}
...

These errors are caused simply by the fact that plugins are initialized
but not loaded. Adding config.LoadAllPlugins() to buffer_test.go "fixes"
this problem.

However, at the moment it doesn't seem a good idea to load plugins in
buffer_test.go, since buffer_test.go doesn't properly initialize Lua. It
only does ulua.L = lua.NewState() but doesn't do the other stuff that
init() in cmd/micro/initlua.go does. As a result, plugins will not be
able to do anything correctly.

So in order to initialize Lua correctly we need to be inside cmd/micro/,
so we cannot do it in buffer_test.go or any other tests except
micro_test.go.
When initializing runtime files (syntax files etc) in tests, initialize
built-in runtime files only, to ensure that the tests are not affected
by whatever is in ~/.config/micro/ on the test machine.

micro_test.go already ensures that, by using its own temporary directory
as an (empty) config directory. So we only need to fix buffer_test.go
and rtfiles_test.go. In those tests, don't repeat the same dance with
a temporary directory, instead just ignore the config directory.
Adding InitRuntimeFiles() to buffer_test.go has changed the behavior
of this test: now it tests not just buffer editing per se, but also
how well buffer editing works together with syntax highlighting (since
InitRuntimeFiles() loads syntax files, and many of the test buffers
match the json header pattern in the json.yaml syntax file, so they are
"highlighted" as json). This revealed long existing races between
buffer editing and syntax highlighting.

Until we fix those races, temporarily disable InitRuntimeFiles() in this
test.
@dmaluka dmaluka force-pushed the tests-rtfiles-fix branch from 4a6c1db to 69dc54b Compare April 3, 2024 02:51
@dmaluka
Copy link
Collaborator Author

dmaluka commented Apr 3, 2024

Will you take care of it and update your PR accordingly?

Yep, just updated.

In the last commit I commented out InitRuntimeFiles() in buffer_test.go, so we can merge this PR straight away if we want to fix github CI failures as soon as possible, and then we can uncomment InitRuntimeFiles() once we fix the races.

@JoeKar JoeKar merged commit c493e14 into zyedidia:master Apr 5, 2024
3 checks passed
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.

2 participants