mongorestore fails with createIndexes command in oplog

Bug #1821391 reported by Simon Richardson
12
This bug affects 1 person
Affects Status Importance Assigned to Milestone
mongodb (Ubuntu)
Fix Released
Critical
Unassigned
Bionic
Fix Released
Critical
Andreas Hasenack
Cosmic
Fix Released
Critical
Andreas Hasenack

Bug Description

[Impact]

When an operator of Juju attempts to restore a backup, it fails with a mongorestore related error[0]. Under the hood, Juju uses the supplied mongo related command line interfaces (mongodump, mongorestore etc), using these in conjunction with the oplog related flags for the former CLIs, the mongorestore fails with the following error:

 > Failed: restore error: error applying oplog: applyOps: applyOps had one or more errors applying ops

The only work around for Juju at the moment is to update mongod, so that it carries the following commit[1]. MongoDB have an identical issue, under a different name, which fixes this[2], but there is unfortunately no work around without upgrading mongod so it caries the former commit.

The original investigation around Juju failing to restore a previous dump can be seen here[3]

I've verified with the 3.6.11 and the same restore, worked fine.

[Test Case]

The following test case doesn't require Juju, and can be replicated quite easily inside a lxc container. It may require 2 or 3 goes, depending on timings of the creation of the index and the mongodump, but I've been getting this consistently.
Please do mind that timing is important, so putting the commands in a script will help a lot to reliably trigger the issue.

You can also find instructions in one pastebin[4]

// Launch a container
lxc launch ubuntu:18.04 mongo
lxc exec mongo bash

// Install a version of mongo that Juju is using.
sudo apt update
sudo apt install -y mongodb

// Edit /etc/mongodb.conf and add the following line:
replSet = "rs0"

// Restart the service
sudo systemctl restart mongodb.service

// not required, but helps diagnose bsondump
sudo snap install jq

// launch the mongo CLI, running each command
mongo --eval "rs.initiate()"
mongo --eval "rs.status()"
mongo --eval "db.foo.insert({'foo':'bar'})"
mongo --eval "db.foo.createIndex({'bar':1})"

// Get the dump
mongodump --oplog

// check if it's going to fail
// if the output contains a createIndex, but doesn't contain an oid then it'll fail.
bsondump dump/oplog.bson | jq

// Drop the foo collection, so we don't get any duplication errors
mongo --eval "db.foo.drop()"

// Now restore the dump

mongorestore --oplogReplay dump/

// It should fail with
2019-03-22T17:26:28.034+0000 preparing collections to restore from
2019-03-22T17:26:28.035+0000 reading metadata for test.foo from dump/test/foo.metadata.json
2019-03-22T17:26:28.053+0000 restoring test.foo from dump/test/foo.bson
2019-03-22T17:26:28.056+0000 restoring indexes for collection test.foo from metadata
2019-03-22T17:26:28.062+0000 finished restoring test.foo (1 document)
2019-03-22T17:26:28.062+0000 replaying oplog
2019-03-22T17:26:28.064+0000 Failed: restore error: error applying oplog: applyOps: applyOps had one or more errors applying ops

After updating the packages, re-run the drop and try to import again, this time it should work:

# mongo --eval "db.foo.drop()"
MongoDB shell version v3.6.3
connecting to: mongodb://127.0.0.1:27017
MongoDB server version: 3.6.3
true
r
# mongorestore --oplogReplay dump/
2019-03-22T19:49:43.838+0000 preparing collections to restore from
2019-03-22T19:49:43.840+0000 reading metadata for test.foo from dump/test/foo.metadata.json
2019-03-22T19:49:43.856+0000 restoring test.foo from dump/test/foo.bson
2019-03-22T19:49:43.858+0000 restoring indexes for collection test.foo from metadata
2019-03-22T19:49:43.866+0000 finished restoring test.foo (1 document)
2019-03-22T19:49:43.866+0000 replaying oplog
2019-03-22T19:49:43.867+0000 done

[Other Info]

 0. https://paste.ubuntu.com/p/9r9pYc9g9D/
 1. https://github.com/mongodb/mongo/commit/0d0ba866052fd2b9ceaaa66c2b725a02822b102d
 2. https://jira.mongodb.org/browse/SERVER-36951
 3. https://bugs.launchpad.net/juju/+bug/1818831
 4. https://paste.ubuntu.com/p/HJsDf5yNkS/

Related branches

Changed in mongodb (Ubuntu):
assignee: nobody → Andreas Hasenack (ahasenack)
status: New → In Progress
importance: Undecided → Critical
Revision history for this message
Andreas Hasenack (ahasenack) wrote :

> https://github.com/mongodb/mongo/commit/0d0ba866052fd2b9ceaaa66c2b725a02822b102d

I was asked, is this commit OK regarding the upsream licensing change? Specifically: "Did they do a release following the commit before the license change?"

description: updated
description: updated
Revision history for this message
Christian Ehrhardt  (paelzer) wrote :

I checked the test instructions and mentioned there that timing is important as that was inhibiting me at first.

Furthermore I checked through releases and marked the tasks accordingly (fixed in Disco already, B/C affected).

description: updated
Changed in mongodb (Ubuntu):
status: In Progress → Fix Released
Changed in mongodb (Ubuntu Bionic):
status: New → In Progress
Changed in mongodb (Ubuntu Cosmic):
status: New → In Progress
Changed in mongodb (Ubuntu Bionic):
assignee: nobody → Andreas Hasenack (ahasenack)
Changed in mongodb (Ubuntu Cosmic):
assignee: nobody → Andreas Hasenack (ahasenack)
Changed in mongodb (Ubuntu):
assignee: Andreas Hasenack (ahasenack) → nobody
Changed in mongodb (Ubuntu Bionic):
importance: Undecided → Critical
Changed in mongodb (Ubuntu Cosmic):
importance: Undecided → Critical
Revision history for this message
Andreas Hasenack (ahasenack) wrote :

Uploaded to bionic and cosmic, awaiting SRU team review.

description: updated
Revision history for this message
Timo Aaltonen (tjaalton) wrote : Please test proposed package

Hello Simon, or anyone else affected,

Accepted mongodb into cosmic-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/mongodb/1:3.6.3-0ubuntu2.1 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation on how to enable and use -proposed. Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested and change the tag from verification-needed-cosmic to verification-done-cosmic. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed-cosmic. In either case, without details of your testing we will not be able to proceed.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance for helping!

N.B. The updated package will be released to -updates after the bug(s) fixed by this package have been verified and the package has been in -proposed for a minimum of 7 days.

Changed in mongodb (Ubuntu Cosmic):
status: In Progress → Fix Committed
tags: added: verification-needed verification-needed-cosmic
Changed in mongodb (Ubuntu Bionic):
status: In Progress → Fix Committed
tags: added: verification-needed-bionic
Revision history for this message
Timo Aaltonen (tjaalton) wrote :

Hello Simon, or anyone else affected,

Accepted mongodb into bionic-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/mongodb/1:3.6.3-0ubuntu1.1 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation on how to enable and use -proposed. Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested and change the tag from verification-needed-bionic to verification-done-bionic. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed-bionic. In either case, without details of your testing we will not be able to proceed.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance for helping!

N.B. The updated package will be released to -updates after the bug(s) fixed by this package have been verified and the package has been in -proposed for a minimum of 7 days.

Revision history for this message
Andreas Hasenack (ahasenack) wrote :

bionic verification

First, reproducing the problem:

Using bionic's package:
 *** 1:3.6.3-0ubuntu1 500
        500 http://br.archive.ubuntu.com/ubuntu bionic/universe amd64 Packages

Fails to load the dump as expected:
ubuntu@bionic:~$ mongorestore --oplogReplay dump/
2019-03-29T18:30:29.529+0000 preparing collections to restore from
2019-03-29T18:30:29.530+0000 reading metadata for test.foo from dump/test/foo.metadata.json
2019-03-29T18:30:29.543+0000 restoring test.foo from dump/test/foo.bson
2019-03-29T18:30:29.545+0000 restoring indexes for collection test.foo from metadata
2019-03-29T18:30:29.552+0000 finished restoring test.foo (1 document)
2019-03-29T18:30:29.552+0000 replaying oplog
2019-03-29T18:30:29.554+0000 Failed: restore error: error applying oplog: applyOps: applyOps had one or more errors applying ops

Updating:
  Version table:
 *** 1:3.6.3-0ubuntu1.1 500
        500 http://br.archive.ubuntu.com/ubuntu bionic-proposed/universe amd64 Packages

restore works just fine now:
ubuntu@bionic:~$ mongo --eval "db.foo.drop()"
MongoDB shell version v3.6.3
connecting to: mongodb://127.0.0.1:27017
MongoDB server version: 3.6.3
true
ubuntu@bionic:~$ mongorestore --oplogReplay dump/
2019-03-29T18:38:01.085+0000 preparing collections to restore from
2019-03-29T18:38:01.086+0000 reading metadata for test.foo from dump/test/foo.metadata.json
2019-03-29T18:38:01.108+0000 restoring test.foo from dump/test/foo.bson
2019-03-29T18:38:01.118+0000 restoring indexes for collection test.foo from metadata
2019-03-29T18:38:01.131+0000 finished restoring test.foo (1 document)
2019-03-29T18:38:01.131+0000 replaying oplog
2019-03-29T18:38:01.131+0000 done

bionic verification succeeded.

tags: added: verification-done-bionic
removed: verification-needed-bionic
Revision history for this message
Andreas Hasenack (ahasenack) wrote :

bionic DEP8 tests are green.

Revision history for this message
Andreas Hasenack (ahasenack) wrote :

Cosmic verification.

Reproducing the bug:
  Version table:
 *** 1:3.6.3-0ubuntu1 500
        500 http://br.archive.ubuntu.com/ubuntu cosmic/universe amd64 Packages

ubuntu@cosmic:~$ mongo --eval "db.foo.drop()"
MongoDB shell version v3.6.3
connecting to: mongodb://127.0.0.1:27017
MongoDB server version: 3.6.3
true

ubuntu@cosmic:~$ mongorestore --oplogReplay dump/
2019-03-29T18:43:56.477+0000 preparing collections to restore from
2019-03-29T18:43:56.478+0000 reading metadata for test.foo from dump/test/foo.metadata.json
2019-03-29T18:43:56.491+0000 restoring test.foo from dump/test/foo.bson
2019-03-29T18:43:56.493+0000 restoring indexes for collection test.foo from metadata
2019-03-29T18:43:56.501+0000 finished restoring test.foo (1 document)
2019-03-29T18:43:56.501+0000 replaying oplog
2019-03-29T18:43:56.502+0000 Failed: restore error: error applying oplog: applyOps: applyOps had one or more errors applying ops

Retrying, with the cosmic updated package:
  Version table:
 *** 1:3.6.3-0ubuntu2.1 500
        500 http://br.archive.ubuntu.com/ubuntu cosmic-proposed/universe amd64 Packages

Restore worked:
ubuntu@cosmic:~$ mongo --eval "db.foo.drop()"
MongoDB shell version v3.6.3
connecting to: mongodb://127.0.0.1:27017
MongoDB server version: 3.6.3
true
ubuntu@cosmic:~$ mongorestore --oplogReplay dump/
2019-03-29T18:45:56.022+0000 preparing collections to restore from
2019-03-29T18:45:56.023+0000 reading metadata for test.foo from dump/test/foo.metadata.json
2019-03-29T18:45:56.039+0000 restoring test.foo from dump/test/foo.bson
2019-03-29T18:45:56.042+0000 restoring indexes for collection test.foo from metadata
2019-03-29T18:45:56.051+0000 finished restoring test.foo (1 document)
2019-03-29T18:45:56.051+0000 replaying oplog
2019-03-29T18:45:56.053+0000 done

Cosmic verification succeeded.

tags: added: verification-done-cosmic
removed: verification-needed-cosmic
Revision history for this message
Andreas Hasenack (ahasenack) wrote :

dep8 tests for cosmic are green.

Revision history for this message
Andreas Hasenack (ahasenack) wrote :

Please only release this once the boost1.67 sru is also done (bug #1821803 and bug #1821762)

Revision history for this message
Andreas Hasenack (ahasenack) wrote :

The boost1.67 sru mentioned in the previous comment is done (released).

Revision history for this message
Launchpad Janitor (janitor) wrote :

This bug was fixed in the package mongodb - 1:3.6.3-0ubuntu2.1

---------------
mongodb (1:3.6.3-0ubuntu2.1) cosmic; urgency=medium

  * d/p/SERVER-36951-applyOps-createIndexes-without-uuid.patch: fix restoring
    of a database backup when applyOps has a createIndexes command without a
    UUID. (LP: #1821391)
  * Fix several FTBFS issues (LP: #1821361):
    - d/p/168c8d65556ab18b05e33b5f4006d1184c30f8f7.patch: copy patch from
      disco to disable new gcc 8.2 warnings
    - d/p/gcc8-parentheses.patch: Remove enclosing parentheses from the _F()
      macro to avoid a gcc8 -Wparentheses complaint
    - d/p/fix-boost-compile.patch: fix build with newer boost

 -- Andreas Hasenack <email address hidden> Thu, 28 Mar 2019 11:26:03 -0300

Changed in mongodb (Ubuntu Cosmic):
status: Fix Committed → Fix Released
Revision history for this message
Brian Murray (brian-murray) wrote : Update Released

The verification of the Stable Release Update for mongodb has completed successfully and the package has now been released to -updates. Subsequently, the Ubuntu Stable Release Updates Team is being unsubscribed and will not receive messages about this bug report. In the event that you encounter a regression using the package from -updates please report a new bug using ubuntu-bug and tag the bug report regression-update so we can easily find any regressions.

Revision history for this message
Launchpad Janitor (janitor) wrote :

This bug was fixed in the package mongodb - 1:3.6.3-0ubuntu1.1

---------------
mongodb (1:3.6.3-0ubuntu1.1) bionic; urgency=medium

  * d/p/SERVER-36951-applyOps-createIndexes-without-uuid.patch: fix restoring
    of a database backup when applyOps has a createIndexes command without a
    UUID. (LP: #1821391)

 -- Andreas Hasenack <email address hidden> Fri, 22 Mar 2019 16:11:02 -0300

Changed in mongodb (Ubuntu Bionic):
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers