[GH-ISSUE #268 ] termdash makes debugging panics difficult #144

Author

Owner

@mum4k commented on GitHub (Nov 21, 2020):

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?

@mum4k commented on GitHub (Nov 21, 2020): 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?

kerem commented

Author

Owner

@dyc3 commented on GitHub (Nov 21, 2020):

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.

@dyc3 commented on GitHub (Nov 21, 2020): 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.

kerem commented

Author

Owner

@mum4k commented on GitHub (Nov 21, 2020):

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?

@mum4k commented on GitHub (Nov 21, 2020): 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?

kerem commented

Author

Owner

@dyc3 commented on GitHub (Nov 21, 2020):

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 commented on GitHub (Nov 21, 2020): 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.

kerem commented

Author

Owner

@dyc3 commented on GitHub (Nov 21, 2020):

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

@dyc3 commented on GitHub (Nov 21, 2020): We could also return the error as an error from `termdash.Run`, letting the user log the error themselves.

kerem commented

Author

Owner

@mum4k commented on GitHub (Nov 21, 2020):

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.

@mum4k commented on GitHub (Nov 21, 2020): 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.

kerem commented

Author

Owner

@dyc3 commented on GitHub (Nov 21, 2020):

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

@dyc3 commented on GitHub (Nov 21, 2020): Yeah, recovering, printing, and re-panicking sounds like the best option.

kerem commented

Author

Owner

@mum4k commented on GitHub (Nov 21, 2020):

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.

@mum4k commented on GitHub (Nov 21, 2020): 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.

kerem commented

Author

Owner

@dyc3 commented on GitHub (Nov 21, 2020):

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

@dyc3 commented on GitHub (Nov 21, 2020): I'd prefer if you'd try to address it.

kerem commented

Author

Owner

@mum4k commented on GitHub (Nov 21, 2020):

Sounds good, I'll give it a try.

@mum4k commented on GitHub (Nov 21, 2020): Sounds good, I'll give it a try.

kerem commented

github.com/mum4k/termdash@fbd21e7904/widgets/barchart/barchartdemo/barchartdemo.go (L63)

Author

Owner

@mum4k commented on GitHub (Nov 21, 2020):

@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:

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:
https://github.com/mum4k/termdash/pull/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?

@mum4k commented on GitHub (Nov 21, 2020): @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: https://github.com/mum4k/termdash/blob/fbd21e790423e0d479d440e6d1f77e1ca7f01382/widgets/barchart/barchartdemo/barchartdemo.go#L63 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: https://github.com/mum4k/termdash/pull/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?

kerem commented

Author

Owner

@dyc3 commented on GitHub (Nov 21, 2020):

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.

@dyc3 commented on GitHub (Nov 21, 2020): 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. ```go 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.

kerem commented

Author

Owner

@mum4k commented on GitHub (Nov 21, 2020):

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.

@mum4k commented on GitHub (Nov 21, 2020): 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.

kerem commented

Author

Owner

@dyc3 commented on GitHub (Nov 22, 2020):

Sure, I'll throw together a branch

@dyc3 commented on GitHub (Nov 22, 2020): Sure, I'll throw together a branch

kerem commented

Author

Owner

@dyc3 commented on GitHub (Nov 22, 2020):

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

@dyc3 commented on GitHub (Nov 22, 2020): 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`

kerem commented

Author

Owner

@mum4k commented on GitHub (Nov 22, 2020):

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 commented on GitHub (Nov 22, 2020): 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.

kerem commented

Author

Owner

@mum4k commented on GitHub (Nov 22, 2020):

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:
github.com/dyc3/teleprompt-studio@1e0dff3e56/main.go (L380)

We find that a goroutine is created that eventually calls osutil.CaptureWithCGo():
github.com/dyc3/teleprompt-studio@1e0dff3e56/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:

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.
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?

@mum4k commented on GitHub (Nov 22, 2020): 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. 1. 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?

kerem commented

Author

Owner

@dyc3 commented on GitHub (Nov 22, 2020):

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.

@dyc3 commented on GitHub (Nov 22, 2020): `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.

kerem commented