search

zyedidia / micro

A modern and intuitive terminal-based text editor
https://micro-editor.github.io
MIT License
24.4k stars 1.16k forks source link

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

Closed dmaluka closed 3 months ago

dmaluka commented 3 months ago

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 commented 3 months ago

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

JoeKar commented 3 months ago

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? :thinking:

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 commented 3 months ago

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 commented 3 months ago

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.

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.

JoeKar commented 3 months ago

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 https://github.com/zyedidia/micro/pull/3062 (specifically by config.InitRuntimeFiles(), specifically RTSyntax* files) and my https://github.com/zyedidia/micro/pull/3208.

I'll have a look at this too.

JoeKar commented 3 months ago

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:

dmaluka commented 3 months ago

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 commented 3 months ago

BTW now it looks like https://github.com/zyedidia/micro/pull/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 commented 3 months ago

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

That's exactly what I meant. :wink: 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. :thinking: 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 commented 3 months ago

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 commented 3 months ago

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

dmaluka commented 3 months ago

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:

dmaluka commented 3 months ago

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 commented 3 months ago

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 commented 3 months ago

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 commented 3 months ago

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 commented 3 months ago

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 commented 3 months ago

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 commented 3 months ago

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 commented 3 months ago

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 commented 3 months ago

...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 commented 3 months ago

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

No, because I was going to bed. :wink: 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. :thinking:

dmaluka commented 3 months ago

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 commented 3 months ago

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 commented 3 months ago

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.