Mongos router not opening a port

R_Birtles · April 30, 2022, 2:34pm

Hi,

I have been following this guide.

I am using Debian 11 with MongoDB v5.0.8. I was working over the Configure Query Router section, however, I am stuck as mongos doesn’t seem to open a port for communication.

Checking for the open port I get no results:

user@mongos:~$ ss -antpl | grep 27017
user@mongos:~$

I can see the process is running:

user@mongos:~$ ps aux|grep mongos
root        1797  0.0  0.1  10592  5068 pts/0    S+   15:26   0:00 sudo -u mongodb mongos --config /etc/mongod.conf
mongodb     1798  0.0  1.2 202976 49704 pts/0    Sl+  15:26   0:00 mongos --config /etc/mongod.conf
user        2021  0.0  0.0   6180   708 pts/1    S+   15:29   0:00 grep mongos

My config is binding to port 27017:

user@mongos:~$ cat /etc/mongod.conf
# mongod.conf

# for documentation of all options, see:
#   http://docs.mongodb.org/manual/reference/configuration-options/

# Where and how to store data.
#storage:
#  dbPath: /var/lib/mongodb
#  journal:
#    enabled: true
#  engine:
#  wiredTiger:

# where to write logging data.
systemLog:
  destination: file
  logAppend: true
  path: /var/log/mongodb/mongod.log

# network interfaces
net:
  port: 27017
  bindIp: 192.168.0.40


# how the process runs
processManagement:
  timeZoneInfo: /usr/share/zoneinfo

#security:

#operationProfiling:

#replication:

sharding:
  configDB: ConfigReplSet/192.168.0.37:27019

## Enterprise-Only Options:

#auditLog:

#snmp:

I can also see that the request to the config server is coming through without any issues:

{"t":{"$date":"2022-04-30T15:32:37.374+01:00"},"s":"I",  "c":"NETWORK",  "id":22943,   "ctx":"listener","msg":"Connection accepted","attr":{"remote":"192.168.0.40:52142","uuid":"5d1c094a-301d-413d-861d-5aed5f9b7a13","connectionId":8,"connectionCount":1}}
{"t":{"$date":"2022-04-30T15:32:37.375+01:00"},"s":"I",  "c":"NETWORK",  "id":22943,   "ctx":"listener","msg":"Connection accepted","attr":{"remote":"192.168.0.40:52144","uuid":"05e26a1a-60b5-4315-ad88-cffe0ffd221c","connectionId":9,"connectionCount":2}}
{"t":{"$date":"2022-04-30T15:32:37.375+01:00"},"s":"I",  "c":"NETWORK",  "id":51800,   "ctx":"conn8","msg":"client metadata","attr":{"remote":"192.168.0.40:52142","client":"conn8","doc":{"driver":{"name":"NetworkInterfaceTL","version":"5.0.8"},"os":{"type":"Linux","name":"PRETTY_NAME=\"Debian GNU/Linux 11 (bullseye)\"","architecture":"x86_64","version":"Kernel 5.10.0-13-amd64"}}}}
{"t":{"$date":"2022-04-30T15:32:37.376+01:00"},"s":"I",  "c":"NETWORK",  "id":51800,   "ctx":"conn9","msg":"client metadata","attr":{"remote":"192.168.0.40:52144","client":"conn9","doc":{"driver":{"name":"NetworkInterfaceTL","version":"5.0.8"},"os":{"type":"Linux","name":"PRETTY_NAME=\"Debian GNU/Linux 11 (bullseye)\"","architecture":"x86_64","version":"Kernel 5.10.0-13-amd64"}}}}
{"t":{"$date":"2022-04-30T15:32:37.377+01:00"},"s":"I",  "c":"NETWORK",  "id":22943,   "ctx":"listener","msg":"Connection accepted","attr":{"remote":"192.168.0.40:52146","uuid":"f0bbbae7-8d6b-4ea3-9867-48d634bf67d1","connectionId":10,"connectionCount":3}}
{"t":{"$date":"2022-04-30T15:32:37.378+01:00"},"s":"I",  "c":"NETWORK",  "id":51800,   "ctx":"conn10","msg":"client metadata","attr":{"remote":"192.168.0.40:52146","client":"conn10","doc":{"driver":{"name":"NetworkInterfaceTL","version":"5.0.8"},"os":{"type":"Linux","name":"PRETTY_NAME=\"Debian GNU/Linux 11 (bullseye)\"","architecture":"x86_64","version":"Kernel 5.10.0-13-amd64"}}}}

Can anyone see any daft mistakes I have made or have advise on how I can get this working?

steevej · April 30, 2022, 3:37pm

The clues to what is happening can probably find in the mongos log. Please share the mongos log.

R_Birtles · April 30, 2022, 4:00pm

The systemd entry for mongodb has been edited to start mongos:

ExecStart=/usr/bin/mongos --config /etc/mongod.conf

Here are the logs from a fresh restart:

user@mongos:~$ sudo systemctl restart mongod && sudo tail -f -n 0 /var/log/mongodb/mongod.log

{"t":{"$date":"2022-04-30T16:54:48.395+01:00"},"s":"I",  "c":"CONTROL",  "id":20698,   "ctx":"-","msg":"***** SERVER RESTARTED *****"}
{"t":{"$date":"2022-04-30T16:54:48.395+01: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":13,"maxWireVersion":13},"isInternalClient":true}}}
{"t":{"$date":"2022-04-30T16:54:48.401+01:00"},"s":"I",  "c":"CONTROL",  "id":23285,   "ctx":"main","msg":"Automatically disabling TLS 1.0, to force-enable TLS 1.0 specify --sslDisabledProtocols 'none'"}
{"t":{"$date":"2022-04-30T16:54:48.427+01:00"},"s":"W",  "c":"ASIO",     "id":22601,   "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"}
{"t":{"$date":"2022-04-30T16:54:48.428+01: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":"2022-04-30T16:54:48.428+01:00"},"s":"I",  "c":"HEALTH",   "id":5936503, "ctx":"main","msg":"Fault manager changed state ","attr":{"state":"StartupCheck"}}
{"t":{"$date":"2022-04-30T16:54:48.428+01:00"},"s":"W",  "c":"CONTROL",  "id":22120,   "ctx":"main","msg":"Access control is not enabled for the database. Read and write access to data and configuration is unrestricted","tags":["startupWarnings"]}
{"t":{"$date":"2022-04-30T16:54:48.429+01:00"},"s":"I",  "c":"CONTROL",  "id":23403,   "ctx":"mongosMain","msg":"Build Info","attr":{"buildInfo":{"version":"5.0.8","gitVersion":"c87e1c23421bf79614baf500fda6622bd90f674e","openSSLVersion":"OpenSSL 1.1.1n  15 Mar 2022","modules":[],"allocator":"tcmalloc","environment":{"distmod":"debian10","distarch":"x86_64","target_arch":"x86_64"}}}}
{"t":{"$date":"2022-04-30T16:54:48.429+01:00"},"s":"I",  "c":"CONTROL",  "id":51765,   "ctx":"mongosMain","msg":"Operating System","attr":{"os":{"name":"PRETTY_NAME=\"Debian GNU/Linux 11 (bullseye)\"","version":"Kernel 5.10.0-13-amd64"}}}
{"t":{"$date":"2022-04-30T16:54:48.430+01:00"},"s":"I",  "c":"CONTROL",  "id":21951,   "ctx":"mongosMain","msg":"Options set by command line","attr":{"options":{"config":"/etc/mongod.conf","net":{"bindIp":"192.168.0.40","port":27017},"processManagement":{"timeZoneInfo":"/usr/share/zoneinfo"},"sharding":{"configDB":"ConfigReplSet/192.168.0.37:27019"},"systemLog":{"destination":"file","logAppend":true,"path":"/var/log/mongodb/mongod.log"}}}}
{"t":{"$date":"2022-04-30T16:54:48.432+01:00"},"s":"I",  "c":"NETWORK",  "id":4603701, "ctx":"mongosMain","msg":"Starting Replica Set Monitor","attr":{"protocol":"streamable","uri":"ConfigReplSet/192.168.0.37:27019"}}
{"t":{"$date":"2022-04-30T16:54:48.433+01:00"},"s":"I",  "c":"-",        "id":4333223, "ctx":"mongosMain","msg":"RSM now monitoring replica set","attr":{"replicaSet":"ConfigReplSet","nReplicaSetMembers":1}}
{"t":{"$date":"2022-04-30T16:54:48.433+01:00"},"s":"I",  "c":"-",        "id":4333226, "ctx":"mongosMain","msg":"RSM host was added to the topology","attr":{"replicaSet":"ConfigReplSet","host":"192.168.0.37:27019"}}
{"t":{"$date":"2022-04-30T16:54:48.433+01:00"},"s":"I",  "c":"-",        "id":4333218, "ctx":"mongosMain","msg":"Rescheduling the next replica set monitoring request","attr":{"replicaSet":"ConfigReplSet","host":"192.168.0.37:27019","delayMillis":0}}
{"t":{"$date":"2022-04-30T16:54:48.434+01:00"},"s":"I",  "c":"-",        "id":4333218, "ctx":"monitoring-keys-for-HMAC","msg":"Rescheduling the next replica set monitoring request","attr":{"replicaSet":"ConfigReplSet","host":"192.168.0.37:27019","delayMillis":0}}
{"t":{"$date":"2022-04-30T16:54:48.434+01:00"},"s":"I",  "c":"-",        "id":4333218, "ctx":"ShardRegistry-0","msg":"Rescheduling the next replica set monitoring request","attr":{"replicaSet":"ConfigReplSet","host":"192.168.0.37:27019","delayMillis":0}}
{"t":{"$date":"2022-04-30T16:54:48.434+01:00"},"s":"I",  "c":"CONNPOOL", "id":22576,   "ctx":"ReplicaSetMonitor-TaskExecutor","msg":"Connecting","attr":{"hostAndPort":"192.168.0.37:27019"}}
{"t":{"$date":"2022-04-30T16:54:48.438+01:00"},"s":"I",  "c":"NETWORK",  "id":23729,   "ctx":"ReplicaSetMonitor-TaskExecutor","msg":"ServerPingMonitor is now monitoring host","attr":{"host":"192.168.0.37:27019","replicaSet":"ConfigReplSet"}}
{"t":{"$date":"2022-04-30T16:54:48.438+01:00"},"s":"I",  "c":"NETWORK",  "id":4333213, "ctx":"ReplicaSetMonitor-TaskExecutor","msg":"RSM Topology Change","attr":{"replicaSet":"ConfigReplSet","newTopologyDescription":"{ id: \"84167836-da59-42e0-b108-b7ebd0a61a57\", topologyType: \"Unknown\", servers: { 192.168.0.37:27019: { address: \"192.168.0.37:27019\", topologyVersion: { processId: ObjectId('626d433d45649ad8597be78c'), counter: 1 }, roundTripTime: 1646, type: \"RSGhost\", minWireVersion: 13, maxWireVersion: 13, lastUpdateTime: new Date(1651334088438), logicalSessionTimeoutMinutes: 30, hosts: {}, arbiters: {}, passives: {} } }, compatible: true }","previousTopologyDescription":"{ id: \"cd1e7cf4-4182-4681-90ee-9098ce49a63f\", topologyType: \"Unknown\", servers: { 192.168.0.37:27019: { address: \"192.168.0.37:27019\", type: \"Unknown\", minWireVersion: 0, maxWireVersion: 0, lastUpdateTime: new Date(-9223372036854775808), hosts: {}, arbiters: {}, passives: {} } }, compatible: true }"}}
{"t":{"$date":"2022-04-30T16:55:03.433+01:00"},"s":"I",  "c":"NETWORK",  "id":4333208, "ctx":"ReplicaSetMonitor-TaskExecutor","msg":"RSM host selection timeout","attr":{"replicaSet":"ConfigReplSet","error":"FailedToSatisfyReadPreference: Could not find host matching read preference { mode: \"nearest\" } for set ConfigReplSet"}}
{"t":{"$date":"2022-04-30T16:55:03.433+01:00"},"s":"W",  "c":"SHARDING", "id":23834,   "ctx":"mongosMain","msg":"Error initializing sharding state, sleeping for 2 seconds and retrying","attr":{"error":{"code":133,"codeName":"FailedToSatisfyReadPreference","errmsg":"Error loading clusterID :: caused by :: Could not find host matching read preference { mode: \"nearest\" } for set ConfigReplSet"}}}
{"t":{"$date":"2022-04-30T16:55:03.434+01:00"},"s":"I",  "c":"NETWORK",  "id":4333208, "ctx":"ReplicaSetMonitor-TaskExecutor","msg":"RSM host selection timeout","attr":{"replicaSet":"ConfigReplSet","error":"FailedToSatisfyReadPreference: Could not find host matching read preference { mode: \"nearest\" } for set ConfigReplSet"}}
{"t":{"$date":"2022-04-30T16:55:03.434+01:00"},"s":"I",  "c":"NETWORK",  "id":4333208, "ctx":"ReplicaSetMonitor-TaskExecutor","msg":"RSM host selection timeout","attr":{"replicaSet":"ConfigReplSet","error":"FailedToSatisfyReadPreference: Could not find host matching read preference { mode: \"nearest\" } for set ConfigReplSet"}}
{"t":{"$date":"2022-04-30T16:55:03.434+01:00"},"s":"I",  "c":"-",        "id":4939300, "ctx":"monitoring-keys-for-HMAC","msg":"Failed to refresh key cache","attr":{"error":"FailedToSatisfyReadPreference: Could not find host matching read preference { mode: \"nearest\" } for set ConfigReplSet","nextWakeupMillis":200}}
{"t":{"$date":"2022-04-30T16:55:03.435+01:00"},"s":"I",  "c":"SHARDING", "id":22727,   "ctx":"shard-registry-reload","msg":"Error running periodic reload of shard registry","attr":{"error":"FailedToSatisfyReadPreference: could not get updated shard list from config server :: caused by :: Could not find host matching read preference { mode: \"nearest\" } for set ConfigReplSet","shardRegistryReloadIntervalSeconds":30}}
{"t":{"$date":"2022-04-30T16:55:18.635+01:00"},"s":"I",  "c":"NETWORK",  "id":4333208, "ctx":"ReplicaSetMonitor-TaskExecutor","msg":"RSM host selection timeout","attr":{"replicaSet":"ConfigReplSet","error":"FailedToSatisfyReadPreference: Could not find host matching read preference { mode: \"nearest\" } for set ConfigReplSet"}}
{"t":{"$date":"2022-04-30T16:55:18.635+01:00"},"s":"I",  "c":"-",        "id":4939300, "ctx":"monitoring-keys-for-HMAC","msg":"Failed to refresh key cache","attr":{"error":"FailedToSatisfyReadPreference: Could not find host matching read preference { mode: \"nearest\" } for set ConfigReplSet","nextWakeupMillis":400}}
{"t":{"$date":"2022-04-30T16:55:20.433+01:00"},"s":"I",  "c":"NETWORK",  "id":4333208, "ctx":"ReplicaSetMonitor-TaskExecutor","msg":"RSM host selection timeout","attr":{"replicaSet":"ConfigReplSet","error":"FailedToSatisfyReadPreference: Could not find host matching read preference { mode: \"nearest\" } for set ConfigReplSet"}}
{"t":{"$date":"2022-04-30T16:55:20.433+01:00"},"s":"W",  "c":"SHARDING", "id":23834,   "ctx":"mongosMain","msg":"Error initializing sharding state, sleeping for 2 seconds and retrying","attr":{"error":{"code":133,"codeName":"FailedToSatisfyReadPreference","errmsg":"Error loading clusterID :: caused by :: Could not find host matching read preference { mode: \"nearest\" } for set ConfigReplSet"}}}

I did have an initial look in here but didn’t see a clear cause.

steevej · May 1, 2022, 2:02pm

This should not be done.

You should create a systemd entry for mongos because

fools everyone by letting us think your start mongod.

Starting mongos or mongod in a inconsistent way is error prone. Choose one of the following and stick to it:

or

The systemctl way should be the prefered way.

The configuration for mongos should be called /etc/mongos.conf, mongos not mongod. It is error prone to name it like you did.

Share your ss command without grep. Also share the command ip addr.

Despite the fact that your mongos seems to connect to your configuration server, something is wrong with it because:

Error initializing sharding state, sleeping for 2 seconds and retrying",
"attr":{"error":{"code":133,
  "codeName": "FailedToSatisfyReadPreference",
  "errmsg":"Error loading clusterID :: caused by :: Could not find host matching read preference { mode: \"nearest\" } for set ConfigReplSet"}}}

Mongos will retried until it is fixed before starting to listen.

I suspect your config server replica set is not initialized correctly. Share rs.status of your configuration server.

R_Birtles · May 9, 2022, 12:28pm

I finally had time to revisit this. As it was just a test concept I was working on, I nuked the whole thing and started again. Now it’s up and running with no issues. Thanks for the help.

system · May 14, 2022, 12:28pm

This topic was automatically closed 5 days after the last reply. New replies are no longer allowed.