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