func (s *oplogSuite) TestRestartsOnError(c *gc.C) {
_, session := s.startMongo(c)
oplog := s.makeFakeOplog(c, session)
tailer := mongo.NewOplogTailer(oplog, nil, time.Time{})
defer tailer.Stop()
// First, ensure that the tailer is seeing oplog inserts.
s.insertDoc(c, session, oplog, &mongo.OplogDoc{
Timestamp: 1,
OperationId: 99,
})
doc := s.getNextOplog(c, tailer)
c.Assert(doc.Timestamp, gc.Equals, bson.MongoTimestamp(1))
s.emptyCapped(c, oplog)
// Ensure that the tailer still works.
s.insertDoc(c, session, oplog, &mongo.OplogDoc{
Timestamp: 2,
OperationId: 42,
})
doc = s.getNextOplog(c, tailer)
c.Assert(doc.Timestamp, gc.Equals, bson.MongoTimestamp(2))
}
func (t *logTailer) tailOplog() error {
recentIds := t.recentIds.AsSet()
newParams := t.params
newParams.StartID = t.lastID // (t.lastID + 1) once Id is a sequential int.
oplogSel := append(t.paramsToSelector(newParams, "o."),
bson.DocElem{"ns", logsDB + "." + logsC},
)
oplog := t.params.Oplog
if oplog == nil {
oplog = mongo.GetOplog(t.session)
}
minOplogTs := t.lastTime.Add(-oplogOverlap)
oplogTailer := mongo.NewOplogTailer(mongo.NewOplogSession(oplog, oplogSel), minOplogTs)
defer oplogTailer.Stop()
logger.Tracef("LogTailer starting oplog tailing: recent id count=%d, lastTime=%s, minOplogTs=%s",
recentIds.Length(), t.lastTime, minOplogTs)
skipCount := 0
for {
select {
case <-t.tomb.Dying():
return errors.Trace(tomb.ErrDying)
case oplogDoc, ok := <-oplogTailer.Out():
if !ok {
return errors.Annotate(oplogTailer.Err(), "oplog tailer died")
}
doc := new(logDoc)
err := oplogDoc.UnmarshalObject(doc)
if err != nil {
return errors.Annotate(err, "oplog unmarshalling failed")
}
if recentIds.Contains(doc.Id) {
// This document has already been reported.
skipCount++
if skipCount%1000 == 0 {
logger.Tracef("LogTailer duplicates skipped: %d", skipCount)
}
continue
}
rec, err := logDocToRecord(doc)
if err != nil {
return errors.Annotate(err, "deserialization failed (possible DB corruption)")
}
select {
case <-t.tomb.Dying():
return errors.Trace(tomb.ErrDying)
case t.logCh <- rec:
}
}
}
}
func (s *oplogSuite) TestDiesOnFatalError(c *gc.C) {
expectedErr := errors.New("oh no, the collection went away!")
session := newFakeSession(
newFakeIterator(expectedErr, &mongo.OplogDoc{Timestamp: 1}),
)
tailer := mongo.NewOplogTailer(session, time.Time{})
defer tailer.Stop()
doc := s.getNextOplog(c, tailer)
c.Assert(doc.Timestamp, gc.Equals, bson.MongoTimestamp(1))
s.assertStopped(c, tailer)
c.Assert(tailer.Err(), gc.Equals, expectedErr)
}
func (s *oplogSuite) TestNoRepeatsAfterIterRestart(c *gc.C) {
// A bunch of documents with the same timestamp but different ids.
// These will be split across 2 iterators.
docs := make([]*mongo.OplogDoc, 11)
for i := 0; i < 10; i++ {
id := int64(i + 10)
docs[i] = &mongo.OplogDoc{
Timestamp: 1,
OperationId: id,
}
}
// Add one more with a different timestamp.
docs[10] = &mongo.OplogDoc{
Timestamp: 2,
OperationId: 42,
}
session := newFakeSession(
// First block of documents, all time 1
newFakeIterator(nil, docs[:5]...),
// Second block, some time 1, one time 2
newFakeIterator(nil, docs[5:]...),
)
tailer := mongo.NewOplogTailer(session, time.Time{})
defer tailer.Stop()
for id := int64(10); id < 15; id++ {
doc := s.getNextOplog(c, tailer)
c.Assert(doc.Timestamp, gc.Equals, bson.MongoTimestamp(1))
c.Assert(doc.OperationId, gc.Equals, id)
}
// Check the query doesn't exclude any in the first request.
session.checkLastArgs(c, mongo.NewMongoTimestamp(time.Time{}), nil)
// The OplogTailer will fall off the end of the iterator and get a new one.
// Ensure that only previously unreported entries are now reported.
for id := int64(15); id < 20; id++ {
doc := s.getNextOplog(c, tailer)
c.Assert(doc.Timestamp, gc.Equals, bson.MongoTimestamp(1))
c.Assert(doc.OperationId, gc.Equals, id)
}
// Check we got the next block correctly
session.checkLastArgs(c, bson.MongoTimestamp(1), []int64{10, 11, 12, 13, 14})
doc := s.getNextOplog(c, tailer)
c.Assert(doc.Timestamp, gc.Equals, bson.MongoTimestamp(2))
c.Assert(doc.OperationId, gc.Equals, int64(42))
}
func (s *oplogSuite) TestNoRepeatsAfterIterRestart(c *gc.C) {
_, session := s.startMongo(c)
oplog := s.makeFakeOplog(c, session)
tailer := mongo.NewOplogTailer(oplog, nil, time.Time{})
defer tailer.Stop()
// Insert a bunch of oplog entries with the same timestamp (but
// with different ids) and see them reported.
for id := int64(10); id < 15; id++ {
s.insertDoc(c, session, oplog, &mongo.OplogDoc{
Timestamp: 1,
OperationId: id,
})
doc := s.getNextOplog(c, tailer)
c.Assert(doc.Timestamp, gc.Equals, bson.MongoTimestamp(1))
c.Assert(doc.OperationId, gc.Equals, id)
}
// Force the OplogTailer's iterator to be recreated.
s.emptyCapped(c, oplog)
// Reinsert the oplog entries that were already there before and a
// few more.
for id := int64(10); id < 20; id++ {
s.insertDoc(c, session, oplog, &mongo.OplogDoc{
Timestamp: 1,
OperationId: id,
})
}
// Insert an entry for a later timestamp.
s.insertDoc(c, session, oplog, &mongo.OplogDoc{
Timestamp: 2,
OperationId: 42,
})
// Ensure that only previously unreported entries are now reported.
for id := int64(15); id < 20; id++ {
doc := s.getNextOplog(c, tailer)
c.Assert(doc.Timestamp, gc.Equals, bson.MongoTimestamp(1))
c.Assert(doc.OperationId, gc.Equals, id)
}
doc := s.getNextOplog(c, tailer)
c.Assert(doc.Timestamp, gc.Equals, bson.MongoTimestamp(2))
c.Assert(doc.OperationId, gc.Equals, int64(42))
}
func (s *oplogSuite) TestStops(c *gc.C) {
_, session := s.startMongo(c)
oplog := s.makeFakeOplog(c, session)
tailer := mongo.NewOplogTailer(oplog, nil, time.Time{})
defer tailer.Stop()
s.insertDoc(c, session, oplog, &mongo.OplogDoc{Timestamp: 1})
s.getNextOplog(c, tailer)
err := tailer.Stop()
c.Assert(err, jc.ErrorIsNil)
s.assertStopped(c, tailer)
c.Assert(tailer.Err(), jc.ErrorIsNil)
}
func (s *oplogSuite) TestWithRealOplog(c *gc.C) {
_, session := s.startMongoWithReplicaset(c)
// Watch for oplog entries for the "bar" collection in the "foo"
// DB.
oplog := mongo.GetOplog(session)
tailer := mongo.NewOplogTailer(
mongo.NewOplogSession(
oplog,
bson.D{{"ns", "foo.bar"}},
),
time.Now().Add(-time.Minute),
)
defer tailer.Stop()
assertOplog := func(expectedOp string, expectedObj, expectedUpdate bson.D) {
doc := s.getNextOplog(c, tailer)
c.Assert(doc.Operation, gc.Equals, expectedOp)
var actualObj bson.D
err := doc.UnmarshalObject(&actualObj)
c.Assert(err, jc.ErrorIsNil)
c.Assert(actualObj, jc.DeepEquals, expectedObj)
var actualUpdate bson.D
err = doc.UnmarshalUpdate(&actualUpdate)
c.Assert(err, jc.ErrorIsNil)
c.Assert(actualUpdate, jc.DeepEquals, expectedUpdate)
}
// Insert into foo.bar and see that the oplog entry is reported.
db := session.DB("foo")
coll := db.C("bar")
s.insertDoc(c, session, coll, bson.M{"_id": "thing"})
assertOplog("i", bson.D{{"_id", "thing"}}, nil)
// Update foo.bar and see the update reported.
err := coll.UpdateId("thing", bson.M{"$set": bson.M{"blah": 42}})
c.Assert(err, jc.ErrorIsNil)
assertOplog("u", bson.D{{"$set", bson.D{{"blah", 42}}}}, bson.D{{"_id", "thing"}})
// Insert into another collection (shouldn't be reported due to filter).
s.insertDoc(c, session, db.C("elsewhere"), bson.M{"_id": "boo"})
s.assertNoOplog(c, tailer)
}
func (s *oplogSuite) TestDiesOnFatalError(c *gc.C) {
_, session := s.startMongo(c)
oplog := s.makeFakeOplog(c, session)
s.insertDoc(c, session, oplog, &mongo.OplogDoc{Timestamp: 1})
tailer := mongo.NewOplogTailer(oplog, nil, time.Time{})
defer tailer.Stop()
doc := s.getNextOplog(c, tailer)
c.Assert(doc.Timestamp, gc.Equals, bson.MongoTimestamp(1))
// Induce a fatal error by removing the oplog collection.
err := oplog.DropCollection()
c.Assert(err, jc.ErrorIsNil)
s.assertStopped(c, tailer)
// The actual error varies by MongoDB version so just check that
// there is one.
c.Assert(tailer.Err(), gc.Not(jc.ErrorIsNil))
}
func (s *oplogSuite) TestRestartsOnErrCursor(c *gc.C) {
session := newFakeSession(
// First iterator terminates with an ErrCursor
newFakeIterator(mgo.ErrCursor, &mongo.OplogDoc{Timestamp: 1, OperationId: 99}),
newFakeIterator(nil, &mongo.OplogDoc{Timestamp: 2, OperationId: 42}),
)
tailer := mongo.NewOplogTailer(session, time.Time{})
defer tailer.Stop()
// First, ensure that the tailer is seeing oplog rows and handles
// the ErrCursor that occurs at the end.
doc := s.getNextOplog(c, tailer)
c.Check(doc.Timestamp, gc.Equals, bson.MongoTimestamp(1))
session.checkLastArgs(c, mongo.NewMongoTimestamp(time.Time{}), nil)
// Ensure that the tailer continues after getting a new iterator.
doc = s.getNextOplog(c, tailer)
c.Check(doc.Timestamp, gc.Equals, bson.MongoTimestamp(2))
session.checkLastArgs(c, bson.MongoTimestamp(1), []int64{99})
}
func (s *oplogSuite) TestHonoursInitialTs(c *gc.C) {
_, session := s.startMongo(c)
t := time.Now()
oplog := s.makeFakeOplog(c, session)
for offset := -1; offset <= 1; offset++ {
tDoc := t.Add(time.Duration(offset) * time.Second)
s.insertDoc(c, session, oplog,
&mongo.OplogDoc{Timestamp: mongo.NewMongoTimestamp(tDoc)},
)
}
tailer := mongo.NewOplogTailer(oplog, nil, t)
defer tailer.Stop()
for offset := 0; offset <= 1; offset++ {
doc := s.getNextOplog(c, tailer)
tExpected := t.Add(time.Duration(offset) * time.Second)
c.Assert(doc.Timestamp, gc.Equals, mongo.NewMongoTimestamp(tExpected))
}
}