Info

When I use 4.3.4 shell to connect to 4.0.16 server I see this in the console: carbon% mongo --port 14020 {"t":{"$date":"2020-03-18T04:10:34.705Z"},"s":"I", "c":"NETWORK", "id":23014,"ctx":"main","msg":"{foStatus_reason}","attr":{"foStatus_reason":"TCP FastOpen support requested, but disabled in kernel. Set /proc/sys/net/ipv4/tcp_fastopen to 3"}} MongoDB shell version v4.3.4 connecting to: mongodb://127.0.0.1:14020/?compressors=disabled&gssapiServiceName=mongodb Implicit session: session { "id" : UUID("4f9892ef-1bf7-4416-9e6a-b97f311fa161") } MongoDB server version: 4.0.16 WARNING: shell and server versions do not match Server has startup warnings: 2020-03-18T00:10:26.404-0400 I CONTROL [initandlisten] 2020-03-18T00:10:26.404-0400 I CONTROL [initandlisten] ** WARNING: Access control is not enabled for the database. 2020-03-18T00:10:26.404-0400 I CONTROL [initandlisten] ** Read and write access to data and configuration is unrestricted. 2020-03-18T00:10:26.404-0400 I CONTROL [initandlisten] 2020-03-18T00:10:26.404-0400 I CONTROL [initandlisten] ** WARNING: This server is bound to localhost. 2020-03-18T00:10:26.404-0400 I CONTROL [initandlisten] ** Remote systems will be unable to connect to this server. 2020-03-18T00:10:26.404-0400 I CONTROL [initandlisten] ** Start the server with --bind_ip to specify which IP 2020-03-18T00:10:26.404-0400 I CONTROL [initandlisten] ** addresses it should serve responses from, or with --bind_ip_all to 2020-03-18T00:10:26.404-0400 I CONTROL [initandlisten] ** bind to all interfaces. If this behavior is desired, start the 2020-03-18T00:10:26.404-0400 I CONTROL [initandlisten] ** server with --bind_ip 127.0.0.1 to disable this warning. 2020-03-18T00:10:26.404-0400 I CONTROL [initandlisten] The first line of the output, I presume, comes from the shell: {"t":{"$date":"2020-03-18T04:10:34.705Z"},"s":"I", "c":"NETWORK", "id":23014,"ctx":"main","msg":"{foStatus_reason}","attr":{"foStatus_reason":"TCP FastOpen support requested, but disabled in kernel. Set /proc/sys/net/ipv4/tcp_fastopen to 3"}} MongoDB shell version v4.3.4 connecting to: mongodb://127.0.0.1:14020/?compressors=disabled&gssapiServiceName=mongodb Implicit session: session { "id" : UUID("4f9892ef-1bf7-4416-9e6a-b97f311fa161") } It is my understanding that the shell is meant to primarily be used by humans rather than be driven by software (the software generally will use a driver rather than the shell). Therefore my expected behavior is: As a user of the shell, I expect the shell to produce its output in a format that is easily human-readable. While it is certainly possible for a human to read json server logs, I do not consider them to be in a format that is easy for a human to read (I listed why I do not consider json logs to be easy to read in https://jira.mongodb.org/browse/SERVER-46911).

Top User Comments

gabriel.russell commented on Thu, 21 May 2020 15:00:14 +0000: Marking this change as "Minor Change of backwards compatibility" but both the kernel and downstream changes have been made aware of details of this change. xgen-internal-githook commented on Wed, 20 May 2020 14:49:34 +0000: Author: {'name': 'Gabriel Russell', 'email': 'gabriel.russell@mongodb.com', 'username': 'gabrielrussell'} Message: SERVER-46932 shell to output ProgramRunner output Branch: v4.4 https://github.com/mongodb/mongo/commit/ae3e03306fe1bf2d31567a4ee3dac2fa5af3a3ff xgen-internal-githook commented on Wed, 20 May 2020 04:20:56 +0000: Author: {'name': 'Gabriel Russell', 'email': 'gabriel.russell@mongodb.com', 'username': 'gabrielrussell'} Message: SERVER-46932 shell to output ProgramRunner output Branch: master https://github.com/mongodb/mongo/commit/7688360d99c522164b6464b44941b862c78634d5 xgen-internal-githook commented on Mon, 18 May 2020 22:30:54 +0000: Author: {'name': 'Gabriel Russell', 'email': 'gabriel.russell@mongodb.com', 'username': 'gabrielrussell'} Message: SERVER-46932 supress more logging in the shell Branch: v4.4 https://github.com/mongodb/mongo/commit/f3335e378658f6e9be2b2343ff76ff27cf421b3b xgen-internal-githook commented on Mon, 18 May 2020 20:12:14 +0000: Author: {'name': 'Gabriel Russell', 'email': 'gabriel.russell@mongodb.com', 'username': 'gabrielrussell'} Message: SERVER-46932 supress more logging in the shell Branch: master https://github.com/mongodb/mongo/commit/eafd8199cbd90915088c505e75810de7b4d52f90 kay.kim@10gen.com commented on Thu, 30 Apr 2020 01:05:00 +0000: Oh, not to add on to this, but if I run the setFeatureCompatibilityVersion command, it also spits out a lot before printing out the result document. For me I'm using both shell and mongod version 4.4.0-rc3-8-ge9c2db4 MongoDB Enterprise shardA:PRIMARY> db.adminCommand( { setFeatureCompatibilityVersion: "4.2" } ) {"t":{"$date":"2020-04-30T01:00:02.078Z"},"s":"I", "c":"NETWORK", "id":4333213,"ctx":"ReplicaSetMonitor-TaskExecutor","msg":"RSM {setName} Topology Change: {topologyDescription}","attr":{"setName":"shardA","topologyDescription":"{ id: \"604076b0-1f10-45e0-9058-c650d2e7b527\", topologyType: \"ReplicaSetWithPrimary\", servers: { Kays-MacBook-Pro.local:27018: { address: \"Kays-MacBook-Pro.local:27018\", topologyVersion: { processId: ObjectId('5eaa1e97c4d650aa78176230'), counter: 6 }, roundTripTime: 0, lastWriteDate: new Date(1588208390000), opTime: { ts: Timestamp(1588208390, 1), t: 1 }, type: \"RSPrimary\", minWireVersion: 0, maxWireVersion: 9, streamable: false, poolResetCounter: 0, me: \"Kays-MacBook-Pro.local:27018\", setName: \"shardA\", setVersion: 1, electionId: ObjectId('7fffffff0000000000000001'), primary: \"Kays-MacBook-Pro.local:27018\", lastUpdateTime: new Date(1588208392075), logicalSessionTimeoutMinutes: 30, hosts: [ \"Kays-MacBook-Pro.local:27018\", \"Kays-MacBook-Pro.local:27019\", \"Kays-MacBook-Pro.local:27020\" ], arbiters: [], passives: [] }, Kays-MacBook-Pro.local:27019: { address: \"Kays-MacBook-Pro.local:27019\", topologyVersion: { processId: ObjectId('5eaa1e987c31e29eb81668a4'), counter: 5 }, roundTripTime: 0, lastWriteDate: new Date(1588208400000), opTime: { ts: Timestamp(1588208400, 1), t: 1 }, type: \"RSSecondary\", minWireVersion: 0, maxWireVersion: 9, streamable: false, poolResetCounter: 0, me: \"Kays-MacBook-Pro.local:27019\", setName: \"shardA\", setVersion: 2, primary: \"Kays-MacBook-Pro.local:27018\", lastUpdateTime: new Date(1588208402078), logicalSessionTimeoutMinutes: 30, hosts: [ \"Kays-MacBook-Pro.local:27018\", \"Kays-MacBook-Pro.local:27019\", \"Kays-MacBook-Pro.local:27020\" ], arbiters: [], passives: [] }, Kays-MacBook-Pro.local:27020: { address: \"Kays-MacBook-Pro.local:27020\", topologyVersion: { processId: ObjectId('5eaa1e99b92524d903f7e0e8'), counter: 4 }, roundTripTime: 0, lastWriteDate: new Date(1588208390000), opTime: { ts: Timestamp(1588208390, 1), t: 1 }, type: \"RSSecondary\", minWireVersion: 0, maxWireVersion: 9, streamable: false, poolResetCounter: 0, me: \"Kays-MacBook-Pro.local:27020\", setName: \"shardA\", setVersion: 1, primary: \"Kays-MacBook-Pro.local:27018\", lastUpdateTime: new Date(1588208392075), logicalSessionTimeoutMinutes: 30, hosts: [ \"Kays-MacBook-Pro.local:27018\", \"Kays-MacBook-Pro.local:27019\", \"Kays-MacBook-Pro.local:27020\" ], arbiters: [], passives: [] } }, logicalSessionTimeoutMinutes: 30, setName: \"shardA\", compatible: true, maxSetVersion: 1, maxElectionId: ObjectId('7fffffff0000000000000001') }"}} {"t":{"$date":"2020-04-30T01:00:02.078Z"},"s":"I", "c":"NETWORK", "id":4333213,"ctx":"ReplicaSetMonitor-TaskExecutor","msg":"RSM {setName} Topology Change: {topologyDescription}","attr":{"setName":"shardA","topologyDescription":"{ id: \"604076b0-1f10-45e0-9058-c650d2e7b527\", topologyType: \"ReplicaSetWithPrimary\", servers: { Kays-MacBook-Pro.local:27018: { address: \"Kays-MacBook-Pro.local:27018\", topologyVersion: { processId: ObjectId('5eaa1e97c4d650aa78176230'), counter: 6 }, roundTripTime: 0, lastWriteDate: new Date(1588208390000), opTime: { ts: Timestamp(1588208390, 1), t: 1 }, type: \"RSPrimary\", minWireVersion: 0, maxWireVersion: 9, streamable: false, poolResetCounter: 0, me: \"Kays-MacBook-Pro.local:27018\", setName: \"shardA\", setVersion: 1, electionId: ObjectId('7fffffff0000000000000001'), primary: \"Kays-MacBook-Pro.local:27018\", lastUpdateTime: new Date(1588208392075), logicalSessionTimeoutMinutes: 30, hosts: [ \"Kays-MacBook-Pro.local:27018\", \"Kays-MacBook-Pro.local:27019\", \"Kays-MacBook-Pro.local:27020\" ], arbiters: [], passives: [] }, Kays-MacBook-Pro.local:27019: { address: \"Kays-MacBook-Pro.local:27019\", topologyVersion: { processId: ObjectId('5eaa1e987c31e29eb81668a4'), counter: 5 }, roundTripTime: 0, lastWriteDate: new Date(1588208400000), opTime: { ts: Timestamp(1588208400, 1), t: 1 }, type: \"RSSecondary\", minWireVersion: 0, maxWireVersion: 9, streamable: false, poolResetCounter: 0, me: \"Kays-MacBook-Pro.local:27019\", setName: \"shardA\", setVersion: 2, primary: \"Kays-MacBook-Pro.local:27018\", lastUpdateTime: new Date(1588208402078), logicalSessionTimeoutMinutes: 30, hosts: [ \"Kays-MacBook-Pro.local:27018\", \"Kays-MacBook-Pro.local:27019\", \"Kays-MacBook-Pro.local:27020\" ], arbiters: [], passives: [] }, Kays-MacBook-Pro.local:27020: { address: \"Kays-MacBook-Pro.local:27020\", topologyVersion: { processId: ObjectId('5eaa1e99b92524d903f7e0e8'), counter: 5 }, roundTripTime: 0, lastWriteDate: new Date(1588208400000), opTime: { ts: Timestamp(1588208400, 1), t: 1 }, type: \"RSSecondary\", minWireVersion: 0, maxWireVersion: 9, streamable: false, poolResetCounter: 0, me: \"Kays-MacBook-Pro.local:27020\", setName: \"shardA\", setVersion: 2, primary: \"Kays-MacBook-Pro.local:27018\", lastUpdateTime: new Date(1588208402078), logicalSessionTimeoutMinutes: 30, hosts: [ \"Kays-MacBook-Pro.local:27018\", \"Kays-MacBook-Pro.local:27019\", \"Kays-MacBook-Pro.local:27020\" ], arbiters: [], passives: [] } }, logicalSessionTimeoutMinutes: 30, setName: \"shardA\", compatible: true, maxSetVersion: 1, maxElectionId: ObjectId('7fffffff0000000000000001') }"}} {"t":{"$date":"2020-04-30T01:00:02.079Z"},"s":"I", "c":"NETWORK", "id":20224, "ctx":"ReplicaSetMonitor-TaskExecutor","msg":"{kLogPrefix}topology max election id set to {newMaxElectionId}","attr":{"kLogPrefix":"sdam : ","newMaxElectionId":{"$oid":"7fffffff0000000000000001"}}} {"t":{"$date":"2020-04-30T01:00:02.079Z"},"s":"I", "c":"NETWORK", "id":20225, "ctx":"ReplicaSetMonitor-TaskExecutor","msg":"{kLogPrefix}topology max set version set to {newMaxSetVersion}","attr":{"kLogPrefix":"sdam : ","newMaxSetVersion":2}} {"t":{"$date":"2020-04-30T01:00:02.079Z"},"s":"I", "c":"NETWORK", "id":20221, "ctx":"ReplicaSetMonitor-TaskExecutor","msg":"{kLogPrefix}the topology type was set to {topologyType}","attr":{"kLogPrefix":"sdam : ","topologyType":"ReplicaSetWithPrimary"}} {"t":{"$date":"2020-04-30T01:00:02.079Z"},"s":"I", "c":"NETWORK", "id":4333213,"ctx":"ReplicaSetMonitor-TaskExecutor","msg":"RSM {setName} Topology Change: {topologyDescription}","attr":{"setName":"shardA","topologyDescription":"{ id: \"604076b0-1f10-45e0-9058-c650d2e7b527\", topologyType: \"ReplicaSetWithPrimary\", servers: { Kays-MacBook-Pro.local:27018: { address: \"Kays-MacBook-Pro.local:27018\", topologyVersion: { processId: ObjectId('5eaa1e97c4d650aa78176230'), counter: 7 }, roundTripTime: 0, lastWriteDate: new Date(1588208400000), opTime: { ts: Timestamp(1588208400, 1), t: 1 }, type: \"RSPrimary\", minWireVersion: 0, maxWireVersion: 9, streamable: false, poolResetCounter: 0, me: \"Kays-MacBook-Pro.local:27018\", setName: \"shardA\", setVersion: 2, electionId: ObjectId('7fffffff0000000000000001'), primary: \"Kays-MacBook-Pro.local:27018\", lastUpdateTime: new Date(1588208402079), logicalSessionTimeoutMinutes: 30, hosts: [ \"Kays-MacBook-Pro.local:27018\", \"Kays-MacBook-Pro.local:27019\", \"Kays-MacBook-Pro.local:27020\" ], arbiters: [], passives: [] }, Kays-MacBook-Pro.local:27019: { address: \"Kays-MacBook-Pro.local:27019\", topologyVersion: { processId: ObjectId('5eaa1e987c31e29eb81668a4'), counter: 5 }, roundTripTime: 0, lastWriteDate: new Date(1588208400000), opTime: { ts: Timestamp(1588208400, 1), t: 1 }, type: \"RSSecondary\", minWireVersion: 0, maxWireVersion: 9, streamable: false, poolResetCounter: 0, me: \"Kays-MacBook-Pro.local:27019\", setName: \"shardA\", setVersion: 2, primary: \"Kays-MacBook-Pro.local:27018\", lastUpdateTime: new Date(1588208402078), logicalSessionTimeoutMinutes: 30, hosts: [ \"Kays-MacBook-Pro.local:27018\", \"Kays-MacBook-Pro.local:27019\", \"Kays-MacBook-Pro.local:27020\" ], arbiters: [], passives: [] }, Kays-MacBook-Pro.local:27020: { address: \"Kays-MacBook-Pro.local:27020\", topologyVersion: { processId: ObjectId('5eaa1e99b92524d903f7e0e8'), counter: 5 }, roundTripTime: 0, lastWriteDate: new Date(1588208400000), opTime: { ts: Timestamp(1588208400, 1), t: 1 }, type: \"RSSecondary\", minWireVersion: 0, maxWireVersion: 9, streamable: false, poolResetCounter: 0, me: \"Kays-MacBook-Pro.local:27020\", setName: \"shardA\", setVersion: 2, primary: \"Kays-MacBook-Pro.local:27018\", lastUpdateTime: new Date(1588208402078), logicalSessionTimeoutMinutes: 30, hosts: [ \"Kays-MacBook-Pro.local:27018\", \"Kays-MacBook-Pro.local:27019\", \"Kays-MacBook-Pro.local:27020\" ], arbiters: [], passives: [] } }, logicalSessionTimeoutMinutes: 30, setName: \"shardA\", compatible: true, maxSetVersion: 2, maxElectionId: ObjectId('7fffffff0000000000000001') }"}} { "ok" : 1, "$clusterTime" : { "clusterTime" : Timestamp(1588208402, 1), "signature" : { "hash" : BinData(0,"BMrSp2qccXBDZoqSJMdHzQxnLHI="), "keyId" : NumberLong("6821298283919441923") } }, "operationTime" : Timestamp(1588208402, 1) } bruce.lucas@10gen.com commented on Thu, 19 Mar 2020 13:15:20 +0000: I think this problem is bad enough that it warrants being P3. When you start a mongo shell against a replica set without --quiet you get about 100 lines of messages related to replica set monitoring. Here's a brief sample: {"t":{"$date":"2020-03-19T12:57:20.996Z"},"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":"2020-03-19T12:57:21.049Z"},"s":"I", "c":"NETWORK", "id":4333205,"ctx":"js","msg":"Starting Streamable ReplicaSetMonitor","attr":{"uri":"r/localhost:27017"}}, {"t":{"$date":"2020-03-19T12:57:21.049Z"},"s":"I", "c":"NETWORK", "id":4333206,"ctx":"js","msg":"Starting Replica Set Monitor","attr":{"uri":"r/localhost:27017"}}, {"t":{"$date":"2020-03-19T12:57:21.049Z"},"s":"I", "c":"-", "id":4333223,"ctx":"js","msg":"RSM monitoring","attr":{"setName":"r","size":1}}, {"t":{"$date":"2020-03-19T12:57:21.049Z"},"s":"I", "c":"-", "id":4333226,"ctx":"js","msg":"RSM host was added to the toplogy","attr":{"setName":"r","hostAndPort":"localhost:27017"}}, {"t":{"$date":"2020-03-19T12:57:21.049Z"},"s":"I", "c":"-", "id":4333227,"ctx":"js","msg":"RSM monitoring host in expedited mode until we detect a primary.","attr":{"hostAndPort":"localhost:27017","setName":"r"}}, {"t":{"$date":"2020-03-19T12:57:21.049Z"},"s":"I", "c":"-", "id":4333218,"ctx":"js","msg":"RSM rescheduling next isMaster check for host","attr":{"hostAndPort":"localhost:27017","delayMillis":0,"setName":"r"}}, {"t":{"$date":"2020-03-19T12:57:21.049Z"},"s":"I", "c":"CONNPOOL","id":22576,"ctx":"ReplicaSetMonitor-TaskExecutor","msg":"Connecting to host","attr":{"hostAndPort":"localhost:27017"}}, {"t":{"$date":"2020-03-19T12:57:21.051Z"},"s":"I", "c":"NETWORK", "id":20221,"ctx":"ReplicaSetMonitor-TaskExecutor","msg":"The topology type was set","attr":{"topologyType":"ReplicaSetNoPrimary"}}, {"t":{"$date":"2020-03-19T12:57:21.051Z"},"s":"I", "c":"NETWORK", "id":20222,"ctx":"ReplicaSetMonitor-TaskExecutor","msg":"The topology setName was set","attr":{"setName":"r"}}, (Note: I've actually modified the "msg" string in the above to meet our current recommendations to log without substitution strings.) When formatted by the code proposed in SERVER-46933 this becomes much more readable: 2020-03-19T12:57:20.996Z I NETWORK [main] Implicit TCP FastOpen unavailable. If TCP FastOpen is required, set tcpFastOpenServer, tcpFastOpenClient, and tcpFastOpenQueueSize. 2020-03-19T12:57:21.049Z I NETWORK [js] Starting Streamable ReplicaSetMonitor uri: r/localhost:27017 2020-03-19T12:57:21.049Z I NETWORK [js] Starting Replica Set Monitor uri: r/localhost:27017 2020-03-19T12:57:21.049Z I - [js] RSM monitoring setName: r size: 1 2020-03-19T12:57:21.049Z I - [js] RSM host was added to the toplogy setName: r hostAndPort: localhost:27017 2020-03-19T12:57:21.049Z I - [js] RSM monitoring host in expedited mode until we detect a primary. hostAndPort: localhost:27017 setName: r 2020-03-19T12:57:21.049Z I - [js] RSM rescheduling next isMaster check for host hostAndPort: localhost:27017 delayMillis: 0 setName: r 2020-03-19T12:57:21.049Z I CONNPOOL [ReplicaSetMonitor-TaskExecutor] Connecting to host hostAndPort: localhost:27017 2020-03-19T12:57:21.051Z I NETWORK [ReplicaSetMonitor-TaskExecutor] The topology type was set topologyType: ReplicaSetNoPrimary 2020-03-19T12:57:21.051Z I NETWORK [ReplicaSetMonitor-TaskExecutor] The topology setName was set setName: r

Steps to Reproduce