1// Copyright 2015 The Go Authors. All rights reserved.
2// Use of this source code is governed by a BSD-style
3// license that can be found in the LICENSE file.
4
5package trace
6
7import (
8	"bytes"
9	"fmt"
10	"html/template"
11	"io"
12	"log"
13	"net/http"
14	"runtime"
15	"sort"
16	"strconv"
17	"strings"
18	"sync"
19	"sync/atomic"
20	"text/tabwriter"
21	"time"
22)
23
24var eventsTmpl = template.Must(template.New("events").Funcs(template.FuncMap{
25	"elapsed":   elapsed,
26	"trimSpace": strings.TrimSpace,
27}).Parse(eventsHTML))
28
29const maxEventsPerLog = 100
30
31type bucket struct {
32	MaxErrAge time.Duration
33	String    string
34}
35
36var buckets = []bucket{
37	{0, "total"},
38	{10 * time.Second, "errs<10s"},
39	{1 * time.Minute, "errs<1m"},
40	{10 * time.Minute, "errs<10m"},
41	{1 * time.Hour, "errs<1h"},
42	{10 * time.Hour, "errs<10h"},
43	{24000 * time.Hour, "errors"},
44}
45
46// RenderEvents renders the HTML page typically served at /debug/events.
47// It does not do any auth checking; see AuthRequest for the default auth check
48// used by the handler registered on http.DefaultServeMux.
49// req may be nil.
50func RenderEvents(w http.ResponseWriter, req *http.Request, sensitive bool) {
51	now := time.Now()
52	data := &struct {
53		Families []string // family names
54		Buckets  []bucket
55		Counts   [][]int // eventLog count per family/bucket
56
57		// Set when a bucket has been selected.
58		Family    string
59		Bucket    int
60		EventLogs eventLogs
61		Expanded  bool
62	}{
63		Buckets: buckets,
64	}
65
66	data.Families = make([]string, 0, len(families))
67	famMu.RLock()
68	for name := range families {
69		data.Families = append(data.Families, name)
70	}
71	famMu.RUnlock()
72	sort.Strings(data.Families)
73
74	// Count the number of eventLogs in each family for each error age.
75	data.Counts = make([][]int, len(data.Families))
76	for i, name := range data.Families {
77		// TODO(sameer): move this loop under the family lock.
78		f := getEventFamily(name)
79		data.Counts[i] = make([]int, len(data.Buckets))
80		for j, b := range data.Buckets {
81			data.Counts[i][j] = f.Count(now, b.MaxErrAge)
82		}
83	}
84
85	if req != nil {
86		var ok bool
87		data.Family, data.Bucket, ok = parseEventsArgs(req)
88		if !ok {
89			// No-op
90		} else {
91			data.EventLogs = getEventFamily(data.Family).Copy(now, buckets[data.Bucket].MaxErrAge)
92		}
93		if data.EventLogs != nil {
94			defer data.EventLogs.Free()
95			sort.Sort(data.EventLogs)
96		}
97		if exp, err := strconv.ParseBool(req.FormValue("exp")); err == nil {
98			data.Expanded = exp
99		}
100	}
101
102	famMu.RLock()
103	defer famMu.RUnlock()
104	if err := eventsTmpl.Execute(w, data); err != nil {
105		log.Printf("net/trace: Failed executing template: %v", err)
106	}
107}
108
109func parseEventsArgs(req *http.Request) (fam string, b int, ok bool) {
110	fam, bStr := req.FormValue("fam"), req.FormValue("b")
111	if fam == "" || bStr == "" {
112		return "", 0, false
113	}
114	b, err := strconv.Atoi(bStr)
115	if err != nil || b < 0 || b >= len(buckets) {
116		return "", 0, false
117	}
118	return fam, b, true
119}
120
121// An EventLog provides a log of events associated with a specific object.
122type EventLog interface {
123	// Printf formats its arguments with fmt.Sprintf and adds the
124	// result to the event log.
125	Printf(format string, a ...interface{})
126
127	// Errorf is like Printf, but it marks this event as an error.
128	Errorf(format string, a ...interface{})
129
130	// Finish declares that this event log is complete.
131	// The event log should not be used after calling this method.
132	Finish()
133}
134
135// NewEventLog returns a new EventLog with the specified family name
136// and title.
137func NewEventLog(family, title string) EventLog {
138	el := newEventLog()
139	el.ref()
140	el.Family, el.Title = family, title
141	el.Start = time.Now()
142	el.events = make([]logEntry, 0, maxEventsPerLog)
143	el.stack = make([]uintptr, 32)
144	n := runtime.Callers(2, el.stack)
145	el.stack = el.stack[:n]
146
147	getEventFamily(family).add(el)
148	return el
149}
150
151func (el *eventLog) Finish() {
152	getEventFamily(el.Family).remove(el)
153	el.unref() // matches ref in New
154}
155
156var (
157	famMu    sync.RWMutex
158	families = make(map[string]*eventFamily) // family name => family
159)
160
161func getEventFamily(fam string) *eventFamily {
162	famMu.Lock()
163	defer famMu.Unlock()
164	f := families[fam]
165	if f == nil {
166		f = &eventFamily{}
167		families[fam] = f
168	}
169	return f
170}
171
172type eventFamily struct {
173	mu        sync.RWMutex
174	eventLogs eventLogs
175}
176
177func (f *eventFamily) add(el *eventLog) {
178	f.mu.Lock()
179	f.eventLogs = append(f.eventLogs, el)
180	f.mu.Unlock()
181}
182
183func (f *eventFamily) remove(el *eventLog) {
184	f.mu.Lock()
185	defer f.mu.Unlock()
186	for i, el0 := range f.eventLogs {
187		if el == el0 {
188			copy(f.eventLogs[i:], f.eventLogs[i+1:])
189			f.eventLogs = f.eventLogs[:len(f.eventLogs)-1]
190			return
191		}
192	}
193}
194
195func (f *eventFamily) Count(now time.Time, maxErrAge time.Duration) (n int) {
196	f.mu.RLock()
197	defer f.mu.RUnlock()
198	for _, el := range f.eventLogs {
199		if el.hasRecentError(now, maxErrAge) {
200			n++
201		}
202	}
203	return
204}
205
206func (f *eventFamily) Copy(now time.Time, maxErrAge time.Duration) (els eventLogs) {
207	f.mu.RLock()
208	defer f.mu.RUnlock()
209	els = make(eventLogs, 0, len(f.eventLogs))
210	for _, el := range f.eventLogs {
211		if el.hasRecentError(now, maxErrAge) {
212			el.ref()
213			els = append(els, el)
214		}
215	}
216	return
217}
218
219type eventLogs []*eventLog
220
221// Free calls unref on each element of the list.
222func (els eventLogs) Free() {
223	for _, el := range els {
224		el.unref()
225	}
226}
227
228// eventLogs may be sorted in reverse chronological order.
229func (els eventLogs) Len() int           { return len(els) }
230func (els eventLogs) Less(i, j int) bool { return els[i].Start.After(els[j].Start) }
231func (els eventLogs) Swap(i, j int)      { els[i], els[j] = els[j], els[i] }
232
233// A logEntry is a timestamped log entry in an event log.
234type logEntry struct {
235	When    time.Time
236	Elapsed time.Duration // since previous event in log
237	NewDay  bool          // whether this event is on a different day to the previous event
238	What    string
239	IsErr   bool
240}
241
242// WhenString returns a string representation of the elapsed time of the event.
243// It will include the date if midnight was crossed.
244func (e logEntry) WhenString() string {
245	if e.NewDay {
246		return e.When.Format("2006/01/02 15:04:05.000000")
247	}
248	return e.When.Format("15:04:05.000000")
249}
250
251// An eventLog represents an active event log.
252type eventLog struct {
253	// Family is the top-level grouping of event logs to which this belongs.
254	Family string
255
256	// Title is the title of this event log.
257	Title string
258
259	// Timing information.
260	Start time.Time
261
262	// Call stack where this event log was created.
263	stack []uintptr
264
265	// Append-only sequence of events.
266	//
267	// TODO(sameer): change this to a ring buffer to avoid the array copy
268	// when we hit maxEventsPerLog.
269	mu            sync.RWMutex
270	events        []logEntry
271	LastErrorTime time.Time
272	discarded     int
273
274	refs int32 // how many buckets this is in
275}
276
277func (el *eventLog) reset() {
278	// Clear all but the mutex. Mutexes may not be copied, even when unlocked.
279	el.Family = ""
280	el.Title = ""
281	el.Start = time.Time{}
282	el.stack = nil
283	el.events = nil
284	el.LastErrorTime = time.Time{}
285	el.discarded = 0
286	el.refs = 0
287}
288
289func (el *eventLog) hasRecentError(now time.Time, maxErrAge time.Duration) bool {
290	if maxErrAge == 0 {
291		return true
292	}
293	el.mu.RLock()
294	defer el.mu.RUnlock()
295	return now.Sub(el.LastErrorTime) < maxErrAge
296}
297
298// delta returns the elapsed time since the last event or the log start,
299// and whether it spans midnight.
300// L >= el.mu
301func (el *eventLog) delta(t time.Time) (time.Duration, bool) {
302	if len(el.events) == 0 {
303		return t.Sub(el.Start), false
304	}
305	prev := el.events[len(el.events)-1].When
306	return t.Sub(prev), prev.Day() != t.Day()
307
308}
309
310func (el *eventLog) Printf(format string, a ...interface{}) {
311	el.printf(false, format, a...)
312}
313
314func (el *eventLog) Errorf(format string, a ...interface{}) {
315	el.printf(true, format, a...)
316}
317
318func (el *eventLog) printf(isErr bool, format string, a ...interface{}) {
319	e := logEntry{When: time.Now(), IsErr: isErr, What: fmt.Sprintf(format, a...)}
320	el.mu.Lock()
321	e.Elapsed, e.NewDay = el.delta(e.When)
322	if len(el.events) < maxEventsPerLog {
323		el.events = append(el.events, e)
324	} else {
325		// Discard the oldest event.
326		if el.discarded == 0 {
327			// el.discarded starts at two to count for the event it
328			// is replacing, plus the next one that we are about to
329			// drop.
330			el.discarded = 2
331		} else {
332			el.discarded++
333		}
334		// TODO(sameer): if this causes allocations on a critical path,
335		// change eventLog.What to be a fmt.Stringer, as in trace.go.
336		el.events[0].What = fmt.Sprintf("(%d events discarded)", el.discarded)
337		// The timestamp of the discarded meta-event should be
338		// the time of the last event it is representing.
339		el.events[0].When = el.events[1].When
340		copy(el.events[1:], el.events[2:])
341		el.events[maxEventsPerLog-1] = e
342	}
343	if e.IsErr {
344		el.LastErrorTime = e.When
345	}
346	el.mu.Unlock()
347}
348
349func (el *eventLog) ref() {
350	atomic.AddInt32(&el.refs, 1)
351}
352
353func (el *eventLog) unref() {
354	if atomic.AddInt32(&el.refs, -1) == 0 {
355		freeEventLog(el)
356	}
357}
358
359func (el *eventLog) When() string {
360	return el.Start.Format("2006/01/02 15:04:05.000000")
361}
362
363func (el *eventLog) ElapsedTime() string {
364	elapsed := time.Since(el.Start)
365	return fmt.Sprintf("%.6f", elapsed.Seconds())
366}
367
368func (el *eventLog) Stack() string {
369	buf := new(bytes.Buffer)
370	tw := tabwriter.NewWriter(buf, 1, 8, 1, '\t', 0)
371	printStackRecord(tw, el.stack)
372	tw.Flush()
373	return buf.String()
374}
375
376// printStackRecord prints the function + source line information
377// for a single stack trace.
378// Adapted from runtime/pprof/pprof.go.
379func printStackRecord(w io.Writer, stk []uintptr) {
380	for _, pc := range stk {
381		f := runtime.FuncForPC(pc)
382		if f == nil {
383			continue
384		}
385		file, line := f.FileLine(pc)
386		name := f.Name()
387		// Hide runtime.goexit and any runtime functions at the beginning.
388		if strings.HasPrefix(name, "runtime.") {
389			continue
390		}
391		fmt.Fprintf(w, "#   %s\t%s:%d\n", name, file, line)
392	}
393}
394
395func (el *eventLog) Events() []logEntry {
396	el.mu.RLock()
397	defer el.mu.RUnlock()
398	return el.events
399}
400
401// freeEventLogs is a freelist of *eventLog
402var freeEventLogs = make(chan *eventLog, 1000)
403
404// newEventLog returns a event log ready to use.
405func newEventLog() *eventLog {
406	select {
407	case el := <-freeEventLogs:
408		return el
409	default:
410		return new(eventLog)
411	}
412}
413
414// freeEventLog adds el to freeEventLogs if there's room.
415// This is non-blocking.
416func freeEventLog(el *eventLog) {
417	el.reset()
418	select {
419	case freeEventLogs <- el:
420	default:
421	}
422}
423
424const eventsHTML = `
425<html>
426	<head>
427		<title>events</title>
428	</head>
429	<style type="text/css">
430		body {
431			font-family: sans-serif;
432		}
433		table#req-status td.family {
434			padding-right: 2em;
435		}
436		table#req-status td.active {
437			padding-right: 1em;
438		}
439		table#req-status td.empty {
440			color: #aaa;
441		}
442		table#reqs {
443			margin-top: 1em;
444		}
445		table#reqs tr.first {
446			{{if $.Expanded}}font-weight: bold;{{end}}
447		}
448		table#reqs td {
449			font-family: monospace;
450		}
451		table#reqs td.when {
452			text-align: right;
453			white-space: nowrap;
454		}
455		table#reqs td.elapsed {
456			padding: 0 0.5em;
457			text-align: right;
458			white-space: pre;
459			width: 10em;
460		}
461		address {
462			font-size: smaller;
463			margin-top: 5em;
464		}
465	</style>
466	<body>
467
468<h1>/debug/events</h1>
469
470<table id="req-status">
471	{{range $i, $fam := .Families}}
472	<tr>
473		<td class="family">{{$fam}}</td>
474
475	        {{range $j, $bucket := $.Buckets}}
476	        {{$n := index $.Counts $i $j}}
477		<td class="{{if not $bucket.MaxErrAge}}active{{end}}{{if not $n}}empty{{end}}">
478	                {{if $n}}<a href="?fam={{$fam}}&b={{$j}}{{if $.Expanded}}&exp=1{{end}}">{{end}}
479		        [{{$n}} {{$bucket.String}}]
480			{{if $n}}</a>{{end}}
481		</td>
482                {{end}}
483
484	</tr>{{end}}
485</table>
486
487{{if $.EventLogs}}
488<hr />
489<h3>Family: {{$.Family}}</h3>
490
491{{if $.Expanded}}<a href="?fam={{$.Family}}&b={{$.Bucket}}">{{end}}
492[Summary]{{if $.Expanded}}</a>{{end}}
493
494{{if not $.Expanded}}<a href="?fam={{$.Family}}&b={{$.Bucket}}&exp=1">{{end}}
495[Expanded]{{if not $.Expanded}}</a>{{end}}
496
497<table id="reqs">
498	<tr><th>When</th><th>Elapsed</th></tr>
499	{{range $el := $.EventLogs}}
500	<tr class="first">
501		<td class="when">{{$el.When}}</td>
502		<td class="elapsed">{{$el.ElapsedTime}}</td>
503		<td>{{$el.Title}}
504	</tr>
505	{{if $.Expanded}}
506	<tr>
507		<td class="when"></td>
508		<td class="elapsed"></td>
509		<td><pre>{{$el.Stack|trimSpace}}</pre></td>
510	</tr>
511	{{range $el.Events}}
512	<tr>
513		<td class="when">{{.WhenString}}</td>
514		<td class="elapsed">{{elapsed .Elapsed}}</td>
515		<td>.{{if .IsErr}}E{{else}}.{{end}}. {{.What}}</td>
516	</tr>
517	{{end}}
518	{{end}}
519	{{end}}
520</table>
521{{end}}
522	</body>
523</html>
524`
525