1// Copyright 2019 Keybase, Inc. All rights reserved. Use of
2// this source code is governed by the included BSD license.
3
4package engine
5
6import (
7	"errors"
8	"strconv"
9	"testing"
10	"time"
11
12	"github.com/stretchr/testify/require"
13
14	"github.com/keybase/client/go/libkb"
15	"github.com/keybase/clockwork"
16)
17
18func TestMerkleAuditWork(t *testing.T) {
19	tc := SetupEngineTest(t, "merkleaudit")
20	defer tc.Cleanup()
21
22	fakeClock := clockwork.NewFakeClockAt(time.Now())
23	tc.G.SetClock(fakeClock)
24
25	advance := func(d time.Duration) {
26		tc.G.Log.Debug("+ fakeClock#advance(%s) start: %s", d, fakeClock.Now())
27		fakeClock.Advance(d)
28		tc.G.Log.Debug("- fakeClock#adance(%s) end: %s", d, fakeClock.Now())
29	}
30
31	metaCh := make(chan string, 100)
32	roundResCh := make(chan error, 100)
33	arg := &MerkleAuditArgs{
34		testingMetaCh:     metaCh,
35		testingRoundResCh: roundResCh,
36	}
37	eng := NewMerkleAudit(tc.G, arg)
38	eng.task.args.Settings.StartStagger = 0 // Disable stagger for deterministic testing
39	m := NewMetaContextForTest(tc)
40	err := RunEngine2(m, eng)
41	require.NoError(t, err)
42
43	// Run a manual root fetch to populate the client
44	_, err = tc.G.MerkleClient.FetchRootFromServer(m, time.Hour)
45	require.NoError(t, err)
46
47	expectMeta(t, metaCh, "loop-start")
48	advance(MerkleAuditSettings.Start + time.Second)
49	expectMeta(t, metaCh, "woke-start")
50
51	// first run doesn't do anything
52	select {
53	case x := <-roundResCh:
54		require.Equal(t, nil, x, "round result")
55	case <-time.After(30 * time.Second):
56		require.FailNow(t, "channel timed out")
57	}
58	expectMeta(t, metaCh, "loop-round-complete")
59
60	err = eng.Shutdown(m)
61	require.NoError(t, err)
62	expectMeta(t, metaCh, "loop-exit")
63	expectMeta(t, metaCh, "")
64}
65
66type retryMerkleAuditMock struct {
67	*libkb.APIArgRecorder
68	tc  libkb.TestContext
69	api libkb.API
70
71	getError error
72	args     []libkb.APIArg
73	resps    []*libkb.APIRes
74}
75
76func newRetryMerkleAuditMock(tc libkb.TestContext) *retryMerkleAuditMock {
77	return &retryMerkleAuditMock{
78		APIArgRecorder: libkb.NewAPIArgRecorderWithNullAPI(),
79		tc:             tc,
80		api:            tc.G.API,
81	}
82}
83
84func (r *retryMerkleAuditMock) GetDecode(mctx libkb.MetaContext, arg libkb.APIArg, w libkb.APIResponseWrapper) error {
85	r.args = append(r.args, arg)
86	if r.getError != nil {
87		return nil
88	}
89
90	return r.api.GetDecode(mctx, arg, w)
91}
92
93func (r *retryMerkleAuditMock) Get(mctx libkb.MetaContext, arg libkb.APIArg) (*libkb.APIRes, error) {
94	r.args = append(r.args, arg)
95	if r.getError != nil {
96		r.resps = append(r.resps, nil)
97		return nil, r.getError
98	}
99
100	res, err := r.api.Get(mctx, arg)
101	r.resps = append(r.resps, res)
102	if err != nil {
103		return nil, err
104	}
105
106	return res, nil
107}
108
109func (r *retryMerkleAuditMock) resetHistory() {
110	r.args = nil
111	r.resps = nil
112}
113
114func TestMerkleAuditRetry(t *testing.T) {
115	tc := SetupEngineTest(t, "merkleaudit")
116	defer tc.Cleanup()
117
118	api := newRetryMerkleAuditMock(tc)
119	tc.G.API = api
120
121	fakeClock := clockwork.NewFakeClockAt(time.Now())
122	tc.G.SetClock(fakeClock)
123
124	advance := func(d time.Duration) {
125		tc.G.Log.Debug("+ fakeClock#advance(%s) start: %s", d, fakeClock.Now())
126		fakeClock.Advance(d)
127		tc.G.Log.Debug("- fakeClock#adance(%s) end: %s", d, fakeClock.Now())
128	}
129
130	metaCh := make(chan string, 100)
131	roundResCh := make(chan error, 100)
132	arg := &MerkleAuditArgs{
133		testingMetaCh:     metaCh,
134		testingRoundResCh: roundResCh,
135	}
136	eng := NewMerkleAudit(tc.G, arg)
137	eng.task.args.Settings.StartStagger = 0 // Disable stagger for deterministic testing
138	m := NewMetaContextForTest(tc)
139	err := RunEngine2(m, eng)
140	require.NoError(t, err)
141
142	// Run a manual root fetch
143	_, err = tc.G.MerkleClient.FetchRootFromServer(m, time.Hour)
144	require.NoError(t, err)
145
146	require.NotEmpty(t, api.args)
147	require.NotEmpty(t, api.resps)
148	require.Equal(t, "merkle/root", api.args[0].Endpoint)
149
150	// Make sure that the initial root fetch worked
151	_, err = api.resps[0].Body.AtKey("seqno").GetInt64()
152	require.NoError(t, err)
153
154	// Make the mock return an error on API.Get
155	internalTestError := errors.New("Fake internal test error")
156	api.getError = internalTestError
157	api.resetHistory()
158
159	expectMeta(t, metaCh, "loop-start")
160	advance(MerkleAuditSettings.Start + time.Second)
161	expectMeta(t, metaCh, "woke-start")
162
163	// first run should fail and write into leveldb
164	select {
165	case x := <-roundResCh:
166		require.Equal(t, internalTestError, x, "round result #1")
167	case <-time.After(30 * time.Second):
168		require.FailNow(t, "channel timed out")
169	}
170	expectMeta(t, metaCh, "loop-round-complete")
171
172	// Figure out what seqno we were trying to fetch
173	require.NotEmpty(t, api.args)
174	require.Equal(t, "merkle/path", api.args[0].Endpoint)
175	startSeqnoStr := api.args[0].Args["start_seqno"].String()
176	startSeqno, err := strconv.ParseInt(startSeqnoStr, 10, 64)
177	require.NoError(t, err)
178
179	tc.G.Log.Debug("Expecting the next iteration to look up %d", startSeqno)
180
181	// The second try should be exactly the same
182	api.resetHistory()
183
184	advance(MerkleAuditSettings.Interval + time.Second)
185	expectMeta(t, metaCh, "woke-interval")
186	expectMeta(t, metaCh, "woke-wakeup")
187	select {
188	case x := <-roundResCh:
189		require.Equal(t, internalTestError, x, "round result #2")
190	case <-time.After(30 * time.Second):
191		require.FailNow(t, "channel timed out")
192	}
193	expectMeta(t, metaCh, "loop-round-complete")
194
195	require.NotEmpty(t, api.args)
196	require.Equal(t, "merkle/path", api.args[0].Endpoint)
197	require.Equal(t, startSeqnoStr, api.args[0].Args["start_seqno"].String())
198	tc.G.Log.Debug("The second iteration correctly tried to look up %d", startSeqno)
199
200	// Reset the mock and retry, now succeeding
201	api.getError = nil
202	api.resetHistory()
203
204	advance(MerkleAuditSettings.Interval + time.Second)
205	expectMeta(t, metaCh, "woke-interval")
206	expectMeta(t, metaCh, "woke-wakeup")
207
208	select {
209	case x := <-roundResCh:
210		require.Equal(t, nil, x, "round result #3")
211	case <-time.After(30 * time.Second):
212		require.FailNow(t, "channel timed out")
213	}
214	expectMeta(t, metaCh, "loop-round-complete")
215
216	require.NotEmpty(t, api.args)
217	require.NotEmpty(t, api.resps)
218	require.Equal(t, "merkle/path", api.args[0].Endpoint)
219
220	successfulSeqno, err := api.resps[0].Body.AtKey("root").AtKey("seqno").GetInt64()
221	require.NoError(t, err)
222	require.Equal(t, startSeqno, successfulSeqno, "result #3 seqno")
223	tc.G.Log.Debug("Third iteration succeeded on validating %d.", successfulSeqno)
224
225	// Fourth iteration should try to audit another block
226	api.resetHistory()
227
228	advance(MerkleAuditSettings.Interval + time.Second)
229	expectMeta(t, metaCh, "woke-interval")
230	expectMeta(t, metaCh, "woke-wakeup")
231
232	select {
233	case x := <-roundResCh:
234		require.Equal(t, nil, x, "round result #4")
235	case <-time.After(30 * time.Second):
236		require.FailNow(t, "channel timed out")
237	}
238	expectMeta(t, metaCh, "loop-round-complete")
239
240	require.NotEmpty(t, api.args)
241	require.NotEmpty(t, api.resps)
242	require.Equal(t, "merkle/path", api.args[0].Endpoint)
243
244	differentSeqno, err := api.resps[0].Body.AtKey("root").AtKey("seqno").GetInt64()
245	require.NoError(t, err)
246	require.NotEqual(t, startSeqno, differentSeqno, "result #4 seqno")
247	tc.G.Log.Debug("Fourth iteration succeeded on validating another root, %d.", differentSeqno)
248
249	err = eng.Shutdown(m)
250	require.NoError(t, err)
251	expectMeta(t, metaCh, "loop-exit")
252	expectMeta(t, metaCh, "")
253}
254
255type merkleAuditErrorListener struct {
256	libkb.NoopNotifyListener
257
258	merkleAuditError chan string
259}
260
261var _ libkb.NotifyListener = (*merkleAuditErrorListener)(nil)
262
263func (m *merkleAuditErrorListener) RootAuditError(msg string) {
264	m.merkleAuditError <- msg
265}
266
267func TestMerkleAuditFail(t *testing.T) {
268	tc := SetupEngineTest(t, "merkleaudit")
269	defer tc.Cleanup()
270
271	api := newRetryMerkleAuditMock(tc)
272	tc.G.API = api
273
274	tc.G.SetService()
275	notifyListener := &merkleAuditErrorListener{
276		merkleAuditError: make(chan string),
277	}
278	tc.G.NotifyRouter.AddListener(notifyListener)
279
280	fakeClock := clockwork.NewFakeClockAt(time.Now())
281	tc.G.SetClock(fakeClock)
282
283	advance := func(d time.Duration) {
284		tc.G.Log.Debug("+ fakeClock#advance(%s) start: %s", d, fakeClock.Now())
285		fakeClock.Advance(d)
286		tc.G.Log.Debug("- fakeClock#adance(%s) end: %s", d, fakeClock.Now())
287	}
288
289	metaCh := make(chan string, 100)
290	roundResCh := make(chan error, 100)
291	arg := &MerkleAuditArgs{
292		testingMetaCh:     metaCh,
293		testingRoundResCh: roundResCh,
294	}
295	eng := NewMerkleAudit(tc.G, arg)
296	eng.task.args.Settings.StartStagger = 0 // Disable stagger for deterministic testing
297	m := NewMetaContextForTest(tc)
298	err := RunEngine2(m, eng)
299	require.NoError(t, err)
300
301	// Run a manual root fetch
302	_, err = tc.G.MerkleClient.FetchRootFromServer(m, time.Hour)
303	require.NoError(t, err)
304
305	require.NotEmpty(t, api.args)
306	require.NotEmpty(t, api.resps)
307	require.Equal(t, "merkle/root", api.args[0].Endpoint)
308
309	// Make sure that the initial root fetch worked
310	x, err := api.resps[0].Body.AtKey("seqno").GetInt64()
311	tc.G.Log.Debug("last seqno %d", x)
312	require.NoError(t, err)
313
314	// Make the mock return an error on API.Get
315	validationError := libkb.NewClientMerkleSkipHashMismatchError("test error")
316	api.getError = validationError
317	api.resetHistory()
318
319	expectMeta(t, metaCh, "loop-start")
320	advance(MerkleAuditSettings.Start + time.Second)
321	expectMeta(t, metaCh, "woke-start")
322
323	// first run should fail and send a notification
324	select {
325	case x := <-notifyListener.merkleAuditError:
326		require.Regexp(t, "Merkle tree audit from [0-9]+ failed: Error checking merkle tree: test error", x, "notification message")
327	case <-time.After(30 * time.Second):
328		require.FailNow(t, "channel timed out")
329	}
330	select {
331	case x := <-roundResCh:
332		require.Equal(t, validationError, x, "round result")
333	case <-time.After(30 * time.Second):
334		require.FailNow(t, "channel timed out")
335	}
336	expectMeta(t, metaCh, "loop-round-complete")
337
338	err = eng.Shutdown(m)
339	require.NoError(t, err)
340	expectMeta(t, metaCh, "loop-exit")
341	expectMeta(t, metaCh, "")
342}
343