[SERVER-46932] Shell produces json output Created: 18/Mar/20  Updated: 29/Oct/23  Resolved: 21/May/20

Status: Closed
Project: Core Server
Component/s: Shell
Affects Version/s: 4.3.4
Fix Version/s: 4.4.0-rc7, 4.7.0

Type: Bug Priority: Major - P3
Reporter: Oleg Pudeyev (Inactive) Assignee: Gabriel Russell (Inactive)
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Backports
Duplicate
is duplicated by SERVER-47362 mongo shell emits replica set monitor... Closed
Related
related to SERVER-48100 "mongo" command line in 4.4.0-rc[0-5]... Closed
is related to SERVER-46911 Allow logging to pipe Closed
Backwards Compatibility: Minor Change
Operating System: ALL
Backport Requested:
v4.4
Sprint: Service arch 2020-05-04, Service arch 2020-05-18, Service arch 2020-06-01
Participants:
Case:

 Description   

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 <address> 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).



 Comments   
Comment by Gabriel Russell (Inactive) [ 21/May/20 ]

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.

Comment by Githook User [ 20/May/20 ]

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

Comment by Githook User [ 20/May/20 ]

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

Comment by Githook User [ 18/May/20 ]

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

Comment by Githook User [ 18/May/20 ]

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

Comment by Kay Kim (Inactive) [ 30/Apr/20 ]

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)
}

Comment by Bruce Lucas (Inactive) [ 19/Mar/20 ]

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

Generated at Thu Feb 08 05:12:50 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.