1package rpc
2
3import (
4	"encoding/json"
5	"fmt"
6	"io"
7	"net"
8	"os"
9	"time"
10)
11
12type Profiler interface {
13	Stop()
14}
15
16type LogInterface interface {
17	TransportStart()
18	TransportError(error)
19	// The passed-in slice should not be mutated.
20	FrameRead([]byte)
21	ClientCall(SeqNumber, string, interface{})
22	ServerCall(SeqNumber, string, error, interface{})
23	ServerReply(SeqNumber, string, error, interface{})
24	ClientCallCompressed(SeqNumber, string, interface{}, CompressionType)
25	ServerCallCompressed(SeqNumber, string, error, interface{}, CompressionType)
26	ServerReplyCompressed(SeqNumber, string, error, interface{}, CompressionType)
27	ClientNotify(string, interface{})
28	ServerNotifyCall(string, error, interface{})
29	ServerNotifyComplete(string, error)
30	ClientCancel(SeqNumber, string, error)
31	ServerCancelCall(SeqNumber, string)
32	ClientReply(SeqNumber, string, error, interface{})
33	StartProfiler(format string, args ...interface{}) Profiler
34	UnexpectedReply(SeqNumber)
35	Warning(format string, args ...interface{})
36	Info(format string, args ...interface{})
37}
38
39type LogFactory interface {
40	NewLog(net.Addr) LogInterface
41}
42
43type LogOutput interface {
44	Error(s string, args ...interface{})
45	Warning(s string, args ...interface{})
46	Info(s string, args ...interface{})
47	Debug(s string, args ...interface{})
48	Profile(s string, args ...interface{})
49}
50
51type LogOutputWithDepthAdder interface {
52	LogOutput
53	CloneWithAddedDepth(depth int) LogOutputWithDepthAdder
54}
55
56type LogOptions interface {
57	ShowAddress() bool
58	ShowArg() bool
59	ShowResult() bool
60	Profile() bool
61	FrameTrace() bool
62	ClientTrace() bool
63	ServerTrace() bool
64	TransportStart() bool
65}
66
67//-------------------------------------------------
68
69type SimpleLogFactory struct {
70	out  LogOutput
71	opts LogOptions
72}
73
74type SimpleLog struct {
75	Addr net.Addr
76	Out  LogOutput
77	Opts LogOptions
78}
79
80type SimpleLogOutput struct{}
81type SimpleLogOptions struct{}
82
83func (s SimpleLogOutput) log(ch string, fmts string, args []interface{}) {
84	fmts = fmt.Sprintf("[%s] %s\n", ch, fmts)
85	fmt.Fprintf(os.Stderr, fmts, args...)
86}
87
88func (s SimpleLogOutput) Info(fmt string, args ...interface{})    { s.log("I", fmt, args) }
89func (s SimpleLogOutput) Error(fmt string, args ...interface{})   { s.log("E", fmt, args) }
90func (s SimpleLogOutput) Debug(fmt string, args ...interface{})   { s.log("D", fmt, args) }
91func (s SimpleLogOutput) Warning(fmt string, args ...interface{}) { s.log("W", fmt, args) }
92func (s SimpleLogOutput) Profile(fmt string, args ...interface{}) { s.log("P", fmt, args) }
93
94func (so SimpleLogOptions) ShowAddress() bool    { return true }
95func (so SimpleLogOptions) ShowArg() bool        { return true }
96func (so SimpleLogOptions) ShowResult() bool     { return true }
97func (so SimpleLogOptions) Profile() bool        { return true }
98func (so SimpleLogOptions) FrameTrace() bool     { return true }
99func (so SimpleLogOptions) ClientTrace() bool    { return true }
100func (so SimpleLogOptions) ServerTrace() bool    { return true }
101func (so SimpleLogOptions) TransportStart() bool { return true }
102
103type StandardLogOptions struct {
104	frameTrace     bool
105	clientTrace    bool
106	serverTrace    bool
107	profile        bool
108	verboseTrace   bool
109	connectionInfo bool
110	noAddress      bool
111}
112
113func (s *StandardLogOptions) ShowAddress() bool    { return !s.noAddress }
114func (s *StandardLogOptions) ShowArg() bool        { return s.verboseTrace }
115func (s *StandardLogOptions) ShowResult() bool     { return s.verboseTrace }
116func (s *StandardLogOptions) Profile() bool        { return s.profile }
117func (s *StandardLogOptions) FrameTrace() bool     { return s.frameTrace }
118func (s *StandardLogOptions) ClientTrace() bool    { return s.clientTrace }
119func (s *StandardLogOptions) ServerTrace() bool    { return s.serverTrace }
120func (s *StandardLogOptions) TransportStart() bool { return s.connectionInfo }
121
122func NewStandardLogOptions(opts string, log LogOutput) LogOptions {
123	var s StandardLogOptions
124	for _, c := range opts {
125		switch c {
126		case 'A':
127			s.noAddress = true
128		case 'f':
129			s.frameTrace = true
130		case 'c':
131			s.clientTrace = true
132		case 's':
133			s.serverTrace = true
134		case 'v':
135			s.verboseTrace = true
136		case 'i':
137			s.connectionInfo = true
138		case 'p':
139			s.profile = true
140		default:
141			log.Warning("Unknown logging flag: %c", c)
142		}
143	}
144	return &s
145}
146
147func NewSimpleLogFactory(out LogOutput, opts LogOptions) SimpleLogFactory {
148	if out == nil {
149		out = SimpleLogOutput{}
150	}
151	if opts == nil {
152		opts = SimpleLogOptions{}
153	}
154	ret := SimpleLogFactory{out, opts}
155	return ret
156}
157
158func (s SimpleLogFactory) NewLog(a net.Addr) LogInterface {
159	ret := SimpleLog{a, s.out, s.opts}
160	ret.TransportStart()
161	return ret
162}
163
164func AddrToString(addr net.Addr) string {
165	if addr == nil {
166		return "-"
167	} else {
168		c := addr.String()
169		if len(c) == 0 {
170			return addr.Network()
171		} else {
172			return addr.Network() + "://" + c
173		}
174	}
175}
176
177func (s SimpleLog) TransportStart() {
178	if s.Opts.TransportStart() {
179		s.Out.Debug(s.msg(true, "New connection"))
180	}
181}
182
183func (s SimpleLog) TransportError(e error) {
184	if e != io.EOF {
185		s.Out.Error(s.msg(true, "Error in transport: %s", e.Error()))
186	} else if s.Opts.TransportStart() {
187		s.Out.Debug(s.msg(true, "EOF"))
188	}
189}
190
191func (s SimpleLog) FrameRead(bytes []byte) {
192	if s.Opts.FrameTrace() {
193		s.Out.Debug(s.msg(false, "Frame read: %x", bytes))
194	}
195}
196
197// Call
198func (s SimpleLog) ClientCall(q SeqNumber, meth string, arg interface{}) {
199	if s.Opts.ClientTrace() {
200		s.trace("call", "arg", s.Opts.ShowArg(), q, meth, nil, arg, nil)
201	}
202}
203func (s SimpleLog) ServerCall(q SeqNumber, meth string, err error, arg interface{}) {
204	if s.Opts.ServerTrace() {
205		s.trace("serve", "arg", s.Opts.ShowArg(), q, meth, err, arg, nil)
206	}
207}
208func (s SimpleLog) ServerReply(q SeqNumber, meth string, err error, res interface{}) {
209	if s.Opts.ServerTrace() {
210		s.trace("reply", "res", s.Opts.ShowResult(), q, meth, err, res, nil)
211	}
212}
213
214// CallCompressed
215func (s SimpleLog) ClientCallCompressed(q SeqNumber, meth string, arg interface{}, ctype CompressionType) {
216	if s.Opts.ClientTrace() {
217		s.trace("call-compressed", "arg", s.Opts.ShowArg(), q, meth, nil, arg, &ctype)
218	}
219}
220func (s SimpleLog) ServerCallCompressed(q SeqNumber, meth string, err error, arg interface{}, ctype CompressionType) {
221	if s.Opts.ServerTrace() {
222		s.trace("serve-compressed", "arg", s.Opts.ShowArg(), q, meth, err, arg, &ctype)
223	}
224}
225func (s SimpleLog) ServerReplyCompressed(q SeqNumber, meth string, err error, res interface{}, ctype CompressionType) {
226	if s.Opts.ServerTrace() {
227		s.trace("reply-compressed", "res", s.Opts.ShowResult(), q, meth, err, res, &ctype)
228	}
229}
230
231// Notify
232func (s SimpleLog) ClientNotify(meth string, arg interface{}) {
233	if s.Opts.ClientTrace() {
234		s.trace("notify", "arg", s.Opts.ShowArg(), 0, meth, nil, arg, nil)
235	}
236}
237func (s SimpleLog) ServerNotifyCall(meth string, err error, arg interface{}) {
238	if s.Opts.ServerTrace() {
239		s.trace("serve-notify", "arg", s.Opts.ShowArg(), 0, meth, err, arg, nil)
240	}
241}
242func (s SimpleLog) ServerNotifyComplete(meth string, err error) {
243	if s.Opts.ServerTrace() {
244		s.trace("complete", "", false, 0, meth, err, nil, nil)
245	}
246}
247
248// Cancel
249func (s SimpleLog) ClientCancel(q SeqNumber, meth string, err error) {
250	if s.Opts.ClientTrace() {
251		s.trace("cancel", "", false, q, meth, err, nil, nil)
252	}
253}
254func (s SimpleLog) ServerCancelCall(q SeqNumber, meth string) {
255	if s.Opts.ServerTrace() {
256		s.trace("serve-cancel", "", false, q, meth, nil, nil, nil)
257	}
258}
259
260func (s SimpleLog) ClientReply(q SeqNumber, meth string, err error, res interface{}) {
261	if s.Opts.ClientTrace() {
262		s.trace("reply", "res", s.Opts.ShowResult(), q, meth, err, res, nil)
263	}
264}
265
266func (s SimpleLog) trace(which string, objname string, verbose bool, q SeqNumber,
267	meth string, err error, obj interface{}, ctype *CompressionType) {
268	args := []interface{}{which, q}
269	fmts := "%s(%d):"
270	if len(meth) > 0 {
271		fmts += " method=%s;"
272		args = append(args, meth)
273	}
274	if ctype != nil {
275		fmts += " ctype=%s;"
276		args = append(args, ctype)
277	}
278
279	fmts += " err=%s;"
280	var es string
281	if err == nil {
282		es = "null"
283	} else {
284		es = err.Error()
285	}
286	args = append(args, es)
287	if verbose {
288		fmts += " %s=%s;"
289		eb, err := json.Marshal(obj)
290		var es string
291		if err != nil {
292			es = fmt.Sprintf(`{"error": "%s"}`, err.Error())
293		} else {
294			es = string(eb)
295		}
296		args = append(args, objname)
297		args = append(args, es)
298	}
299	s.Out.Debug(s.msg(false, fmts, args...))
300}
301
302func (s SimpleLog) StartProfiler(format string, args ...interface{}) Profiler {
303	if s.Opts.Profile() {
304		return &SimpleProfiler{
305			start: time.Now(),
306			msg:   fmt.Sprintf(format, args...),
307			log:   s,
308		}
309	} else {
310		return NilProfiler{}
311	}
312}
313
314func (s SimpleLog) UnexpectedReply(seqno SeqNumber) {
315	s.Out.Warning(s.msg(false, "Unexpected seqno %d in incoming reply", seqno))
316}
317
318func (s SimpleLog) Warning(format string, args ...interface{}) {
319	s.Out.Warning(s.msg(false, format, args...))
320}
321
322func (s SimpleLog) Info(format string, args ...interface{}) {
323	s.Out.Info(s.msg(false, format, args...))
324}
325
326func (s SimpleLog) msg(force bool, format string, args ...interface{}) string {
327	m1 := fmt.Sprintf(format, args...)
328	if s.Opts.ShowAddress() || force {
329		m2 := fmt.Sprintf("{%s} %s", AddrToString(s.Addr), m1)
330		m1 = m2
331	}
332	return m1
333}
334
335type SimpleProfiler struct {
336	start time.Time
337	msg   string
338	log   SimpleLog
339}
340
341func (s *SimpleProfiler) Stop() {
342	stop := time.Now()
343	diff := stop.Sub(s.start)
344	s.log.Out.Profile(s.log.msg(false, "%s ran in %dms", s.msg, diff/time.Millisecond))
345}
346
347// Callers shouldn't have to worry about whether an interface is satisfied or not
348type NilProfiler struct{}
349
350func (n NilProfiler) Stop() {}
351