1// Copyright 2015 The etcd Authors
2//
3// Licensed under the Apache License, Version 2.0 (the "License");
4// you may not use this file except in compliance with the License.
5// You may obtain a copy of the License at
6//
7//     http://www.apache.org/licenses/LICENSE-2.0
8//
9// Unless required by applicable law or agreed to in writing, software
10// distributed under the License is distributed on an "AS IS" BASIS,
11// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
12// See the License for the specific language governing permissions and
13// limitations under the License.
14
15// Package logutil includes utilities to facilitate logging.
16package logutil
17
18import (
19	"fmt"
20	"sync"
21	"time"
22
23	"github.com/coreos/pkg/capnslog"
24)
25
26var (
27	defaultMergePeriod     = time.Second
28	defaultTimeOutputScale = 10 * time.Millisecond
29
30	outputInterval = time.Second
31)
32
33// line represents a log line that can be printed out
34// through capnslog.PackageLogger.
35type line struct {
36	level capnslog.LogLevel
37	str   string
38}
39
40func (l line) append(s string) line {
41	return line{
42		level: l.level,
43		str:   l.str + " " + s,
44	}
45}
46
47// status represents the merge status of a line.
48type status struct {
49	period time.Duration
50
51	start time.Time // start time of latest merge period
52	count int       // number of merged lines from starting
53}
54
55func (s *status) isInMergePeriod(now time.Time) bool {
56	return s.period == 0 || s.start.Add(s.period).After(now)
57}
58
59func (s *status) isEmpty() bool { return s.count == 0 }
60
61func (s *status) summary(now time.Time) string {
62	ts := s.start.Round(defaultTimeOutputScale)
63	took := now.Round(defaultTimeOutputScale).Sub(ts)
64	return fmt.Sprintf("[merged %d repeated lines in %s]", s.count, took)
65}
66
67func (s *status) reset(now time.Time) {
68	s.start = now
69	s.count = 0
70}
71
72// MergeLogger supports merge logging, which merges repeated log lines
73// and prints summary log lines instead.
74//
75// For merge logging, MergeLogger prints out the line when the line appears
76// at the first time. MergeLogger holds the same log line printed within
77// defaultMergePeriod, and prints out summary log line at the end of defaultMergePeriod.
78// It stops merging when the line doesn't appear within the
79// defaultMergePeriod.
80type MergeLogger struct {
81	*capnslog.PackageLogger
82
83	mu      sync.Mutex // protect statusm
84	statusm map[line]*status
85}
86
87func NewMergeLogger(logger *capnslog.PackageLogger) *MergeLogger {
88	l := &MergeLogger{
89		PackageLogger: logger,
90		statusm:       make(map[line]*status),
91	}
92	go l.outputLoop()
93	return l
94}
95
96func (l *MergeLogger) MergeInfo(entries ...interface{}) {
97	l.merge(line{
98		level: capnslog.INFO,
99		str:   fmt.Sprint(entries...),
100	})
101}
102
103func (l *MergeLogger) MergeInfof(format string, args ...interface{}) {
104	l.merge(line{
105		level: capnslog.INFO,
106		str:   fmt.Sprintf(format, args...),
107	})
108}
109
110func (l *MergeLogger) MergeNotice(entries ...interface{}) {
111	l.merge(line{
112		level: capnslog.NOTICE,
113		str:   fmt.Sprint(entries...),
114	})
115}
116
117func (l *MergeLogger) MergeNoticef(format string, args ...interface{}) {
118	l.merge(line{
119		level: capnslog.NOTICE,
120		str:   fmt.Sprintf(format, args...),
121	})
122}
123
124func (l *MergeLogger) MergeWarning(entries ...interface{}) {
125	l.merge(line{
126		level: capnslog.WARNING,
127		str:   fmt.Sprint(entries...),
128	})
129}
130
131func (l *MergeLogger) MergeWarningf(format string, args ...interface{}) {
132	l.merge(line{
133		level: capnslog.WARNING,
134		str:   fmt.Sprintf(format, args...),
135	})
136}
137
138func (l *MergeLogger) MergeError(entries ...interface{}) {
139	l.merge(line{
140		level: capnslog.ERROR,
141		str:   fmt.Sprint(entries...),
142	})
143}
144
145func (l *MergeLogger) MergeErrorf(format string, args ...interface{}) {
146	l.merge(line{
147		level: capnslog.ERROR,
148		str:   fmt.Sprintf(format, args...),
149	})
150}
151
152func (l *MergeLogger) merge(ln line) {
153	l.mu.Lock()
154
155	// increase count if the logger is merging the line
156	if status, ok := l.statusm[ln]; ok {
157		status.count++
158		l.mu.Unlock()
159		return
160	}
161
162	// initialize status of the line
163	l.statusm[ln] = &status{
164		period: defaultMergePeriod,
165		start:  time.Now(),
166	}
167	// release the lock before IO operation
168	l.mu.Unlock()
169	// print out the line at its first time
170	l.PackageLogger.Logf(ln.level, ln.str)
171}
172
173func (l *MergeLogger) outputLoop() {
174	for now := range time.Tick(outputInterval) {
175		var outputs []line
176
177		l.mu.Lock()
178		for ln, status := range l.statusm {
179			if status.isInMergePeriod(now) {
180				continue
181			}
182			if status.isEmpty() {
183				delete(l.statusm, ln)
184				continue
185			}
186			outputs = append(outputs, ln.append(status.summary(now)))
187			status.reset(now)
188		}
189		l.mu.Unlock()
190
191		for _, o := range outputs {
192			l.PackageLogger.Logf(o.level, o.str)
193		}
194	}
195}
196