Hang on shutdown #424

walles · 2021-01-11T20:08:39Z

Repro instructions

Save the below program in the _demos folder as repro.go and go run repro.go
Give your mouse wheel a good whirl so that momentum keeps the screen updating after release
While the screen is repeatedly redrawing, hit a keyboard button

Current result

When I do this on macOS with the latest tcell sources, the numbers screen disappears, but the program never exits. In this state, CTRL-C doesn't work.

If I skip the scroll wheel the program exits just fine.

Expected result

Program should shut down nicely.

Code

(butchered from mouse.go)

// +build ignore
package main

import (
	"fmt"
	"os"
	"strconv"
	"unicode/utf8"

	"github.com/gdamore/tcell/v2"
	"github.com/gdamore/tcell/v2/encoding"
	"github.com/mattn/go-runewidth"
)

func emitStr(s tcell.Screen, x, y int, style tcell.Style, str string) {
	for _, c := range str {
		var comb []rune
		w := runewidth.RuneWidth(c)
		if w == 0 {
			comb = []rune{c}
			c = ' '
			w = 1
		}
		s.SetContent(x, y, c, comb, style)
		x += w
	}
}

func main() {
	encoding.Register()

	s, e := tcell.NewScreen()
	if e != nil {
		fmt.Fprintf(os.Stderr, "%v\n", e)
		os.Exit(1)
	}
	if e := s.Init(); e != nil {
		fmt.Fprintf(os.Stderr, "%v\n", e)
		os.Exit(1)
	}
	defer func() {
		// Restore screen...
		s.Fini()
	}()
	s.EnableMouse()
	s.Show()

	i := 0
	for {
		i++
		if i > 9 {
			i = 0
		}

		w, h := s.Size()
		for row := 0; row < h; row++ {
			for column := 0; column < w; column++ {
				numberString := strconv.Itoa(i)
				numberRune, _ := utf8.DecodeRuneInString(numberString)
				s.SetContent(column, row, numberRune, nil, tcell.StyleDefault.Foreground(tcell.ColorDarkGray))
			}
		}
		emitStr(s, 2, 2, tcell.StyleDefault.Background(tcell.ColorBlack).Foreground(tcell.ColorWhite), "Move mouse for action, any key exits")

		s.Show()
		ev := s.PollEvent()

		switch ev.(type) {
		case *tcell.EventKey:
			return
		}
	}
}

Notes

Discovered in walles/moar#37.

For moar I came this far in tracking this down:

This feels like a deadlock between waiting for events in two different places:

(*tScreen).termioFini() tscreen_darwin.go:106
(*tScreen).PostEventWait(...) tscreen.go:969

Thread dump

Constructed using this trick.

goroutine 53 [running]:
runtime/pprof.writeGoroutineStacks(0x17f6980, 0xc000584380, 0xc0005c7770, 0x0)
	/usr/local/Cellar/go/1.15.6/libexec/src/runtime/pprof/pprof.go:693 +0x9f
runtime/pprof.writeGoroutine(0x17f6980, 0xc000584380, 0x2, 0x1b3cf20, 0xc0004e6580)
	/usr/local/Cellar/go/1.15.6/libexec/src/runtime/pprof/pprof.go:682 +0x45
runtime/pprof.(*Profile).WriteTo(0x1b3fd60, 0x17f6980, 0xc000584380, 0x2, 0xc000584380, 0xc0001279d8)
	/usr/local/Cellar/go/1.15.6/libexec/src/runtime/pprof/pprof.go:331 +0x3f2
net/http/pprof.handler.ServeHTTP(0xc0000284c1, 0x9, 0x17fda00, 0xc000584380, 0xc00022a600)
	/usr/local/Cellar/go/1.15.6/libexec/src/net/http/pprof/pprof.go:256 +0x385
net/http/pprof.Index(0x17fda00, 0xc000584380, 0xc00022a600)
	/usr/local/Cellar/go/1.15.6/libexec/src/net/http/pprof/pprof.go:367 +0x945
net/http.HandlerFunc.ServeHTTP(0x176a668, 0x17fda00, 0xc000584380, 0xc00022a600)
	/usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:2042 +0x44
net/http.(*ServeMux).ServeHTTP(0x1b58d40, 0x17fda00, 0xc000584380, 0xc00022a600)
	/usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:2417 +0x1ad
net/http.serverHandler.ServeHTTP(0xc0008a40e0, 0x17fda00, 0xc000584380, 0xc00022a600)
	/usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:2843 +0xa3
net/http.(*conn).serve(0xc00027c000, 0x17fe8c0, 0xc0004b4040)
	/usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:1925 +0x8ad
created by net/http.(*Server).Serve
	/usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:2969 +0x36c

goroutine 1 [chan receive]:
github.com/gdamore/tcell/v2.(*tScreen).termioFini(0xc0002b7200)
	/Users/johan/go/pkg/mod/github.com/gdamore/tcell/v2@v2.0.0/tscreen_darwin.go:106 +0x54
github.com/gdamore/tcell/v2.(*tScreen).finish(0xc0002b7200)
	/Users/johan/go/pkg/mod/github.com/gdamore/tcell/v2@v2.0.0/tscreen.go:497 +0x275
sync.(*Once).doSlow(0xc0002b73c4, 0xc000123da0)
	/usr/local/Cellar/go/1.15.6/libexec/src/sync/once.go:66 +0xec
sync.(*Once).Do(...)
	/usr/local/Cellar/go/1.15.6/libexec/src/sync/once.go:57
github.com/gdamore/tcell/v2.(*tScreen).Fini(0xc0002b7200)
	/Users/johan/go/pkg/mod/github.com/gdamore/tcell/v2@v2.0.0/tscreen.go:469 +0x6a
main.startPaging.func1(0x18035e0, 0xc0002b7200, 0xc00088c020)
	/Users/johan/src/moar/moar.go:156 +0x35
main.startPaging(0xc0000701e0)
	/Users/johan/src/moar/moar.go:176 +0x139
main.main()
	/Users/johan/src/moar/moar.go:144 +0x335

goroutine 50 [syscall]:
os/signal.signal_recv(0x0)
	/usr/local/Cellar/go/1.15.6/libexec/src/runtime/sigqueue.go:144 +0x9d
os/signal.loop()
	/usr/local/Cellar/go/1.15.6/libexec/src/os/signal/signal_unix.go:23 +0x25
created by os/signal.Notify.func1.1
	/usr/local/Cellar/go/1.15.6/libexec/src/os/signal/signal.go:150 +0x45

goroutine 23 [IO wait]:
internal/poll.runtime_pollWait(0x9569000, 0x72, 0x0)
	/usr/local/Cellar/go/1.15.6/libexec/src/runtime/netpoll.go:222 +0x55
internal/poll.(*pollDesc).wait(0xc0002ea998, 0x72, 0x0, 0x0, 0x1696535)
	/usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:87 +0x45
internal/poll.(*pollDesc).waitRead(...)
	/usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Accept(0xc0002ea980, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
	/usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_unix.go:394 +0x1fc
net.(*netFD).accept(0xc0002ea980, 0xd12de411cd93dea0, 0x1070dcd93dea0, 0x100000001)
	/usr/local/Cellar/go/1.15.6/libexec/src/net/fd_unix.go:172 +0x45
net.(*TCPListener).accept(0xc00000e960, 0x5ffbe98d, 0xc000057e00, 0x10ca4c6)
	/usr/local/Cellar/go/1.15.6/libexec/src/net/tcpsock_posix.go:139 +0x32
net.(*TCPListener).Accept(0xc00000e960, 0xc000057e50, 0x18, 0xc00041c000, 0x136160c)
	/usr/local/Cellar/go/1.15.6/libexec/src/net/tcpsock.go:261 +0x65
net/http.(*Server).Serve(0xc0008a40e0, 0x17fd780, 0xc00000e960, 0x0, 0x0)
	/usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:2937 +0x266
net/http.(*Server).ListenAndServe(0xc0008a40e0, 0xc0008a40e0, 0x0)
	/usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:2866 +0xb7
net/http.ListenAndServe(...)
	/usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:3120
github.com/walles/moar/m.(*Pager).StartPaging.func1()
	/Users/johan/src/moar/m/pager.go:679 +0x58
created by github.com/walles/moar/m.(*Pager).StartPaging
	/Users/johan/src/moar/m/pager.go:678 +0x47

goroutine 54 [IO wait]:
internal/poll.runtime_pollWait(0x9568e30, 0x72, 0x17f7800)
	/usr/local/Cellar/go/1.15.6/libexec/src/runtime/netpoll.go:222 +0x55
internal/poll.(*pollDesc).wait(0xc0002eae98, 0x72, 0x17f7800, 0x1b00908, 0x0)
	/usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:87 +0x45
internal/poll.(*pollDesc).waitRead(...)
	/usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc0002eae80, 0xc00080a000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_unix.go:159 +0x1a5
net.(*netFD).Read(0xc0002eae80, 0xc00080a000, 0x1000, 0x1000, 0xc0000cc240, 0xc0000597c0, 0x1356465)
	/usr/local/Cellar/go/1.15.6/libexec/src/net/fd_posix.go:55 +0x4f
net.(*conn).Read(0xc000208038, 0xc00080a000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/Cellar/go/1.15.6/libexec/src/net/net.go:182 +0x8e
net/http.(*connReader).Read(0xc000892360, 0xc00080a000, 0x1000, 0x1000, 0x10000000e, 0x104bb5f, 0x9291888)
	/usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:798 +0x1ad
bufio.(*Reader).fill(0xc0004a6480)
	/usr/local/Cellar/go/1.15.6/libexec/src/bufio/bufio.go:101 +0x105
bufio.(*Reader).ReadSlice(0xc0004a6480, 0xa, 0x9291888, 0xc000059988, 0x100f6d0, 0xc00022a500, 0x100)
	/usr/local/Cellar/go/1.15.6/libexec/src/bufio/bufio.go:360 +0x3d
bufio.(*Reader).ReadLine(0xc0004a6480, 0xc00022a500, 0x1b89f3c, 0xc000600480, 0x0, 0x1010038, 0x30)
	/usr/local/Cellar/go/1.15.6/libexec/src/bufio/bufio.go:389 +0x34
net/textproto.(*Reader).readLineSlice(0xc0008923c0, 0xc00022a500, 0x10d450d, 0xc0002eae80, 0x2000, 0xc00000ea60)
	/usr/local/Cellar/go/1.15.6/libexec/src/net/textproto/reader.go:58 +0x6c
net/textproto.(*Reader).ReadLine(...)
	/usr/local/Cellar/go/1.15.6/libexec/src/net/textproto/reader.go:39
net/http.readRequest(0xc0004a6480, 0x0, 0xc00022a500, 0x0, 0x0)
	/usr/local/Cellar/go/1.15.6/libexec/src/net/http/request.go:1012 +0xaa
net/http.(*conn).readRequest(0xc00027c0a0, 0x17fe8c0, 0xc0000cc0c0, 0x0, 0x0, 0x0)
	/usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:984 +0x19a
net/http.(*conn).serve(0xc00027c0a0, 0x17fe8c0, 0xc0000cc0c0)
	/usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:1851 +0x705
created by net/http.(*Server).Serve
	/usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:2969 +0x36c

goroutine 51 [chan send]:
github.com/gdamore/tcell/v2.(*tScreen).PostEventWait(...)
	/Users/johan/go/pkg/mod/github.com/gdamore/tcell/v2@v2.0.0/tscreen.go:969
github.com/gdamore/tcell/v2.(*tScreen).scanInput(0xc0002b7200, 0xc00079ff00, 0x1b58f00)
	/Users/johan/go/pkg/mod/github.com/gdamore/tcell/v2@v2.0.0/tscreen.go:1323 +0xa7
github.com/gdamore/tcell/v2.(*tScreen).mainLoop(0xc0002b7200)
	/Users/johan/go/pkg/mod/github.com/gdamore/tcell/v2@v2.0.0/tscreen.go:1447 +0x30f
created by github.com/gdamore/tcell/v2.(*tScreen).Init
	/Users/johan/go/pkg/mod/github.com/gdamore/tcell/v2@v2.0.0/tscreen.go:185 +0x631

goroutine 52 [chan send]:
github.com/gdamore/tcell/v2.(*tScreen).inputLoop(0xc0002b7200)
	/Users/johan/go/pkg/mod/github.com/gdamore/tcell/v2@v2.0.0/tscreen.go:1473 +0x6e
created by github.com/gdamore/tcell/v2.(*tScreen).Init
	/Users/johan/go/pkg/mod/github.com/gdamore/tcell/v2@v2.0.0/tscreen.go:186 +0x656

goroutine 9 [chan receive (nil chan)]:
github.com/walles/moar/m.(*Pager).StartPaging.func2(0xc0000d02a0, 0x18035e0, 0xc0002b7200)
	/Users/johan/src/moar/m/pager.go:700 +0x7d
created by github.com/walles/moar/m.(*Pager).StartPaging
	/Users/johan/src/moar/m/pager.go:697 +0x1d1

goroutine 12 [IO wait]:
internal/poll.runtime_pollWait(0x9568f18, 0x72, 0x17f7800)
	/usr/local/Cellar/go/1.15.6/libexec/src/runtime/netpoll.go:222 +0x55
internal/poll.(*pollDesc).wait(0xc0002ead18, 0x72, 0x17f7800, 0x1b00908, 0x0)
	/usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:87 +0x45
internal/poll.(*pollDesc).waitRead(...)
	/usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc0002ead00, 0xc0005c6041, 0x1, 0x1, 0x0, 0x0, 0x0)
	/usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_unix.go:159 +0x1a5
net.(*netFD).Read(0xc0002ead00, 0xc0005c6041, 0x1, 0x1, 0xc0004b4658, 0xc000511f68, 0x10866dc)
	/usr/local/Cellar/go/1.15.6/libexec/src/net/fd_posix.go:55 +0x4f
net.(*conn).Read(0xc000208030, 0xc0005c6041, 0x1, 0x1, 0x0, 0x0, 0x0)
	/usr/local/Cellar/go/1.15.6/libexec/src/net/net.go:182 +0x8e
net/http.(*connReader).backgroundRead(0xc0005c6030)
	/usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:690 +0x58
created by net/http.(*connReader).startBackgroundRead
	/usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:686 +0xd5

The text was updated successfully, but these errors were encountered:

walles · 2021-01-12T07:10:14Z

Or is it this code that steals the quit event without closing t.indoneq?

tcell/tscreen.go

Lines 895 to 902 in 29bb185

    
           func (t *tScreen) PollEvent() Event { 
        
           	select { 
        
           	case <-t.quit: 
        
           		return nil 
        
           	case ev := <-t.evch: 
        
           		return ev 
        
           	} 
        
           }

walles · 2021-01-12T16:27:55Z

I think my first hunch was right.

Shutdown sequence:

User calls s.Fini() and stops polling for events
termioFini() pauses, waiting for t.indoneq to be closed
main loop has paused waiting for the user to poll an event in PostEventWait(), so it never closes t.indoneq

So termioFini() waits for the main loop, the main loop waits for the user to poll for an event, and the user has left.

gdamore · 2021-01-12T16:29:40Z

There are multiple problems here -- I'm going to be redesigning some of this soon. We need to stop using /dev/tty for one.
It may be a week or so before I find time to get it done though.

walles · 2021-01-23T13:04:55Z

In my case this might be mitigated by a fix for #422.

That would make me drain the events buffer much faster, making it contain fewer events on average and thus be less likely to be full on shutdown, which is when this lockup happens.

gdamore · 2021-01-24T21:26:20Z

This bug is actually a dup of #394 -- fix is coming shortly.

gdamore · 2021-01-24T21:48:21Z

Closing this as a dup of #394.

gdamore closed this as completed Jan 24, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Hang on shutdown #424

Hang on shutdown #424

walles commented Jan 11, 2021

walles commented Jan 12, 2021

walles commented Jan 12, 2021

gdamore commented Jan 12, 2021

walles commented Jan 23, 2021

gdamore commented Jan 24, 2021

gdamore commented Jan 24, 2021

Hang on shutdown #424

Hang on shutdown #424

Comments

walles commented Jan 11, 2021

Repro instructions

Current result

Expected result

Code

Notes

Thread dump

walles commented Jan 12, 2021

walles commented Jan 12, 2021

gdamore commented Jan 12, 2021

walles commented Jan 23, 2021

gdamore commented Jan 24, 2021

gdamore commented Jan 24, 2021