[PBM219] RESTORE FAILS WITH UNRECOGNIZED COMMAND IN OP IF

[PBM219] RESTORE FAILS WITH UNRECOGNIZED COMMAND IN OP IF






[#PBM-219] restore fails with "Unrecognized command in op" if new collections created in the oplog

[PBM-219] restore fails with "Unrecognized command in op" if new collections created in the oplog Created: 10/Apr/19  Updated: 20/Nov/19  Resolved: 20/May/19

Status:

Done

Project:

Percona Backup for MongoDB

Component/s:

None

Affects Version/s:

None

Fix Version/s:

0.5.0


Type:

Bug

Priority:

High

Reporter:

Tomislav Plavcic

Assignee:

Carlos Salguero

Resolution:

Fixed

Votes:

0

Labels:

None

Remaining Estimate:

0 minutes

Time Spent:

1 hour, 45 minutes

Original Estimate:

Not Specified



 Description 

 

I have tried this with 3.6 and 4.0 and it's the same.
This test is based on the build with git hash: 3e865e9308ed5b10d9a4aa425077c1f493194254

Steps to reproduce:
#1: run this in the mongodb client:

use test;
for(i=1; i <= 1000; i++) { db.series[i].insert( {_id: i })}

if "1000" is not enough on your system to start the next step while this is running then increase this.

#2: while that is running in another shell run pbm backup:

pbmctl run backup --description="backup1" --storage=local-filesystem

#3: when both actions complete go to mongodb client and drop "test" database:

rs1:PRIMARY> db.dropDatabase()
{
        "dropped" : "test",
        "ok" : 1,
        "operationTime" : Timestamp(1554923196, 1),
        "$clusterTime" : {
                "clusterTime" : Timestamp(1554923196, 1),
                "signature" : {
                        "hash" : BinData(0,"WYu80PvL4n4uD0s+pijYKCTCB5c="),
                        "keyId" : NumberLong("6678343643251605505")
                }
        }
}

rs1:PRIMARY> show dbs;
admin   0.000GB
config  0.000GB
local   0.000GB

#4: now do the restore and observe it will fail:

plavi@bender$ ./pbmctl run restore --storage=local-filesystem 2019-04-10T19:04:41Z.json
restoring
FATA[0027] Cannot send the RestoreBackup command to the gRPC server: rpc error: code = Unknown desc = 1 error occurred:
        * received error in RestoreCompleted from client [localhost:27018] cannot restore Oplog backup file 2019-04-10T19:04:41Z_rs1.oplog: error while running the oplog applier: cannot apply oplog operation: Unrecognized command in op: localhost:27018

pbm-agent stderr says this:

2019/04/10 21:07:50 error cannot apply oplog: Unrecognized command in op
map[h:-701623004300991224 ns:test.$cmd o:map[create:series.58 idIndex:map[key:map[_id:1] name:_id_ ns:test.series.58 v:2]] op:c t:1 ts:6678343784985526291 ui:{Kind:4 Data:[66 37 203 49 14 156 73 235 182 100 78 71 62 8 133 65]} v:2 wall:2019-04-10 19:04:42.48 +0000 UTC]

time="2019-04-10T21:07:50+02:00" level=error msg="[client localhost:27018] cannot process restore: [localhost:27018] cannot restore Oplog backup file 2019-04-10T19:04:41Z_rs1.oplog: error while running the oplog applier: cannot apply oplog operation: Unrecognized command in op"

mongod log has this:

2019-04-10T21:07:50.808+0200 I STORAGE  [conn26] createCollection: test.series.57 with provided UUID: 7a4f3dc1-2cb5-4943-a694-3efb078ec13e
2019-04-10T21:07:50.870+0200 I ACCESS   [conn26] FailedToParse: Unrecognized command in op



 Comments 

 

Comment by Carlos Salguero [ 29/Apr/19 ]

Adamo Tonete What could be the reason of this error? If we are tailing the oplog and then replaying it, why MongoDB says "unrecognized command in op"?

Comment by Akira Kurogane (Inactive) [ 10/Jul/19 ]

I'm not sure if this is the UUID problem, or an issue caused by the code not having a method to deal with this sort of oplog record.

For interest this is what I got when I ran db.dropDatabase() in a v4.0 instance. It dropped the test collection(s) inside (I didn't request that explicitly) with a "drop" command then ran "dropDatabase"

{
        "ts" : Timestamp(1562733460, 2),
        "t" : NumberLong(8),
        "h" : NumberLong("4276643388783434793"),
        "v" : 2,
        "op" : "c",
        "ns" : "fuzz.$cmd",
        "wall" : ISODate("2019-07-10T04:37:40.805Z"),
        "o" : {
                "dropDatabase" : 1
        }
}
{
        "ts" : Timestamp(1562733460, 1),
        "t" : NumberLong(8),
        "h" : NumberLong("-5056640765490911511"),
        "v" : 2,
        "op" : "c",
        "ns" : "fuzz.$cmd",
        "ui" : UUID("b47184f9-4191-4dbd-8aea-7a2fa3a17f7f"),
        "wall" : ISODate("2019-07-10T04:37:40.749Z"),
        "o" : {
                "drop" : "foo"
        }
}

Comment by Carlos Salguero [ 10/Jul/19 ]

This error is fixed.
The problem was that the oplogApply command in MongoDB only recognizes Insert, Update and Delete.
All other operations should be handled manually.

Generated at Mon Nov 08 11:57:17 UTC 2021 using Jira 8.13.13#813013-sha1:3ab5fbe7b6c572b1ee4ccec98a9f447334884e00.





Tags: command in, oplogapply command, fails, unrecognized, command, [pbm219], restore