Skip to content

PBM-1114

PBM-1114 #173

GitHub Actions / JUnit Test Report failed Sep 19, 2024 in 0s

32 tests run, 21 passed, 9 skipped, 2 failed.

Annotations

Check failure on line 56 in pbm-functional/pytest/test_PBM-1114.py

See this annotation in the file changed.

@github-actions github-actions / JUnit Test Report

test_PBM-1114.test_logical_PBM_T266

AssertionError: Starting backup '2024-09-19T06:57:06Z'....
  Waiting for '2024-09-19T06:57:06Z' backup.......................... done
  Backup '2024-09-19T06:57:06Z' to remote store 'http://nginx-minio:21114/bcp/pbme2etest'
  
assert 0 != 0
 +  where 0 = CommandResult(backend=<testinfra.backend.docker.DockerBackend object at 0x7fae6e7c9cd0>, exit_status=0, command=b'pbm ........... done\nBackup '2024-09-19T06:57:06Z' to remote store 'http://nginx-minio:21114/bcp/pbme2etest'\n", _stderr=b'').rc
Raw output
start_cluster = True, cluster = <cluster.Cluster object at 0x7fae6f873090>

    @pytest.mark.timeout(300, func_only=True)
    def test_logical_PBM_T266(start_cluster, cluster):
        cluster.check_pbm_status()
        pymongo.MongoClient(cluster.connection)["test"]["test"].insert_many(documents)
        result = cluster.exec_pbm_cli("backup --wait")
>       assert result.rc != 0, result.stdout + result.stderr
E       AssertionError: Starting backup '2024-09-19T06:57:06Z'....
E         Waiting for '2024-09-19T06:57:06Z' backup.......................... done
E         Backup '2024-09-19T06:57:06Z' to remote store 'http://nginx-minio:21114/bcp/pbme2etest'
E         
E       assert 0 != 0
E        +  where 0 = CommandResult(backend=<testinfra.backend.docker.DockerBackend object at 0x7fae6e7c9cd0>, exit_status=0, command=b'pbm ........... done\nBackup '2024-09-19T06:57:06Z' to remote store 'http://nginx-minio:21114/bcp/pbme2etest'\n", _stderr=b'').rc

test_PBM-1114.py:56: AssertionError

Check failure on line 86 in pbm-functional/pytest/test_PBM-1297.py

See this annotation in the file changed.

@github-actions github-actions / JUnit Test Report

test_PBM-1297.test_logical_pitr_PBM_T253

AssertionError: Starting restore 2024-09-19T07:17:04.22898465Z to point-in-time 2024-09-19T07:15:29 from '2024-09-19T07:14:06Z'...Started logical restore.
Waiting to finish....Error: operation failed with: reply oplog: replay chunk 1726730050.1726730127: apply oplog for chunk: applying a transaction entry: apply txn: {
 "Timestamp": {
  "T": 1726730098,
  "I": 1
 },
 "Term": 1,
 "Hash": null,
 "Version": 2,
 "Operation": "c",
 "Namespace": "admin.$cmd",
 "Object": [
  {
   "Key": "applyOps",
   "Value": [
    [
     {
      "Key": "op",
      "Value": "c"
     },
     {
      "Key": "ns",
      "Value": "config.$cmd"
     },
     {
      "Key": "ui",
      "Value": {
       "Subtype": 4,
       "Data": "8+c6Ptq3Qi2vIlaOhCpTxw=="
      }
     },
     {
      "Key": "o",
      "Value": [
       {
        "Key": "create",
        "Value": "databases"
       },
       {
        "Key": "idIndex",
        "Value": [
         {
          "Key": "v",
          "Value": 2
         },
         {
          "Key": "key",
          "Value": [
           {
            "Key": "_id",
            "Value": 1
           }
          ]
         },
         {
          "Key": "name",
          "Value": "_id_"
         }
        ]
       }
      ]
     }
    ],
    [
     {
      "Key": "op",
      "Value": "i"
     },
     {
      "Key": "ns",
      "Value": "config.databases"
     },
     {
      "Key": "ui",
      "Value": {
       "Subtype": 4,
       "Data": "8+c6Ptq3Qi2vIlaOhCpTxw=="
      }
     },
     {
      "Key": "o",
      "Value": [
       {
        "Key": "_id",
        "Value": "test"
       },
       {
        "Key": "primary",
        "Value": "rs1"
       },
       {
        "Key": "partitioned",
        "Value": false
       },
       {
        "Key": "version",
        "Value": [
         {
          "Key": "uuid",
          "Value": {
           "Subtype": 4,
           "Data": "LxPZ1siyR4O38qK3935D/Q=="
          }
         },
         {
          "Key": "timestamp",
          "Value": {
           "T": 1726730097,
           "I": 15
          }
         },
         {
          "Key": "lastMod",
          "Value": 1
         }
        ]
       }
      ]
     },
     {
      "Key": "o2",
      "Value": [
       {
        "Key": "_id",
        "Value": "test"
       }
      ]
     }
    ],
    [
     {
      "Key": "op",
      "Value": "i"
     },
     {
      "Key": "ns",
      "Value": "config.placementHistory"
     },
     {
      "Key": "ui",
      "Value": {
       "Subtype": 4,
       "Data": "tLfUxD8NRY+Af+grGB3Erg=="
      }
     },
     {
      "Key": "o",
      "Value": [
       {
        "Key": "_id",
        "Value": "66ebcf72cd5d23614db0abe6"
       },
       {
        "Key": "nss",
        "Value": "test"
       },
       {
        "Key": "timestamp",
        "Value": {
         "T": 1726730097,
         "I": 15
        }
       },
       {
        "Key": "shards",
        "Value": [
         "rs1"
        ]
       }
      ]
     },
     {
      "Key": "o2",
      "Value": [
       {
        "Key": "_id",
        "Value": "66ebcf72cd5d23614db0abe6"
       }
      ]
     }
    ]
   ]
  }
 ],
 "Query": null,
 "UI": null,
 "LSID": "ZgAAAAVpZAAQAAAABEmrjt+obEB/hQNOzRv5olMFdWlkACAAAAAAY5mrDaxi8gv8RmdTsQ+1j7fmkr7JUsabhNmXAheU0fgFdHhuVVVJRAAQAAAABB8KS2vzlUkZnWV23DlBVbsA",
 "TxnNumber": 0,
 "PrevOpTime": "HAAAABF0cwAAAAAAAAAAABJ0AP//////////AA==",
 "MultiOpType": null
}: applying transaction op: op: {"Timestamp":{"T":1726730098,"I":1},"Term":1,"Hash":null,"Version":0,"Operation":"i","Namespace":"config.databases","Object":[{"Key":"_id","Value":"test"},{"Key":"primary","Value":"rs1"},{"Key":"partitioned","Value":false},{"Key":"version","Value":[{"Key":"uuid","Value":{"Subtype":4,"Data":"LxPZ1siyR4O38qK3935D/Q=="}},{"Key":"timestamp","Value":{"T":1726730097,"I":15}},{"Key":"lastMod","Value":1}]}],"Query":[{"Key":"_id","Value":"test"}],"UI":{"Subtype":4,"Data":"8+c6Ptq3Qi2vIlaOhCpTxw=="},"LSID":null,"TxnNumber":null,"PrevOpTime":null,"MultiOpType":null} | merr <nil>: applyOps: (UnknownError) applyOps had one or more errors applying ops
Raw output
start_cluster = True, cluster = <cluster.Cluster object at 0x7fae6e43d050>
newcluster = <cluster.Cluster object at 0x7fae6e5821d0>

    @pytest.mark.timeout(600, func_only=True)
    def test_logical_pitr_PBM_T253(start_cluster,cluster,newcluster):
        cluster.check_pbm_status()
        cluster.make_backup("logical")
        cluster.enable_pitr(pitr_extra_args="--set pitr.oplogSpanMin=0.5")
        #Create the first database during oplog slicing
        client=pymongo.MongoClient(cluster.connection)
        client.admin.command("enableSharding", "test")
        client.admin.command("shardCollection", "test.test", key={"_id": "hashed"})
        for i in range(100):
            pymongo.MongoClient(cluster.connection)["test"]["test"].insert_one({"doc":i})
        time.sleep(30)
        pitr = datetime.utcnow().strftime("%Y-%m-%dT%H:%M:%S")
        backup="--time=" + pitr
        Cluster.log("Time for PITR is: " + pitr)
        time.sleep(30)
        cluster.disable_pitr()
        time.sleep(10)
        cluster.destroy()
    
        newcluster.create()
        newcluster.setup_pbm()
        time.sleep(10)
        newcluster.check_pbm_status()
>       newcluster.make_restore(backup,check_pbm_status=True)

test_PBM-1297.py:86: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <cluster.Cluster object at 0x7fae6e5821d0>
name = '--time=2024-09-19T07:15:29', kwargs = {'check_pbm_status': True}
client = MongoClient(host=['newmongos:27017'], document_class=dict, tz_aware=False, connect=True)
result = CommandResult(backend=<testinfra.backend.docker.DockerBackend object at 0x7fae6e469950>, exit_status=1, command=b'time...MultiOpType":null} | merr <nil>: applyOps: (UnknownError) applyOps had one or more errors applying ops\n', _stderr=b'')
n = <testinfra.host.Host docker://newrscfg01>, timeout = 240, error = ''
host = 'newrscfg01', container = <Container: 8f547b1188d9>

    def make_restore(self, name, **kwargs):
        if self.layout == "sharded":
            client = pymongo.MongoClient(self.connection)
            result = client.admin.command("balancerStop")
            client.close()
            Cluster.log("Stopping balancer: " + str(result))
            self.stop_mongos()
        self.stop_arbiters()
        n = testinfra.get_host("docker://" + self.pbm_cli)
        timeout = time.time() + 60
    
        while True:
            if not self.get_status()['running']:
                break
            if time.time() > timeout:
                assert False, "Cannot start restore, another operation running"
            time.sleep(1)
        Cluster.log("Restore started")
        timeout=kwargs.get('timeout', 240)
        result = n.run('timeout ' + str(timeout) + ' pbm restore ' + name + ' --wait')
    
        if result.rc == 0:
            Cluster.log(result.stdout)
        else:
            # try to catch possible failures if timeout exceeded
            error=''
            for host in self.mongod_hosts:
                try:
                    container = docker.from_env().containers.get(host)
                    get_logs = container.exec_run(
                        'cat /var/lib/mongo/pbm.restore.log', stderr=False)
                    if get_logs.exit_code == 0:
                        Cluster.log(
                            "!!!!Possible failure on {}, file pbm.restore.log was found:".format(host))
                        logs = get_logs.output.decode('utf-8')
                        Cluster.log(logs)
                        if '"s":"F"' in logs:
                            error = logs
                except docker.errors.APIError:
                    pass
            if error:
                assert False, result.stdout + result.stderr + "\n" + error
            else:
>               assert False, result.stdout + result.stderr
E               AssertionError: Starting restore 2024-09-19T07:17:04.22898465Z to point-in-time 2024-09-19T07:15:29 from '2024-09-19T07:14:06Z'...Started logical restore.
E               Waiting to finish....Error: operation failed with: reply oplog: replay chunk 1726730050.1726730127: apply oplog for chunk: applying a transaction entry: apply txn: {
E                "Timestamp": {
E                 "T": 1726730098,
E                 "I": 1
E                },
E                "Term": 1,
E                "Hash": null,
E                "Version": 2,
E                "Operation": "c",
E                "Namespace": "admin.$cmd",
E                "Object": [
E                 {
E                  "Key": "applyOps",
E                  "Value": [
E                   [
E                    {
E                     "Key": "op",
E                     "Value": "c"
E                    },
E                    {
E                     "Key": "ns",
E                     "Value": "config.$cmd"
E                    },
E                    {
E                     "Key": "ui",
E                     "Value": {
E                      "Subtype": 4,
E                      "Data": "8+c6Ptq3Qi2vIlaOhCpTxw=="
E                     }
E                    },
E                    {
E                     "Key": "o",
E                     "Value": [
E                      {
E                       "Key": "create",
E                       "Value": "databases"
E                      },
E                      {
E                       "Key": "idIndex",
E                       "Value": [
E                        {
E                         "Key": "v",
E                         "Value": 2
E                        },
E                        {
E                         "Key": "key",
E                         "Value": [
E                          {
E                           "Key": "_id",
E                           "Value": 1
E                          }
E                         ]
E                        },
E                        {
E                         "Key": "name",
E                         "Value": "_id_"
E                        }
E                       ]
E                      }
E                     ]
E                    }
E                   ],
E                   [
E                    {
E                     "Key": "op",
E                     "Value": "i"
E                    },
E                    {
E                     "Key": "ns",
E                     "Value": "config.databases"
E                    },
E                    {
E                     "Key": "ui",
E                     "Value": {
E                      "Subtype": 4,
E                      "Data": "8+c6Ptq3Qi2vIlaOhCpTxw=="
E                     }
E                    },
E                    {
E                     "Key": "o",
E                     "Value": [
E                      {
E                       "Key": "_id",
E                       "Value": "test"
E                      },
E                      {
E                       "Key": "primary",
E                       "Value": "rs1"
E                      },
E                      {
E                       "Key": "partitioned",
E                       "Value": false
E                      },
E                      {
E                       "Key": "version",
E                       "Value": [
E                        {
E                         "Key": "uuid",
E                         "Value": {
E                          "Subtype": 4,
E                          "Data": "LxPZ1siyR4O38qK3935D/Q=="
E                         }
E                        },
E                        {
E                         "Key": "timestamp",
E                         "Value": {
E                          "T": 1726730097,
E                          "I": 15
E                         }
E                        },
E                        {
E                         "Key": "lastMod",
E                         "Value": 1
E                        }
E                       ]
E                      }
E                     ]
E                    },
E                    {
E                     "Key": "o2",
E                     "Value": [
E                      {
E                       "Key": "_id",
E                       "Value": "test"
E                      }
E                     ]
E                    }
E                   ],
E                   [
E                    {
E                     "Key": "op",
E                     "Value": "i"
E                    },
E                    {
E                     "Key": "ns",
E                     "Value": "config.placementHistory"
E                    },
E                    {
E                     "Key": "ui",
E                     "Value": {
E                      "Subtype": 4,
E                      "Data": "tLfUxD8NRY+Af+grGB3Erg=="
E                     }
E                    },
E                    {
E                     "Key": "o",
E                     "Value": [
E                      {
E                       "Key": "_id",
E                       "Value": "66ebcf72cd5d23614db0abe6"
E                      },
E                      {
E                       "Key": "nss",
E                       "Value": "test"
E                      },
E                      {
E                       "Key": "timestamp",
E                       "Value": {
E                        "T": 1726730097,
E                        "I": 15
E                       }
E                      },
E                      {
E                       "Key": "shards",
E                       "Value": [
E                        "rs1"
E                       ]
E                      }
E                     ]
E                    },
E                    {
E                     "Key": "o2",
E                     "Value": [
E                      {
E                       "Key": "_id",
E                       "Value": "66ebcf72cd5d23614db0abe6"
E                      }
E                     ]
E                    }
E                   ]
E                  ]
E                 }
E                ],
E                "Query": null,
E                "UI": null,
E                "LSID": "ZgAAAAVpZAAQAAAABEmrjt+obEB/hQNOzRv5olMFdWlkACAAAAAAY5mrDaxi8gv8RmdTsQ+1j7fmkr7JUsabhNmXAheU0fgFdHhuVVVJRAAQAAAABB8KS2vzlUkZnWV23DlBVbsA",
E                "TxnNumber": 0,
E                "PrevOpTime": "HAAAABF0cwAAAAAAAAAAABJ0AP//////////AA==",
E                "MultiOpType": null
E               }: applying transaction op: op: {"Timestamp":{"T":1726730098,"I":1},"Term":1,"Hash":null,"Version":0,"Operation":"i","Namespace":"config.databases","Object":[{"Key":"_id","Value":"test"},{"Key":"primary","Value":"rs1"},{"Key":"partitioned","Value":false},{"Key":"version","Value":[{"Key":"uuid","Value":{"Subtype":4,"Data":"LxPZ1siyR4O38qK3935D/Q=="}},{"Key":"timestamp","Value":{"T":1726730097,"I":15}},{"Key":"lastMod","Value":1}]}],"Query":[{"Key":"_id","Value":"test"}],"UI":{"Subtype":4,"Data":"8+c6Ptq3Qi2vIlaOhCpTxw=="},"LSID":null,"TxnNumber":null,"PrevOpTime":null,"MultiOpType":null} | merr <nil>: applyOps: (UnknownError) applyOps had one or more errors applying ops

cluster.py:464: AssertionError