Replica set down after issues in Brindisi datacenter

Title

Status

Due

Scheduled

Context

Project

Category

Notes Saved

## 31 Mar 2026

## Report

# MongoDB Troubleshooting Report

**Date:** 2026-03-31
**Environment:** CommsNet Production — Replica Set `rs0`
**Reported Issue:** Application timeouts / slow queries on MongoDB

***

## 1\. Initial Symptoms

Application teams reported write timeouts and slow query responses. No immediate cause was apparent from the application side.

***

## 2\. Log Analysis

### 2.1 First Indicator — Flow Control Warning

The first meaningful signal in the MongoDB logs was the only `WARNING` level entry in the entire log set:

```
{"t":"2026-03-31T12:54:26.675Z","s":"W","c":"STORAGE","id":22225,
"ctx":"FlowControlRefresher",
"msg":"Flow control is engaged and the sustainer point is not moving. 
Please check the health of all secondaries."}
```

MongoDB's flow control mechanism throttles writes on the primary when secondaries fall behind in replication. The phrase *"sustainer point is not moving"* indicates a complete stall, not just lag.

### 2.2 Second Indicator — Slow Queries Caused by Flow Control

Two slow queries were logged. In both cases, nearly 100% of the query duration was spent waiting for a flow control token — not performing actual work:

| Collection | Total Duration | Flow Control Wait | Root Cause |
| ---------- | -------------- | ----------------- | ---------- |
| `config.system.sessions` | 973ms | 982ms | Flow control throttle |
| `CommsNet.NotificationStatus` | 530ms | 531ms | Flow control throttle |

Example from logs:

```
{"c":"WRITE","msg":"Slow query","attr":{
  "ns":"CommsNet.NotificationStatus",
  "durationMillis":530,
  "flowControl":{"acquireWaitCount":1,"timeAcquiringMicros":531000}
}}
```

This ruled out bad query plans or missing indexes as the primary cause. The bottleneck was replication.

### 2.3 Third Indicator — `comms-p-db-01` Unreachable

The log was flooded with repeating errors every \~500ms:

```
HostUnreachable: Error connecting to comms-p-db-01.global.un.org:27017 (10.130.244.54:27017)
:: caused by :: Connection refused
```

Replication heartbeats were also failing:

```
"Heartbeat failed after max retries" — target: comms-p-db-01
```

The Replica Set Monitor switched to expedited mode attempting to locate a primary across all 5 members.

***

## 3\. Replica Set Status Analysis

`rs.status()` was run twice, approximately 5 minutes apart, confirming the issue was not self-resolving.

### 3.1 Member States

| Member | State | Last Optime |
| ------ | ----- | ----------- |
| `comms-p-db-01` | ❌ DOWN (state 8) | `1970-01-01` (zeroed) |
| `comms-p-db-02` | ⚠️ RECOVERING | `2026-03-28T03:05:09` (3.5 days behind) |
| `comms-p-db-03` | ✅ PRIMARY | Current |
| `comms-p-db-04` | ✅ SECONDARY | Current (0 lag) |
| `vsys-p-srv-001` | ✅ ARBITER | n/a |

### 3.2 Frozen `lastCommittedOpTime` — The Core Problem

The definitive proof of the majority write blockage was found in the `optimes` block:

```
lastCommittedOpTime:  2026-03-31T12:03:39  ← frozen since db-01 went down
appliedOpTime:        2026-03-31T12:46:37  ← ~43 minutes ahead and growing
```

This field did **not move** across both `rs.status()` calls. Writes were being applied on db-03 and db-04 but could never reach majority acknowledgment.

### 3.3 Why Majority Was Unreachable

The replica set requires `writeMajorityCount: 3` out of 4 writable data members. With db-01 down and db-02 in RECOVERING state, only 2 healthy data nodes existed — one short of the required majority. The arbiter cannot contribute to write majority by design.

***

## 4\. Root Cause Chain

```
comms-p-db-01 went down at ~12:03 UTC
        ↓
db-02 (already 3.5 days behind, tooStale) had no sync source
        ↓
Only db-03 + db-04 healthy = 2 of 3 required write majority nodes
        ↓
lastCommittedOpTime frozen — no write could be majority-acknowledged
        ↓
Flow control engaged on primary — all writes throttled
        ↓
Application timeouts
```

***

## 5\. db\-02 Deep Dive

Connecting directly to db-02 and running `rs.status()` revealed:

```
"tooStale": true,
"maintenanceMode": 1,
"syncSourceHost": ""
```

* `tooStale: true` — db-02 had fallen completely off the primary's oplog. Its last optime was March 28; the primary's oplog no longer contained entries that old.
* `maintenanceMode: 1` — MongoDB automatically placed itself in maintenance mode.
* `syncSourceHost: ""` — not syncing from anyone; no recovery possible incrementally.

**Conclusion:** Initial sync (full data copy) was the only viable recovery path.

***

## 6\. Recovery Steps

### Step 1 — Initiate Initial Sync on db-02

```
# Stop mongod
sudo systemctl stop mongod

# Confirm data path
grep dbPath /etc/mongod.conf

# Wipe data directory
sudo rm -rf /var/lib/mongodb/*

# Fix ownership
sudo chown -R mongod:mongod /var/lib/mongodb

# Start mongod — initial sync triggers automatically
sudo systemctl start mongod

### Step 2 — Monitor from Primary (db-03)

```
rs.printSecondaryReplicationInfo()
```

db-02 showed `syncedTo: 1970-01-01` during data copy phase (expected — no oplog entries applied yet), then transitioned to `STARTUP2` state as collections were cloned.

### Step 3 — Outcome

db-02 completed initial sync and triggered a **priority takeover election** (term 442), becoming the new primary at `13:16:18 UTC`. This is expected behavior — db-02 has higher priority than db-03.
Final state after recovery:

| Member | State | Lag |
| ------ | ----- | --- |
| `comms-p-db-01` | ❌ Still DOWN | — |
| `comms-p-db-02` | ✅ PRIMARY | current |
| `comms-p-db-03` | ✅ SECONDARY | \~0 secs |
| `comms-p-db-04` | ✅ SECONDARY | \~1 sec |
| `vsys-p-srv-001` | ✅ ARBITER | n/a |

`lastCommittedOpTime` unfroze immediately and flow control disengaged automatically.

***

## 7\. Secondary Finding — Missing Index

A full collection scan (`COLLSCAN`) was observed on `CommsNet.NotificationStatus`:

```
"planSummary": "COLLSCAN",
"ns": "CommsNet.NotificationStatus",
"command": {"q": {"module": "trb_crawler", "host": "comms-p-api-01.global.un.org"}}
```

**Recommended fix:**

```
db.NotificationStatus.createIndex({ module: 1, host: 1 })
```

This does not affect the main incident but will improve query performance once flow control is resolved.

***

## 8\. Remaining Actions

* Investigate and recover `comms-p-db-01` (still down as of end of incident)
* Increase oplog size on all nodes (see Architecture Report)
* Review and adjust member priorities if db-03 is the intended permanent primary
* Add missing index on `CommsNet.NotificationStatus`

***

*Report generated: 2026\-03\-31 \| Author: Operations Team*

Supports Markdown: bold, italics, code, lists, links. Auto-saves.

AI Notes - managed by Claude

No AI notes yet.

📂 Activities for this Item

➕ Add Activity

Open Activities

No open activities.

Closed Activities

Synced from Mission Control

Service Requests / Work Orders

IM-1-12846442970

Service Request

WO-IM-1-12846744171

Normalized time tracking

Last 30 days

Logged: 0:00 · Normalized: 0:00

No normalized entries for this item yet.

Meeting Notes (Project / Context)

Select a meeting to preview details.

iNeed Text

Title

Description

CommsNet - Replica set down after issues in Brindisi datacenter
Assign to Carlos Rodrigo - AOM DS

Asset#

Defined per context on the Taxonomy page.

Templates

Change Title

Change Description

Change Steps

Template Notes

Communications

Label

Order

Subject

Email Body

Attachments

No attachments yet.