User Asserts on Replica Set running on Kubernetes

I have setup a 3 node Replica Set within Kubernetes. I noticed there was a very high number of User Asserts and I’ve listed them about below from the logs after raising the log level to 5.

On the Primary they seem to be : "error": "NotWritablePrimary: Transaction coordinator is not a primary",

On the Secondary’s they seem to be : "error": "HostUnreachable: Connection closed by peer",

and then on all of them Internal assertion : "errmsg": "operation exceeded time limit"


repository: bitnami/mongodb
tag: 5.0.7-debian-10-r5

rs0:PRIMARY> db.serverStatus().asserts
{
        "regular" : 0,
        "warning" : 0,
        "msg" : 0,
        "user" : 8628,
        "tripwire" : 0,
        "rollovers" : 0
}

rs0:SECONDARY> db.serverStatus().asserts
{
        "regular" : 0,
        "warning" : 0,
        "msg" : 0,
        "user" : 4999,
        "tripwire" : 0,
        "rollovers" : 0
}

rs0:SECONDARY> db.serverStatus().asserts
{
        "regular" : 0,
        "warning" : 0,
        "msg" : 0,
        "user" : 4995,
        "tripwire" : 0,
        "rollovers" : 0
}

db.setLogLevel(5)

rs0:PRIMARY> rs.status()
{
        "set" : "rs0",
        "date" : ISODate("2022-05-09T13:25:57.985Z"),
        "myState" : 1,
        "term" : NumberLong(2),
        "syncSourceHost" : "",
        "syncSourceId" : -1,
        "heartbeatIntervalMillis" : NumberLong(2000),
        "majorityVoteCount" : 2,
        "writeMajorityCount" : 2,
        "votingMembersCount" : 3,
        "writableVotingMembersCount" : 3,
        "optimes" : {
                "lastCommittedOpTime" : {
                        "ts" : Timestamp(1652102749, 1),
                        "t" : NumberLong(2)
                },
                "lastCommittedWallTime" : ISODate("2022-05-09T13:25:49.210Z"),
                "readConcernMajorityOpTime" : {
                        "ts" : Timestamp(1652102749, 1),
                        "t" : NumberLong(2)
                },
                "appliedOpTime" : {
                        "ts" : Timestamp(1652102749, 1),
                        "t" : NumberLong(2)
                },
                "durableOpTime" : {
                        "ts" : Timestamp(1652102749, 1),
                        "t" : NumberLong(2)
                },
                "lastAppliedWallTime" : ISODate("2022-05-09T13:25:49.210Z"),
                "lastDurableWallTime" : ISODate("2022-05-09T13:25:49.210Z")
        },
        "lastStableRecoveryTimestamp" : Timestamp(1652102708, 4),
        "electionCandidateMetrics" : {
                "lastElectionReason" : "electionTimeout",
                "lastElectionDate" : ISODate("2022-05-09T09:40:08.666Z"),
                "electionTerm" : NumberLong(2),
                "lastCommittedOpTimeAtElection" : {
                        "ts" : Timestamp(0, 0),
                        "t" : NumberLong(-1)
                },
                "lastSeenOpTimeAtElection" : {
                        "ts" : Timestamp(1652089206, 1),
                        "t" : NumberLong(1)
                },
                "numVotesNeeded" : 1,
                "priorityAtElection" : 5,
                "electionTimeoutMillis" : NumberLong(10000),
                "newTermStartDate" : ISODate("2022-05-09T09:40:08.668Z"),
                "wMajorityWriteAvailabilityDate" : ISODate("2022-05-09T09:40:08.670Z")
        },
        "members" : [
                {
                        "_id" : 0,
                        "name" : "mongodb-0.mongodb-headless.mongodb.svc.cluster.local:27017",
                        "health" : 1,
                        "state" : 1,
                        "stateStr" : "PRIMARY",
                        "uptime" : 13549,
                        "optime" : {
                                "ts" : Timestamp(1652102749, 1),
                                "t" : NumberLong(2)
                        },
                        "optimeDate" : ISODate("2022-05-09T13:25:49Z"),
                        "lastAppliedWallTime" : ISODate("2022-05-09T13:25:49.210Z"),
                        "lastDurableWallTime" : ISODate("2022-05-09T13:25:49.210Z"),
                        "syncSourceHost" : "",
                        "syncSourceId" : -1,
                        "infoMessage" : "",
                        "electionTime" : Timestamp(1652089208, 1),
                        "electionDate" : ISODate("2022-05-09T09:40:08Z"),
                        "configVersion" : 7,
                        "configTerm" : 2,
                        "self" : true,
                        "lastHeartbeatMessage" : ""
                },
                {
                        "_id" : 1,
                        "name" : "mongodb-1.mongodb-headless.mongodb.svc.cluster.local:27017",
                        "health" : 1,
                        "state" : 2,
                        "stateStr" : "SECONDARY",
                        "uptime" : 13501,
                        "optime" : {
                                "ts" : Timestamp(1652102749, 1),
                                "t" : NumberLong(2)
                        },
                        "optimeDurable" : {
                                "ts" : Timestamp(1652102749, 1),
                                "t" : NumberLong(2)
                        },
                        "optimeDate" : ISODate("2022-05-09T13:25:49Z"),
                        "optimeDurableDate" : ISODate("2022-05-09T13:25:49Z"),
                        "lastAppliedWallTime" : ISODate("2022-05-09T13:25:49.210Z"),
                        "lastDurableWallTime" : ISODate("2022-05-09T13:25:49.210Z"),
                        "lastHeartbeat" : ISODate("2022-05-09T13:25:57.796Z"),
                        "lastHeartbeatRecv" : ISODate("2022-05-09T13:25:56.955Z"),
                        "pingMs" : NumberLong(0),
                        "lastHeartbeatMessage" : "",
                        "syncSourceHost" : "mongodb-0.mongodb-headless.mongodb.svc.cluster.local:27017",
                        "syncSourceId" : 0,
                        "infoMessage" : "",
                        "configVersion" : 7,
                        "configTerm" : 2
                },
                {
                        "_id" : 2,
                        "name" : "mongodb-2.mongodb-headless.mongodb.svc.cluster.local:27017",
                        "health" : 1,
                        "state" : 2,
                        "stateStr" : "SECONDARY",
                        "uptime" : 13489,
                        "optime" : {
                                "ts" : Timestamp(1652102749, 1),
                                "t" : NumberLong(2)
                        },
                        "optimeDurable" : {
                                "ts" : Timestamp(1652102749, 1),
                                "t" : NumberLong(2)
                        },
                        "optimeDate" : ISODate("2022-05-09T13:25:49Z"),
                        "optimeDurableDate" : ISODate("2022-05-09T13:25:49Z"),
                        "lastAppliedWallTime" : ISODate("2022-05-09T13:25:49.210Z"),
                        "lastDurableWallTime" : ISODate("2022-05-09T13:25:49.210Z"),
                        "lastHeartbeat" : ISODate("2022-05-09T13:25:57.347Z"),
                        "lastHeartbeatRecv" : ISODate("2022-05-09T13:25:56.084Z"),
                        "pingMs" : NumberLong(0),
                        "lastHeartbeatMessage" : "",
                        "syncSourceHost" : "mongodb-1.mongodb-headless.mongodb.svc.cluster.local:27017",
                        "syncSourceId" : 1,
                        "infoMessage" : "",
                        "configVersion" : 7,
                        "configTerm" : 2
                }
        ],
        "ok" : 1,
        "$clusterTime" : {
                "clusterTime" : Timestamp(1652102749, 1),
                "signature" : {
                        "hash" : BinData(0,"RWRwa4dwXKGCqa4L4iyqbRg1dIw="),
                        "keyId" : NumberLong("7095669105549639685")
                }
        },
        "operationTime" : Timestamp(1652102749, 1)
}

mongodb-0

{
  "t": {
    "$date": "2022-05-09T19:14:04.032+00:00"
  },
  "s": "D1",
  "c": "-",
  "id": 23074,
  "ctx": "conn5219",
  "msg": "User assertion",
  "attr": {
    "error": "NotWritablePrimary: Transaction coordinator is not a primary",
    "file": "src/mongo/db/s/transaction_coordinator_service.cpp",
    "line": 286
  }
}

{
  "t": {
    "$date": "2022-05-09T19:14:02.864+00:00"
  },
  "s": "D3",
  "c": "-",
  "id": 4892201,
  "ctx": "conn3436",
  "msg": "Internal assertion",
  "attr": {
    "error": {
      "code": 262,
      "codeName": "ExceededTimeLimit",
      "errmsg": "operation exceeded time limit"
    },
    "location": "{fileName:\"src/mongo/util/interruptible.h\", line:395, functionName:\"operator()\"}"
  }
}

mongodb-1

{
  "t": {
    "$date": "2022-05-09T19:19:16.329+00:00"
  },
  "s": "D3",
  "c": "-",
  "id": 4892201,
  "ctx": "conn8",
  "msg": "Internal assertion",
  "attr": {
    "error": {
      "code": 262,
      "codeName": "ExceededTimeLimit",
      "errmsg": "operation exceeded time limit"
    },
    "location": "{fileName:\"src/mongo/util/interruptible.h\", line:395, functionName:\"operator()\"}"
  }
}

{
  "t": {
    "$date": "2022-05-09T19:19:09.603+00:00"
  },
  "s": "D1",
  "c": "-",
  "id": 23074,
  "ctx": "conn7151",
  "msg": "User assertion",
  "attr": {
    "error": "HostUnreachable: Connection closed by peer",
    "file": "src/mongo/transport/service_state_machine.cpp",
    "line": 536
  }
}

mongodb-2

{
  "t": {
    "$date": "2022-05-09T19:21:31.468+00:00"
  },
  "s": "D1",
  "c": "-",
  "id": 23074,
  "ctx": "conn7137",
  "msg": "User assertion",
  "attr": {
    "error": "HostUnreachable: Connection closed by peer",
    "file": "src/mongo/transport/service_state_machine.cpp",
    "line": 536
  }
}

{
  "t": {
    "$date": "2022-05-09T19:21:31.468+00:00"
  },
  "s": "D2",
  "c": "NETWORK",
  "id": 22986,
  "ctx": "conn7137",
  "msg": "Session from remote encountered a network error during SourceMessage",
  "attr": {
    "remote": "127.0.0.1:50380",
    "error": {
      "code": 6,
      "codeName": "HostUnreachable",
      "errmsg": "Connection closed by peer"
    }
  }
}

Hi @Tim_Pynegar

Log level 5 is the maximum verbosity level, so it will include a lot of information that could help with debugging a specific issue. The user assertions you posted doesn’t seem like they’re interfering with normal operations. For example, HostUnreachable: Connection closed by peer would mean that a connection was closed unexpectedly by a client, operation exceeded time limit is something hitting a timeout, etc.

I don’t believe that those messages means that anything is wrong with your deployment. However, if you set the log level back to 0 and resume your normal operations, are you seeing any issues?

Best regards
Kevin

1 Like