git » gofer » commit 35685dd

Improve logging and tracing

author Alberto Bertogli
2020-04-26 02:18:55 UTC
committer Alberto Bertogli
2020-04-26 09:21:50 UTC
parent f5923819c860795b231e37e67bd6a7409860d0a5
Improve logging and tracing

This patch changes the way events are logged. Instead of writing every
request to the log, we use the tracing framework to do it in a more
manageable way.
debug/debug.go +118 -0
go.mod +1 -0
go.sum +6 -0
gofer.go +4 -37
gofer_test.go +2 -1
proxy/http.go +127 -39
proxy/raw.go +13 -8
trace/trace.go +130 -0 
diff --git a/debug/debug.go b/debug/debug.go
new file mode 100644
index 0000000..b318ee8
--- /dev/null
+++ b/debug/debug.go
@@ -0,0 +1,118 @@
+package debug
+
+import (
+	"html/template"
+	"net/http"
+	"os"
+	"strconv"
+	"time"
+
+	// Remote profiling support.
+	_ "net/http/pprof"
+
+	"blitiri.com.ar/go/gofer/config"
+	"blitiri.com.ar/go/log"
+)
+
+// Build information, overridden at build time using
+// -ldflags="-X blitiri.com.ar/go/gofer/internal/debug.Version=blah".
+var (
+	Version      = "undefined"
+	SourceDateTs = "0"
+
+	// Derived from SourceDateTs.
+	SourceDate    = time.Time{}
+	SourceDateStr = ""
+)
+
+func init() {
+	sdts, err := strconv.ParseInt(SourceDateTs, 10, 0)
+	if err != nil {
+		panic(err)
+	}
+
+	SourceDate = time.Unix(sdts, 0)
+	SourceDateStr = SourceDate.Format("2006-01-02 15:04:05 -0700")
+}
+
+func ServeDebugging(addr string, conf *config.Config) {
+	log.Infof("Debugging HTTP server listening on %s", addr)
+
+	indexData := struct {
+		Version    string
+		SourceDate time.Time
+		StartTime  time.Time
+		Args       []string
+	}{
+		Version:    Version,
+		SourceDate: SourceDate,
+		StartTime:  time.Now(),
+		Args:       os.Args,
+	}
+
+	http.HandleFunc("/debug/config", DumpConfigFunc(conf))
+	http.HandleFunc("/", func(w http.ResponseWriter, r *http.Request) {
+		if r.URL.Path != "/" {
+			http.NotFound(w, r)
+			return
+		}
+		if err := htmlIndex.Execute(w, indexData); err != nil {
+			log.Infof("Monitoring handler error: %v", err)
+		}
+	})
+
+	http.ListenAndServe(addr, nil)
+}
+
+func DumpConfigFunc(conf *config.Config) http.HandlerFunc {
+	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		s, err := conf.ToString()
+		if err != nil {
+			http.Error(w, err.Error(), http.StatusInternalServerError)
+			return
+		}
+
+		w.Header().Set("Content-Type", "text/plain; charset=utf-8")
+		w.Write([]byte(s))
+	})
+}
+
+// Static index for the debugging website.
+var htmlIndex = template.Must(template.New("index").Funcs(
+	template.FuncMap{"since": time.Since}).Parse(
+	`<!DOCTYPE html>
+<html>
+  <head>
+    <title>gofer debugging</title>
+  </head>
+  <body>
+    <h1>gofer debugging</h1>
+
+	version {{.Version}}<br>
+	source date {{.SourceDate.Format "2006-01-02 15:04:05 -0700"}}<p>
+
+	started {{.StartTime.Format "Mon, 2006-01-02 15:04:05 -0700"}}<br>
+	up for {{.StartTime | since}}<p>
+
+	args: <tt>{{.Args}}</tt><p>
+
+    <ul>
+      <li><a href="/debug/config">configuration</a>
+	  <li>traces <small><a href="https://godoc.org/golang.org/x/net/trace">
+            (ref)</a></small>
+        <ul>
+          <li><a href="/debug/requests?exp=1">requests (short-lived)</a>
+          <li><a href="/debug/events?exp=1">events (long-lived)</a>
+        </ul>
+      <li><a href="/debug/vars">exported variables</a>
+	       <small><a href="https://golang.org/pkg/expvar/">(ref)</a></small>
+      <li><a href="/debug/pprof">pprof</a>
+          <small><a href="https://golang.org/pkg/net/http/pprof/">
+            (ref)</a></small>
+        <ul>
+          <li><a href="/debug/pprof/goroutine?debug=1">goroutines</a>
+        </ul>
+    </ul>
+  </body>
+</html>
+`))
diff --git a/go.mod b/go.mod
index 360c226..7c0aec9 100644
--- a/go.mod
+++ b/go.mod
@@ -6,4 +6,5 @@ require (
 	blitiri.com.ar/go/log v0.0.0-20171003035348-6cd06f6ca2f8
 	blitiri.com.ar/go/systemd v0.0.0-20171003041308-cdc4fd023aa4
 	github.com/BurntSushi/toml v0.3.1
+	golang.org/x/net v0.0.0-20200425230154-ff2c4b7c35a0
 )
diff --git a/go.sum b/go.sum
index 240c70d..96efb0d 100644
--- a/go.sum
+++ b/go.sum
@@ -4,3 +4,9 @@ blitiri.com.ar/go/systemd v0.0.0-20171003041308-cdc4fd023aa4 h1:ceTBe2TiHNkhA7q/
 blitiri.com.ar/go/systemd v0.0.0-20171003041308-cdc4fd023aa4/go.mod h1:FmDkVlYnOzDHOhtSwtLHh6z9WVVx+aPjrHkPtfA3qhI=
 github.com/BurntSushi/toml v0.3.1 h1:WXkYYl6Yr3qBf1K79EBnL4mak0OimBfB0XUf9Vl28OQ=
 github.com/BurntSushi/toml v0.3.1/go.mod h1:xHWCNGjB5oqiDr8zfno3MHue2Ht5sIBksp03qcyfWMU=
+golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w=
+golang.org/x/net v0.0.0-20200425230154-ff2c4b7c35a0 h1:Jcxah/M+oLZ/R4/z5RzfPzGbPXnVDPkEDtf2JnuxN+U=
+golang.org/x/net v0.0.0-20200425230154-ff2c4b7c35a0/go.mod h1:qpuaurCH72eLCgpAm/N6yyVIVM9cpaDIP3A8BGJEC5A=
+golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
+golang.org/x/sys v0.0.0-20200323222414-85ca7c5b95cd/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
+golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=
diff --git a/gofer.go b/gofer.go
index dcb473c..7fa7d0c 100644
--- a/gofer.go
+++ b/gofer.go
@@ -2,11 +2,10 @@ package main
 
 import (
 	"flag"
-	"net/http"
-	"runtime"
 	"time"
 
 	"blitiri.com.ar/go/gofer/config"
+	"blitiri.com.ar/go/gofer/debug"
 	"blitiri.com.ar/go/gofer/proxy"
 	"blitiri.com.ar/go/log"
 )
@@ -42,43 +41,11 @@ func main() {
 		go proxy.Raw(raw)
 	}
 
-	// Monitoring server.
 	if conf.ControlAddr != "" {
-		mux := http.NewServeMux()
-		mux.HandleFunc("/debug/stack", dumpStack)
-		mux.HandleFunc("/debug/config", dumpConfigFunc(conf))
-
-		server := http.Server{
-			Addr:    conf.ControlAddr,
-			Handler: mux,
-		}
+		go debug.ServeDebugging(conf.ControlAddr, conf)
+	}
 
-		log.Infof("%s Starting monitoring server ", server.Addr)
-		log.Fatalf("%v", server.ListenAndServe())
-	} else {
-		log.Infof("No monitoring server, idle loop")
+	for {
 		time.Sleep(1 * time.Hour)
 	}
 }
-
-// dumpStack handler for the control listener.
-func dumpStack(w http.ResponseWriter, r *http.Request) {
-	w.Header().Set("Content-Type", "text/plain; charset=utf-8")
-	buf := make([]byte, 500*1024)
-	c := runtime.Stack(buf, true)
-	w.Write(buf[:c])
-}
-
-// dumpConfig handler for the control listener.
-func dumpConfigFunc(conf *config.Config) http.HandlerFunc {
-	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-		s, err := conf.ToString()
-		if err != nil {
-			http.Error(w, err.Error(), http.StatusInternalServerError)
-			return
-		}
-
-		w.Header().Set("Content-Type", "text/plain; charset=utf-8")
-		w.Write([]byte(s))
-	})
-}
diff --git a/gofer_test.go b/gofer_test.go
index 0a374a4..1b21c81 100644
--- a/gofer_test.go
+++ b/gofer_test.go
@@ -8,6 +8,7 @@ import (
 	"testing"
 
 	"blitiri.com.ar/go/gofer/config"
+	"blitiri.com.ar/go/gofer/debug"
 )
 
 func TestDumpConfig(t *testing.T) {
@@ -16,7 +17,7 @@ func TestDumpConfig(t *testing.T) {
 		t.Fatalf("error loading config example: %v", err)
 	}
 
-	srv := httptest.NewServer(http.HandlerFunc(dumpConfigFunc(conf)))
+	srv := httptest.NewServer(http.HandlerFunc(debug.DumpConfigFunc(conf)))
 
 	res, err := http.Get(srv.URL)
 	if err != nil {
diff --git a/proxy/http.go b/proxy/http.go
index b1127c9..78a26e6 100644
--- a/proxy/http.go
+++ b/proxy/http.go
@@ -2,13 +2,13 @@ package proxy
 
 import (
 	"crypto/tls"
-	"fmt"
 	"net/http"
 	"net/http/httputil"
 	"net/url"
 	"strings"
 
 	"blitiri.com.ar/go/gofer/config"
+	"blitiri.com.ar/go/gofer/trace"
 	"blitiri.com.ar/go/gofer/util"
 	"blitiri.com.ar/go/log"
 	"blitiri.com.ar/go/systemd"
@@ -52,11 +52,11 @@ func HTTP(conf config.HTTP) {
 	srv := httpServer(conf)
 	lis, err := systemd.Listen("tcp", conf.Addr)
 	if err != nil {
-		log.Fatalf("HTTP proxy error listening on %q: %v", conf.Addr, err)
+		log.Fatalf("%s error listening: %v", conf.Addr, err)
 	}
-	log.Infof("HTTP proxy on %q (%q)", conf.Addr, lis.Addr())
+	log.Infof("%s http proxy starting on %q", conf.Addr, lis.Addr())
 	err = srv.Serve(lis)
-	log.Fatalf("HTTP proxy exited: %v", err)
+	log.Fatalf("%s http proxy exited: %v", conf.Addr, err)
 }
 
 func HTTPS(conf config.HTTPS) {
@@ -65,12 +65,12 @@ func HTTPS(conf config.HTTPS) {
 
 	srv.TLSConfig, err = util.LoadCerts(conf.Certs)
 	if err != nil {
-		log.Fatalf("error loading certs: %v", err)
+		log.Fatalf("%s error loading certs: %v", conf.Addr, err)
 	}
 
 	rawLis, err := systemd.Listen("tcp", conf.Addr)
 	if err != nil {
-		log.Fatalf("HTTPS proxy error listening on %q: %v", conf.Addr, err)
+		log.Fatalf("%s error listening: %v", conf.Addr, err)
 	}
 
 	// We need to set the NextProtos manually before creating the TLS
@@ -79,9 +79,9 @@ func HTTPS(conf config.HTTPS) {
 		"h2", "http/1.1")
 	lis := tls.NewListener(rawLis, srv.TLSConfig)
 
-	log.Infof("HTTPS proxy on %q (%q)", conf.Addr, lis.Addr())
+	log.Infof("%s https proxy starting on %q", conf.Addr, lis.Addr())
 	err = srv.Serve(lis)
-	log.Fatalf("HTTPS proxy exited: %v", err)
+	log.Fatalf("%s https proxy exited: %v", conf.Addr, err)
 }
 
 func makeProxy(from string, to url.URL) http.Handler {
@@ -119,7 +119,7 @@ func makeProxy(from string, to url.URL) http.Handler {
 		//req.Host = to.Host
 	}
 
-	return proxy
+	return newReverseProxy(proxy)
 }
 
 // joinPath joins to HTTP paths. We can't use path.Join because it strips the
@@ -163,19 +163,29 @@ func makeDir(from string, to url.URL) http.Handler {
 	from = stripDomain(from)
 
 	fs := http.FileServer(http.Dir(to.Path))
-	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-		r.URL.Path = strings.TrimPrefix(r.URL.Path, from)
-		if r.URL.Path == "" || r.URL.Path[0] != '/' {
-			r.URL.Path = "/" + r.URL.Path
-		}
-		fs.ServeHTTP(w, r)
-	})
+	return WithLogging("http:dir",
+		http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+			tr, _ := trace.FromContext(r.Context())
+			tr.Printf("serving dir root %q", to.Path)
+
+			r.URL.Path = strings.TrimPrefix(r.URL.Path, from)
+			if r.URL.Path == "" || r.URL.Path[0] != '/' {
+				r.URL.Path = "/" + r.URL.Path
+			}
+			tr.Printf("adjusted path: %q", r.URL.Path)
+			fs.ServeHTTP(w, r)
+		}),
+	)
 }
 
 func makeStatic(from string, to url.URL) http.Handler {
-	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-		http.ServeFile(w, r, to.Path)
-	})
+	return WithLogging("http:static",
+		http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+			tr, _ := trace.FromContext(r.Context())
+			tr.Printf("statically serving %q", to.Path)
+			http.ServeFile(w, r, to.Path)
+		}),
+	)
 }
 
 func makeRedirect(from string, to url.URL) http.Handler {
@@ -187,37 +197,115 @@ func makeRedirect(from string, to url.URL) http.Handler {
 			to.Opaque, err)
 	}
 
-	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-		target := *dst
-		target.RawQuery = r.URL.RawQuery
-		target.Path = adjustPath(r.URL.Path, from, dst.Path)
-
-		http.Redirect(w, r, target.String(), http.StatusTemporaryRedirect)
-	})
+	return WithLogging("http:redirect",
+		http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+			tr, _ := trace.FromContext(r.Context())
+			target := *dst
+			target.RawQuery = r.URL.RawQuery
+			target.Path = adjustPath(r.URL.Path, from, dst.Path)
+			tr.Printf("redirect to %q", target.String())
+
+			http.Redirect(w, r, target.String(), http.StatusTemporaryRedirect)
+		}),
+	)
 }
 
 type loggingTransport struct{}
 
 func (t *loggingTransport) RoundTrip(req *http.Request) (*http.Response, error) {
-	response, err := http.DefaultTransport.RoundTrip(req)
+	tr, _ := trace.FromContext(req.Context())
 
-	errs := ""
-	if err != nil {
-		errs = " (" + err.Error() + ")"
-	}
+	tr.Printf("proxy to: %s %s %s",
+		req.Proto, req.Method, req.URL.String())
 
-	resps := "<nil>"
-	if response != nil {
-		resps = fmt.Sprintf("%d", response.StatusCode)
+	response, err := http.DefaultTransport.RoundTrip(req)
+	if response == nil || err != nil {
+		// errorHandler will be invoked for these, avoid double error logging.
+		tr.Printf("response: %v", response)
+		tr.Printf("%v", err)
+		tr.SetError()
+	} else {
+		tr.Printf("%s", response.Status)
+		tr.Printf("%d bytes", response.ContentLength)
+		if response.StatusCode >= 400 {
+			tr.SetError()
+		}
 	}
 
-	// 1.2.3.4:34575 HTTP/2.0 domain.com https://backend/path -> 200
-	log.Infof("%s %s %s %s -> %s%s",
-		req.RemoteAddr, req.Proto, req.Host, req.URL,
-		resps, errs)
-
 	return response, err
 }
 
 // Use a single logging transport, we don't need more than one.
 var transport = &loggingTransport{}
+
+type reverseProxy struct {
+	rp *httputil.ReverseProxy
+}
+
+func newReverseProxy(rp *httputil.ReverseProxy) http.Handler {
+	p := &reverseProxy{
+		rp: rp,
+	}
+	rp.ErrorHandler = p.errorHandler
+	return p
+}
+
+func (p *reverseProxy) ServeHTTP(rw http.ResponseWriter, req *http.Request) {
+	tr := trace.New("http:proxy", req.Host+req.URL.String())
+	defer tr.Finish()
+
+	tr.Printf("%s %s %s %s %s",
+		req.RemoteAddr, req.Proto, req.Method, req.Host, req.URL.String())
+
+	// Associate the trace with this request.
+	req = req.WithContext(trace.NewContext(req.Context(), tr))
+
+	p.rp.ServeHTTP(rw, req)
+}
+
+func (p *reverseProxy) errorHandler(w http.ResponseWriter, r *http.Request, err error) {
+	tr, _ := trace.FromContext(r.Context())
+	tr.Errorf("proxy: %v", err)
+	w.WriteHeader(http.StatusBadGateway)
+}
+
+// Wrapper around http.ResponseWriter so we can extract status and length.
+type statusWriter struct {
+	http.ResponseWriter
+	status int
+	length int
+}
+
+func (w *statusWriter) WriteHeader(status int) {
+	w.status = status
+	w.ResponseWriter.WriteHeader(status)
+}
+
+func (w *statusWriter) Write(b []byte) (int, error) {
+	n, err := w.ResponseWriter.Write(b)
+	w.length += n
+	return n, err
+}
+
+func WithLogging(name string, parent http.Handler) http.Handler {
+	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		tr := trace.New(name, r.Host+r.URL.String())
+		defer tr.Finish()
+
+		// Associate the trace with this request.
+		r = r.WithContext(trace.NewContext(r.Context(), tr))
+
+		// Wrap the writer so we can get output information.
+		sw := statusWriter{ResponseWriter: w}
+
+		tr.Printf("%s %s %s %s %s",
+			r.RemoteAddr, r.Proto, r.Method, r.Host, r.URL.String())
+		parent.ServeHTTP(&sw, r)
+		tr.Printf("%d %s", sw.status, http.StatusText(sw.status))
+		tr.Printf("%d bytes", sw.length)
+
+		if sw.status >= 400 {
+			tr.SetError()
+		}
+	})
+}
diff --git a/proxy/raw.go b/proxy/raw.go
index 5a26fd2..68ba7e0 100644
--- a/proxy/raw.go
+++ b/proxy/raw.go
@@ -2,10 +2,11 @@ package proxy
 
 import (
 	"crypto/tls"
+	"fmt"
 	"net"
-	"time"
 
 	"blitiri.com.ar/go/gofer/config"
+	"blitiri.com.ar/go/gofer/trace"
 	"blitiri.com.ar/go/gofer/util"
 	"blitiri.com.ar/go/log"
 	"blitiri.com.ar/go/systemd"
@@ -47,7 +48,13 @@ func Raw(conf config.Raw) {
 func forward(src net.Conn, dstAddr string, dstTLS bool) {
 	defer src.Close()
 
-	start := time.Now()
+	tr := trace.New("raw", fmt.Sprintf("%s -> %s", src.LocalAddr(), dstAddr))
+	defer tr.Finish()
+
+	tr.Printf("remote: %s ", src.RemoteAddr())
+	tr.Printf("%s -> %s (tls=%v)",
+		src.LocalAddr(), dstAddr, dstTLS)
+
 	var dst net.Conn
 	var err error
 	if dstTLS {
@@ -57,16 +64,14 @@ func forward(src net.Conn, dstAddr string, dstTLS bool) {
 	}
 
 	if err != nil {
-		log.Errorf("%s error dialing back: %v", src.LocalAddr(), err)
+		tr.Errorf("%s error dialing %v : %v", src.LocalAddr(), dstAddr, err)
 		return
 	}
 	defer dst.Close()
 
-	startCopy := time.Now()
+	tr.Printf("dial complete: %v -> %v", dst.LocalAddr(), dst.RemoteAddr())
+
 	util.BidirCopy(src, dst)
-	end := time.Now()
 
-	log.Infof("%s raw %s -> %s (%s+%s=%s)",
-		src.RemoteAddr(), src.LocalAddr(), dst.RemoteAddr(),
-		startCopy.Sub(start), end.Sub(startCopy), end.Sub(start))
+	tr.Printf("copy complete")
 }
diff --git a/trace/trace.go b/trace/trace.go
new file mode 100644
index 0000000..aa9d5c9
--- /dev/null
+++ b/trace/trace.go
@@ -0,0 +1,130 @@
+// Package trace extends golang.org/x/net/trace.
+package trace
+
+import (
+	"context"
+	"fmt"
+	"strconv"
+
+	"blitiri.com.ar/go/log"
+
+	nettrace "golang.org/x/net/trace"
+)
+
+const contextKey = "blitiri.com.ar/go/gofer/trace.Trace"
+
+// A Trace represents an active request.
+type Trace struct {
+	family string
+	title  string
+	t      nettrace.Trace
+}
+
+// New trace.
+func New(family, title string) *Trace {
+	return &Trace{family, title, nettrace.New(family, title)}
+}
+
+func NewContext(ctx context.Context, tr *Trace) context.Context {
+	return context.WithValue(ctx, contextKey, tr)
+}
+
+func FromContext(ctx context.Context) (tr *Trace, ok bool) {
+	tr, ok = ctx.Value(contextKey).(*Trace)
+	return
+}
+
+// Printf adds this message to the trace's log.
+func (t *Trace) Printf(format string, a ...interface{}) {
+	t.t.LazyPrintf(format, a...)
+
+	log.Log(log.Debug, 1, "%#p %s %s: %s", t, t.family, t.title,
+		quote(fmt.Sprintf(format, a...)))
+}
+
+// Debugf adds this message to the trace's log, with a debugging level.
+func (t *Trace) Debugf(format string, a ...interface{}) {
+	t.t.LazyPrintf(format, a...)
+
+	log.Log(log.Debug, 1, "%#p %s %s: %s",
+		t, t.family, t.title, quote(fmt.Sprintf(format, a...)))
+}
+
+// Errorf adds this message to the trace's log, with an error level.
+func (t *Trace) Errorf(format string, a ...interface{}) error {
+	// Note we can't just call t.Error here, as it breaks caller logging.
+	err := fmt.Errorf(format, a...)
+	t.t.SetError()
+	t.t.LazyPrintf("error: %v", err)
+
+	log.Log(log.Info, 1, "%#p %s %s error: %s", t, t.family, t.title,
+		quote(err.Error()))
+	return err
+}
+
+// Error marks the trace as having seen an error, and also logs it to the
+// trace's log.
+func (t *Trace) Error(err error) error {
+	t.t.SetError()
+	t.t.LazyPrintf("error: %v", err)
+
+	log.Log(log.Info, 1, "%#p %s %s error: %s", t, t.family, t.title,
+		quote(err.Error()))
+
+	return err
+}
+
+// SetError marks the trace as having received an error, without emitting any
+// particular output.
+func (t *Trace) SetError() {
+	t.t.SetError()
+}
+
+// Finish the trace. It should not be changed after this is called.
+func (t *Trace) Finish() {
+	t.t.Finish()
+}
+
+// EventLog is used for tracing long-lived objects.
+type EventLog struct {
+	family string
+	title  string
+	e      nettrace.EventLog
+}
+
+// NewEventLog returns a new EventLog.
+func NewEventLog(family, title string) *EventLog {
+	return &EventLog{family, title, nettrace.NewEventLog(family, title)}
+}
+
+// Printf adds the message to the EventLog.
+func (e *EventLog) Printf(format string, a ...interface{}) {
+	e.e.Printf(format, a...)
+
+	log.Log(log.Debug, 1, "%#p %s %s: %s", e, e.family, e.title,
+		quote(fmt.Sprintf(format, a...)))
+}
+
+// Debugf adds the message to the EventLog, with a debugging level.
+func (e *EventLog) Debugf(format string, a ...interface{}) {
+	e.e.Printf(format, a...)
+
+	log.Log(log.Debug, 1, "%#p %s %s: %s", e, e.family, e.title,
+		quote(fmt.Sprintf(format, a...)))
+}
+
+// Errorf adds the message to the EventLog, with an error level.
+func (e *EventLog) Errorf(format string, a ...interface{}) error {
+	err := fmt.Errorf(format, a...)
+	e.e.Errorf("error: %v", err)
+
+	log.Log(log.Info, 1, "%#p %s %s: error: %s",
+		e, e.family, e.title, quote(err.Error()))
+
+	return err
+}
+
+func quote(s string) string {
+	qs := strconv.Quote(s)
+	return qs[1 : len(qs)-1]
+}