Improve error context and add events buffer

cmd/puma-dev/main_darwin.go

@@ -82,9 +82,12 @@ func main() {
 		log.Fatalf("Unable to create dir '%s': %s", dir, err)
 	}
 
+	var events dev.Events
+
 	var pool dev.AppPool
 	pool.Dir = dir
 	pool.IdleTime = *fTimeout
+	pool.Events = &events
 
 	purge := make(chan os.Signal, 1)
 
@@ -142,6 +145,7 @@ func main() {
 	http.TLSAddress = fmt.Sprintf("127.0.0.1:%d", *fTLSPort)
 	http.Pool = &pool
 	http.Debug = *fDebug
+	http.Events = &events
 
 	http.Setup()
 

cmd/puma-dev/main_linux.go

@@ -45,9 +45,12 @@ func main() {
 		log.Fatalf("Unable to create dir '%s': %s", dir, err)
 	}
 
+	var events dev.Events
+
 	var pool dev.AppPool
 	pool.Dir = dir
 	pool.IdleTime = *fTimeout
+	pool.Events = &events
 
 	purge := make(chan os.Signal, 1)
 
@@ -87,6 +90,7 @@ func main() {
 	http.TLSAddress = fmt.Sprintf("127.0.0.1:%d", *fTLSPort)
 	http.Pool = &pool
 	http.Debug = *fDebug
+	http.Events = &events
 
 	http.Setup()
 

dev/app.go

@@ -3,7 +3,6 @@ package dev
 import (
 	"bufio"
 	"bytes"
-	"errors"
 	"fmt"
 	"io"
 	"io/ioutil"
@@ -18,6 +17,7 @@ import (
 
 	"github.com/puma/puma-dev/linebuffer"
 	"github.com/puma/puma-dev/watch"
+	"github.com/vektra/errors"
 	"gopkg.in/tomb.v2"
 )
 
@@ -32,6 +32,7 @@ type App struct {
 	Port    int
 	Command *exec.Cmd
 	Public  bool
+	Events  *Events
 
 	lines linebuffer.LineBuffer
 
@@ -51,6 +52,13 @@ type App struct {
 	readyChan chan struct{}
 }
 
+func (a *App) eventAdd(name string, args ...interface{}) {
+	args = append([]interface{}{"app", a.Name}, args...)
+
+	str := a.Events.Add(name, args...)
+	a.lines.Append("#event " + str)
+}
+
 func (a *App) SetAddress(scheme, host string, port int) {
 	a.Scheme = scheme
 	a.Host = host
@@ -71,10 +79,19 @@ func (a *App) Address() string {
 	return fmt.Sprintf("%s:%d", a.Host, a.Port)
 }
 
-func (a *App) Kill() error {
+func (a *App) Kill(reason string) error {
+	a.eventAdd("killing_app",
+		"pid", a.Command.Process.Pid,
+		"reason", reason,
+	)
+
 	fmt.Printf("! Killing '%s' (%d)\n", a.Name, a.Command.Process.Pid)
 	err := a.Command.Process.Kill()
 	if err != nil {
+		a.eventAdd("killing_error",
+			"pid", a.Command.Process.Pid,
+			"error", err.Error(),
+		)
 		fmt.Printf("! Error trying to kill %s: %s", a.Name, err)
 	}
 	return err
@@ -102,21 +119,26 @@ func (a *App) watch() error {
 
 	var err error
 
+	reason := "detected interval shutdown"
+
 	select {
 	case err = <-c:
+		reason = "stdout/stderr closed"
 		err = ErrUnexpectedExit
 	case <-a.t.Dying():
 		err = nil
 	}
 
-	a.Kill()
+	a.Kill(reason)
 	a.Command.Wait()
 	a.pool.remove(a)
 
 	if a.Scheme == "httpu" {
 		os.Remove(a.Address())
 	}
 
+	a.eventAdd("shutdown")
+
 	fmt.Printf("* App '%s' shutdown and cleaned up\n", a.Name)
 
 	return err
@@ -130,7 +152,7 @@ func (a *App) idleMonitor() error {
 		select {
 		case <-ticker.C:
 			if a.pool.maybeIdle(a) {
-				a.Kill()
+				a.Kill("app is idle")
 				return nil
 			}
 		case <-a.t.Dying():
@@ -157,7 +179,7 @@ func (a *App) restartMonitor() error {
 	f.Close()
 
 	return watch.Watch(restart, a.t.Dying(), func() {
-		a.Kill()
+		a.Kill("restart.txt touched")
 	})
 }
 
@@ -254,8 +276,6 @@ func (pool *AppPool) LaunchApp(name, dir string) (*App, error) {
 		"CONFIG=-",
 	)
 
-	cmd.Stderr = os.Stderr
-
 	stdout, err := cmd.StdoutPipe()
 	if err != nil {
 		return nil, err
@@ -265,20 +285,23 @@ func (pool *AppPool) LaunchApp(name, dir string) (*App, error) {
 
 	err = cmd.Start()
 	if err != nil {
-		return nil, err
+		return nil, errors.Context(err, "starting app")
 	}
 
 	fmt.Printf("! Booting app '%s' on socket %s\n", name, socket)
 
 	app := &App{
 		Name:      name,
 		Command:   cmd,
+		Events:    pool.Events,
 		stdout:    stdout,
 		dir:       dir,
 		pool:      pool,
 		readyChan: make(chan struct{}),
 	}
 
+	app.eventAdd("booting_app", "socket", socket)
+
 	stat, err := os.Stat(filepath.Join(dir, "public"))
 	if err == nil {
 		app.Public = stat.IsDir()
@@ -294,17 +317,21 @@ func (pool *AppPool) LaunchApp(name, dir string) (*App, error) {
 		// This is a poor substitute for getting an actual readiness signal
 		// from puma but it's good enough.
 
+		app.eventAdd("waiting_on_app")
+
 		ticker := time.NewTicker(250 * time.Millisecond)
 		defer ticker.Stop()
 		for {
 			select {
 			case <-app.t.Dying():
+				app.eventAdd("dying_on_start")
 				fmt.Printf("! Detecting app '%s' dying on start\n", name)
 				return fmt.Errorf("app died before booting")
 			case <-ticker.C:
 				c, err := net.Dial("unix", socket)
 				if err == nil {
 					c.Close()
+					app.eventAdd("app_ready")
 					fmt.Printf("! App '%s' booted\n", name)
 					close(app.readyChan)
 					return nil
@@ -324,6 +351,7 @@ func (pool *AppPool) readProxy(name, path string) (*App, error) {
 
 	app := &App{
 		Name:      name,
+		Events:    pool.Events,
 		pool:      pool,
 		readyChan: make(chan struct{}),
 	}
@@ -357,6 +385,9 @@ func (pool *AppPool) readProxy(name, path string) (*App, error) {
 		app.SetAddress(u.Scheme, host, port)
 	}
 
+	app.eventAdd("proxy_created",
+		"destination", fmt.Sprintf("%s://%s"), app.Scheme, app.Address())
+
 	fmt.Printf("* Generated proxy connection for '%s' to %s://%s\n",
 		name, app.Scheme, app.Address())
 
@@ -375,6 +406,7 @@ type AppPool struct {
 	Dir      string
 	IdleTime time.Duration
 	Debug    bool
+	Events   *Events
 
 	AppClosed func(*App)
 
@@ -388,6 +420,7 @@ func (a *AppPool) maybeIdle(app *App) bool {
 
 	diff := time.Since(app.lastUse)
 	if diff > a.IdleTime {
+		app.eventAdd("idle_app", "last_used", diff.String())
 		delete(a.apps, app.Name)
 		return true
 	}
@@ -412,9 +445,19 @@ func (a *AppPool) App(name string) (*App, error) {
 
 	path := filepath.Join(a.Dir, name)
 
+	a.Events.Add("app_lookup", "path", path)
+
 	stat, err := os.Stat(path)
 	if err != nil {
 		if os.IsNotExist(err) {
+			// Check there might be a link there but it's not valid
+			_, err := os.Lstat(path)
+			if err == nil {
+				dest, _ := os.Readlink(path)
+				fmt.Printf("! Bad symlink detected '%s'. Destination '%s' doesn't exist\n", path, dest)
+				a.Events.Add("bad_symlink", "path", path, "dest", dest)
+			}
+
 			return nil, ErrUnknownApp
 		}
 
@@ -428,6 +471,7 @@ func (a *AppPool) App(name string) (*App, error) {
 	}
 
 	if err != nil {
+		a.Events.Add("error_starting_app", "app", name, "error", err.Error())
 		return nil, err
 	}
 
@@ -468,10 +512,13 @@ func (a *AppPool) Purge() {
 	a.lock.Unlock()
 
 	for _, app := range apps {
+		app.eventAdd("purging_app")
 		app.t.Kill(nil)
 	}
 
 	for _, app := range apps {
 		app.t.Wait()
 	}
+
+	a.Events.Add("apps_purged")
 }

dev/events.go

@@ -0,0 +1,40 @@
+package dev
+
+import (
+	"bytes"
+	"fmt"
+	"io"
+	"time"
+
+	"github.com/puma/puma-dev/linebuffer"
+)
+
+type Events struct {
+	events linebuffer.LineBuffer
+}
+
+func (e *Events) Add(name string, args ...interface{}) string {
+	var buf bytes.Buffer
+
+	buf.WriteString("{")
+
+	fmt.Fprintf(&buf, `"time":"%s","event":"%s"`, time.Now(), name)
+
+	for i := 0; i < len(args); i += 2 {
+		k := args[i]
+		v := args[i+1]
+		fmt.Fprintf(&buf, `,"%s":%#v`, k, v)
+	}
+
+	buf.WriteString("}\n")
+
+	str := buf.String()
+
+	e.events.Append(str)
+
+	return str
+}
+
+func (e *Events) WriteTo(w io.Writer) (int64, error) {
+	return e.events.WriteTo(w)
+}

dev/http.go

@@ -2,6 +2,7 @@ package dev
 
 import (
 	"encoding/json"
+	"fmt"
 	"net"
 	"net/http"
 	"os"
@@ -20,6 +21,7 @@ type HTTPServer struct {
 	TLSAddress string
 	Pool       *AppPool
 	Debug      bool
+	Events     *Events
 
 	mux       *pat.PatternServeMux
 	transport *httpu.Transport
@@ -48,6 +50,7 @@ func (h *HTTPServer) Setup() {
 	h.mux = pat.New()
 
 	h.mux.Get("/status", http.HandlerFunc(h.status))
+	h.mux.Get("/events", http.HandlerFunc(h.events))
 }
 
 func (h *HTTPServer) AppClosed(app *App) {
@@ -169,6 +172,12 @@ func (h *HTTPServer) proxyReq(w http.ResponseWriter, req *http.Request) error {
 
 	app, err := h.findApp(name)
 	if err != nil {
+		if err == ErrUnknownApp {
+			h.Events.Add("unknown_app", "name", name, "host", req.Host)
+		} else {
+			h.Events.Add("lookup_error", "error", err.Error())
+		}
+
 		return err
 	}
 
@@ -187,6 +196,12 @@ func (h *HTTPServer) proxyReq(w http.ResponseWriter, req *http.Request) error {
 }
 
 func (h *HTTPServer) ServeHTTP(w http.ResponseWriter, req *http.Request) {
+	if h.Debug {
+		fmt.Fprintf(os.Stderr, "%s: %s '%s' (host=%s)\n",
+			time.Now().Format(time.RFC3339Nano),
+			req.Method, req.URL.Path, req.Host)
+	}
+
 	if req.Host == "puma-dev" {
 		h.mux.ServeHTTP(w, req)
 	} else {
@@ -228,3 +243,7 @@ func (h *HTTPServer) status(w http.ResponseWriter, req *http.Request) {
 
 	json.NewEncoder(w).Encode(statuses)
 }
+
+func (h *HTTPServer) events(w http.ResponseWriter, req *http.Request) {
+	h.Events.WriteTo(w)
+}