From 643989157cb1079c89fcf9cde51155ae7af6225c Mon Sep 17 00:00:00 2001 From: Evan Phoenix Date: Thu, 11 Aug 2016 21:18:08 -0600 Subject: [PATCH] Improve error context and add events buffer --- cmd/puma-dev/main_darwin.go | 4 +++ cmd/puma-dev/main_linux.go | 4 +++ dev/app.go | 63 ++++++++++++++++++++++++++++++++----- dev/events.go | 40 +++++++++++++++++++++++ dev/http.go | 19 +++++++++++ dev/setup.go | 7 +++-- 6 files changed, 126 insertions(+), 11 deletions(-) create mode 100644 dev/events.go diff --git a/cmd/puma-dev/main_darwin.go b/cmd/puma-dev/main_darwin.go index 50dfb87c..5ea64872 100644 --- a/cmd/puma-dev/main_darwin.go +++ b/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() diff --git a/cmd/puma-dev/main_linux.go b/cmd/puma-dev/main_linux.go index 5df659a8..f5edd004 100644 --- a/cmd/puma-dev/main_linux.go +++ b/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() diff --git a/dev/app.go b/dev/app.go index 801cfe6f..b2901aa7 100644 --- a/dev/app.go +++ b/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,14 +119,17 @@ 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) @@ -117,6 +137,8 @@ func (a *App) watch() error { 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,7 +285,7 @@ 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) @@ -273,12 +293,15 @@ func (pool *AppPool) LaunchApp(name, dir string) (*App, error) { 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") } diff --git a/dev/events.go b/dev/events.go new file mode 100644 index 00000000..fa2d6f6d --- /dev/null +++ b/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) +} diff --git a/dev/http.go b/dev/http.go index a1d7e038..c495f094 100644 --- a/dev/http.go +++ b/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) +} diff --git a/dev/setup.go b/dev/setup.go index a777f141..b19e6183 100644 --- a/dev/setup.go +++ b/dev/setup.go @@ -10,6 +10,7 @@ import ( "github.com/kardianos/osext" "github.com/mitchellh/go-homedir" + "github.com/vektra/errors" ) func Setup() error { @@ -111,7 +112,7 @@ func InstallIntoSystem(listenPort, tlsPort int, dir, domains, timeout string) er binPath, err := osext.Executable() if err != nil { - return err + return errors.Context(err, "calculating executable path") } fmt.Printf("* Use '%s' as the location of puma-dev\n", binPath) @@ -173,7 +174,7 @@ func InstallIntoSystem(listenPort, tlsPort int, dir, domains, timeout string) er ) if err != nil { - return err + return errors.Context(err, "writing LaunchAgent plist") } // Unload a previous one if need be. @@ -181,7 +182,7 @@ func InstallIntoSystem(listenPort, tlsPort int, dir, domains, timeout string) er err = exec.Command("launchctl", "load", plist).Run() if err != nil { - return err + return errors.Context(err, "loading plist into launchctl") } fmt.Printf("* Installed puma-dev on ports: http %d, https %d\n", listenPort, tlsPort)