Testcontainers version
4.3.0
Using the latest Testcontainers version?
No
Host OS
Linux
Host arch
x86
.NET version
.NET 8
Docker version
Client:
Version: 27.2.0
API version: 1.47
Go version: go1.21.13
Git commit: 3ab4256
Built: Tue Aug 27 14:17:17 2024
OS/Arch: windows/amd64
Context: desktop-linux
Server: Docker Desktop 4.34.2 (167172)
Engine:
Version: 27.2.0
API version: 1.47 (minimum version 1.24)
Go version: go1.21.13
Git commit: 3ab5c7d
Built: Tue Aug 27 14:15:15 2024
OS/Arch: linux/amd64
Experimental: false
containerd:
Version: 1.7.20
GitCommit: 8fc6bcff51318944179630522a095cc9dbf9f353
runc:
Version: 1.1.13
GitCommit: v1.1.13-0-g58aa920
docker-init:
Version: 0.19.0
GitCommit: de40ad0
Docker info
Client:
Version: 27.2.0
Context: desktop-linux
Debug Mode: false
Plugins:
buildx: Docker Buildx (Docker Inc.)
Version: v0.16.2-desktop.1
Path: C:\Program Files\Docker\cli-plugins\docker-buildx.exe
compose: Docker Compose (Docker Inc.)
Version: v2.29.2-desktop.2
Path: C:\Program Files\Docker\cli-plugins\docker-compose.exe
debug: Get a shell into any image or container (Docker Inc.)
Version: 0.0.34
Path: C:\Program Files\Docker\cli-plugins\docker-debug.exe
desktop: Docker Desktop commands (Alpha) (Docker Inc.)
Version: v0.0.15
Path: C:\Program Files\Docker\cli-plugins\docker-desktop.exe
dev: Docker Dev Environments (Docker Inc.)
Version: v0.1.2
Path: C:\Program Files\Docker\cli-plugins\docker-dev.exe
extension: Manages Docker extensions (Docker Inc.)
Version: v0.2.25
Path: C:\Program Files\Docker\cli-plugins\docker-extension.exe
feedback: Provide feedback, right in your terminal! (Docker Inc.)
Version: v1.0.5
Path: C:\Program Files\Docker\cli-plugins\docker-feedback.exe
init: Creates Docker-related starter files for your project (Docker Inc.)
Version: v1.3.0
Path: C:\Program Files\Docker\cli-plugins\docker-init.exe
sbom: View the packaged-based Software Bill Of Materials (SBOM) for an image (Anchore Inc.)
Version: 0.6.0
Path: C:\Program Files\Docker\cli-plugins\docker-sbom.exe
scout: Docker Scout (Docker Inc.)
Version: v1.13.0
Path: C:\Program Files\Docker\cli-plugins\docker-scout.exe
Server:
Containers: 7
Running: 5
Paused: 0
Stopped: 2
Images: 17
Server Version: 27.2.0
Storage Driver: overlay2
Backing Filesystem: extfs
Supports d_type: true
Using metacopy: false
Native Overlay Diff: true
userxattr: false
Logging Driver: json-file
Cgroup Driver: cgroupfs
Cgroup Version: 1
Plugins:
Volume: local
Network: bridge host ipvlan macvlan null overlay
Log: awslogs fluentd gcplogs gelf journald json-file local splunk syslog
Swarm: inactive
Runtimes: io.containerd.runc.v2 nvidia runc
Default Runtime: runc
Init Binary: docker-init
containerd version: 8fc6bcff51318944179630522a095cc9dbf9f353
runc version: v1.1.13-0-g58aa920
init version: de40ad0
Security Options:
seccomp
Profile: unconfined
Kernel Version: 5.15.153.1-microsoft-standard-WSL2
Operating System: Docker Desktop
OSType: linux
Architecture: x86_64
CPUs: 24
Total Memory: 31.22GiB
Name: docker-desktop
ID: 013b6fcb-be8b-43a8-b578-96ca0a4f9fdf
Docker Root Dir: /var/lib/docker
Debug Mode: false
HTTP Proxy: http.docker.internal:3128
HTTPS Proxy: http.docker.internal:3128
No Proxy: hubproxy.docker.internal
Labels:
com.docker.desktop.address=npipe://\.\pipe\docker_cli
Experimental: false
Insecure Registries:
hubproxy.docker.internal:5555
127.0.0.0/8
Live Restore Enabled: false
What happened?
Hi, I would like to re-open the #1284
We did a great job on fixing connection to replica set. And it worked for some long time to me. But I've found that MongoDB.Driver.MongoNotPrimaryException : Server returned not primary error. did not disappear, it just started to appear much more randomly and in more rare cases. Moreover, due to unknown reasons, this problem started to appear more often to me. May be my Linux machine became more overloaded, idk.
Nothing got changed in my repro environment, so, you can read the old issue for some details. I think that just checking rs.status().ok is still not enough for the mongodb to treat it as ready to accept queries. Pretty sure we got into some kind of concurrency here, when rs.status() is already ok, but cluster is not ready in fact in time window recent after replica set status changed.
I've come with solution that, as I think, should solve the issue with no-primary error completely.
In order to identify that rare bug I've injected some diagnostic logs that can show the replica status on the machine where the issue appears during wait strategy execution.
I have: 1 Windows machine where tests run fine; 1 Linux machine where tests are fail.
On both machines I did a print-out of rs.status() and compared them via KDiff. I've found few valuable differences.
1st difference is that healthy machine has electionCandidateMetrics.newTermStartDate set, while unhealthy machine is not:
Term is mongodb autoincrement value that is changed after the primary node becomes valid. For a fresh mongodb server this value will very kindly be equal to 1, and it can be seen in the rs.conf() output. So, checking the start date of a term refresh seems valuable.
2nd difference is that healthy machine has $clusterTime object while unhealthy machine is not:
So, I ended up with custom wait strategy for the TC container:
public WaitInitiateReplicaSet(string replicaName)
{
string rsInit = "rs.initiate({_id:'" + replicaName + "',members:[{_id:0,host:'127.0.0.1:27017'}]});";
_scriptContent = """
var result;
try {
result = rs.status();
}
catch (e) {
""" + rsInit +
"""
throw 1;
}
if (result.ok !== 1) {
""" + rsInit +
"""
throw 1;
}
if (!result["electionCandidateMetrics"] || !result["electionCandidateMetrics"].newTermStartDate) {
throw 2;
}
if (!result["$clusterTime"] || !result["$clusterTime"].clusterTime) {
throw 3;
}
var hasPrimary = false;
for (var i = 0; i < result.members.length; ++i) {
var member = result.members[i];
if (member.stateStr === "PRIMARY") {
hasPrimary = true;
break;
}
}
if (!hasPrimary) {
throw 4;
}
""";
}After applying this script, all tests ran fine on both machines. As for now, I see that problem has disappeared. Much hope for ever.
Note: as the wait strategy script got more complexity, may be, we could also add some max-retries option to the wait strategy. Otherwise, strategy script may run for ever.
I would be glad if you review the suggested strategy script and replace the old one.
Relevant log output
Full unhealthy `rs.status()`:
{
set: 'rs0',
date: ISODate('2025-10-01T09:23:33.956Z'),
myState: 1,
term: Long('1'),
syncSourceHost: '',
syncSourceId: -1,
heartbeatIntervalMillis: Long('2000'),
majorityVoteCount: 1,
writeMajorityCount: 1,
votingMembersCount: 1,
writableVotingMembersCount: 1,
optimes: {
lastCommittedOpTime: {
ts: Timestamp({ t: 1759310611, i: 1 }),
t: Long('-1')
},
lastCommittedWallTime: ISODate('2025-10-01T09:23:31.345Z'),
readConcernMajorityOpTime: {
ts: Timestamp({ t: 1759310611, i: 1 }),
t: Long('-1')
},
appliedOpTime: {
ts: Timestamp({ t: 1759310612, i: 3 }),
t: Long('1')
},
durableOpTime: {
ts: Timestamp({ t: 1759310612, i: 3 }),
t: Long('1')
},
lastAppliedWallTime: ISODate('2025-10-01T09:23:32.991Z'),
lastDurableWallTime: ISODate('2025-10-01T09:23:32.991Z')
},
lastStableRecoveryTimestamp: Timestamp({ t: 1759310611, i: 1 }),
electionCandidateMetrics: {
lastElectionReason: 'electionTimeout',
lastElectionDate: ISODate('2025-10-01T09:23:32.536Z'),
electionTerm: Long('1'),
lastCommittedOpTimeAtElection: {
ts: Timestamp({ t: 1759310611, i: 1 }),
t: Long('-1')
},
lastSeenOpTimeAtElection: {
ts: Timestamp({ t: 1759310611, i: 1 }),
t: Long('-1')
},
numVotesNeeded: 1,
priorityAtElection: 1,
electionTimeoutMillis: Long('10000')
},
members: [
{
_id: 0,
name: '127.0.0.1:27017',
health: 1,
state: 1,
stateStr: 'PRIMARY',
uptime: 9,
optime: {
ts: Timestamp({ t: 1759310612, i: 3 }),
t: Long('1')
},
optimeDate: ISODate('2025-10-01T09:23:32.000Z'),
lastAppliedWallTime: ISODate('2025-10-01T09:23:32.991Z'),
lastDurableWallTime: ISODate('2025-10-01T09:23:32.991Z'),
syncSourceHost: '',
syncSourceId: -1,
infoMessage: 'Could not find member to sync from',
electionTime: Timestamp({ t: 1759310612, i: 1 }),
electionDate: ISODate('2025-10-01T09:23:32.000Z'),
configVersion: 1,
configTerm: 1,
self: true,
lastHeartbeatMessage: ''
}
],
ok: 1
}
Full healthy machine `rs.status()`:
{
set: 'rs0',
date: ISODate('2025-10-01T09:22:03.318Z'),
myState: 1,
term: Long('1'),
syncSourceHost: '',
syncSourceId: -1,
heartbeatIntervalMillis: Long('2000'),
majorityVoteCount: 1,
writeMajorityCount: 1,
votingMembersCount: 1,
writableVotingMembersCount: 1,
optimes: {
lastCommittedOpTime: {
ts: Timestamp({ t: 1759310522, i: 6 }),
t: Long('1')
},
lastCommittedWallTime: ISODate('2025-10-01T09:22:02.077Z'),
readConcernMajorityOpTime: {
ts: Timestamp({ t: 1759310522, i: 6 }),
t: Long('1')
},
appliedOpTime: {
ts: Timestamp({ t: 1759310522, i: 6 }),
t: Long('1')
},
durableOpTime: {
ts: Timestamp({ t: 1759310522, i: 6 }),
t: Long('1')
},
lastAppliedWallTime: ISODate('2025-10-01T09:22:02.077Z'),
lastDurableWallTime: ISODate('2025-10-01T09:22:02.077Z')
},
lastStableRecoveryTimestamp: Timestamp({ t: 1759310521, i: 1 }),
electionCandidateMetrics: {
lastElectionReason: 'electionTimeout',
lastElectionDate: ISODate('2025-10-01T09:22:01.920Z'),
electionTerm: Long('1'),
lastCommittedOpTimeAtElection: {
ts: Timestamp({ t: 1759310521, i: 1 }),
t: Long('-1')
},
lastSeenOpTimeAtElection: {
ts: Timestamp({ t: 1759310521, i: 1 }),
t: Long('-1')
},
numVotesNeeded: 1,
priorityAtElection: 1,
electionTimeoutMillis: Long('10000'),
newTermStartDate: ISODate('2025-10-01T09:22:01.967Z'),
wMajorityWriteAvailabilityDate: ISODate('2025-10-01T09:22:01.997Z')
},
members: [
{
_id: 0,
name: '127.0.0.1:27017',
health: 1,
state: 1,
stateStr: 'PRIMARY',
uptime: 3,
optime: {
ts: Timestamp({ t: 1759310522, i: 6 }),
t: Long('1')
},
optimeDate: ISODate('2025-10-01T09:22:02.000Z'),
lastAppliedWallTime: ISODate('2025-10-01T09:22:02.077Z'),
lastDurableWallTime: ISODate('2025-10-01T09:22:02.077Z'),
syncSourceHost: '',
syncSourceId: -1,
infoMessage: 'Could not find member to sync from',
electionTime: Timestamp({ t: 1759310521, i: 2 }),
electionDate: ISODate('2025-10-01T09:22:01.000Z'),
configVersion: 1,
configTerm: 1,
self: true,
lastHeartbeatMessage: ''
}
],
ok: 1,
'$clusterTime': {
clusterTime: Timestamp({ t: 1759310522, i: 6 }),
signature: {
hash: Binary.createFromBase64('ulkQyvMEI5PWBMOIcAvV2EdPvec=', 0),
keyId: Long('7556181151203721222')
}
},
operationTime: Timestamp({ t: 1759310522, i: 6 })
}Additional information
No response
Testcontainers version
4.3.0
Using the latest Testcontainers version?
No
Host OS
Linux
Host arch
x86
.NET version
.NET 8
Docker version
Client: Version: 27.2.0 API version: 1.47 Go version: go1.21.13 Git commit: 3ab4256 Built: Tue Aug 27 14:17:17 2024 OS/Arch: windows/amd64 Context: desktop-linux Server: Docker Desktop 4.34.2 (167172) Engine: Version: 27.2.0 API version: 1.47 (minimum version 1.24) Go version: go1.21.13 Git commit: 3ab5c7d Built: Tue Aug 27 14:15:15 2024 OS/Arch: linux/amd64 Experimental: false containerd: Version: 1.7.20 GitCommit: 8fc6bcff51318944179630522a095cc9dbf9f353 runc: Version: 1.1.13 GitCommit: v1.1.13-0-g58aa920 docker-init: Version: 0.19.0 GitCommit: de40ad0Docker info
What happened?
Hi, I would like to re-open the #1284
We did a great job on fixing connection to replica set. And it worked for some long time to me. But I've found that
MongoDB.Driver.MongoNotPrimaryException : Server returned not primary error.did not disappear, it just started to appear much more randomly and in more rare cases. Moreover, due to unknown reasons, this problem started to appear more often to me. May be my Linux machine became more overloaded, idk.Nothing got changed in my repro environment, so, you can read the old issue for some details. I think that just checking
rs.status().okis still not enough for the mongodb to treat it as ready to accept queries. Pretty sure we got into some kind of concurrency here, whenrs.status()is already ok, but cluster is not ready in fact in time window recent after replica set status changed.I've come with solution that, as I think, should solve the issue with no-primary error completely.
In order to identify that rare bug I've injected some diagnostic logs that can show the replica status on the machine where the issue appears during wait strategy execution.
I have: 1 Windows machine where tests run fine; 1 Linux machine where tests are fail.
On both machines I did a print-out of
rs.status()and compared them via KDiff. I've found few valuable differences.1st difference is that healthy machine has
electionCandidateMetrics.newTermStartDateset, while unhealthy machine is not:Term is mongodb autoincrement value that is changed after the primary node becomes valid. For a fresh mongodb server this value will very kindly be equal to
1, and it can be seen in thers.conf()output. So, checking the start date of atermrefresh seems valuable.2nd difference is that healthy machine has
$clusterTimeobject while unhealthy machine is not:So, I ended up with custom wait strategy for the TC container:
After applying this script, all tests ran fine on both machines. As for now, I see that problem has disappeared. Much hope for ever.
Note: as the wait strategy script got more complexity, may be, we could also add some
max-retriesoption to the wait strategy. Otherwise, strategy script may run for ever.I would be glad if you review the suggested strategy script and replace the old one.
Relevant log output
Additional information
No response