Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

PBM-1265 STR #134

Merged
merged 5 commits into from
Mar 29, 2024
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
6 changes: 3 additions & 3 deletions .github/workflows/PBM-CUSTOM.yml
Original file line number Diff line number Diff line change
Expand Up @@ -18,15 +18,15 @@ on:

jobs:
test:
runs-on: ubuntu-20.04
runs-on: ubuntu-latest
timeout-minutes: 60
env:
PSMDB: ${{ github.event.inputs.psmdb || 'percona/percona-server-mongodb' }}
PBM_BRANCH: ${{ github.event.inputs.pbm_branch || 'main' }}
GO_VER: ${{ github.event.inputs.go_ver || 'bullseye' }}
TEST: ${{ github.event.inputs.test || '-k logical --verbose test_sharded.py' }}
steps:
- uses: actions/checkout@v2
- uses: actions/checkout@v4
- name: Setup environment
run: |
docker-compose build
Expand All @@ -37,7 +37,7 @@ jobs:
docker-compose run --rm test pytest -s --junitxml=junit.xml ${{ env.TEST }}
working-directory: ./pbm-functional/pytest
- name: Publish Test Report
uses: mikepenz/action-junit-report@v3
uses: mikepenz/action-junit-report@v4
if: success() || failure()
with:
report_paths: '**/junit.xml'
Expand Down
10 changes: 3 additions & 7 deletions .github/workflows/PBM-FULL.yml
Original file line number Diff line number Diff line change
Expand Up @@ -10,10 +10,6 @@ on:
description: "golang version"
required: false

# push:
# branches:
# - main

pull_request:
branches:
- main
Expand All @@ -22,7 +18,7 @@ on:

jobs:
test:
runs-on: ubuntu-20.04
runs-on: ubuntu-latest
timeout-minutes: 120
strategy:
fail-fast: false
Expand All @@ -33,7 +29,7 @@ jobs:
PBM_BRANCH: ${{ github.event.inputs.pbm_branch || 'main' }}
GO_VER: ${{ github.event.inputs.go_ver || 'bullseye' }}
steps:
- uses: actions/checkout@v2
- uses: actions/checkout@v4
- name: Setup environment with PSMDB ${{ matrix.psmdb }} and PBM branch ${{ env.PBM_BRANCH }}
run: |
PSMDB=percona/percona-server-mongodb:${{ matrix.psmdb }} docker-compose build
Expand All @@ -44,7 +40,7 @@ jobs:
docker-compose run --rm test pytest -s --junitxml=junit.xml -k ${{ matrix.test }}
working-directory: ./pbm-functional/pytest
- name: Publish Test Report
uses: mikepenz/action-junit-report@v3
uses: mikepenz/action-junit-report@v4
if: success() || failure()
with:
report_paths: '**/junit.xml'
Expand Down
16 changes: 4 additions & 12 deletions .github/workflows/PBM.yml
Original file line number Diff line number Diff line change
Expand Up @@ -13,28 +13,20 @@ on:
description: "golang version"
required: false

# push:
# branches:
# - main

# pull_request:
# branches:
# - main

jobs:
test:
runs-on: ubuntu-20.04
runs-on: ubuntu-latest
timeout-minutes: 60
strategy:
fail-fast: false
matrix:
test: [logical, physical, incremental]
env:
PSMDB: ${{ github.event.inputs.psmdb || 'percona/percona-server-mongodb:4.4' }}
PSMDB: ${{ github.event.inputs.psmdb || 'percona/percona-server-mongodb' }}
PBM_BRANCH: ${{ github.event.inputs.pbm_branch || 'main' }}
GO_VER: ${{ github.event.inputs.go_ver || 'latest' }}
steps:
- uses: actions/checkout@v2
- uses: actions/checkout@v4
- name: Setup environment with PSMDB ${{ env.PSMDB }} and PBM branch ${{ env.PBM_BRANCH }}
run: |
docker-compose build
Expand All @@ -45,7 +37,7 @@ jobs:
docker-compose run --rm test pytest -s --junitxml=junit.xml -k ${{ matrix.test }}
working-directory: ./pbm-functional/pytest
- name: Publish Test Report
uses: mikepenz/action-junit-report@v3
uses: mikepenz/action-junit-report@v4
if: success() || failure()
with:
report_paths: '**/junit.xml'
Expand Down
22 changes: 14 additions & 8 deletions pbm-functional/pytest/cluster.py
Original file line number Diff line number Diff line change
Expand Up @@ -431,8 +431,12 @@ def make_restore(self, name, **kwargs):
Cluster.log("Restore started")
timeout=kwargs.get('timeout', 240)
result = n.run('timeout ' + str(timeout) + ' pbm restore ' + name + ' --wait')
if result.rc == 124:

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)
Expand All @@ -441,14 +445,16 @@ def make_restore(self, name, **kwargs):
if get_logs.exit_code == 0:
Cluster.log(
"!!!!Possible failure on {}, file pbm.restore.log was found:".format(host))
Cluster.log(get_logs.output.decode('utf-8'))
logs = get_logs.output.decode('utf-8')
Cluster.log(logs)
if '"s":"F"' in logs:
error = logs
except docker.errors.APIError:
pass
assert False, "Timeout for restore exceeded"
elif result.rc == 0:
Cluster.log(result.stdout)
else:
assert False, result.stdout + result.stderr
if error:
assert False, result.stdout + result.stderr + "\n" + error
else:
assert False, result.stdout + result.stderr

restart_cluster=kwargs.get('restart_cluster', False)
if restart_cluster:
Expand Down Expand Up @@ -478,7 +484,7 @@ def destroy(self,**kwargs):
if cleanup:
result=self.exec_pbm_cli("delete-pitr --all --force --yes ")
Cluster.log(result.stdout + result.stderr)
result=self.exec_pbm_cli("delete-backup --older-than=9999-01-01 --force --yes")
result=self.exec_pbm_cli("delete-backup --older-than=0d --force --yes")
Cluster.log(result.stdout + result.stderr)
for host in self.all_hosts:
try:
Expand Down
91 changes: 91 additions & 0 deletions pbm-functional/pytest/test_PBM-1265.py
Original file line number Diff line number Diff line change
@@ -0,0 +1,91 @@
import pytest
import pymongo
import bson
import testinfra
import time
import os
import docker
import threading
import json

from datetime import datetime
from cluster import Cluster

@pytest.fixture(scope="package")
def docker_client():
return docker.from_env()

@pytest.fixture(scope="package")
def config():
return { "mongos": "mongos",
"configserver":
{"_id": "rscfg", "members": [{"host":"rscfg01"},{"host":"rscfg02"},{"host":"rscfg03"}]},
"shards":[
{"_id": "rs1", "members": [{"host":"rs101"},{"host":"rs102"},{"host":"rs103"}]},
{"_id": "rs2", "members": [{"host":"rs201"},{"host":"rs202"},{"host":"rs203"}]}
]}


@pytest.fixture(scope="package")
def cluster(config):
return Cluster(config, mongod_extra_args="--setParameter logicalSessionRefreshMillis=180000") # 3minutes

@pytest.fixture(scope="function")
def start_cluster(cluster,request):
try:
cluster.destroy()
os.chmod("/backups",0o777)
os.system("rm -rf /backups/*")
cluster.create()
cluster.setup_pbm()
result = cluster.exec_pbm_cli("config --set storage.type=filesystem --set storage.filesystem.path=/backups --set backup.compression=none --out json")
assert result.rc == 0
Cluster.log("Setup PBM with fs storage:\n" + result.stdout)
client=pymongo.MongoClient(cluster.connection)
client.admin.command("enableSharding", "test")
client.admin.command("shardCollection", "test.test", key={"_id": "hashed"})
yield True

finally:
if request.config.getoption("--verbose"):
cluster.get_logs()
cluster.destroy()
os.system("rm -rf /backups/*")

@pytest.mark.timeout(1200, func_only=True)
def test_physical_pitr_PBM_T251(start_cluster,cluster):
cluster.check_pbm_status()
for i in range(30):
pymongo.MongoClient(cluster.connection)["test"]["test"].insert_one({"a": i})
cluster.make_backup("logical")
cluster.enable_pitr(pitr_extra_args="--set pitr.oplogSpanMin=3")
backup=cluster.make_backup("physical")
for i in range(30):
pymongo.MongoClient(cluster.connection)["test"]["test"].insert_one({"b": i})
timeout = time.time() + 360
while True:
status = cluster.get_status()
for snapshot in status['backups']['snapshot']:
if snapshot['name'] == backup:
backup_epoch = snapshot['restoreTo']
if 'pitrChunks' in status['backups']:
if 'pitrChunks' in status['backups']['pitrChunks']:
pitr_epoch = status['backups']['pitrChunks']['pitrChunks'][-1]['range']['end']
if pitr_epoch > backup_epoch:
pitr = datetime.utcfromtimestamp(pitr_epoch).strftime("%Y-%m-%dT%H:%M:%S")
Cluster.log("Time for PITR is: " + pitr)
break
if time.time() > timeout:
assert False
time.sleep(1)
time.sleep(30)
backup="--time=" + pitr + " --base-snapshot=" + backup
cluster.disable_pitr()
cluster.make_restore(backup,restart_cluster=True,check_pbm_status=True)
assert pymongo.MongoClient(cluster.connection)["test"]["test"].count_documents({}) == 60


backup=cluster.make_backup("physical")
cluster.make_restore(backup,restart_cluster=True,check_pbm_status=True)

Check failure on line 89 in pbm-functional/pytest/test_PBM-1265.py

View workflow job for this annotation

GitHub Actions / JUnit Test Report

test_PBM-1265.test_physical_pitr_PBM_T251

AssertionError: Starting restore 2024-03-29T09:37:06.667867381Z from '2024-03-29T09:36:44Z'..........................Started physical restore. Waiting to finish..................................................................................................................................................................................................................... {"t":{"$date":"2024-03-29T09:37:51.981+00:00"},"s":"I", "c":"CONTROL", "id":23285, "ctx":"-","msg":"Automatically disabling TLS 1.0, to force-enable TLS 1.0 specify --sslDisabledProtocols 'none'"} {"t":{"$date":"2024-03-29T09:37:51.983+00:00"},"s":"I", "c":"NETWORK", "id":4915701, "ctx":"-","msg":"Initialized wire specification","attr":{"spec":{"incomingExternalClient":{"minWireVersion":0,"maxWireVersion":13},"incomingInternalClient":{"minWireVersion":0,"maxWireVersion":13},"outgoing":{"minWireVersion":0,"maxWireVersion":13},"isInternalClient":true}}} {"t":{"$date":"2024-03-29T09:37:51.983+00:00"},"s":"W", "c":"ASIO", "id":22601, "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"} {"t":{"$date":"2024-03-29T09:37:51.983+00:00"},"s":"I", "c":"NETWORK", "id":4648601, "ctx":"main","msg":"Implicit TCP FastOpen unavailable. If TCP FastOpen is required, set tcpFastOpenServer, tcpFastOpenClient, and tcpFastOpenQueueSize."} {"t":{"$date":"2024-03-29T09:37:51.984+00:00"},"s":"W", "c":"ASIO", "id":22601, "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"} {"t":{"$date":"2024-03-29T09:37:51.984+00:00"},"s":"I", "c":"REPL", "id":5123008, "ctx":"main","msg":"Successfully registered PrimaryOnlyService","attr":{"service":"TenantMigrationDonorService","ns":"config.tenantMigrationDonors"}} {"t":{"$date":"2024-03-29T09:37:51.984+00:00"},"s":"I", "c":"REPL", "id":5123008, "ctx":"main","msg":"Successfully registered PrimaryOnlyService","attr":{"service":"TenantMigrationRecipientService","ns":"config.tenantMigrationRecipients"}} {"t":{"$date":"2024-03-29T09:37:51.984+00:00"},"s":"I", "c":"CONTROL", "id":5945603, "ctx":"main","msg":"Multi threading initialized"} {"t":{"$date":"2024-03-29T09:37:51.985+00:00"},"s":"I", "c":"CONTROL", "id":4615611, "ctx":"initandlisten","msg":"MongoDB starting","attr":{"pid":293,"port":28034,"dbPath":"/var/lib/mongo","architecture":"64-bit","host":"rs103"}} {"t":{"$date":"2024-03-29T09:37:51.985+00:00"},"s":"I", "c":"CONTROL", "id":23403, "ctx":"initandlisten","msg":"Build Info","attr":{"buildInfo":{"version":"5.0.24-21","gitVersion":"751fc35891514cf219872e1134196614b972d9d3","openSSLVersion":"OpenSSL 1.1.1k FIPS 25 Mar 2021","modules":[],"allocator":"tcmalloc","environment":{"distarch":"x86_64","target_arch":"x86_64"}}}} {"t":{"$date":"2024-03-29T09:37:51.985+00:00"},"s":"I", "c":"CONTROL", "id":51765, "ctx":"initandlisten","msg":"Operating System","attr":{"os":{"name":"Oracle Linux Server release 8.9","version":"Kernel 6.5.0-1016-azure"}}} {"t":{"$date":"2024-03-29T09:37:51.985+00:00"},"s":"I", "c":"CONTROL", "id":21951, "ctx":"initandlisten","msg":"Options set by command line","attr":{"options":{"config":"/tmp/pbmMongdTmpConf1974481778","net":{"bindIp":"localhost","port":28034},"setParameter":{"recoverFromOplogAsStandalone":"true","takeUnstableCheckpointOnShutdown":"true"},"storage":{"dbPath":"/var/lib/mongo","directoryPerDB":false,"wiredTiger":{"collectionConfig":{"blockCompressor":"snappy"},"engineConfig":{"directoryForIndexes":false,"journalCompressor":"snappy"},"indexConfig":{"prefixCompression":true}}},"systemLog":{"destination":"file","path":"/var/lib/mongo/pbm.restore.log"}}}} {"t":{"$date":"2024-03-29T09:37:51.985+00:00"},"s":"I", "c":"STORAGE", "id":22270, "ctx":"initandlisten","msg":"Storage engine to use detected by data files","attr":{"dbpath":"/var/lib/mongo","storageEngine":"wiredTiger"}} {"t":{"$date":"2024-03-29T09:37:51.985+00:00"},"s":"I", "c":"STORAGE", "id":22315, "ctx":"initandlisten","msg":"Opening WiredTiger","attr":{"config":"create,cache_size=7478M,session_max=33000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),builtin_extension_config=(zstd=(compression_level=6)),file_manager=(close_idle_time=600,close_scan_interval=10,close_handle_minimum=250),statistics_log=(wait=0),verbose=[recovery_progress,checkpoint_progress,compact_progress],"}} {"t":{"$date":"2024-03-29T09:37:52.125+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1711705072:125586][293:0x7f65f37d6c00], txn-recover: [WT_VERB_RECOVERY_PROGRESS] Recovering log 8 through 9"}} {"t":{"$date":"2024-03-29T09:37:52.154+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1711705072:154066][293:0x7f65f37d6c00], txn-recover: [WT_VERB_RECOVERY_PROGRESS] Recovering log 9 through 9"}} {"t":{"$date":"2024-03-29T09:37:52.209+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1711705072:209493][293:0x7f65f37d6c00], txn-recover: [WT_VERB_RECOVERY_ALL] Main recovery loop: starting at 8/65664 to 9/256"}} {"t":{"$date":"2024-03-29T09:37:52.256+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1711705072:256872][293:0x7f65f37d6c00], txn-recover: [WT_VERB_RECOVERY_PROGRESS] Recovering log 8 through 9"}} {"t":{"$date":"2024-03-29T09:37:52.292+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1711705072:292608][293:0x7f65f37d6c00], txn-recover: [WT_VERB_RECOVERY_PROGRESS] Recovering log 9 through 9"}} {"t":{"$date":"2024-03-29T09:37:52.314+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1711705072:314803][293:0x7f65f37d6c00], txn-recover: [WT_VERB_RECOVERY_ALL] Set global recovery timestamp: (1711704840, 33)"}} {"t":{"$date":"2024-03-29T09:37:52.314+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1711705072:314850][293:0x7f65f37d6c00], txn-recover: [WT_VERB_RECOVERY_ALL] Set global oldest timestamp: (1711704540, 33)"}} {"t":{"$date":"2024-03-29T09:37:52.317+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1711705072:317636][293:0x7f65f37d6c00], WT_SESSION.checkpoint: [WT_VERB_CHECKPOINT_PROGRESS] saving checkpoint snapshot min: 1, snapshot max: 1 snapshot count: 0, oldest timestamp: (1711704540, 33) , meta checkpoint timestamp: (1711704840, 33) base write gen: 65"}} {"t":{"$date":"2024-03-29T09:37:52.320+00:00"},"s":"I", "c":"STORAGE", "id":4795906, "ctx":"initandlisten","msg":"WiredTiger opened","attr":{"durationMillis":334}} {"t":{"$date":"2024-03-29T09:37:52.320+00:00"},"s":"I", "c":"RECOVERY", "id":23987, "ctx":"initandlisten","msg":"WiredTiger recoveryTimestamp","attr":{"recoveryTimestamp":{"$timestamp":{"t":1711704840,"i":33}}}} {"t":{"$date":"2024-03-29T09:37:52.320+00:00"},"s":"I", "c":"RECOVERY", "id":5380106, "ctx":"initandlisten","msg":"WiredTiger oldestTimestamp","attr":{"oldestTimestamp":{"$timestamp":{"t":1711704540,"i":33}}}} {"t":{"$date":"2024-03-29T09:37:52.340+00:00"},"s":"I", "c":"STORAGE", "id":22262, "ctx":"initandlisten","msg":"Timestamp monitor starting"} {"t":{"$date":"2024-03-29T09:37:52.341+00:00"},"s":"W", "c":"CONTROL", "id":22120, "ctx":"initandlisten","msg":"Access control is not enabled for the database. Read and write access to data and configuration is unrestricted. You can use percona-server-mongodb-enable-auth.sh to fix it","tags":["startupWarnings"]} {"t":{"$date":"2024-03-29T09:37:52.341+00:00"},"s":"W", "c":"CONTROL", "id":22178, "ctx":"initandlisten","msg":"/sys/kernel/mm/transparent_hugepage/enabled is 'always'. We suggest setting it to 'never'","tags":["startupWarnings"]} {"t":{"$date":"2024-03-29T09:37:52.348+00:00"},"s":"I", "c":"NETWORK", "id":4915702, "ctx":"initandlisten","msg":"Updated wire specification","attr":{"oldSpec":{"incomingExternalClient":{"minWireVersion":0,"maxWireVersion":13},"incomingInternalClient":{"minWireVersion":0,"maxWireVersion":13},"outgoing":{"minWireVersion":0,"maxWireVersion":13},"isInternalClient":true},"newSpec":{"incomingExternalClient":{"minWireVersion":0,"maxWireVersion":13},"incomingInternalClient":{"minWireVersion":13,"maxWireVersion":13},"outgoing":{"minWireVersion":13,"maxWireVersion":13},"isInternalClient":true}}} {"t":{"$date":"2024-03-29T09:37:52.349+00:00"},"s":"I", "c":"STORAGE", "id":5071100, "ctx":"initandlisten","msg":"Clearing temp directory"} {"t":{"$date":"2024-03-29T09:37:52.366+00:00"},"s":"I", "c":"CONTROL", "id":20536, "ctx":"initandlisten","msg":"Flow Control is enabled on this deployment"} {"t":{"$date":"2024-03-29T09:37:52.366+00:00"},"s":"I", "c":"STORAGE", "id":5380103, "ctx":"initandlisten","msg":"Unpin oldest timestamp request","attr":{"service":"_wt_startup","requestedTs":{"$timestamp":{"t":1711704540,"i":33}}}} {"t":{"$date":"2024-03-29T09:37:52.367+00:00"},"s":"W", "c":"SHARDING", "id":22075, "ctx":"initandlisten","msg":"Not started with --shardsvr, but a shardIdentity document was found on disk","attr":{"namespace":"admin.system.version","shardIdentityDocument":{"_id":"shardIdentity","shardName":"rs1","clusterId":{"$oid":"660689a017271609d88f9015"},"configsvrConnectionString":"rscfg/rscfg01:27017,rscfg02:27017,rscfg03:27017"}}} {"t":{"$date":"2024-03-29T09:37:52.367+00:00"},"s":"I", "c":"FTDC", "id":20625, "ctx":"initandlisten","msg":"Initializing full-time diagnostic data capture","attr":{"dataDirectory":"/var/lib/mongo/diagnostic.data"}} {"t":{"$date":"2024-03-29T09:37:52.370+00:00"},"s":"I", "c":"REPL", "id":21557, "ctx":"initandlisten","msg":"Removing unapplied oplog entries after oplogTruncateAfterPoint","attr":{"oplogTruncateAfterPoint":{"":{"$timestamp":{"t":1711705007,"i":3}}}}} {"t":{"$date":"2024-03-29T09:37:52.370+00:00"},"s":"I", "c":"REPL", "id":21553, "ctx":"initandlisten","msg":"Truncating oplog from truncateAfterOplogEntryTimestamp (non-inclusive)","attr":{"truncateAfterOplogEntryTimestamp":{"$timestamp":{"t":1711705005,"i":58}},"oplogTruncateAfterPoint":{"$timestamp":{"t":1711705007,"i":3}}}} {"t":{"$date":"2024-03-29T09:37:52.370+00:00"},"s":"I", "c":"REPL", "id":21554, "ctx":"initandlisten","msg":"Replication recovery oplog truncation finished","attr":{"durationMillis":0}} {"t":{"$date":"2024-03-29T09:37:52.371+00:00"},"s":"I", "c":"REPL", "id":21544, "ctx":"initandlisten","msg":"Recovering from stable timestamp","attr":{"stableTimestamp":{"$timestamp":{"t":1711704840,"i":33}},"topOfOplog":{"ts":{"$timestamp":{"t":1711705005,"i":58}},"t":4},"appliedThrough":{"ts":{"$timestamp":{"t":0,"i":0}},"t":-1}}} {"t":{"$date":"2024-03-29T09:37:52.371+00:00"},"s":"I", "c":"REPL", "id":21545, "ctx":"initandlisten","msg":"Starting recovery oplog application at the stable timestamp","attr":{"stableTimestamp":{"$timestamp":{"t":1711704840,"i":33}}}} {"t":{"$date":"2024-03-29T09:37:52.372+00:00"},"s":"I", "c":"REPL", "id":5466604, "ctx":"initandlisten","msg":"Start point for recovery oplog application exists in oplog. No adjustment necessary","attr":{"startPoint":{"$timestamp":{"t":1711704840,"i":33}}}} {"t":{"$date":"2024-03-29T09:37:52.372+00:00"},"s":"I", "c":"REPL", "id":21550, "ctx":"initandlisten","msg":"Replaying stored operations from startPoint (exclusive) to endPoint (inclusive)","attr":{"startPoint":{"$timestamp":{"t":1711704840,"i":33}},"endPoint":{"$timestamp":{"t":1711705005,"i":58}}}} {"t":{"$date":"2024-03-29T09:37:52.374+00:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"ReplWriterWorker-1","msg":"createCollection","attr":{"namespace":"config.cache.chunks.config.system.sessions","uuidDisposition":"provided","uuid":{"uuid":{"$uuid":"4129f180-3ebe-433d-9cc2-eb9e08c8050d"}},"options":{"uuid":{"$uuid":"4129f180-3ebe-433d-9cc2-eb9e08c8050d"}}}} {"t":{"$date":"2024-03-29T09:37:52.380+00:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"ReplWriterWorker-1","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.cache.chunks.config.system.sessions","index":"_id_","commitTimestamp":{"$timestamp":{"t":1711704956,"i":1030}}}} {"t":{"$date":"2024-03-29T09:37:52.387+00:00"},"s":"I", "c":"INDEX", "id":20384, "ctx":"ReplWriterWorker-1","msg":"Index build: starting","attr":{"buildUUID":null,"collectionUUID":{"uuid":{"$uuid":"4129f180-3ebe-433d-9cc2-eb9e08c8050d"}},"namespace":"config.cache.chunks.config.system.sessions","properties":{"v":2,"key":{"lastmod":1},"name":"lastmod_1"},"method":"Hybrid","maxTemporaryMemoryUsageMB":200}} {"t":{"$date":"2024-03-29T09:37:52.387+00:00"},"s":"I", "c":"INDEX", "id":20391, "ctx":"ReplWriterWorker-1","msg":"Index build: collection scan done","attr":{"buildUUID":null,"collectionUUID":{"uuid":{"$uuid":"4129f180-3ebe-433d-9cc2-eb9e08c8050d"}},"namespace":"config.cache.chunks.config.system.sessions","totalRecords":0,"readSource":"kNoTimestamp","durationMillis":0}} {"t":{"$date":"2024-03-29T09:37:52.388+00:00"},"s":"I", "c":"INDEX", "id":20685, "ctx":"ReplWriterWorker-1","msg":"Index build: inserted keys from external sorter into index","attr":{"namespace":"config.cache.chunks.config.system.sessions","index":"lastmod_1","keysInserted":0,"durationMillis":0}} {"t":{"$date":"2024-03-29T09:37:52.388+00:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"ReplWriterWorker-1","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.cache.chunks.config.system.sessions","index":"lastmod_1","commitTimestamp":{"$timestamp":{"t":1711704956,"i":1032}}}} {"t":{"$date":"2024-03-29T09:37:52.391+00:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"ReplWriterWorker-7","msg":"createCollection","attr":{"namespace":"config.system.sessions","uuidDisposition":"provided","uuid":{"uuid":{"$uuid":"c42bf6bd-c00e-42a6-9366-3ecf72ad0d7e"}},"options":{"uuid":{"$uuid":"c42bf6bd-c00e-42a6-9366-3ecf72ad0d7e"}}}} {"t":{"$date":"2024-03-29T09:37:52.396+00:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"ReplWriterWorker-7","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.system.sessions","index":"_id_","commitTimestamp":{"$timestamp":{"t":1711704956,"i":1097}}}} {"t":{"$date":"2024-03-29T09:37:52.399+00:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"ReplWriterWorker-3","msg":"createCollection","attr":{"namespace":"config.migrationCoordinators","uuidDisposition":"provided","uuid":{"uuid":{"$uuid":"14cd4c11-d4fb-4731-a735-a2e06f234791"}},"options":{"uuid":{"$uuid":"14cd4c11-d4fb-4731-a735-a2e06f234791"}}}} {"t":{"$date":"2024-03-29T09:37:52.403+00:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"ReplWriterWorker-3","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.migrationCoordinators","index":"_id_","commitTimestamp":{"$timestamp":{"t":1711704957,"i":63}}}} {"t":{"$date":"2024-03-29T09:37:52.404+00:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"ReplWriterWorker-6","msg":"createCollection","attr":{"namespace":"config.rangeDeletions","uuidDisposition":"provided","uuid":{"uuid":{"$uuid":"1b380725-3145-40d4-ac52-09ceaea23126"}},"options":{"uuid":{"$uuid":"1b380725-3145-40d4-ac52-09ceaea23126"}}}} {"t":{"$date":"2024-03-29T09:37:52.409+00:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"ReplWriterWorker-6","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.rangeDeletions","index":"_id_","commitTimestamp":{"$timestamp":{"t":1711704957,"i":132}}}} {"t":{"$date":"2024-03-29T09:37:52.415+00:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"ReplWriterWorker-6","msg":"createCollection","attr":{"namespace":"config.vectorClock","uuidDisposition":"provided","uuid":{"uuid":{"$uuid":"5c7fb5a4-3901-4961-b403-add1ca7f9da4"}},"options":{"uuid":{"$uuid":"5c7fb5a4-3901-4961-b403-add1ca7f9da4"}}}} {"t":{"$date":"2024-03-29T09:37:52.420+00:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"ReplWriterWorker-6","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.vectorClock","index":"_id_","commitTimestamp":{"$timestamp":{"t":1711704957,"i":1201}}}} {"t":{"$date":"2024-03-29T09:37:52.498+00:00"},"s":"I", "c":"REPL", "id":21536, "ctx":"initandlisten","msg":"Completed oplog application for recovery","attr":{"numOpsApplied":1866,"numBatches":192,"applyThroughOpTime":{"ts":{"$timestamp":{"t":1711705005,"i":58}},"t":4}}} {"t":{"$date":"2024-03-29T09:37:52.499+00:00"},"s":"W", "c":"REPL", "id":21558, "ctx":"initandlisten","msg":"Setting mongod to readOnly mode as a result of specifying 'recoverFromOplogAsStandalone'"} {"t":{"$date":"2024-03-29T09:37:52.499+00:00"},"s":"I", "c":"REPL", "id":6015317, "ctx":"initandlisten","msg":"Setting new configuration state","attr":{"newState":"ConfigReplicationDisabled","oldState":"ConfigPreStart"}} {"t":{"$date":"2024-03-29T09:37:52.500+00:00"},"s":"I", "c":"INDEX", "id":20438, "ctx":"LogicalSessionCacheRefresh","msg":"Index build: registering","attr":{"buildUUID":{"uuid":{"$uuid":"089c6dc7-fe3a-4ada-9ab6-3331012422ee"}},"namespace":"config.system.sessions","collectionUUID":{"uuid":{"$uuid":"c42bf6bd-c00e-42a6-9366-3ecf72ad0d7e"}},"indexes":1,"firstIndex":{"name":"lsidTTLIndex"}}} {"t":{"$date":"2024-03-29T09:37:52.500+00:00"},"s":"I", "c":"CONTROL", "id":20712, "ctx":"LogicalSessionCacheReap","msg":"Sessions collection is not set up; waiting until next sessions reap interval","attr":{"error":"IndexNotFound: config.system.sessions does not have the required TTL index"}} {"t":{"$date":"2024-03-29T09:37:52.500+00:00"},"s":"I", "c":"NETWORK", "id":23015, "ctx":"listener","msg":"Listening on","attr":{"address":"/tmp/mongodb-28034.sock"}} {"t":{"$date":"2024-03-29T09:37:52.500+00:00"},"s":"I", "c":"NETWORK", "id":23015, "ctx":"listener","msg":"Listening on","attr":{"address":"127.0.0.1"}} {"t":{"$date":"2024-03-29T09:37:52.500+00:00"},"s":"I", "c":"NETWORK", "id":23016, "ctx":"listener","msg":"Waiting for connections","attr":{"port":28034,"ssl":"off"}} {"t":{"$date":"2024-03-29T09:37:52.500+00:00"},"s":"E", "c":"INDEX", "id":20393, "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Caught exception while cleaning up partially built indexes","attr":{"error":"IllegalOperation: Cannot execute a write operation in read-only mode"}} {"t":{"$date":"2024-03-29T09:37:52.500+00:00"},"s":"F", "c":"-", "id":23089, "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Fatal assertion","attr":{"msgid":18644,"file":"src/mongo/db/catalog/multi_index_block.cpp","line":152}} {"t":{"$date":"2024-03-29T09:37:52.500+00:00"},"s":"F", "c":"-", "id":23090, "ctx":"IndexBuildsCoordinatorMongod-0","msg":"\n\n***aborting after fassert() failure\n\n"} {"t":{"$date":"2024-03-29T09:37:52.500+00:00"},"s":"F", "c":"CONTROL", "id":6384300, "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Writing fatal message","attr":{"message":"Got signal: 6 (Aborted).\n"}} {"t":{"$date":"2024-03-29T09:37:52.551+00:00"},"s":"I", "c":"CONTROL", "id":31380, "ctx":"IndexBuildsCoordinatorMongod-0","msg":"BACKTRACE","attr":{"bt":{"backtrace":[{"a":"555BFBB466E3","b":"555BF7981000","o":"41C56E3","s":"_ZN5mongo34StackTraceAddressMetadataGenerator4loadEPv","s+":"FC3"},{"a":"555BFBB49127","b":"555BF7981000","o":"41C8127","s":"_ZN5mongo15printStackTraceEv","s+":"37"},{"a":"555BFBB412D6","b":"555BF7981000","o":"41C02D6","s":"abruptQuit","s+":"66"},{"a":"7F65F0F55D40","b":"7F65F0F43000","o":"12D40","s":"funlockfile","s+":"50"},{"a":"7F65F0BCCB8F","b":"7F65F0B7E000","o":"4EB8F","s":"gsignal","s+":"10F"},{"a":"7F65F0B9FEA5","b":"7F65F0B7E000","o":"21EA5","s":"abort","s+":"127"},{"a":"555BF8EE6D2B","b":"555BF7981000","o":"1565D2B","s":"_ZN5mongo25fassertFailedWithLocationEiPKcj","s+":"F6"},{"a":"555BF8C9573F","b":"555BF7981000","o":"131473F","s":"_ZN5mongo21AuthzVersionParameter13setFromStringERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEE","s+":"55EF"},{"a":"555BFA154AAF","b":"555BF7981000","o":"27D3AAF","s":"_ZN5mongo18IndexBuildsManager15abortIndexBuildEPNS_16OperationContextERNS_16CollectionWriterERKNS_4UUIDESt8functionIFvvEE","s+":"FF"},{"a":"555BF8C037D8","b":"555BF7981000","o":"12827D8","s":"_ZZNK5mongo11BSONElement6NumberEvENKUlvE_clEv","s+":"7C08"},{"a":"555BFA0C5947","b":"555BF7981000","o":"2744947","s":"_ZN5mongo22IndexBuildsCoordinator16_setUpIndexBuildEPNS_16OperationContextERKNS_4UUIDENS_9TimestampERKNS0_17IndexBuildOptionsE","s+":"D7"},{"a":"555BF9DD4B78","b":"555BF7981000","o":"2453B78","s":"_ZN5mongo28IndexBuildsCoordinatorMongod33_checkVoteCommitIndexCmdSucceededERKNS_7BSONObjERKNS_4UUIDE","s+":"CB8"},{"a":"555BFB8FFBB5","b":"555BF7981000","o":"3F7EBB5","s":"_ZN5mongo10ThreadPool4Impl10_doOneTaskEPSt11unique_lockINS_12latch_detail5LatchEE","s+":"135"},{"a":"555BFB90140B","b":"555BF7981000","o":"3F8040B","s":"_ZN5mongo10ThreadPool4Impl13_consumeTasksEv","s+":"8B"},{"a":"555BFB90292C","b":"555BF7981000","o":"3F8192C","s":"_ZN5mongo10ThreadPool4Impl17_workerThreadBodyERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEE","s+":"26C"},{"a":"555BFB902ED0","b":"555BF7981000","o":"3F81ED0","s":"_ZN5mongo10ThreadPool4Impl17_workerThreadBodyERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEE","s+":"810"},{"a":"7F65F17C0B23","b":"7F65F16FE000","o":"C2B23","s":"_ZNKSt10error_code23default_error_conditionEv","s+":"33"},{"a":"7F65F0F4B1DA","b":"7F65F0F43000","o":"81DA","s":"start_thread","s+":"EA"},{"a":"7F65F0BB7E73","b":"7F65F0B7E000","o":"39E73","s":"clone","s+":"43"}],"processInfo":{"mongodbVersion":"5.0.24-21","gitVersion":"751fc35891514cf219872e1134196614b972d9d3","compiledModules":[],"uname":{"sysname":"Linux","release":"6.5.0-1016-azure","version":"#16~22.04.1-Ubuntu SMP Fri Feb 16 15:42:02 UTC 2024","machine":"x86_64"},"somap":[{"b":"555BF7981000","elfType":3,"buildId":"DA4870CDDA3114158E5C3DAB653D63D4F6C9E499"},{"b":"7F65F16FE000","path":"/lib64/libstdc++.so.6","elfType":3,"buildId":"5CA844DFEE0FE8E20B2A0F7CF8EF4291838E8806"},{"b":"7F65F0F43000","path":"/lib64/libpthread.so.0","elfType":3,"buildId":"D1ADEF9579CE9780C97DB1A37BD08552A91F4564"},{"b":"7F65F0B7E000","path":"/lib64/libc.so.6","elfType":3,"buildId":"BA5A6A6FF582CD9C692D725BAD086CBB48AC723D"}]}}}} {"t":{"$date":"2024-03-29T09:37:52.551+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"555BFBB466E3","b":"555BF7981000","o":"41C56E3","s":"_ZN5mongo34StackTraceAddressMetadataGenerator4loadEPv","s+":"FC3"}}} {"t":{"$date":"2024-03-29T09:37:52.551+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"555BFBB49127","b":"555BF7981000","o":"41C8127","s":"_ZN5mongo15printStackTraceEv","s+":"37"}}} {"t":{"$date":"2024-03-29T09:37:52.551+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"555BFBB412D6","b":"555BF7981000","o":"41C02D6","s":"abruptQuit","s+":"66"}}} {"t":{"$date":"2024-03-29T09:37:52.551+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"7F65F0F55D40","b":"7F65F0F43000","o":"12D40","s":"funlockfile","s+":"50"}}} {"t":{"$date":"2024-03-29T09:37:52.551+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"7F65F0BCCB8F","b":"7F65F0B7E000","o":"4EB8F","s":"gsignal","s+":"10F"}}} {"t":{"$date":"2024-03-29T09:37:52.551+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"7F65F0B9FEA5","b":"7F65F0B7E000","o":"21EA5","s":"abort","s+":"127"}}} {"t":{"$date":"2024-03-29T09:37:52.551+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"555BF8EE6D2B","b":"555BF7981000","o":"1565D2B","s":"_ZN5mongo25fassertFailedWithLocationEiPKcj","s+":"F6"}}} {"t":{"$date":"2024-03-29T09:37:52.551+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"555BF8C9573F","b":"555BF7981000","o":"131473F","s":"_ZN5mongo21AuthzVersionParameter13setFromStringERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEE","s+":"55EF"}}} {"t":{"$date":"2024-03-29T09:37:52.551+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"555BFA154AAF","b":"555BF7981000","o":"27D3AAF","s":"_ZN5mongo18IndexBuildsManager15abortIndexBuildEPNS_16OperationContextERNS_16CollectionWriterERKNS_4UUIDESt8functionIFvvEE","s+":"FF"}}} {"t":{"$date":"2024-03-29T09:37:52.551+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"555BF8C037D8","b":"555BF7981000","o":"12827D8","s":"_ZZNK5mongo11BSONElement6NumberEvENKUlvE_clEv","s+":"7C08"}}} {"t":{"$date":"2024-03-29T09:37:52.551+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"555BFA0C5947","b":"555BF7981000","o":"2744947","s":"_ZN5mongo22IndexBuildsCoordinator16_setUpIndexBuildEPNS_16OperationContextERKNS_4UUIDENS_9TimestampERKNS0_17IndexBuildOptionsE","s+":"D7"}}} {"t":{"$date":"2024-03-29T09:37:52.551+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"555BF9DD4B78","b":"555BF7981000","o":"2453B78","s":"_ZN5mongo28IndexBuildsCoordinatorMongod33_checkVoteCommitIndexCmdSucceededERKNS_7BSONObjERKNS_4UUIDE","s+":"CB8"}}} {"t":{"$date":"2024-03-29T09:37:52.551+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"555BFB8FFBB5","b":"555BF7981000","o":"3F7EBB5","s":"_ZN5mongo10ThreadPool4Impl10_doOneTaskEPSt11unique_lockINS_12latch_detail5LatchEE","s+":"135"}}} {"t":{"$date":"2024-03-29T09:37:52.551+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"555BFB90140B","b":"555BF7981000","o":"3F8040B","s":"_ZN5mongo10ThreadPool4Impl13_consumeTasksEv","s+":"8B"}}} {"t":{"$date":"2024-03-29T09:37:52.551+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"555BFB90292C","b":"555BF7981000","o":"3F8192C","s":"_ZN5mongo10ThreadPool4Impl17_workerThreadBodyERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEE","s+":"26C"}}} {"t":{"$date":"2024-03-29T09:37:52.551+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"555BFB902ED0","b":"555BF7981000","o":"3F81ED0","s":"_ZN5mongo10ThreadPool4Impl17_workerThreadBodyERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEE","s+":"810"}}} {"t":{"$date":"2024-03-29T09:37:52.551+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"7F65F17C0B23","b":"7F65F16FE000","o":"C2B23","s":"_ZNKSt10error_code23default_error_conditionEv","s+":"33"}}} {"t":{"$date":"2024-03-29T09:37:52.551+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"7F65F0F4B1DA","b":"7F65F0F43000","o":"81DA","s":"start_thread","s+":"EA"}}} {"t":{"$date":"2024-03-29T09:37:52.551+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"7F65F0BB7E73","b":"7F65F0B7E000","o":"39E73","s":"clone","s+":"43"}}}
Raw output
start_cluster = True, cluster = <cluster.Cluster object at 0x7f3d42c67e10>

    @pytest.mark.timeout(1200, func_only=True)
    def test_physical_pitr_PBM_T251(start_cluster,cluster):
        cluster.check_pbm_status()
        for i in range(30):
             pymongo.MongoClient(cluster.connection)["test"]["test"].insert_one({"a": i})
        cluster.make_backup("logical")
        cluster.enable_pitr(pitr_extra_args="--set pitr.oplogSpanMin=3")
        backup=cluster.make_backup("physical")
        for i in range(30):
             pymongo.MongoClient(cluster.connection)["test"]["test"].insert_one({"b": i})
        timeout = time.time() + 360
        while True:
            status = cluster.get_status()
            for snapshot in status['backups']['snapshot']:
                if snapshot['name'] == backup:
                    backup_epoch = snapshot['restoreTo']
            if 'pitrChunks' in status['backups']:
                if 'pitrChunks' in status['backups']['pitrChunks']:
                    pitr_epoch = status['backups']['pitrChunks']['pitrChunks'][-1]['range']['end']
                    if pitr_epoch > backup_epoch:
                        pitr = datetime.utcfromtimestamp(pitr_epoch).strftime("%Y-%m-%dT%H:%M:%S")
                        Cluster.log("Time for PITR is: " + pitr)
                        break
            if time.time() > timeout:
                assert False
            time.sleep(1)
        time.sleep(30)
        backup="--time=" + pitr + " --base-snapshot=" + backup
        cluster.disable_pitr()
        cluster.make_restore(backup,restart_cluster=True,check_pbm_status=True)
        assert pymongo.MongoClient(cluster.connection)["test"]["test"].count_documents({}) == 60
    
    
        backup=cluster.make_backup("physical")
>       cluster.make_restore(backup,restart_cluster=True,check_pbm_status=True)

test_PBM-1265.py:89: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <cluster.Cluster object at 0x7f3d42c67e10>, name = '2024-03-29T09:36:44Z'
kwargs = {'check_pbm_status': True, 'restart_cluster': True}
client = MongoClient(host=['mongos:27017'], document_class=dict, tz_aware=False, connect=True)
result = CommandResult(backend=<testinfra.backend.docker.DockerBackend object at 0x7f3d42bf1750>, exit_status=124, command=b'ti...........................................................................................................", _stderr=b'')
n = <testinfra.host.Host docker://rscfg01>, timeout = 240
error = '{"t":{"$date":"2024-03-29T09:37:51.981+00:00"},"s":"I",  "c":"CONTROL",  "id":23285,   "ctx":"-","msg":"Automatically...rMongod-0","msg":"Frame","attr":{"frame":{"a":"7F65F0BB7E73","b":"7F65F0B7E000","o":"39E73","s":"clone","s+":"43"}}}\n'
host = 'rscfg03', container = <Container: 93dfd1bbe88a>

    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
E               AssertionError: Starting restore 2024-03-29T09:37:06.667867381Z from '2024-03-29T09:36:44Z'..........................Started physical restore.
E               Waiting to finish.....................................................................................................................................................................................................................
E               {"t":{"$date":"2024-03-29T09:37:51.981+00:00"},"s":"I",  "c":"CONTROL",  "id":23285,   "ctx":"-","msg":"Automatically disabling TLS 1.0, to force-enable TLS 1.0 specify --sslDisabledProtocols 'none'"}
E               {"t":{"$date":"2024-03-29T09:37:51.983+00:00"},"s":"I",  "c":"NETWORK",  "id":4915701, "ctx":"-","msg":"Initialized wire specification","attr":{"spec":{"incomingExternalClient":{"minWireVersion":0,"maxWireVersion":13},"incomingInternalClient":{"minWireVersion":0,"maxWireVersion":13},"outgoing":{"minWireVersion":0,"maxWireVersion":13},"isInternalClient":true}}}
E               {"t":{"$date":"2024-03-29T09:37:51.983+00:00"},"s":"W",  "c":"ASIO",     "id":22601,   "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"}
E               {"t":{"$date":"2024-03-29T09:37:51.983+00:00"},"s":"I",  "c":"NETWORK",  "id":4648601, "ctx":"main","msg":"Implicit TCP FastOpen unavailable. If TCP FastOpen is required, set tcpFastOpenServer, tcpFastOpenClient, and tcpFastOpenQueueSize."}
E               {"t":{"$date":"2024-03-29T09:37:51.984+00:00"},"s":"W",  "c":"ASIO",     "id":22601,   "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"}
E               {"t":{"$date":"2024-03-29T09:37:51.984+00:00"},"s":"I",  "c":"REPL",     "id":5123008, "ctx":"main","msg":"Successfully registered PrimaryOnlyService","attr":{"service":"TenantMigrationDonorService","ns":"config.tenantMigrationDonors"}}
E               {"t":{"$date":"2024-03-29T09:37:51.984+00:00"},"s":"I",  "c":"REPL",     "id":5123008, "ctx":"main","msg":"Successfully registered PrimaryOnlyService","attr":{"service":"TenantMigrationRecipientService","ns":"config.tenantMigrationRecipients"}}
E               {"t":{"$date":"2024-03-29T09:37:51.984+00:00"},"s":"I",  "c":"CONTROL",  "id":5945603, "ctx":"main","msg":"Multi threading initialized"}
E               {"t":{"$date":"2024-03-29T09:37:51.985+00:00"},"s":"I",  "c":"CONTROL",  "id":4615611, "ctx":"initandlisten","msg":"MongoDB starting","attr":{"pid":293,"port":28034,"dbPath":"/var/lib/mongo","architecture":"64-bit","host":"rs103"}}
E               {"t":{"$date":"2024-03-29T09:37:51.985+00:00"},"s":"I",  "c":"CONTROL",  "id":23403,   "ctx":"initandlisten","msg":"Build Info","attr":{"buildInfo":{"version":"5.0.24-21","gitVersion":"751fc35891514cf219872e1134196614b972d9d3","openSSLVersion":"OpenSSL 1.1.1k  FIPS 25 Mar 2021","modules":[],"allocator":"tcmalloc","environment":{"distarch":"x86_64","target_arch":"x86_64"}}}}
E               {"t":{"$date":"2024-03-29T09:37:51.985+00:00"},"s":"I",  "c":"CONTROL",  "id":51765,   "ctx":"initandlisten","msg":"Operating System","attr":{"os":{"name":"Oracle Linux Server release 8.9","version":"Kernel 6.5.0-1016-azure"}}}
E               {"t":{"$date":"2024-03-29T09:37:51.985+00:00"},"s":"I",  "c":"CONTROL",  "id":21951,   "ctx":"initandlisten","msg":"Options set by command line","attr":{"options":{"config":"/tmp/pbmMongdTmpConf1974481778","net":{"bindIp":"localhost","port":28034},"setParameter":{"recoverFromOplogAsStandalone":"true","takeUnstableCheckpointOnShutdown":"true"},"storage":{"dbPath":"/var/lib/mongo","directoryPerDB":false,"wiredTiger":{"collectionConfig":{"blockCompressor":"snappy"},"engineConfig":{"directoryForIndexes":false,"journalCompressor":"snappy"},"indexConfig":{"prefixCompression":true}}},"systemLog":{"destination":"file","path":"/var/lib/mongo/pbm.restore.log"}}}}
E               {"t":{"$date":"2024-03-29T09:37:51.985+00:00"},"s":"I",  "c":"STORAGE",  "id":22270,   "ctx":"initandlisten","msg":"Storage engine to use detected by data files","attr":{"dbpath":"/var/lib/mongo","storageEngine":"wiredTiger"}}
E               {"t":{"$date":"2024-03-29T09:37:51.985+00:00"},"s":"I",  "c":"STORAGE",  "id":22315,   "ctx":"initandlisten","msg":"Opening WiredTiger","attr":{"config":"create,cache_size=7478M,session_max=33000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),builtin_extension_config=(zstd=(compression_level=6)),file_manager=(close_idle_time=600,close_scan_interval=10,close_handle_minimum=250),statistics_log=(wait=0),verbose=[recovery_progress,checkpoint_progress,compact_progress],"}}
E               {"t":{"$date":"2024-03-29T09:37:52.125+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1711705072:125586][293:0x7f65f37d6c00], txn-recover: [WT_VERB_RECOVERY_PROGRESS] Recovering log 8 through 9"}}
E               {"t":{"$date":"2024-03-29T09:37:52.154+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1711705072:154066][293:0x7f65f37d6c00], txn-recover: [WT_VERB_RECOVERY_PROGRESS] Recovering log 9 through 9"}}
E               {"t":{"$date":"2024-03-29T09:37:52.209+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1711705072:209493][293:0x7f65f37d6c00], txn-recover: [WT_VERB_RECOVERY_ALL] Main recovery loop: starting at 8/65664 to 9/256"}}
E               {"t":{"$date":"2024-03-29T09:37:52.256+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1711705072:256872][293:0x7f65f37d6c00], txn-recover: [WT_VERB_RECOVERY_PROGRESS] Recovering log 8 through 9"}}
E               {"t":{"$date":"2024-03-29T09:37:52.292+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1711705072:292608][293:0x7f65f37d6c00], txn-recover: [WT_VERB_RECOVERY_PROGRESS] Recovering log 9 through 9"}}
E               {"t":{"$date":"2024-03-29T09:37:52.314+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1711705072:314803][293:0x7f65f37d6c00], txn-recover: [WT_VERB_RECOVERY_ALL] Set global recovery timestamp: (1711704840, 33)"}}
E               {"t":{"$date":"2024-03-29T09:37:52.314+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1711705072:314850][293:0x7f65f37d6c00], txn-recover: [WT_VERB_RECOVERY_ALL] Set global oldest timestamp: (1711704540, 33)"}}
E               {"t":{"$date":"2024-03-29T09:37:52.317+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1711705072:317636][293:0x7f65f37d6c00], WT_SESSION.checkpoint: [WT_VERB_CHECKPOINT_PROGRESS] saving checkpoint snapshot min: 1, snapshot max: 1 snapshot count: 0, oldest timestamp: (1711704540, 33) , meta checkpoint timestamp: (1711704840, 33) base write gen: 65"}}
E               {"t":{"$date":"2024-03-29T09:37:52.320+00:00"},"s":"I",  "c":"STORAGE",  "id":4795906, "ctx":"initandlisten","msg":"WiredTiger opened","attr":{"durationMillis":334}}
E               {"t":{"$date":"2024-03-29T09:37:52.320+00:00"},"s":"I",  "c":"RECOVERY", "id":23987,   "ctx":"initandlisten","msg":"WiredTiger recoveryTimestamp","attr":{"recoveryTimestamp":{"$timestamp":{"t":1711704840,"i":33}}}}
E               {"t":{"$date":"2024-03-29T09:37:52.320+00:00"},"s":"I",  "c":"RECOVERY", "id":5380106, "ctx":"initandlisten","msg":"WiredTiger oldestTimestamp","attr":{"oldestTimestamp":{"$timestamp":{"t":1711704540,"i":33}}}}
E               {"t":{"$date":"2024-03-29T09:37:52.340+00:00"},"s":"I",  "c":"STORAGE",  "id":22262,   "ctx":"initandlisten","msg":"Timestamp monitor starting"}
E               {"t":{"$date":"2024-03-29T09:37:52.341+00:00"},"s":"W",  "c":"CONTROL",  "id":22120,   "ctx":"initandlisten","msg":"Access control is not enabled for the database. Read and write access to data and configuration is unrestricted. You can use percona-server-mongodb-enable-auth.sh to fix it","tags":["startupWarnings"]}
E               {"t":{"$date":"2024-03-29T09:37:52.341+00:00"},"s":"W",  "c":"CONTROL",  "id":22178,   "ctx":"initandlisten","msg":"/sys/kernel/mm/transparent_hugepage/enabled is 'always'. We suggest setting it to 'never'","tags":["startupWarnings"]}
E               {"t":{"$date":"2024-03-29T09:37:52.348+00:00"},"s":"I",  "c":"NETWORK",  "id":4915702, "ctx":"initandlisten","msg":"Updated wire specification","attr":{"oldSpec":{"incomingExternalClient":{"minWireVersion":0,"maxWireVersion":13},"incomingInternalClient":{"minWireVersion":0,"maxWireVersion":13},"outgoing":{"minWireVersion":0,"maxWireVersion":13},"isInternalClient":true},"newSpec":{"incomingExternalClient":{"minWireVersion":0,"maxWireVersion":13},"incomingInternalClient":{"minWireVersion":13,"maxWireVersion":13},"outgoing":{"minWireVersion":13,"maxWireVersion":13},"isInternalClient":true}}}
E               {"t":{"$date":"2024-03-29T09:37:52.349+00:00"},"s":"I",  "c":"STORAGE",  "id":5071100, "ctx":"initandlisten","msg":"Clearing temp directory"}
E               {"t":{"$date":"2024-03-29T09:37:52.366+00:00"},"s":"I",  "c":"CONTROL",  "id":20536,   "ctx":"initandlisten","msg":"Flow Control is enabled on this deployment"}
E               {"t":{"$date":"2024-03-29T09:37:52.366+00:00"},"s":"I",  "c":"STORAGE",  "id":5380103, "ctx":"initandlisten","msg":"Unpin oldest timestamp request","attr":{"service":"_wt_startup","requestedTs":{"$timestamp":{"t":1711704540,"i":33}}}}
E               {"t":{"$date":"2024-03-29T09:37:52.367+00:00"},"s":"W",  "c":"SHARDING", "id":22075,   "ctx":"initandlisten","msg":"Not started with --shardsvr, but a shardIdentity document was found on disk","attr":{"namespace":"admin.system.version","shardIdentityDocument":{"_id":"shardIdentity","shardName":"rs1","clusterId":{"$oid":"660689a017271609d88f9015"},"configsvrConnectionString":"rscfg/rscfg01:27017,rscfg02:27017,rscfg03:27017"}}}
E               {"t":{"$date":"2024-03-29T09:37:52.367+00:00"},"s":"I",  "c":"FTDC",     "id":20625,   "ctx":"initandlisten","msg":"Initializing full-time diagnostic data capture","attr":{"dataDirectory":"/var/lib/mongo/diagnostic.data"}}
E               {"t":{"$date":"2024-03-29T09:37:52.370+00:00"},"s":"I",  "c":"REPL",     "id":21557,   "ctx":"initandlisten","msg":"Removing unapplied oplog entries after oplogTruncateAfterPoint","attr":{"oplogTruncateAfterPoint":{"":{"$timestamp":{"t":1711705007,"i":3}}}}}
E               {"t":{"$date":"2024-03-29T09:37:52.370+00:00"},"s":"I",  "c":"REPL",     "id":21553,   "ctx":"initandlisten","msg":"Truncating oplog from truncateAfterOplogEntryTimestamp (non-inclusive)","attr":{"truncateAfterOplogEntryTimestamp":{"$timestamp":{"t":1711705005,"i":58}},"oplogTruncateAfterPoint":{"$timestamp":{"t":1711705007,"i":3}}}}
E               {"t":{"$date":"2024-03-29T09:37:52.370+00:00"},"s":"I",  "c":"REPL",     "id":21554,   "ctx":"initandlisten","msg":"Replication recovery oplog truncation finished","attr":{"durationMillis":0}}
E               {"t":{"$date":"2024-03-29T09:37:52.371+00:00"},"s":"I",  "c":"REPL",     "id":21544,   "ctx":"initandlisten","msg":"Recovering from stable timestamp","attr":{"stableTimestamp":{"$timestamp":{"t":1711704840,"i":33}},"topOfOplog":{"ts":{"$timestamp":{"t":1711705005,"i":58}},"t":4},"appliedThrough":{"ts":{"$timestamp":{"t":0,"i":0}},"t":-1}}}
E               {"t":{"$date":"2024-03-29T09:37:52.371+00:00"},"s":"I",  "c":"REPL",     "id":21545,   "ctx":"initandlisten","msg":"Starting recovery oplog application at the stable timestamp","attr":{"stableTimestamp":{"$timestamp":{"t":1711704840,"i":33}}}}
E               {"t":{"$date":"2024-03-29T09:37:52.372+00:00"},"s":"I",  "c":"REPL",     "id":5466604, "ctx":"initandlisten","msg":"Start point for recovery oplog application exists in oplog. No adjustment necessary","attr":{"startPoint":{"$timestamp":{"t":1711704840,"i":33}}}}
E               {"t":{"$date":"2024-03-29T09:37:52.372+00:00"},"s":"I",  "c":"REPL",     "id":21550,   "ctx":"initandlisten","msg":"Replaying stored operations from startPoint (exclusive) to endPoint (inclusive)","attr":{"startPoint":{"$timestamp":{"t":1711704840,"i":33}},"endPoint":{"$timestamp":{"t":1711705005,"i":58}}}}
E               {"t":{"$date":"2024-03-29T09:37:52.374+00:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"ReplWriterWorker-1","msg":"createCollection","attr":{"namespace":"config.cache.chunks.config.system.sessions","uuidDisposition":"provided","uuid":{"uuid":{"$uuid":"4129f180-3ebe-433d-9cc2-eb9e08c8050d"}},"options":{"uuid":{"$uuid":"4129f180-3ebe-433d-9cc2-eb9e08c8050d"}}}}
E               {"t":{"$date":"2024-03-29T09:37:52.380+00:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"ReplWriterWorker-1","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.cache.chunks.config.system.sessions","index":"_id_","commitTimestamp":{"$timestamp":{"t":1711704956,"i":1030}}}}
E               {"t":{"$date":"2024-03-29T09:37:52.387+00:00"},"s":"I",  "c":"INDEX",    "id":20384,   "ctx":"ReplWriterWorker-1","msg":"Index build: starting","attr":{"buildUUID":null,"collectionUUID":{"uuid":{"$uuid":"4129f180-3ebe-433d-9cc2-eb9e08c8050d"}},"namespace":"config.cache.chunks.config.system.sessions","properties":{"v":2,"key":{"lastmod":1},"name":"lastmod_1"},"method":"Hybrid","maxTemporaryMemoryUsageMB":200}}
E               {"t":{"$date":"2024-03-29T09:37:52.387+00:00"},"s":"I",  "c":"INDEX",    "id":20391,   "ctx":"ReplWriterWorker-1","msg":"Index build: collection scan done","attr":{"buildUUID":null,"collectionUUID":{"uuid":{"$uuid":"4129f180-3ebe-433d-9cc2-eb9e08c8050d"}},"namespace":"config.cache.chunks.config.system.sessions","totalRecords":0,"readSource":"kNoTimestamp","durationMillis":0}}
E               {"t":{"$date":"2024-03-29T09:37:52.388+00:00"},"s":"I",  "c":"INDEX",    "id":20685,   "ctx":"ReplWriterWorker-1","msg":"Index build: inserted keys from external sorter into index","attr":{"namespace":"config.cache.chunks.config.system.sessions","index":"lastmod_1","keysInserted":0,"durationMillis":0}}
E               {"t":{"$date":"2024-03-29T09:37:52.388+00:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"ReplWriterWorker-1","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.cache.chunks.config.system.sessions","index":"lastmod_1","commitTimestamp":{"$timestamp":{"t":1711704956,"i":1032}}}}
E               {"t":{"$date":"2024-03-29T09:37:52.391+00:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"ReplWriterWorker-7","msg":"createCollection","attr":{"namespace":"config.system.sessions","uuidDisposition":"provided","uuid":{"uuid":{"$uuid":"c42bf6bd-c00e-42a6-9366-3ecf72ad0d7e"}},"options":{"uuid":{"$uuid":"c42bf6bd-c00e-42a6-9366-3ecf72ad0d7e"}}}}
E               {"t":{"$date":"2024-03-29T09:37:52.396+00:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"ReplWriterWorker-7","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.system.sessions","index":"_id_","commitTimestamp":{"$timestamp":{"t":1711704956,"i":1097}}}}
E               {"t":{"$date":"2024-03-29T09:37:52.399+00:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"ReplWriterWorker-3","msg":"createCollection","attr":{"namespace":"config.migrationCoordinators","uuidDisposition":"provided","uuid":{"uuid":{"$uuid":"14cd4c11-d4fb-4731-a735-a2e06f234791"}},"options":{"uuid":{"$uuid":"14cd4c11-d4fb-4731-a735-a2e06f234791"}}}}
E               {"t":{"$date":"2024-03-29T09:37:52.403+00:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"ReplWriterWorker-3","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.migrationCoordinators","index":"_id_","commitTimestamp":{"$timestamp":{"t":1711704957,"i":63}}}}
E               {"t":{"$date":"2024-03-29T09:37:52.404+00:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"ReplWriterWorker-6","msg":"createCollection","attr":{"namespace":"config.rangeDeletions","uuidDisposition":"provided","uuid":{"uuid":{"$uuid":"1b380725-3145-40d4-ac52-09ceaea23126"}},"options":{"uuid":{"$uuid":"1b380725-3145-40d4-ac52-09ceaea23126"}}}}
E               {"t":{"$date":"2024-03-29T09:37:52.409+00:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"ReplWriterWorker-6","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.rangeDeletions","index":"_id_","commitTimestamp":{"$timestamp":{"t":1711704957,"i":132}}}}
E               {"t":{"$date":"2024-03-29T09:37:52.415+00:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"ReplWriterWorker-6","msg":"createCollection","attr":{"namespace":"config.vectorClock","uuidDisposition":"provided","uuid":{"uuid":{"$uuid":"5c7fb5a4-3901-4961-b403-add1ca7f9da4"}},"options":{"uuid":{"$uuid":"5c7fb5a4-3901-4961-b403-add1ca7f9da4"}}}}
E               {"t":{"$date":"2024-03-29T09:37:52.420+00:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"ReplWriterWorker-6","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.vectorClock","index":"_id_","commitTimestamp":{"$timestamp":{"t":1711704957,"i":1201}}}}
E               {"t":{"$date":"2024-03-29T09:37:52.498+00:00"},"s":"I",  "c":"REPL",     "id":21536,   "ctx":"initandlisten","msg":"Completed oplog application for recovery","attr":{"numOpsApplied":1866,"numBatches":192,"applyThroughOpTime":{"ts":{"$timestamp":{"t":1711705005,"i":58}},"t":4}}}
E               {"t":{"$date":"2024-03-29T09:37:52.499+00:00"},"s":"W",  "c":"REPL",     "id":21558,   "ctx":"initandlisten","msg":"Setting mongod to readOnly mode as a result of specifying 'recoverFromOplogAsStandalone'"}
E               {"t":{"$date":"2024-03-29T09:37:52.499+00:00"},"s":"I",  "c":"REPL",     "id":6015317, "ctx":"initandlisten","msg":"Setting new configuration state","attr":{"newState":"ConfigReplicationDisabled","oldState":"ConfigPreStart"}}
E               {"t":{"$date":"2024-03-29T09:37:52.500+00:00"},"s":"I",  "c":"INDEX",    "id":20438,   "ctx":"LogicalSessionCacheRefresh","msg":"Index build: registering","attr":{"buildUUID":{"uuid":{"$uuid":"089c6dc7-fe3a-4ada-9ab6-3331012422ee"}},"namespace":"config.system.sessions","collectionUUID":{"uuid":{"$uuid":"c42bf6bd-c00e-42a6-9366-3ecf72ad0d7e"}},"indexes":1,"firstIndex":{"name":"lsidTTLIndex"}}}
E               {"t":{"$date":"2024-03-29T09:37:52.500+00:00"},"s":"I",  "c":"CONTROL",  "id":20712,   "ctx":"LogicalSessionCacheReap","msg":"Sessions collection is not set up; waiting until next sessions reap interval","attr":{"error":"IndexNotFound: config.system.sessions does not have the required TTL index"}}
E               {"t":{"$date":"2024-03-29T09:37:52.500+00:00"},"s":"I",  "c":"NETWORK",  "id":23015,   "ctx":"listener","msg":"Listening on","attr":{"address":"/tmp/mongodb-28034.sock"}}
E               {"t":{"$date":"2024-03-29T09:37:52.500+00:00"},"s":"I",  "c":"NETWORK",  "id":23015,   "ctx":"listener","msg":"Listening on","attr":{"address":"127.0.0.1"}}
E               {"t":{"$date":"2024-03-29T09:37:52.500+00:00"},"s":"I",  "c":"NETWORK",  "id":23016,   "ctx":"listener","msg":"Waiting for connections","attr":{"port":28034,"ssl":"off"}}
E               {"t":{"$date":"2024-03-29T09:37:52.500+00:00"},"s":"E",  "c":"INDEX",    "id":20393,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Caught exception while cleaning up partially built indexes","attr":{"error":"IllegalOperation: Cannot execute a write operation in read-only mode"}}
E               {"t":{"$date":"2024-03-29T09:37:52.500+00:00"},"s":"F",  "c":"-",        "id":23089,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Fatal assertion","attr":{"msgid":18644,"file":"src/mongo/db/catalog/multi_index_block.cpp","line":152}}
E               {"t":{"$date":"2024-03-29T09:37:52.500+00:00"},"s":"F",  "c":"-",        "id":23090,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"\n\n***aborting after fassert() failure\n\n"}
E               {"t":{"$date":"2024-03-29T09:37:52.500+00:00"},"s":"F",  "c":"CONTROL",  "id":6384300, "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Writing fatal message","attr":{"message":"Got signal: 6 (Aborted).\n"}}
E               {"t":{"$date":"2024-03-29T09:37:52.551+00:00"},"s":"I",  "c":"CONTROL",  "id":31380,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"BACKTRACE","attr":{"bt":{"backtrace":[{"a":"555BFBB466E3","b":"555BF7981000","o":"41C56E3","s":"_ZN5mongo34StackTraceAddressMetadataGenerator4loadEPv","s+":"FC3"},{"a":"555BFBB49127","b":"555BF7981000","o":"41C8127","s":"_ZN5mongo15printStackTraceEv","s+":"37"},{"a":"555BFBB412D6","b":"555BF7981000","o":"41C02D6","s":"abruptQuit","s+":"66"},{"a":"7F65F0F55D40","b":"7F65F0F43000","o":"12D40","s":"funlockfile","s+":"50"},{"a":"7F65F0BCCB8F","b":"7F65F0B7E000","o":"4EB8F","s":"gsignal","s+":"10F"},{"a":"7F65F0B9FEA5","b":"7F65F0B7E000","o":"21EA5","s":"abort","s+":"127"},{"a":"555BF8EE6D2B","b":"555BF7981000","o":"1565D2B","s":"_ZN5mongo25fassertFailedWithLocationEiPKcj","s+":"F6"},{"a":"555BF8C9573F","b":"555BF7981000","o":"131473F","s":"_ZN5mongo21AuthzVersionParameter13setFromStringERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEE","s+":"55EF"},{"a":"555BFA154AAF","b":"555BF7981000","o":"27D3AAF","s":"_ZN5mongo18IndexBuildsManager15abortIndexBuildEPNS_16OperationContextERNS_16CollectionWriterERKNS_4UUIDESt8functionIFvvEE","s+":"FF"},{"a":"555BF8C037D8","b":"555BF7981000","o":"12827D8","s":"_ZZNK5mongo11BSONElement6NumberEvENKUlvE_clEv","s+":"7C08"},{"a":"555BFA0C5947","b":"555BF7981000","o":"2744947","s":"_ZN5mongo22IndexBuildsCoordinator16_setUpIndexBuildEPNS_16OperationContextERKNS_4UUIDENS_9TimestampERKNS0_17IndexBuildOptionsE","s+":"D7"},{"a":"555BF9DD4B78","b":"555BF7981000","o":"2453B78","s":"_ZN5mongo28IndexBuildsCoordinatorMongod33_checkVoteCommitIndexCmdSucceededERKNS_7BSONObjERKNS_4UUIDE","s+":"CB8"},{"a":"555BFB8FFBB5","b":"555BF7981000","o":"3F7EBB5","s":"_ZN5mongo10ThreadPool4Impl10_doOneTaskEPSt11unique_lockINS_12latch_detail5LatchEE","s+":"135"},{"a":"555BFB90140B","b":"555BF7981000","o":"3F8040B","s":"_ZN5mongo10ThreadPool4Impl13_consumeTasksEv","s+":"8B"},{"a":"555BFB90292C","b":"555BF7981000","o":"3F8192C","s":"_ZN5mongo10ThreadPool4Impl17_workerThreadBodyERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEE","s+":"26C"},{"a":"555BFB902ED0","b":"555BF7981000","o":"3F81ED0","s":"_ZN5mongo10ThreadPool4Impl17_workerThreadBodyERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEE","s+":"810"},{"a":"7F65F17C0B23","b":"7F65F16FE000","o":"C2B23","s":"_ZNKSt10error_code23default_error_conditionEv","s+":"33"},{"a":"7F65F0F4B1DA","b":"7F65F0F43000","o":"81DA","s":"start_thread","s+":"EA"},{"a":"7F65F0BB7E73","b":"7F65F0B7E000","o":"39E73","s":"clone","s+":"43"}],"processInfo":{"mongodbVersion":"5.0.24-21","gitVersion":"751fc35891514cf219872e1134196614b972d9d3","compiledModules":[],"uname":{"sysname":"Linux","release":"6.5.0-1016-azure","version":"#16~22.04.1-Ubuntu SMP Fri Feb 16 15:42:02 UTC 2024","machine":"x86_64"},"somap":[{"b":"555BF7981000","elfType":3,"buildId":"DA4870CDDA3114158E5C3DAB653D63D4F6C9E499"},{"b":"7F65F16FE000","path":"/lib64/libstdc++.so.6","elfType":3,"buildId":"5CA844DFEE0FE8E20B2A0F7CF8EF4291838E8806"},{"b":"7F65F0F43000","path":"/lib64/libpthread.so.0","elfType":3,"buildId":"D1ADEF9579CE9780C97DB1A37BD08552A91F4564"},{"b":"7F65F0B7E000","path":"/lib64/libc.so.6","elfType":3,"buildId":"BA5A6A6FF582CD9C692D725BAD086CBB48AC723D"}]}}}}
E               {"t":{"$date":"2024-03-29T09:37:52.551+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"555BFBB466E3","b":"555BF7981000","o":"41C56E3","s":"_ZN5mongo34StackTraceAddressMetadataGenerator4loadEPv","s+":"FC3"}}}
E               {"t":{"$date":"2024-03-29T09:37:52.551+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"555BFBB49127","b":"555BF7981000","o":"41C8127","s":"_ZN5mongo15printStackTraceEv","s+":"37"}}}
E               {"t":{"$date":"2024-03-29T09:37:52.551+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"555BFBB412D6","b":"555BF7981000","o":"41C02D6","s":"abruptQuit","s+":"66"}}}
E               {"t":{"$date":"2024-03-29T09:37:52.551+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"7F65F0F55D40","b":"7F65F0F43000","o":"12D40","s":"funlockfile","s+":"50"}}}
E               {"t":{"$date":"2024-03-29T09:37:52.551+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"7F65F0BCCB8F","b":"7F65F0B7E000","o":"4EB8F","s":"gsignal","s+":"10F"}}}
E               {"t":{"$date":"2024-03-29T09:37:52.551+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"7F65F0B9FEA5","b":"7F65F0B7E000","o":"21EA5","s":"abort","s+":"127"}}}
E               {"t":{"$date":"2024-03-29T09:37:52.551+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"555BF8EE6D2B","b":"555BF7981000","o":"1565D2B","s":"_ZN5mongo25fassertFailedWithLocationEiPKcj","s+":"F6"}}}
E               {"t":{"$date":"2024-03-29T09:37:52.551+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"555BF8C9573F","b":"555BF7981000","o":"131473F","s":"_ZN5mongo21AuthzVersionParameter13setFromStringERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEE","s+":"55EF"}}}
E               {"t":{"$date":"2024-03-29T09:37:52.551+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"555BFA154AAF","b":"555BF7981000","o":"27D3AAF","s":"_ZN5mongo18IndexBuildsManager15abortIndexBuildEPNS_16OperationContextERNS_16CollectionWriterERKNS_4UUIDESt8functionIFvvEE","s+":"FF"}}}
E               {"t":{"$date":"2024-03-29T09:37:52.551+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"555BF8C037D8","b":"555BF7981000","o":"12827D8","s":"_ZZNK5mongo11BSONElement6NumberEvENKUlvE_clEv","s+":"7C08"}}}
E               {"t":{"$date":"2024-03-29T09:37:52.551+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"555BFA0C5947","b":"555BF7981000","o":"2744947","s":"_ZN5mongo22IndexBuildsCoordinator16_setUpIndexBuildEPNS_16OperationContextERKNS_4UUIDENS_9TimestampERKNS0_17IndexBuildOptionsE","s+":"D7"}}}
E               {"t":{"$date":"2024-03-29T09:37:52.551+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"555BF9DD4B78","b":"555BF7981000","o":"2453B78","s":"_ZN5mongo28IndexBuildsCoordinatorMongod33_checkVoteCommitIndexCmdSucceededERKNS_7BSONObjERKNS_4UUIDE","s+":"CB8"}}}
E               {"t":{"$date":"2024-03-29T09:37:52.551+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"555BFB8FFBB5","b":"555BF7981000","o":"3F7EBB5","s":"_ZN5mongo10ThreadPool4Impl10_doOneTaskEPSt11unique_lockINS_12latch_detail5LatchEE","s+":"135"}}}
E               {"t":{"$date":"2024-03-29T09:37:52.551+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"555BFB90140B","b":"555BF7981000","o":"3F8040B","s":"_ZN5mongo10ThreadPool4Impl13_consumeTasksEv","s+":"8B"}}}
E               {"t":{"$date":"2024-03-29T09:37:52.551+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"555BFB90292C","b":"555BF7981000","o":"3F8192C","s":"_ZN5mongo10ThreadPool4Impl17_workerThreadBodyERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEE","s+":"26C"}}}
E               {"t":{"$date":"2024-03-29T09:37:52.551+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"555BFB902ED0","b":"555BF7981000","o":"3F81ED0","s":"_ZN5mongo10ThreadPool4Impl17_workerThreadBodyERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEE","s+":"810"}}}
E               {"t":{"$date":"2024-03-29T09:37:52.551+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"7F65F17C0B23","b":"7F65F16FE000","o":"C2B23","s":"_ZNKSt10error_code23default_error_conditionEv","s+":"33"}}}
E               {"t":{"$date":"2024-03-29T09:37:52.551+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"7F65F0F4B1DA","b":"7F65F0F43000","o":"81DA","s":"start_thread","s+":"EA"}}}
E               {"t":{"$date":"2024-03-29T09:37:52.551+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"7F65F0BB7E73","b":"7F65F0B7E000","o":"39E73","s":"clone","s+":"43"}}}

cluster.py:455: AssertionError
assert pymongo.MongoClient(cluster.connection)["test"]["test"].count_documents({}) == 60

Loading