← Back to branch summary

~nskaggs/+junk/xenial-test

« back to all changes in this revision

Viewing changes to src/github.com/juju/juju/state/logs_test.go

  • Committer: Nicholas Skaggs
  • Date: 2016-10-24 20:56:05 UTC
  • Revision ID: nicholas.skaggs@canonical.com-20161024205605-z8lta0uvuhtxwzwl
Initi with beta15

Show diffs side-by-side

added added

removed removed

Lines of Context:
src/github.com/juju/juju/state/logs_test.go
 
1
// Copyright 2015 Canonical Ltd.
 
2
// Licensed under the AGPLv3, see LICENCE file for details.
 
3
 
 
4
package state_test
 
5
 
 
6
import (
 
7
        "math/rand"
 
8
        "strconv"
 
9
        "strings"
 
10
        "time"
 
11
 
 
12
        "github.com/juju/loggo"
 
13
        jc "github.com/juju/testing/checkers"
 
14
        "github.com/juju/version"
 
15
        gc "gopkg.in/check.v1"
 
16
        "gopkg.in/juju/names.v2"
 
17
        "gopkg.in/mgo.v2"
 
18
        "gopkg.in/mgo.v2/bson"
 
19
 
 
20
        "github.com/juju/juju/state"
 
21
        coretesting "github.com/juju/juju/testing"
 
22
        jujuversion "github.com/juju/juju/version"
 
23
)
 
24
 
 
25
type LogsSuite struct {
 
26
        ConnSuite
 
27
        logsColl *mgo.Collection
 
28
}
 
29
 
 
30
var _ = gc.Suite(&LogsSuite{})
 
31
 
 
32
func (s *LogsSuite) SetUpTest(c *gc.C) {
 
33
        s.ConnSuite.SetUpTest(c)
 
34
 
 
35
        session := s.State.MongoSession()
 
36
        s.logsColl = session.DB("logs").C("logs")
 
37
}
 
38
 
 
39
func (s *LogsSuite) TestLastSentLogTrackerSetGet(c *gc.C) {
 
40
        tracker := state.NewLastSentLogTracker(s.State, s.State.ModelUUID(), "test-sink")
 
41
        defer tracker.Close()
 
42
 
 
43
        err := tracker.Set(10, 100)
 
44
        c.Assert(err, jc.ErrorIsNil)
 
45
        id1, ts1, err := tracker.Get()
 
46
        c.Assert(err, jc.ErrorIsNil)
 
47
        err = tracker.Set(20, 200)
 
48
        c.Assert(err, jc.ErrorIsNil)
 
49
        id2, ts2, err := tracker.Get()
 
50
        c.Assert(err, jc.ErrorIsNil)
 
51
 
 
52
        c.Check(id1, gc.Equals, int64(10))
 
53
        c.Check(ts1, gc.Equals, int64(100))
 
54
        c.Check(id2, gc.Equals, int64(20))
 
55
        c.Check(ts2, gc.Equals, int64(200))
 
56
}
 
57
 
 
58
func (s *LogsSuite) TestLastSentLogTrackerGetNeverSet(c *gc.C) {
 
59
        tracker := state.NewLastSentLogTracker(s.State, s.State.ModelUUID(), "test")
 
60
        defer tracker.Close()
 
61
 
 
62
        _, _, err := tracker.Get()
 
63
 
 
64
        c.Check(err, gc.ErrorMatches, state.ErrNeverForwarded.Error())
 
65
}
 
66
 
 
67
func (s *LogsSuite) TestLastSentLogTrackerIndependentModels(c *gc.C) {
 
68
        tracker0 := state.NewLastSentLogTracker(s.State, s.State.ModelUUID(), "test-sink")
 
69
        defer tracker0.Close()
 
70
        otherModel := s.NewStateForModelNamed(c, "test-model")
 
71
        defer otherModel.Close()
 
72
        tracker1 := state.NewLastSentLogTracker(otherModel, otherModel.ModelUUID(), "test-sink") // same sink
 
73
        defer tracker1.Close()
 
74
        err := tracker0.Set(10, 100)
 
75
        c.Assert(err, jc.ErrorIsNil)
 
76
        id0, ts0, err := tracker0.Get()
 
77
        c.Assert(err, jc.ErrorIsNil)
 
78
        c.Assert(id0, gc.Equals, int64(10))
 
79
        c.Assert(ts0, gc.Equals, int64(100))
 
80
 
 
81
        _, _, errBefore := tracker1.Get()
 
82
        err = tracker1.Set(20, 200)
 
83
        c.Assert(err, jc.ErrorIsNil)
 
84
        id1, ts1, errAfter := tracker1.Get()
 
85
        c.Assert(errAfter, jc.ErrorIsNil)
 
86
        id0, ts0, err = tracker0.Get()
 
87
        c.Assert(err, jc.ErrorIsNil)
 
88
 
 
89
        c.Check(errBefore, gc.ErrorMatches, state.ErrNeverForwarded.Error())
 
90
        c.Check(id1, gc.Equals, int64(20))
 
91
        c.Check(ts1, gc.Equals, int64(200))
 
92
        c.Check(id0, gc.Equals, int64(10))
 
93
        c.Check(ts0, gc.Equals, int64(100))
 
94
}
 
95
 
 
96
func (s *LogsSuite) TestLastSentLogTrackerIndependentSinks(c *gc.C) {
 
97
        tracker0 := state.NewLastSentLogTracker(s.State, s.State.ModelUUID(), "test-sink0")
 
98
        defer tracker0.Close()
 
99
        tracker1 := state.NewLastSentLogTracker(s.State, s.State.ModelUUID(), "test-sink1")
 
100
        defer tracker1.Close()
 
101
        err := tracker0.Set(10, 100)
 
102
        c.Assert(err, jc.ErrorIsNil)
 
103
        id0, ts0, err := tracker0.Get()
 
104
        c.Assert(err, jc.ErrorIsNil)
 
105
        c.Assert(id0, gc.Equals, int64(10))
 
106
        c.Assert(ts0, gc.Equals, int64(100))
 
107
 
 
108
        _, _, errBefore := tracker1.Get()
 
109
        err = tracker1.Set(20, 200)
 
110
        c.Assert(err, jc.ErrorIsNil)
 
111
        id1, ts1, errAfter := tracker1.Get()
 
112
        c.Assert(errAfter, jc.ErrorIsNil)
 
113
        id0, ts0, err = tracker0.Get()
 
114
        c.Assert(err, jc.ErrorIsNil)
 
115
 
 
116
        c.Check(errBefore, gc.ErrorMatches, state.ErrNeverForwarded.Error())
 
117
        c.Check(id1, gc.Equals, int64(20))
 
118
        c.Check(ts1, gc.Equals, int64(200))
 
119
        c.Check(id0, gc.Equals, int64(10))
 
120
        c.Check(ts0, gc.Equals, int64(100))
 
121
}
 
122
 
 
123
func (s *LogsSuite) TestAllLastSentLogTrackerSetGet(c *gc.C) {
 
124
        st, err := s.State.ForModel(names.NewModelTag(s.State.ControllerUUID()))
 
125
        c.Assert(err, jc.ErrorIsNil)
 
126
        defer st.Close()
 
127
        tracker, err := state.NewAllLastSentLogTracker(st, "test-sink")
 
128
        c.Assert(err, jc.ErrorIsNil)
 
129
        defer tracker.Close()
 
130
 
 
131
        err = tracker.Set(10, 100)
 
132
        c.Assert(err, jc.ErrorIsNil)
 
133
        id1, ts1, err := tracker.Get()
 
134
        c.Assert(err, jc.ErrorIsNil)
 
135
        err = tracker.Set(20, 200)
 
136
        c.Assert(err, jc.ErrorIsNil)
 
137
        id2, ts2, err := tracker.Get()
 
138
        c.Assert(err, jc.ErrorIsNil)
 
139
 
 
140
        c.Check(id1, gc.Equals, int64(10))
 
141
        c.Check(ts1, gc.Equals, int64(100))
 
142
        c.Check(id2, gc.Equals, int64(20))
 
143
        c.Check(ts2, gc.Equals, int64(200))
 
144
}
 
145
 
 
146
func (s *LogsSuite) TestAllLastSentLogTrackerNotController(c *gc.C) {
 
147
        st := s.NewStateForModelNamed(c, "test-model")
 
148
        defer st.Close()
 
149
 
 
150
        _, err := state.NewAllLastSentLogTracker(st, "test")
 
151
 
 
152
        c.Check(err, gc.ErrorMatches, `only the admin model can track all log records`)
 
153
}
 
154
 
 
155
func (s *LogsSuite) TestIndexesCreated(c *gc.C) {
 
156
        // Indexes should be created on the logs collection when state is opened.
 
157
        indexes, err := s.logsColl.Indexes()
 
158
        c.Assert(err, jc.ErrorIsNil)
 
159
        var keys []string
 
160
        for _, index := range indexes {
 
161
                keys = append(keys, strings.Join(index.Key, "-"))
 
162
        }
 
163
        c.Assert(keys, jc.SameContents, []string{
 
164
                "_id", // default index
 
165
                "e-t", // model-uuid and timestamp
 
166
                "e-n", // model-uuid and entity
 
167
        })
 
168
}
 
169
 
 
170
func (s *LogsSuite) TestDbLogger(c *gc.C) {
 
171
        logger := state.NewDbLogger(s.State, names.NewMachineTag("22"), jujuversion.Current)
 
172
        defer logger.Close()
 
173
        t0 := time.Now().Truncate(time.Millisecond) // MongoDB only stores timestamps with ms precision.
 
174
        logger.Log(t0, "some.where", "foo.go:99", loggo.INFO, "all is well")
 
175
        t1 := t0.Add(time.Second)
 
176
        logger.Log(t1, "else.where", "bar.go:42", loggo.ERROR, "oh noes")
 
177
 
 
178
        var docs []bson.M
 
179
        err := s.logsColl.Find(nil).Sort("t").All(&docs)
 
180
        c.Assert(err, jc.ErrorIsNil)
 
181
        c.Assert(docs, gc.HasLen, 2)
 
182
 
 
183
        c.Assert(docs[0]["t"], gc.Equals, t0.UnixNano())
 
184
        c.Assert(docs[0]["e"], gc.Equals, s.State.ModelUUID())
 
185
        c.Assert(docs[0]["n"], gc.Equals, "machine-22")
 
186
        c.Assert(docs[0]["m"], gc.Equals, "some.where")
 
187
        c.Assert(docs[0]["l"], gc.Equals, "foo.go:99")
 
188
        c.Assert(docs[0]["v"], gc.Equals, int(loggo.INFO))
 
189
        c.Assert(docs[0]["x"], gc.Equals, "all is well")
 
190
 
 
191
        c.Assert(docs[1]["t"], gc.Equals, t1.UnixNano())
 
192
        c.Assert(docs[1]["e"], gc.Equals, s.State.ModelUUID())
 
193
        c.Assert(docs[1]["n"], gc.Equals, "machine-22")
 
194
        c.Assert(docs[1]["m"], gc.Equals, "else.where")
 
195
        c.Assert(docs[1]["l"], gc.Equals, "bar.go:42")
 
196
        c.Assert(docs[1]["v"], gc.Equals, int(loggo.ERROR))
 
197
        c.Assert(docs[1]["x"], gc.Equals, "oh noes")
 
198
}
 
199
 
 
200
func (s *LogsSuite) TestPruneLogsByTime(c *gc.C) {
 
201
        dbLogger := state.NewDbLogger(s.State, names.NewMachineTag("22"), jujuversion.Current)
 
202
        defer dbLogger.Close()
 
203
        log := func(t time.Time, msg string) {
 
204
                err := dbLogger.Log(t, "module", "loc", loggo.INFO, msg)
 
205
                c.Assert(err, jc.ErrorIsNil)
 
206
        }
 
207
 
 
208
        now := time.Now()
 
209
        maxLogTime := now.Add(-time.Minute)
 
210
        log(now, "keep")
 
211
        log(maxLogTime.Add(time.Second), "keep")
 
212
        log(maxLogTime, "keep")
 
213
        log(maxLogTime.Add(-time.Second), "prune")
 
214
        log(maxLogTime.Add(-(2 * time.Second)), "prune")
 
215
 
 
216
        noPruneMB := 100
 
217
        err := state.PruneLogs(s.State, maxLogTime, noPruneMB)
 
218
        c.Assert(err, jc.ErrorIsNil)
 
219
 
 
220
        // After pruning there should just be 3 "keep" messages left.
 
221
        var docs []bson.M
 
222
        err = s.logsColl.Find(nil).All(&docs)
 
223
        c.Assert(err, jc.ErrorIsNil)
 
224
        c.Assert(docs, gc.HasLen, 3)
 
225
        for _, doc := range docs {
 
226
                c.Assert(doc["x"], gc.Equals, "keep")
 
227
        }
 
228
}
 
229
 
 
230
func (s *LogsSuite) TestPruneLogsBySize(c *gc.C) {
 
231
        // Set up 3 models and generate different amounts of logs
 
232
        // for them.
 
233
        now := time.Now().Truncate(time.Millisecond)
 
234
 
 
235
        s0 := s.State
 
236
        startingLogsS0 := 10
 
237
        s.generateLogs(c, s0, now, startingLogsS0)
 
238
 
 
239
        s1 := s.Factory.MakeModel(c, nil)
 
240
        defer s1.Close()
 
241
        startingLogsS1 := 10000
 
242
        s.generateLogs(c, s1, now, startingLogsS1)
 
243
 
 
244
        s2 := s.Factory.MakeModel(c, nil)
 
245
        defer s2.Close()
 
246
        startingLogsS2 := 12000
 
247
        s.generateLogs(c, s2, now, startingLogsS2)
 
248
 
 
249
        // Prune logs collection back to 1 MiB.
 
250
        tsNoPrune := time.Now().Add(-3 * 24 * time.Hour)
 
251
        err := state.PruneLogs(s.State, tsNoPrune, 1)
 
252
        c.Assert(err, jc.ErrorIsNil)
 
253
 
 
254
        // Logs for first env should not be touched.
 
255
        c.Assert(s.countLogs(c, s0), gc.Equals, startingLogsS0)
 
256
 
 
257
        // Logs for second env should be pruned.
 
258
        c.Assert(s.countLogs(c, s1), jc.LessThan, startingLogsS1)
 
259
 
 
260
        // Logs for third env should be pruned to a similar level as
 
261
        // second env.
 
262
        c.Assert(s.countLogs(c, s2), jc.LessThan, startingLogsS1)
 
263
 
 
264
        // Ensure that the latest log records are still there.
 
265
        assertLatestTs := func(st *state.State) {
 
266
                var doc bson.M
 
267
                err := s.logsColl.Find(bson.M{"e": st.ModelUUID()}).Sort("-t").One(&doc)
 
268
                c.Assert(err, jc.ErrorIsNil)
 
269
                c.Assert(doc["t"], gc.Equals, now.UnixNano())
 
270
        }
 
271
        assertLatestTs(s0)
 
272
        assertLatestTs(s1)
 
273
        assertLatestTs(s2)
 
274
}
 
275
 
 
276
func (s *LogsSuite) generateLogs(c *gc.C, st *state.State, endTime time.Time, count int) {
 
277
        dbLogger := state.NewDbLogger(st, names.NewMachineTag("0"), jujuversion.Current)
 
278
        defer dbLogger.Close()
 
279
        for i := 0; i < count; i++ {
 
280
                ts := endTime.Add(-time.Duration(i) * time.Second)
 
281
                err := dbLogger.Log(ts, "module", "loc", loggo.INFO, "message")
 
282
                c.Assert(err, jc.ErrorIsNil)
 
283
        }
 
284
}
 
285
 
 
286
func (s *LogsSuite) countLogs(c *gc.C, st *state.State) int {
 
287
        count, err := s.logsColl.Find(bson.M{"e": st.ModelUUID()}).Count()
 
288
        c.Assert(err, jc.ErrorIsNil)
 
289
        return count
 
290
}
 
291
 
 
292
type LogTailerSuite struct {
 
293
        ConnSuite
 
294
        logsColl   *mgo.Collection
 
295
        oplogColl  *mgo.Collection
 
296
        otherState *state.State
 
297
}
 
298
 
 
299
var _ = gc.Suite(&LogTailerSuite{})
 
300
 
 
301
func (s *LogTailerSuite) SetUpTest(c *gc.C) {
 
302
        s.ConnSuite.SetUpTest(c)
 
303
 
 
304
        session := s.State.MongoSession()
 
305
        s.logsColl = session.DB("logs").C("logs")
 
306
 
 
307
        // Create a fake oplog collection.
 
308
        s.oplogColl = session.DB("logs").C("oplog.fake")
 
309
        err := s.oplogColl.Create(&mgo.CollectionInfo{
 
310
                Capped:   true,
 
311
                MaxBytes: 1024 * 1024,
 
312
        })
 
313
        c.Assert(err, jc.ErrorIsNil)
 
314
        s.AddCleanup(func(*gc.C) { s.oplogColl.DropCollection() })
 
315
 
 
316
        s.otherState = s.NewStateForModelNamed(c, "test-model")
 
317
        c.Assert(s.otherState, gc.NotNil)
 
318
        s.AddCleanup(func(c *gc.C) {
 
319
                err := s.otherState.Close()
 
320
                c.Assert(err, jc.ErrorIsNil)
 
321
        })
 
322
}
 
323
 
 
324
func (s *LogTailerSuite) TestTimeFiltering(c *gc.C) {
 
325
        // Add 10 logs that shouldn't be returned.
 
326
        threshT := time.Now()
 
327
        s.writeLogsT(c,
 
328
                threshT.Add(-5*time.Second), threshT.Add(-time.Millisecond), 5,
 
329
                logTemplate{Message: "dont want"},
 
330
        )
 
331
 
 
332
        // Add 5 logs that should be returned.
 
333
        want := logTemplate{Message: "want"}
 
334
        s.writeLogsT(c, threshT, threshT.Add(5*time.Second), 5, want)
 
335
        tailer, err := state.NewLogTailer(s.otherState, &state.LogTailerParams{
 
336
                StartTime: threshT,
 
337
                Oplog:     s.oplogColl,
 
338
        })
 
339
        c.Assert(err, jc.ErrorIsNil)
 
340
        defer tailer.Stop()
 
341
        s.assertTailer(c, tailer, 5, want)
 
342
 
 
343
        // Write more logs. These will be read from the the oplog.
 
344
        want2 := logTemplate{Message: "want 2"}
 
345
        s.writeLogsT(c, threshT.Add(6*time.Second), threshT.Add(10*time.Second), 5, want2)
 
346
        s.assertTailer(c, tailer, 5, want2)
 
347
 
 
348
}
 
349
 
 
350
func (s *LogTailerSuite) TestOplogTransition(c *gc.C) {
 
351
        // Ensure that logs aren't repeated as the log tailer moves from
 
352
        // reading from the logs collection to tailing the oplog.
 
353
        //
 
354
        // All logs are written out with the same timestamp to create a
 
355
        // challenging scenario for the tailer.
 
356
 
 
357
        for i := 0; i < 5; i++ {
 
358
                s.writeLogs(c, 1, logTemplate{Message: strconv.Itoa(i)})
 
359
        }
 
360
 
 
361
        tailer, err := state.NewLogTailer(s.otherState, &state.LogTailerParams{
 
362
                Oplog: s.oplogColl,
 
363
        })
 
364
        c.Assert(err, jc.ErrorIsNil)
 
365
        defer tailer.Stop()
 
366
        for i := 0; i < 5; i++ {
 
367
                s.assertTailer(c, tailer, 1, logTemplate{Message: strconv.Itoa(i)})
 
368
        }
 
369
 
 
370
        // Write more logs. These will be read from the the oplog.
 
371
        for i := 5; i < 10; i++ {
 
372
                lt := logTemplate{Message: strconv.Itoa(i)}
 
373
                s.writeLogs(c, 2, lt)
 
374
                s.assertTailer(c, tailer, 2, lt)
 
375
        }
 
376
}
 
377
 
 
378
func (s *LogTailerSuite) TestModelFiltering(c *gc.C) {
 
379
        good := logTemplate{Message: "good"}
 
380
        writeLogs := func() {
 
381
                s.writeLogs(c, 1, logTemplate{
 
382
                        ModelUUID: "someuuid0",
 
383
                        Message:   "bad",
 
384
                })
 
385
                s.writeLogs(c, 1, logTemplate{
 
386
                        ModelUUID: "someuuid1",
 
387
                        Message:   "bad",
 
388
                })
 
389
                s.writeLogs(c, 1, good)
 
390
        }
 
391
 
 
392
        assert := func(tailer state.LogTailer) {
 
393
                // Only the entries the s.State's UUID should be reported.
 
394
                s.assertTailer(c, tailer, 1, good)
 
395
        }
 
396
 
 
397
        s.checkLogTailerFiltering(c, s.otherState, &state.LogTailerParams{}, writeLogs, assert)
 
398
}
 
399
 
 
400
func (s *LogTailerSuite) TestTailingLogsForAllModels(c *gc.C) {
 
401
        writeLogs := func() {
 
402
                s.writeLogs(c, 1, logTemplate{
 
403
                        ModelUUID: "someuuid0",
 
404
                        Message:   "bad",
 
405
                })
 
406
                s.writeLogs(c, 1, logTemplate{
 
407
                        ModelUUID: "someuuid1",
 
408
                        Message:   "bad",
 
409
                })
 
410
                s.writeLogs(c, 1, logTemplate{Message: "good"})
 
411
        }
 
412
 
 
413
        assert := func(tailer state.LogTailer) {
 
414
                messagesFrom := map[string]bool{
 
415
                        s.otherState.ModelUUID(): false,
 
416
                        "someuuid0":              false,
 
417
                        "someuuid1":              false,
 
418
                }
 
419
                defer func() {
 
420
                        c.Assert(messagesFrom, gc.HasLen, 3)
 
421
                        for _, v := range messagesFrom {
 
422
                                c.Assert(v, jc.IsTrue)
 
423
                        }
 
424
                }()
 
425
                count := 0
 
426
                for {
 
427
                        select {
 
428
                        case log := <-tailer.Logs():
 
429
                                messagesFrom[log.ModelUUID] = true
 
430
                                count++
 
431
                                c.Logf("count %d", count)
 
432
                                if count >= 3 {
 
433
                                        return
 
434
                                }
 
435
                        case <-time.After(coretesting.ShortWait):
 
436
                                c.Fatalf("timeout waiting for logs %d", count)
 
437
                        }
 
438
                }
 
439
        }
 
440
        s.checkLogTailerFiltering(c, s.State, &state.LogTailerParams{AllModels: true}, writeLogs, assert)
 
441
}
 
442
 
 
443
func (s *LogTailerSuite) TestTailingLogsOnlyForControllerModel(c *gc.C) {
 
444
        writeLogs := func() {
 
445
                s.writeLogs(c, 1, logTemplate{
 
446
                        ModelUUID: s.otherState.ModelUUID(),
 
447
                        Message:   "bad"},
 
448
                )
 
449
                s.writeLogs(c, 1, logTemplate{
 
450
                        ModelUUID: s.State.ModelUUID(),
 
451
                        Message:   "good1",
 
452
                })
 
453
                s.writeLogs(c, 1, logTemplate{
 
454
                        ModelUUID: s.State.ModelUUID(),
 
455
                        Message:   "good2",
 
456
                })
 
457
        }
 
458
 
 
459
        assert := func(tailer state.LogTailer) {
 
460
                messages := map[string]bool{}
 
461
                defer func() {
 
462
                        c.Assert(messages, gc.HasLen, 2)
 
463
                        for m, _ := range messages {
 
464
                                if m != "good1" && m != "good2" {
 
465
                                        c.Fatalf("received message: %v", m)
 
466
                                }
 
467
                        }
 
468
                }()
 
469
                count := 0
 
470
                for {
 
471
                        select {
 
472
                        case log := <-tailer.Logs():
 
473
                                c.Assert(log.ModelUUID, gc.Equals, s.State.ModelUUID())
 
474
                                messages[log.Message] = true
 
475
                                count++
 
476
                                c.Logf("count %d", count)
 
477
                                if count >= 2 {
 
478
                                        return
 
479
                                }
 
480
                        case <-time.After(coretesting.ShortWait):
 
481
                                c.Fatalf("timeout waiting for logs %d", count)
 
482
                        }
 
483
                }
 
484
        }
 
485
        s.checkLogTailerFiltering(c, s.State, &state.LogTailerParams{}, writeLogs, assert)
 
486
}
 
487
 
 
488
func (s *LogTailerSuite) TestTailingAllLogsFromNonController(c *gc.C) {
 
489
        _, err := state.NewLogTailer(s.otherState, &state.LogTailerParams{AllModels: true})
 
490
        c.Assert(err, gc.ErrorMatches, "not allowed to tail logs from all models: not a controller")
 
491
}
 
492
 
 
493
func (s *LogTailerSuite) TestLevelFiltering(c *gc.C) {
 
494
        info := logTemplate{Level: loggo.INFO}
 
495
        error := logTemplate{Level: loggo.ERROR}
 
496
        writeLogs := func() {
 
497
                s.writeLogs(c, 1, logTemplate{Level: loggo.DEBUG})
 
498
                s.writeLogs(c, 1, info)
 
499
                s.writeLogs(c, 1, error)
 
500
        }
 
501
        params := &state.LogTailerParams{
 
502
                MinLevel: loggo.INFO,
 
503
        }
 
504
        assert := func(tailer state.LogTailer) {
 
505
                s.assertTailer(c, tailer, 1, info)
 
506
                s.assertTailer(c, tailer, 1, error)
 
507
        }
 
508
        s.checkLogTailerFiltering(c, s.otherState, params, writeLogs, assert)
 
509
}
 
510
 
 
511
func (s *LogTailerSuite) TestInitialLines(c *gc.C) {
 
512
        expected := logTemplate{Message: "want"}
 
513
        s.writeLogs(c, 3, logTemplate{Message: "dont want"})
 
514
        s.writeLogs(c, 5, expected)
 
515
 
 
516
        tailer, err := state.NewLogTailer(s.otherState, &state.LogTailerParams{
 
517
                InitialLines: 5,
 
518
        })
 
519
        c.Assert(err, jc.ErrorIsNil)
 
520
        defer tailer.Stop()
 
521
 
 
522
        // Should see just the last 5 lines as requested.
 
523
        s.assertTailer(c, tailer, 5, expected)
 
524
}
 
525
 
 
526
func (s *LogTailerSuite) TestInitialLinesWithNotEnoughLines(c *gc.C) {
 
527
        expected := logTemplate{Message: "want"}
 
528
        s.writeLogs(c, 2, expected)
 
529
 
 
530
        tailer, err := state.NewLogTailer(s.otherState, &state.LogTailerParams{
 
531
                InitialLines: 5,
 
532
        })
 
533
        c.Assert(err, jc.ErrorIsNil)
 
534
        defer tailer.Stop()
 
535
 
 
536
        // Should see just the 2 lines that existed, even though 5 were
 
537
        // asked for.
 
538
        s.assertTailer(c, tailer, 2, expected)
 
539
}
 
540
 
 
541
func (s *LogTailerSuite) TestNoTail(c *gc.C) {
 
542
        expected := logTemplate{Message: "want"}
 
543
        s.writeLogs(c, 2, expected)
 
544
 
 
545
        // Write a log entry that's only in the oplog.
 
546
        doc := s.logTemplateToDoc(logTemplate{Message: "dont want"}, time.Now())
 
547
        err := s.writeLogToOplog(doc)
 
548
        c.Assert(err, jc.ErrorIsNil)
 
549
 
 
550
        tailer, err := state.NewLogTailer(s.otherState, &state.LogTailerParams{
 
551
                NoTail: true,
 
552
        })
 
553
        c.Assert(err, jc.ErrorIsNil)
 
554
        // Not strictly necessary, just in case NoTail doesn't work in the test.
 
555
        defer tailer.Stop()
 
556
 
 
557
        // Logs only in the oplog shouldn't be reported and the tailer
 
558
        // should stop itself once the log collection has been read.
 
559
        s.assertTailer(c, tailer, 2, expected)
 
560
        select {
 
561
        case _, ok := <-tailer.Logs():
 
562
                if ok {
 
563
                        c.Fatal("shouldn't be any further logs")
 
564
                }
 
565
        case <-time.After(coretesting.LongWait):
 
566
                c.Fatal("timed out waiting for logs channel to close")
 
567
        }
 
568
 
 
569
        select {
 
570
        case <-tailer.Dying():
 
571
                // Success.
 
572
        case <-time.After(coretesting.LongWait):
 
573
                c.Fatal("tailer didn't stop itself")
 
574
        }
 
575
}
 
576
 
 
577
func (s *LogTailerSuite) TestIncludeEntity(c *gc.C) {
 
578
        machine0 := logTemplate{Entity: names.NewMachineTag("0")}
 
579
        foo0 := logTemplate{Entity: names.NewUnitTag("foo/0")}
 
580
        foo1 := logTemplate{Entity: names.NewUnitTag("foo/1")}
 
581
        writeLogs := func() {
 
582
                s.writeLogs(c, 3, machine0)
 
583
                s.writeLogs(c, 2, foo0)
 
584
                s.writeLogs(c, 1, foo1)
 
585
                s.writeLogs(c, 3, machine0)
 
586
        }
 
587
        params := &state.LogTailerParams{
 
588
                IncludeEntity: []string{
 
589
                        "unit-foo-0",
 
590
                        "unit-foo-1",
 
591
                },
 
592
        }
 
593
        assert := func(tailer state.LogTailer) {
 
594
                s.assertTailer(c, tailer, 2, foo0)
 
595
                s.assertTailer(c, tailer, 1, foo1)
 
596
        }
 
597
        s.checkLogTailerFiltering(c, s.otherState, params, writeLogs, assert)
 
598
}
 
599
 
 
600
func (s *LogTailerSuite) TestIncludeEntityWildcard(c *gc.C) {
 
601
        machine0 := logTemplate{Entity: names.NewMachineTag("0")}
 
602
        foo0 := logTemplate{Entity: names.NewUnitTag("foo/0")}
 
603
        foo1 := logTemplate{Entity: names.NewUnitTag("foo/1")}
 
604
        writeLogs := func() {
 
605
                s.writeLogs(c, 3, machine0)
 
606
                s.writeLogs(c, 2, foo0)
 
607
                s.writeLogs(c, 1, foo1)
 
608
                s.writeLogs(c, 3, machine0)
 
609
        }
 
610
        params := &state.LogTailerParams{
 
611
                IncludeEntity: []string{
 
612
                        "unit-foo*",
 
613
                },
 
614
        }
 
615
        assert := func(tailer state.LogTailer) {
 
616
                s.assertTailer(c, tailer, 2, foo0)
 
617
                s.assertTailer(c, tailer, 1, foo1)
 
618
        }
 
619
        s.checkLogTailerFiltering(c, s.otherState, params, writeLogs, assert)
 
620
}
 
621
 
 
622
func (s *LogTailerSuite) TestExcludeEntity(c *gc.C) {
 
623
        machine0 := logTemplate{Entity: names.NewMachineTag("0")}
 
624
        foo0 := logTemplate{Entity: names.NewUnitTag("foo/0")}
 
625
        foo1 := logTemplate{Entity: names.NewUnitTag("foo/1")}
 
626
        writeLogs := func() {
 
627
                s.writeLogs(c, 3, machine0)
 
628
                s.writeLogs(c, 2, foo0)
 
629
                s.writeLogs(c, 1, foo1)
 
630
                s.writeLogs(c, 3, machine0)
 
631
        }
 
632
        params := &state.LogTailerParams{
 
633
                ExcludeEntity: []string{
 
634
                        "machine-0",
 
635
                        "unit-foo-0",
 
636
                },
 
637
        }
 
638
        assert := func(tailer state.LogTailer) {
 
639
                s.assertTailer(c, tailer, 1, foo1)
 
640
        }
 
641
        s.checkLogTailerFiltering(c, s.otherState, params, writeLogs, assert)
 
642
}
 
643
 
 
644
func (s *LogTailerSuite) TestExcludeEntityWildcard(c *gc.C) {
 
645
        machine0 := logTemplate{Entity: names.NewMachineTag("0")}
 
646
        foo0 := logTemplate{Entity: names.NewUnitTag("foo/0")}
 
647
        foo1 := logTemplate{Entity: names.NewUnitTag("foo/1")}
 
648
        writeLogs := func() {
 
649
                s.writeLogs(c, 3, machine0)
 
650
                s.writeLogs(c, 2, foo0)
 
651
                s.writeLogs(c, 1, foo1)
 
652
                s.writeLogs(c, 3, machine0)
 
653
        }
 
654
        params := &state.LogTailerParams{
 
655
                ExcludeEntity: []string{
 
656
                        "machine*",
 
657
                        "unit-*-0",
 
658
                },
 
659
        }
 
660
        assert := func(tailer state.LogTailer) {
 
661
                s.assertTailer(c, tailer, 1, foo1)
 
662
        }
 
663
        s.checkLogTailerFiltering(c, s.otherState, params, writeLogs, assert)
 
664
}
 
665
func (s *LogTailerSuite) TestIncludeModule(c *gc.C) {
 
666
        mod0 := logTemplate{Module: "foo.bar"}
 
667
        mod1 := logTemplate{Module: "juju.thing"}
 
668
        subMod1 := logTemplate{Module: "juju.thing.hai"}
 
669
        mod2 := logTemplate{Module: "elsewhere"}
 
670
        writeLogs := func() {
 
671
                s.writeLogs(c, 1, mod0)
 
672
                s.writeLogs(c, 1, mod1)
 
673
                s.writeLogs(c, 1, mod0)
 
674
                s.writeLogs(c, 1, subMod1)
 
675
                s.writeLogs(c, 1, mod0)
 
676
                s.writeLogs(c, 1, mod2)
 
677
        }
 
678
        params := &state.LogTailerParams{
 
679
                IncludeModule: []string{"juju.thing", "elsewhere"},
 
680
        }
 
681
        assert := func(tailer state.LogTailer) {
 
682
                s.assertTailer(c, tailer, 1, mod1)
 
683
                s.assertTailer(c, tailer, 1, subMod1)
 
684
                s.assertTailer(c, tailer, 1, mod2)
 
685
        }
 
686
        s.checkLogTailerFiltering(c, s.otherState, params, writeLogs, assert)
 
687
}
 
688
 
 
689
func (s *LogTailerSuite) TestExcludeModule(c *gc.C) {
 
690
        mod0 := logTemplate{Module: "foo.bar"}
 
691
        mod1 := logTemplate{Module: "juju.thing"}
 
692
        subMod1 := logTemplate{Module: "juju.thing.hai"}
 
693
        mod2 := logTemplate{Module: "elsewhere"}
 
694
        writeLogs := func() {
 
695
                s.writeLogs(c, 1, mod0)
 
696
                s.writeLogs(c, 1, mod1)
 
697
                s.writeLogs(c, 1, mod0)
 
698
                s.writeLogs(c, 1, subMod1)
 
699
                s.writeLogs(c, 1, mod0)
 
700
                s.writeLogs(c, 1, mod2)
 
701
        }
 
702
        params := &state.LogTailerParams{
 
703
                ExcludeModule: []string{"juju.thing", "elsewhere"},
 
704
        }
 
705
        assert := func(tailer state.LogTailer) {
 
706
                s.assertTailer(c, tailer, 2, mod0)
 
707
        }
 
708
        s.checkLogTailerFiltering(c, s.otherState, params, writeLogs, assert)
 
709
}
 
710
 
 
711
func (s *LogTailerSuite) TestIncludeExcludeModule(c *gc.C) {
 
712
        foo := logTemplate{Module: "foo"}
 
713
        bar := logTemplate{Module: "bar"}
 
714
        barSub := logTemplate{Module: "bar.thing"}
 
715
        baz := logTemplate{Module: "baz"}
 
716
        qux := logTemplate{Module: "qux"}
 
717
        writeLogs := func() {
 
718
                s.writeLogs(c, 1, foo)
 
719
                s.writeLogs(c, 1, bar)
 
720
                s.writeLogs(c, 1, barSub)
 
721
                s.writeLogs(c, 1, baz)
 
722
                s.writeLogs(c, 1, qux)
 
723
        }
 
724
        params := &state.LogTailerParams{
 
725
                IncludeModule: []string{"foo", "bar", "qux"},
 
726
                ExcludeModule: []string{"foo", "bar"},
 
727
        }
 
728
        assert := func(tailer state.LogTailer) {
 
729
                // Except just "qux" because "foo" and "bar" were included and
 
730
                // then excluded.
 
731
                s.assertTailer(c, tailer, 1, qux)
 
732
        }
 
733
        s.checkLogTailerFiltering(c, s.otherState, params, writeLogs, assert)
 
734
}
 
735
 
 
736
func (s *LogTailerSuite) checkLogTailerFiltering(
 
737
        c *gc.C,
 
738
        st *state.State,
 
739
        params *state.LogTailerParams,
 
740
        writeLogs func(),
 
741
        assertTailer func(state.LogTailer),
 
742
) {
 
743
        // Check the tailer does the right thing when reading from the
 
744
        // logs collection.
 
745
        writeLogs()
 
746
        params.Oplog = s.oplogColl
 
747
        tailer, err := state.NewLogTailer(st, params)
 
748
        c.Assert(err, jc.ErrorIsNil)
 
749
        defer tailer.Stop()
 
750
        assertTailer(tailer)
 
751
 
 
752
        // Now write out logs and check the tailer again. These will be
 
753
        // read from the oplog.
 
754
        writeLogs()
 
755
        assertTailer(tailer)
 
756
}
 
757
 
 
758
type logTemplate struct {
 
759
        ModelUUID string
 
760
        Entity    names.Tag
 
761
        Version   version.Number
 
762
        Module    string
 
763
        Location  string
 
764
        Level     loggo.Level
 
765
        Message   string
 
766
}
 
767
 
 
768
// writeLogs creates count log messages at the current time using
 
769
// the supplied template. As well as writing to the logs collection,
 
770
// entries are also made into the fake oplog collection.
 
771
func (s *LogTailerSuite) writeLogs(c *gc.C, count int, lt logTemplate) {
 
772
        t := time.Now()
 
773
        s.writeLogsT(c, t, t, count, lt)
 
774
}
 
775
 
 
776
// writeLogsT creates count log messages between startTime and
 
777
// endTime using the supplied template. As well as writing to the logs
 
778
// collection, entries are also made into the fake oplog collection.
 
779
func (s *LogTailerSuite) writeLogsT(c *gc.C, startTime, endTime time.Time, count int, lt logTemplate) {
 
780
        interval := endTime.Sub(startTime) / time.Duration(count)
 
781
        t := startTime
 
782
        for i := 0; i < count; i++ {
 
783
                doc := s.logTemplateToDoc(lt, t)
 
784
                err := s.writeLogToOplog(doc)
 
785
                c.Assert(err, jc.ErrorIsNil)
 
786
                err = s.logsColl.Insert(doc)
 
787
                c.Assert(err, jc.ErrorIsNil)
 
788
                t = t.Add(interval)
 
789
        }
 
790
}
 
791
 
 
792
// writeLogToOplog writes out a log record to the a (probably fake)
 
793
// oplog collection.
 
794
func (s *LogTailerSuite) writeLogToOplog(doc interface{}) error {
 
795
        return s.oplogColl.Insert(bson.D{
 
796
                {"ts", bson.MongoTimestamp(time.Now().Unix() << 32)}, // an approximation which will do
 
797
                {"h", rand.Int63()},                                  // again, a suitable fake
 
798
                {"op", "i"},                                          // this will always be an insert
 
799
                {"ns", "logs.logs"},
 
800
                {"o", doc},
 
801
        })
 
802
}
 
803
 
 
804
func (s *LogTailerSuite) normaliseLogTemplate(lt *logTemplate) {
 
805
        if lt.ModelUUID == "" {
 
806
                lt.ModelUUID = s.otherState.ModelUUID()
 
807
        }
 
808
        if lt.Entity == nil {
 
809
                lt.Entity = names.NewMachineTag("0")
 
810
        }
 
811
        if lt.Version == version.Zero {
 
812
                lt.Version = jujuversion.Current
 
813
        }
 
814
        if lt.Module == "" {
 
815
                lt.Module = "module"
 
816
        }
 
817
        if lt.Location == "" {
 
818
                lt.Location = "loc"
 
819
        }
 
820
        if lt.Level == loggo.UNSPECIFIED {
 
821
                lt.Level = loggo.INFO
 
822
        }
 
823
        if lt.Message == "" {
 
824
                lt.Message = "message"
 
825
        }
 
826
}
 
827
 
 
828
func (s *LogTailerSuite) logTemplateToDoc(lt logTemplate, t time.Time) interface{} {
 
829
        s.normaliseLogTemplate(&lt)
 
830
        return state.MakeLogDoc(
 
831
                lt.ModelUUID,
 
832
                lt.Entity,
 
833
                t,
 
834
                lt.Module,
 
835
                lt.Location,
 
836
                lt.Level,
 
837
                lt.Message,
 
838
        )
 
839
}
 
840
 
 
841
func (s *LogTailerSuite) assertTailer(c *gc.C, tailer state.LogTailer, expectedCount int, lt logTemplate) {
 
842
        s.normaliseLogTemplate(&lt)
 
843
 
 
844
        timeout := time.After(coretesting.LongWait)
 
845
        count := 0
 
846
        for {
 
847
                select {
 
848
                case log, ok := <-tailer.Logs():
 
849
                        if !ok {
 
850
                                c.Fatalf("tailer died unexpectedly: %v", tailer.Err())
 
851
                        }
 
852
                        c.Assert(log.Version, gc.Equals, lt.Version)
 
853
                        c.Assert(log.Entity, gc.Equals, lt.Entity)
 
854
                        c.Assert(log.Module, gc.Equals, lt.Module)
 
855
                        c.Assert(log.Location, gc.Equals, lt.Location)
 
856
                        c.Assert(log.Level, gc.Equals, lt.Level)
 
857
                        c.Assert(log.Message, gc.Equals, lt.Message)
 
858
                        c.Assert(log.ModelUUID, gc.Equals, lt.ModelUUID)
 
859
                        count++
 
860
                        if count == expectedCount {
 
861
                                return
 
862
                        }
 
863
                case <-timeout:
 
864
                        c.Fatalf("timed out waiting for logs (received %d)", count)
 
865
                }
 
866
        }
 
867
}