`log.Trigger()` buries panics

[dhermes]

Consider the following example:

wg := sync.WaitGroup{}
listener := makeWaitListener(&wg)
log.Listen(webutil.HTTPResponse, "stats", webutil.NewHTTPResponseEventListener(listener))
// ...
wg.Add(1)
log.Trigger(context.Background(), *event)
wg.Wait()

wg.Add(1)
log.Trigger(context.Background(), *event)
wg.Wait()

// This should panic.
log.Trigger(context.Background(), *event)
wg.Wait()

But running this we get:

$ go run ./main.go
::: Listener fired (1)
::: Listener fired (2)
$ echo "${?}"
0

---

Full script that snippet above came from:

package main

import (
	"bytes"
	"context"
	"fmt"
	"net/http"
	"os"
	"sync"

	"github.com/blend/go-sdk/logger"
	"github.com/blend/go-sdk/webutil"
)

func main() {
	err := runMain()
	if err != nil {
		fmt.Fprintf(os.Stderr, "%v\n", err)
		os.Exit(1)
	}
}

func runMain() error {
	var logBuffer bytes.Buffer
	log := inMemoryLog(&logBuffer)

	// Register a listener.
	wg := sync.WaitGroup{}
	listener := makeWaitListener(&wg)
	log.Listen(webutil.HTTPResponse, "stats", webutil.NewHTTPResponseEventListener(listener))

	event, err := makeEvent("/foo/bar")
	if err != nil {
		return err
	}

	wg.Add(1)
	log.Trigger(context.Background(), *event)
	wg.Wait()

	wg.Add(1)
	log.Trigger(context.Background(), *event)
	wg.Wait()

	// This should panic.
	log.Trigger(context.Background(), *event)
	wg.Wait()

	return nil
}

func inMemoryLog(logBuffer *bytes.Buffer) *logger.Logger {
	return logger.MustNew(
		logger.OptAll(),
		logger.OptOutput(logBuffer),
		logger.OptFormatter(logger.NewTextOutputFormatter(
			logger.OptTextNoColor(),
			logger.OptTextHideTimestamp(),
		)),
	)
}

func makeEvent(path string) (*webutil.HTTPResponseEvent, error) {
	r, err := http.NewRequest("GET", "http://web.invalid:8080/foo/bar", nil)
	if err != nil {
		return nil, err
	}

	event := webutil.NewHTTPResponseEvent(
		r,
		webutil.OptHTTPResponseRoute(path),
		webutil.OptHTTPResponseStatusCode(http.StatusOK),
	)
	return &event, nil
}

func makeWaitListener(wg *sync.WaitGroup) func(context.Context, webutil.HTTPResponseEvent) {
	callCount := 0
	return func(_ context.Context, _ webutil.HTTPResponseEvent) {
		defer wg.Done()
		callCount++
		if callCount == 3 {
			panic("Really do panic")
		}
		fmt.Printf("::: Listener fired (%d)\n", callCount)
		return
	}
}

[dhermes]

This is where the listener goroutine gets triggered: https://github.com/blend/go-sdk/blob/5bb3dbebdd043d45a90f53333efed4bb9b9c42bc/logger/logger.go#L125

I was hoping the explanation was just that a panic in a goroutine doesn't cause the main goroutine to fail but https://play.golang.org/p/5gkWQhNI-F7 put that hunch to rest.

[dhermes]

OK I see the recover(): https://github.com/blend/go-sdk/blob/5bb3dbebdd043d45a90f53333efed4bb9b9c42bc/logger/worker.go#L130-L135

and then the place where the recovered panic gets put in an error channel owned by the worker: https://github.com/blend/go-sdk/blob/5bb3dbebdd043d45a90f53333efed4bb9b9c42bc/logger/worker.go#L121-L123

---

However, when log.Listen() is invoked, it calls NewWorker: https://github.com/blend/go-sdk/blob/5bb3dbebdd043d45a90f53333efed4bb9b9c42bc/logger/logger.go#L123

and NewWorker leaves the Worker.Errors channel as nil: https://github.com/blend/go-sdk/blob/5bb3dbebdd043d45a90f53333efed4bb9b9c42bc/logger/worker.go#L11-L17

so these errors just end up getting swallowed.

---

This "problem" is not so easy to solve since using a buffered channel, e.g.

	return &Worker{
		Latch:    async.NewLatch(),
		Listener: listener,
		Work:     make(chan EventWithContext, DefaultWorkerQueueDepth),
		Errors:   make(chan error, 100),
	}

would eventually fill up and block the listener fully (until some other code started consuming the Errors channel).