Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-31255

certain sequence of collection and index operations can cause dropIndex rollback to fail.

    • Type: Icon: Bug Bug
    • Resolution: Fixed
    • Priority: Icon: Major - P3 Major - P3
    • 3.6.0-rc1
    • Affects Version/s: 3.5.13
    • Component/s: Replication
    • Labels:
    • Fully Compatible
    • ALL
    • Repl 2017-10-02, Repl 2017-10-23

      Certain sequences of collection and index operations can cause a dropIndex to be rolled back as an index creation on a collection that doesn't yet exist, causing rollback to fassert.

      Please see the attached file for a repro.

      est:index_builder] 2017-09-25T19:07:02.443-0400 d20013| 2017-09-25T19:07:02.443-0400 I ROLLBACK [rsBackgroundSync] Finding the Common Point
      [js_test:index_builder] 2017-09-25T19:07:02.444-0400 d20013| 2017-09-25T19:07:02.444-0400 I ROLLBACK [rsBackgroundSync] our last optime:   Sep 25 19:06:46:9
      [js_test:index_builder] 2017-09-25T19:07:02.444-0400 d20013| 2017-09-25T19:07:02.444-0400 I ROLLBACK [rsBackgroundSync] their last optime: Sep 25 19:06:57:2
      [js_test:index_builder] 2017-09-25T19:07:02.444-0400 d20013| 2017-09-25T19:07:02.444-0400 I ROLLBACK [rsBackgroundSync] diff in end of log times: -11 seconds
      [js_test:index_builder] 2017-09-25T19:07:02.445-0400 d20013| 2017-09-25T19:07:02.445-0400 I ROLLBACK [rsBackgroundSync] Rollback common point is { ts: Timestamp 1506380800000|8, t: 1 }
      [js_test:index_builder] 2017-09-25T19:07:02.445-0400 d20013| 2017-09-25T19:07:02.445-0400 I ROLLBACK [rsBackgroundSync] Starting refetching documents
      [js_test:index_builder] 2017-09-25T19:07:02.445-0400 d20013| 2017-09-25T19:07:02.445-0400 I ROLLBACK [rsBackgroundSync] Finished refetching documents. Total size of documents refetched: 0
      [js_test:index_builder] 2017-09-25T19:07:02.445-0400 d20013| 2017-09-25T19:07:02.445-0400 I ROLLBACK [rsBackgroundSync] Checking the RollbackID and updating the MinValid if necessary
      [js_test:index_builder] 2017-09-25T19:07:02.446-0400 d20013| 2017-09-25T19:07:02.446-0400 I ROLLBACK [rsBackgroundSync] Setting minvalid to { ts: Timestamp 1506380817000|2, t: 2 }
      [js_test:index_builder] 2017-09-25T19:07:02.447-0400 d20013| 2017-09-25T19:07:02.446-0400 I ROLLBACK [rsBackgroundSync] Dropping collections to roll back create operations
      [js_test:index_builder] 2017-09-25T19:07:02.457-0400 d20013| 2017-09-25T19:07:02.456-0400 I ROLLBACK [rsBackgroundSync] Dropped collection with UUID: c2a33d6e-4b99-4729-8604-02233cb2b409 and nss: test.system.drop.1506380806i9t1.two
      [js_test:index_builder] 2017-09-25T19:07:02.457-0400 d20013| 2017-09-25T19:07:02.456-0400 I ROLLBACK [rsBackgroundSync] Rolling back renameCollection commands and collection drop commands.
      [js_test:index_builder] 2017-09-25T19:07:02.462-0400 d20013| 2017-09-25T19:07:02.461-0400 I ROLLBACK [rsBackgroundSync] Renamed collection from test.system.drop.1506380806i4t1.twoto test.three with uuid: f3b6102f-c359-4652-916d-66c45ef1d8a0
      [js_test:index_builder] 2017-09-25T19:07:02.462-0400 d20013| 2017-09-25T19:07:02.461-0400 I ROLLBACK [rsBackgroundSync] Rolling back collections pending being dropped: Removing them from the list of drop-pending collections in the DropPendingCollectionReaper.
      [js_test:index_builder] 2017-09-25T19:07:02.462-0400 d20013| 2017-09-25T19:07:02.462-0400 I REPL     [rsBackgroundSync] Rolling back collection drop for test.system.drop.1506380806i4t1.two with drop OpTime { ts: Timestamp 1506380806000|4, t: 1 } to namespace test.two
      [js_test:index_builder] 2017-09-25T19:07:02.462-0400 d20013| 2017-09-25T19:07:02.462-0400 I REPL     [rsBackgroundSync] Rolling back collection drop for test.system.drop.1506380806i9t1.two with drop OpTime { ts: Timestamp 1506380806000|9, t: 1 } to namespace test.two
      [js_test:index_builder] 2017-09-25T19:07:02.462-0400 d20013| 2017-09-25T19:07:02.462-0400 I ROLLBACK [rsBackgroundSync] Resyncing collection metadata, uuid: f3b6102f-c359-4652-916d-66c45ef1d8a0
      [js_test:index_builder] 2017-09-25T19:07:02.463-0400 d20013| 2017-09-25T19:07:02.463-0400 I ROLLBACK [rsBackgroundSync] Rechecking the Rollback ID and minValid
      [js_test:index_builder] 2017-09-25T19:07:02.464-0400 d20013| 2017-09-25T19:07:02.464-0400 I ROLLBACK [rsBackgroundSync] Setting minvalid to { ts: Timestamp 1506380817000|2, t: 2 }
      [js_test:index_builder] 2017-09-25T19:07:02.465-0400 d20013| 2017-09-25T19:07:02.464-0400 I ROLLBACK [rsBackgroundSync] Rolling back createIndexes commands.
      [js_test:index_builder] 2017-09-25T19:07:02.465-0400 d20013| 2017-09-25T19:07:02.464-0400 I ROLLBACK [rsBackgroundSync] Rolling back dropIndexes commands.
      [js_test:index_builder] 2017-09-25T19:07:02.465-0400 d20013| 2017-09-25T19:07:02.464-0400 F -        [rsBackgroundSync] Fatal Assertion 40409 at src/mongo/db/index_builder.cpp 131
      [js_test:index_builder] 2017-09-25T19:07:02.465-0400 d20013| 2017-09-25T19:07:02.465-0400 F -        [rsBackgroundSync]
      [js_test:index_builder] 2017-09-25T19:07:02.465-0400 d20013|
      [js_test:index_builder] 2017-09-25T19:07:02.465-0400 d20013| ***aborting after fassert() failure
      

      stack trace:

      mongo::fassertFailedWithLocation(int, char const*, unsigned int)
      mongo::fassertWithLocation(int, bool, char const*, unsigned int)
      mongo::IndexBuilder::_build(mongo::OperationContext*, mongo::Database*, bool, mongo::Lock::DBLock*) const
      mongo::IndexBuilder::buildInForeground(mongo::OperationContext*, mongo::Database*) const
      mongo::repl::createIndexForApplyOps(mongo::OperationContext*, mongo::BSONObj const&, mongo::NamespaceString const&, std::__1::function<void ()>)
      mongo::repl::(anonymous namespace)::rollbackDropIndexes(mongo::OperationContext*, mongo::UUID, std::__1::map<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, mongo::BSONObj, std::__1::less<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >, std::__1::allocator<std::__1::pair<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const, mongo::BSONObj> > >)
      mongo::repl::rollback_internal::syncFixUp(mongo::OperationContext*, mongo::repl::rollback_internal::FixUpInfo const&, mongo::repl::RollbackSource const&, mongo::repl::ReplicationCoordinator*, mongo::repl::ReplicationProcess*)
      mongo::repl::(anonymous namespace)::_syncRollback(mongo::OperationContext*, mongo::repl::OplogInterface const&, mongo::repl::RollbackSource const&, int, mongo::repl::ReplicationCoordinator*, mongo::repl::ReplicationProcess*)
      mongo::repl::syncRollback(mongo::OperationContext*, mongo::repl::OplogInterface const&, mongo::repl::RollbackSource const&, int, mongo::repl::ReplicationCoordinator*, mongo::repl::ReplicationProcess*)
      mongo::repl::rollback(mongo::OperationContext*, mongo::repl::OplogInterface const&, mongo::repl::RollbackSource const&, int, mongo::repl::ReplicationCoordinator*, mongo::repl::ReplicationProcess*, std::__1::function<void (int)>)
      mongo::repl::BackgroundSync::_fallBackOnRollbackViaRefetch(mongo::OperationContext*, mongo::HostAndPort const&, int, mongo::repl::OplogInterface*, bool, std::__1::function<mongo::DBClientBase* ()>)
      mongo::repl::BackgroundSync::_runRollback(mongo::OperationContext*, mongo::Status const&, mongo::HostAndPort const&, int, mongo::repl::StorageInterface*)
      mongo::repl::BackgroundSync::_produce(mongo::OperationContext*)
      mongo::repl::BackgroundSync::_runProducer()
      

            Assignee:
            katherine.walker@mongodb.com Katherine Walker (Inactive)
            Reporter:
            robert.guo@mongodb.com Robert Guo (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            5 Start watching this issue

              Created:
              Updated:
              Resolved: