From 14fb7f723d88d4936fee4076c3b49c77eb98b202 Mon Sep 17 00:00:00 2001 From: Christine Dodrill Date: Sun, 1 Oct 2017 06:54:56 -0700 Subject: [PATCH] start adding go stdlib tracing --- cmd/routed/main.go | 6 ++- {cmd/routed => internal}/gops.go | 2 +- internal/init.go | 11 +++++ internal/manhole.go | 27 +++++++++++ internal/middleware/trace.go | 41 ++++++++++++++++ vendor-log | 5 ++ vendor/github.com/Xe/ln/ex/doc.go | 7 +++ vendor/github.com/Xe/ln/ex/gotrace.go | 68 +++++++++++++++++++++++++++ vendor/github.com/Xe/ln/ex/http.go | 36 ++++++++++++++ vendor/github.com/Xe/ln/ex/l2met.go | 25 ++++++++++ 10 files changed, 225 insertions(+), 3 deletions(-) rename {cmd/routed => internal}/gops.go (88%) create mode 100644 internal/init.go create mode 100644 internal/manhole.go create mode 100644 internal/middleware/trace.go create mode 100644 vendor/github.com/Xe/ln/ex/doc.go create mode 100644 vendor/github.com/Xe/ln/ex/gotrace.go create mode 100644 vendor/github.com/Xe/ln/ex/http.go create mode 100644 vendor/github.com/Xe/ln/ex/l2met.go diff --git a/cmd/routed/main.go b/cmd/routed/main.go index 94c789d..2899bb4 100644 --- a/cmd/routed/main.go +++ b/cmd/routed/main.go @@ -9,6 +9,8 @@ import ( "net/http" "time" + _ "git.xeserv.us/xena/route/internal" + "git.xeserv.us/xena/route/internal/middleware" "git.xeserv.us/xena/route/internal/routecrypto" "git.xeserv.us/xena/route/internal/server" "github.com/Xe/ln" @@ -52,7 +54,7 @@ func main() { defer l.Close() hs := &http.Server{ - Handler: s, + Handler: middleware.Trace(s), Addr: scfg.WebAddr, } @@ -61,7 +63,7 @@ func main() { func setupTLS(s *server.Server, scfg server.Config) { hs := &http.Server{ - Handler: s, + Handler: middleware.Trace(s), Addr: scfg.SSLAddr, TLSConfig: &tls.Config{ GetCertificate: s.GetCertificate, diff --git a/cmd/routed/gops.go b/internal/gops.go similarity index 88% rename from cmd/routed/gops.go rename to internal/gops.go index 184b656..51620fc 100644 --- a/cmd/routed/gops.go +++ b/internal/gops.go @@ -1,4 +1,4 @@ -package main +package internal import ( "log" diff --git a/internal/init.go b/internal/init.go new file mode 100644 index 0000000..f9cb251 --- /dev/null +++ b/internal/init.go @@ -0,0 +1,11 @@ +// Package internal contains autoloading packages and tools. +package internal + +import ( + "github.com/Xe/ln" + "github.com/Xe/ln/ex" +) + +func init() { + ln.DefaultLogger.Filters = append(ln.DefaultLogger.Filters, ex.NewGoTraceLogger()) +} diff --git a/internal/manhole.go b/internal/manhole.go new file mode 100644 index 0000000..9de919b --- /dev/null +++ b/internal/manhole.go @@ -0,0 +1,27 @@ +package internal + +import ( + "log" + "net" + "net/http" + "net/rpc" + + // Add HTTP pprof routes + _ "net/http/pprof" + + // Add tracing routes + _ "golang.org/x/net/trace" +) + +func init() { + l, err := net.Listen("tcp", "127.0.0.1:0") + if err != nil { + log.Printf("manhole: cannot bind to 127.0.0.1:0: %v", err) + return + } + + log.Printf("manhole: Now listening on http://%s", l.Addr()) + + rpc.HandleHTTP() + go http.Serve(l, nil) +} diff --git a/internal/middleware/trace.go b/internal/middleware/trace.go new file mode 100644 index 0000000..3db56c1 --- /dev/null +++ b/internal/middleware/trace.go @@ -0,0 +1,41 @@ +package middleware + +import ( + "context" + "net/http" + "os" + "path/filepath" + "time" + + "github.com/Xe/ln" + "golang.org/x/net/trace" +) + +// Trace adds go stdlib tracing to this http handler. +func Trace(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + sp := trace.New(filepath.Base(os.Args[0]), "http://"+r.Host+r.RequestURI) + defer sp.Finish() + ctx, cancel := context.WithTimeout(r.Context(), 30*time.Second) + defer cancel() + + ctx = trace.NewContext(ctx, sp) + f := ln.F{ + "method": r.Method, + "path": r.URL.Path, + "remote_addr": r.RemoteAddr, + "user_agent": r.UserAgent(), + } + + next.ServeHTTP(w, r.WithContext(ctx)) + + ws, ok := w.(interface { + Status() int + }) + if ok { + f["status"] = ws.Status() + } + + ln.Log(ctx, f) + }) +} diff --git a/vendor-log b/vendor-log index 6495569..f67b125 100644 --- a/vendor-log +++ b/vendor-log @@ -325,3 +325,8 @@ b6e1ae21643682ce023deb8d152024597b0e9bb4 golang.org/x/sys/unix 8443e311d3925f5e20494496790670942ed48504 google.golang.org/grpc/transport 466e05b2ef3e48ce08a367b6aaac09ee29a124e5 github.com/Xe/ln 2b3a18b5f0fb6b4f9190549597d3f962c02bc5eb github.com/pkg/errors +466e05b2ef3e48ce08a367b6aaac09ee29a124e5 github.com/Xe/ln +466e05b2ef3e48ce08a367b6aaac09ee29a124e5 github.com/Xe/ln/ex +2b3a18b5f0fb6b4f9190549597d3f962c02bc5eb github.com/pkg/errors +0a9397675ba34b2845f758fe3cd68828369c6517 golang.org/x/net/internal/timeseries +0a9397675ba34b2845f758fe3cd68828369c6517 golang.org/x/net/trace diff --git a/vendor/github.com/Xe/ln/ex/doc.go b/vendor/github.com/Xe/ln/ex/doc.go new file mode 100644 index 0000000..932ed42 --- /dev/null +++ b/vendor/github.com/Xe/ln/ex/doc.go @@ -0,0 +1,7 @@ +/* +Package ex is a set of extensions and middleware for ln. + +This package will (inevitably) have a lot of third-party dependencies and +as such might be broken apart into other packages in the future. +*/ +package ex diff --git a/vendor/github.com/Xe/ln/ex/gotrace.go b/vendor/github.com/Xe/ln/ex/gotrace.go new file mode 100644 index 0000000..5579879 --- /dev/null +++ b/vendor/github.com/Xe/ln/ex/gotrace.go @@ -0,0 +1,68 @@ +package ex + +import ( + "context" + "log" + + "github.com/Xe/ln" + "golang.org/x/net/trace" +) + +type goEventLogger struct { + ev trace.EventLog +} + +// NewGoEventLogger will log ln information to a given trace.EventLog instance. +func NewGoEventLogger(ev trace.EventLog) ln.Filter { + return &goEventLogger{ev: ev} +} + +func (gel *goEventLogger) Apply(ctx context.Context, e ln.Event) bool { + data, err := ln.DefaultFormatter.Format(ctx, e) + if err != nil { + log.Printf("wtf: error in log formatting: %v", err) + return false + } + + if everr := e.Data["err"]; everr != nil { + gel.ev.Errorf("%s", string(data)) + return true + } + + gel.ev.Printf("%s", string(data)) + return true +} + +func (gel *goEventLogger) Close() { gel.ev.Finish() } +func (gel *goEventLogger) Run() {} + +type sst string + +func (s sst) String() string { return string(s) } + +func goTraceLogger(ctx context.Context, e ln.Event) bool { + sp, ok := trace.FromContext(ctx) + if !ok { + return true // no trace in context + } + + data, err := ln.DefaultFormatter.Format(ctx, e) + if err != nil { + log.Printf("wtf: error in log formatting: %v", err) + return false + } + + if everr := e.Data["err"]; everr != nil { + sp.SetError() + } + + sp.LazyLog(sst(string(data)), false) + + return true +} + +// NewGoTraceLogger will log ln information to a golang.org/x/net/trace.Trace +// if it is present in the context of ln calls. +func NewGoTraceLogger() ln.Filter { + return ln.FilterFunc(goTraceLogger) +} diff --git a/vendor/github.com/Xe/ln/ex/http.go b/vendor/github.com/Xe/ln/ex/http.go new file mode 100644 index 0000000..c5715a3 --- /dev/null +++ b/vendor/github.com/Xe/ln/ex/http.go @@ -0,0 +1,36 @@ +package ex + +import ( + "net" + "net/http" + "time" + + "github.com/Xe/ln" +) + +func HTTPLog(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + host, _, _ := net.SplitHostPort(r.RemoteAddr) + f := ln.F{ + "remote_ip": host, + "x_forwarded_for": r.Header.Get("X-Forwarded-For"), + "path": r.URL.Path, + } + ctx := ln.WithF(r.Context(), f) + st := time.Now() + + next.ServeHTTP(w, r.WithContext(ctx)) + + af := time.Now() + f["request_duration"] = af.Sub(st) + + ws, ok := w.(interface { + Status() int + }) + if ok { + f["status"] = ws.Status() + } + + ln.Log(r.Context(), f) + }) +} diff --git a/vendor/github.com/Xe/ln/ex/l2met.go b/vendor/github.com/Xe/ln/ex/l2met.go new file mode 100644 index 0000000..e2a7f19 --- /dev/null +++ b/vendor/github.com/Xe/ln/ex/l2met.go @@ -0,0 +1,25 @@ +package ex + +import ( + "time" + + "github.com/Xe/ln" +) + +// This file deals with formatting of [l2met] style metrics. +// [l2met]: https://r.32k.io/l2met-introduction + +// Counter formats a value as a metrics counter. +func Counter(name string, value int) ln.Fer { + return ln.F{"count#" + name: value} +} + +// Gauge formats a value as a metrics gauge. +func Gauge(name string, value int) ln.Fer { + return ln.F{"gauge#" + name: value} +} + +// Measure formats a value as a metrics measure. +func Measure(name string, ts time.Time) ln.Fer { + return ln.F{"measure#" + name: time.Since(ts)} +}