termdash makes debugging panics difficult

[dyc3]

termdash makes debugging panics difficult

[mum4k]

Thank you for the question @dyc3. This is remotely related to #247.

The short answer is - I don't think we can do it within termdash, because Go only allows recovery from a panic from within the panicking goroutine. The termdash infrastructure would only be able to capture panics originating within the termdash infrastructure. If you are facing those, we can add something to catch them, but it might be more interesting to solve the issues that cause termdash to panic.

If the panics originate from the code that uses termdash, the recovery must happen within the same code (goroutine). Note that I have recently added a wiki page on how I usually debug issues: https://github.com/mum4k/termdash/wiki/Debugging

I suspect that most of the content will be fairly obvious and known, but thought that it might be worth mentioning.

Would you mind sharing what sort of panics you are encountering?

[dyc3]

Just panics when I'm developing my own widgets. Mostly index out of bounds mistakes.

When I'm debugging stuff, I've found that the log package does a pretty good job. log.SetOutput lets you set a writer to output log messages to, which I direct to a file. For some reason, I'm unable to attach delve to debug my specific application, and I'm not sure why. IIRC, that would catch panics and show them to me.

[mum4k]

The advice about log.SetOutput is a good one, I didn't know about it and it likely provides an easier way to setup debugging that the one in the wiki.

Panics originating from widgets actually do originate in termdash, so catching the panic there and logging it or similar before exiting would be a viable solution. We could also partially address #247 by catching a panic, resetting the terminal and reprinting the panic in clear. Or just provide a top level option that will let users of termdash specify a file to log panics to. What do you think?

[dyc3]

I think it should reset the terminal and reprint the panic in clear.

It looks like the recover() builtin recovers from panics, and it returns the error that it panicked with to print out.

[dyc3]

We could also return the error as an error from termdash.Run, letting the user log the error themselves.

[mum4k]

Logging or printing the panic is very likely a good idea. To be clear we would use recover() only for the purposes to clear the terminal and then panic again.

Turning a panic into an error (essentially stopping the panicking process) needs more thought. There usually is a reason why the program is panicking and recovery from that state is often impossible or impractical. The program could also remain in an undefined state if we do that.

Assuming the first approach achieves our goal, I think we have a path forward. Please let me know.

[dyc3]

Yeah, recovering, printing, and re-panicking sounds like the best option.

[mum4k]

Sounds good. Care should be taken as to where we apply this code. Termdash itself runs a couple of goroutines internally. If we want to recover from panics in the widget's Draw function we need to recover in the goroutine that calls it.

Is this something you would like to look into yourself, or would you prefer if I try to address it? As before I will be happy to provide some code pointers if you are interested in giving it a try.

[dyc3]

I'd prefer if you'd try to address it.

[mum4k]

Sounds good, I'll give it a try.

[mum4k]

@dyc3 I am having some trouble reproducing the problem and hoping you can give me advice.

I have added a panic() call directly inside the Draw() method of one of the widgets. When the code reaches the panic(), it actually correctly closes the terminal and prints the panic in clear. That is because Draw() is actually called from the main goroutine which is the same one that defers a call to the terminal closure method here:

termdash/widgets/barchart/barchartdemo/barchartdemo.go

Line 63 in fbd21e7

defer t.Close()

Here is the panic that I got in a clear readable form on the terminal:

$ go run widgets/barchart/barchartdemo/barchartdemo.go
panic: drawCount panic

goroutine 1 [running]:
github.com/mum4k/termdash/widgets/barchart.(*BarChart).Draw(0xc00006a0c0, 0xc00006b840, 0xc0001fc63c, 0x0, 0x0)
	/Users/mum4k/go/src/github.com/mum4k/termdash/widgets/barchart/barchart.go:83 +0x7ba
github.com/mum4k/termdash/container.drawWidget(0xc00007c000, 0x0, 0x0)
	/Users/mum4k/go/src/github.com/mum4k/termdash/container/draw.go:138 +0x2b5
github.com/mum4k/termdash/container.drawCont(0xc00007c000, 0x1, 0x1)
	/Users/mum4k/go/src/github.com/mum4k/termdash/container/draw.go:171 +0x147
github.com/mum4k/termdash/container.drawTree.func1(0xc00007c000, 0x67, 0x26)
	/Users/mum4k/go/src/github.com/mum4k/termdash/container/draw.go:63 +0x85
github.com/mum4k/termdash/container.preOrder(0xc00007c000, 0xc0000cbb78, 0x119bea0)
	/Users/mum4k/go/src/github.com/mum4k/termdash/container/traversal.go:43 +0x4f
github.com/mum4k/termdash/container.drawTree(0xc00007c000, 0x26, 0x0)
	/Users/mum4k/go/src/github.com/mum4k/termdash/container/draw.go:43 +0x125
github.com/mum4k/termdash/container.(*Container).Draw(0xc00007c000, 0x0, 0x0)
	/Users/mum4k/go/src/github.com/mum4k/termdash/container/container.go:226 +0x11c
github.com/mum4k/termdash.(*termdash).redraw(0xc000046180, 0x0, 0x0)
	/Users/mum4k/go/src/github.com/mum4k/termdash/termdash.go:274 +0x3d
github.com/mum4k/termdash.(*termdash).periodicRedraw(0xc000046180, 0x0, 0x0)
	/Users/mum4k/go/src/github.com/mum4k/termdash/termdash.go:301 +0x71
github.com/mum4k/termdash.(*termdash).start(0xc000046180, 0x11c3900, 0xc00006b000, 0x0, 0x0)
	/Users/mum4k/go/src/github.com/mum4k/termdash/termdash.go:344 +0x216
github.com/mum4k/termdash.Run(0x11c3900, 0xc00006a080, 0x11c41e0, 0xc00009aa20, 0xc00007c000, 0xc0000cbed8, 0x1, 0x1, 0xfde4866c2ddc381d, 0xc0000cbed8)
	/Users/mum4k/go/src/github.com/mum4k/termdash/termdash.go:108 +0x94
main.main()
	/Users/mum4k/go/src/github.com/mum4k/termdash/widgets/barchart/barchartdemo/barchartdemo.go:112 +0x5c5
exit status 2

Here is a PR that shows how I caused the panic:
#269

Can you help me identify what is different in your setup? Is the panic originating from a different method on the widget? Do you also have a deferred call to t.Close() in your main? Or can you maybe share a panic that can help me reproduce the problem?

[dyc3]

Strange... maybe tcell is handling the panics?

The project I'm working on is this: https://github.com/dyc3/teleprompt-studio
The specific widget I was working on: https://github.com/dyc3/teleprompt-studio/blob/main/script_display_widget.go

Causing an index out of bounds panic in that widget's Draw will reproduce what I was getting. Maybe it's a different type of panic?

In main.go, I'm handling the panics with this little snippet in func main, so it has to be disabled to reproduce.

        defer func() {
		if r := recover(); r != nil {
			log.Printf("Panic: %v", r)
			log.Printf("Stacktrace: %s", string(debug.Stack()))
		}
	}()

I do have defer t.Close() in my main.

[mum4k]

Thank you for that. Would you be able to point me to a PR or a branch where I can execute something that directly reproduces the kind of panic we are discussing here? If that is possible, that would help me a lot in trying to address the issue.

[dyc3]

Sure, I'll throw together a branch

[dyc3]

The panic branch reliably reproduces the behavior I was getting last night. https://github.com/dyc3/teleprompt-studio/tree/panic

Run with

go build && ./teleprompt-studio --script examples/example-script.md

The log gets outputted to ./debug.log

[mum4k]

Perfect, I managed to reproduce it. This is a different problem than I thought originally. The terminal actually gets reset to the correct state, but literally nothing gets printed out.

I will poke at it a bit and update with what I found.

[mum4k]

I think understand it now, or well at least have a workable theory. This is (as with most hard to figure out problems) a race condition.

When we follow the call to StartSession() in the main:
https://github.com/dyc3/teleprompt-studio/blob/1e0dff3e568431ba3e44b26e783b86b77608e0fd/main.go#L380

We find that a goroutine is created that eventually calls osutil.CaptureWithCGo():
https://github.com/dyc3/teleprompt-studio/blob/1e0dff3e568431ba3e44b26e783b86b77608e0fd/recording.go#L38-L40

I don't know much about the function, but from it description it looks like it either captures stderr or changes where that goes.

Now with goroutines, we don't know when they get scheduled. My theory is that we lose the output of the panic if it happens concurrently with the execution of osutil.CaptureWithCGo().

I have two experiments that seem to confirm that:

1. If we remove the call to osutil.CaptureWithCGo() and just call the inner portaudio.Initialize() directly, I can no longer reproduce the problem of the disappearing panic. It seems to be correctly reported on the screen.

2. If I add a time.Sleep(1*time.Seconds) just above the call to termdash.Run(), the panic again displays properly.

Does this ring any bells? Maybe you know a it more about what osutil.CaptureWithCGo() does? Does the explanation above make sense?

[dyc3]

osutil.CaptureWithCGo() eats both stdout and stderr output from portaudio when it initializes, and lets me redirect it to the log file. If we don't do this, then that output goes directly to the terminal and it messes with the rendering.

It seems like the best thing for me to do is initialize portaudio in the main goroutine. I feel kinda bad for making you debug my program for me haha.

[mum4k]

No worries about that at all @dyc3, I am happy we figured it out. Helping each other is exactly what open source is about. Besides I too am grateful for your contribution to termdash.

Yes initializing in the main goroutine before the UI (termdash) get started is likely a good solution. It sounds like, at least for now, we don't have anything actionable in termdash itself, but please feel free to reopen this if you do find something.

And do reach out if you encounter further issues or missing features.