[SERVER-46933] Shell floods screen with server's json logs 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
Related
is related to SERVER-46911 Allow logging to pipe Closed
Backwards Compatibility: Fully Compatible
Operating System: ALL
Backport Requested:
v4.4
Steps To Reproduce:

Connect to 4.4 server

Sprint: Service arch 2020-05-04, Service arch 2020-05-18, Service arch 2020-06-01
Participants:

 Description   

With the change to json logging on the server and removal of text logs, if I connect to a 4.4 server with the shell my screen is flooded by server json logs.

The following is what a 4.3.4 shell produces when connecting to a 4.3.4 server (I haven't entered any commands yet, this is purely shell startup output):

carbon% /usr/local/m/versions/4.4/mongo
{"t":{"$date":"2020-03-18T04:03:57.164Z"},"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:27017/?compressors=disabled&gssapiServiceName=mongodb
Implicit session: session { "id" : UUID("95cb2a32-2548-4f1e-bf49-a506cfb0a7f9") }
MongoDB server version: 4.3.4
Welcome to the MongoDB shell.
For interactive help, type "help".
For more comprehensive documentation, see
	http://docs.mongodb.org/
Questions? Try the support group
	http://groups.google.com/group/mongodb-user
Server has startup warnings: 
{"t":{"$date":"2020-03-18T00:02:31.980-0400"},"s":"I", "c":"CONTROL", "id":22116,"ctx":"initandlisten","msg":"","tags":["startupWarnings"]}
{"t":{"$date":"2020-03-18T00:02:31.980-0400"},"s":"I", "c":"CONTROL", "id":22117,"ctx":"initandlisten","msg":"** NOTE: This is a development version ({vii_version}) of MongoDB.","attr":{"vii_version":"4.3.4"},"tags":["startupWarnings"]}
{"t":{"$date":"2020-03-18T00:02:31.980-0400"},"s":"I", "c":"CONTROL", "id":22118,"ctx":"initandlisten","msg":"**       Not recommended for production.","tags":["startupWarnings"]}
{"t":{"$date":"2020-03-18T00:02:31.980-0400"},"s":"I", "c":"CONTROL", "id":22119,"ctx":"initandlisten","msg":"","tags":["startupWarnings"]}
{"t":{"$date":"2020-03-18T00:02:31.980-0400"},"s":"I", "c":"CONTROL", "id":22120,"ctx":"initandlisten","msg":"** WARNING: Access control is not enabled for the database.","tags":["startupWarnings"]}
{"t":{"$date":"2020-03-18T00:02:31.980-0400"},"s":"I", "c":"CONTROL", "id":22121,"ctx":"initandlisten","msg":"**          Read and write access to data and configuration is unrestricted.","tags":["startupWarnings"]}
{"t":{"$date":"2020-03-18T00:02:31.980-0400"},"s":"I", "c":"CONTROL", "id":22139,"ctx":"initandlisten","msg":"","tags":["startupWarnings"]}
{"t":{"$date":"2020-03-18T00:02:31.980-0400"},"s":"I", "c":"CONTROL", "id":22140,"ctx":"initandlisten","msg":"** WARNING: This server is bound to localhost.","tags":["startupWarnings"]}
{"t":{"$date":"2020-03-18T00:02:31.980-0400"},"s":"I", "c":"CONTROL", "id":22141,"ctx":"initandlisten","msg":"**          Remote systems will be unable to connect to this server. ","tags":["startupWarnings"]}
{"t":{"$date":"2020-03-18T00:02:31.980-0400"},"s":"I", "c":"CONTROL", "id":22142,"ctx":"initandlisten","msg":"**          Start the server with --bind_ip <address> to specify which IP ","tags":["startupWarnings"]}
{"t":{"$date":"2020-03-18T00:02:31.980-0400"},"s":"I", "c":"CONTROL", "id":22143,"ctx":"initandlisten","msg":"**          addresses it should serve responses from, or with --bind_ip_all to","tags":["startupWarnings"]}
{"t":{"$date":"2020-03-18T00:02:31.980-0400"},"s":"I", "c":"CONTROL", "id":22144,"ctx":"initandlisten","msg":"**          bind to all interfaces. If this behavior is desired, start the","tags":["startupWarnings"]}
{"t":{"$date":"2020-03-18T00:02:31.980-0400"},"s":"I", "c":"CONTROL", "id":22145,"ctx":"initandlisten","msg":"**          server with --bind_ip 127.0.0.1 to disable this warning.","tags":["startupWarnings"]}
{"t":{"$date":"2020-03-18T00:02:31.980-0400"},"s":"I", "c":"CONTROL", "id":22150,"ctx":"initandlisten","msg":"","tags":["startupWarnings"]}
{"t":{"$date":"2020-03-18T00:02:31.980-0400"},"s":"I", "c":"CONTROL", "id":22183,"ctx":"initandlisten","msg":"","tags":["startupWarnings"]}
{"t":{"$date":"2020-03-18T00:02:31.980-0400"},"s":"I", "c":"CONTROL", "id":22184,"ctx":"initandlisten","msg":"** WARNING: soft rlimits too low. Number of files is {rlnofile_rlim_cur}, should be at least {minNumFiles}","attr":{"rlnofile_rlim_cur":1024,"minNumFiles":64000},"tags":["startupWarnings"]}
MongoDB Enterprise > 

This is a full screen of output in my terminal (which wraps long lines) and my first reaction to seeing this is that something has gone horribly wrong somewhere. I do not think this is a great experience, and this seems to be especially poor first experience for a user starting with MongoDB.

In my opinion there are two specific problems with providing server json logs in the shell:

1. There is simply too much output. The previous server versions produced I would say about 1/3 of this volume which was much more manageable.
2. The output is not at all easy to read for a human being (the reasons I think so I listed in https://jira.mongodb.org/browse/SERVER-46911).

For comparison this is the output that 4.2.3 shell produces when connecting to a 4.2.3 server:

carbon% /usr/local/m/versions/4.2/mongo --port 14220
MongoDB shell version v4.2.3
connecting to: mongodb://127.0.0.1:14220/?compressors=disabled&gssapiServiceName=mongodb
Implicit session: session { "id" : UUID("37e46b31-68d0-43a0-8e82-ed456d2c2cbd") }
MongoDB server version: 4.2.3
Server has startup warnings: 
2020-03-18T00:10:20.490-0400 I  CONTROL  [initandlisten] 
2020-03-18T00:10:20.490-0400 I  CONTROL  [initandlisten] ** WARNING: Access control is not enabled for the database.
2020-03-18T00:10:20.490-0400 I  CONTROL  [initandlisten] **          Read and write access to data and configuration is unrestricted.
2020-03-18T00:10:20.490-0400 I  CONTROL  [initandlisten] 
2020-03-18T00:10:20.490-0400 I  CONTROL  [initandlisten] ** WARNING: This server is bound to localhost.
2020-03-18T00:10:20.490-0400 I  CONTROL  [initandlisten] **          Remote systems will be unable to connect to this server. 
2020-03-18T00:10:20.490-0400 I  CONTROL  [initandlisten] **          Start the server with --bind_ip <address> to specify which IP 
2020-03-18T00:10:20.490-0400 I  CONTROL  [initandlisten] **          addresses it should serve responses from, or with --bind_ip_all to
2020-03-18T00:10:20.490-0400 I  CONTROL  [initandlisten] **          bind to all interfaces. If this behavior is desired, start the
2020-03-18T00:10:20.490-0400 I  CONTROL  [initandlisten] **          server with --bind_ip 127.0.0.1 to disable this warning.
2020-03-18T00:10:20.490-0400 I  CONTROL  [initandlisten] 
MongoDB Enterprise ruby-driver-rs:SECONDARY> 

This is both much less voluminous and much more readable, in my opinion. I can immediately see that there are two warnings, I can quickly identify what they are for, and as a result I can quickly decide that they are not an issue I need to deal with. With the 4.4 shell/server output I cannot quickly identify what the output is conveying and I therefore cannot figure out what action is needed from me, if any.

Expected behavior:

As a user of MongoDB, I expect the shell to produce a reasonable amount of output when it starts and when it connects to my deployment. I expect the output to be provided in a way that permits me to quickly scan it and determine what it is conveying, and what action is required from me to deal with it, if any.

Note that using a pre-4.4 shell with a 4.4 server suffers from the same issue - the server startup warnings are shown in json format.



 Comments   
Comment by Githook User [ 18/May/20 ]

Author:

{'name': 'Gabriel Russell', 'email': 'gabriel.russell@mongodb.com', 'username': 'gabrielrussell'}

Message: SERVER-46933 reformat the json startupWarnings
Branch: v4.4
https://github.com/mongodb/mongo/commit/45f0a9e4b58b583925496f5a5b2b0b61e2cd2fa9

Comment by Githook User [ 18/May/20 ]

Author:

{'name': 'Gabriel Russell', 'email': 'gabriel.russell@mongodb.com', 'username': 'gabrielrussell'}

Message: SERVER-46933 reformat the json startupWarnings
Branch: master
https://github.com/mongodb/mongo/commit/bab691491a8db3419dab5ecd79689d5357f1e0cc

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

These messages could fairly easily be presented in a more human-readable form similar to the 4.2 shell. For example, this code

function human(doc) {
    
    let s = doc.t.$date
        + " " + doc.s.padEnd(2)
        + " " + doc.c.padEnd(8)
        + " [" + doc.ctx + "] "
        + " " + doc.msg
        + " " + _human(doc.attr)
    return s
}
 
function _human(doc) {
    let sep = ""
    let s = ""
    for (const f in doc) {
        let v = doc[f]
        s += sep
        if (!(doc instanceof Array))
            s += f + ": "
        if (v instanceof Array) {
            s += "[" + _human(v) + "]"
        } else if (v instanceof Object) {
            s += "{" + _human(v) + "}"
        } else {
            if (v && v instanceof Date)
                s += v.toISOString()
            else
                s += String(v)
        }
        sep = doc instanceof Array? ", " : " "
    }
    return s
}

formats them as follows:

2020-03-18T00:02:31.980-0400 I  CONTROL  [initandlisten]   
2020-03-18T00:02:31.980-0400 I  CONTROL  [initandlisten]  ** NOTE: This is a development version ({vii_version}) of MongoDB. vii_version: 4.3.4
2020-03-18T00:02:31.980-0400 I  CONTROL  [initandlisten]  **       Not recommended for production. 
2020-03-18T00:02:31.980-0400 I  CONTROL  [initandlisten]   
2020-03-18T00:02:31.980-0400 I  CONTROL  [initandlisten]  ** WARNING: Access control is not enabled for the database. 
2020-03-18T00:02:31.980-0400 I  CONTROL  [initandlisten]  **          Read and write access to data and configuration is unrestricted. 
2020-03-18T00:02:31.980-0400 I  CONTROL  [initandlisten]   
2020-03-18T00:02:31.980-0400 I  CONTROL  [initandlisten]  ** WARNING: This server is bound to localhost. 
2020-03-18T00:02:31.980-0400 I  CONTROL  [initandlisten]  **          Remote systems will be unable to connect to this server.  
2020-03-18T00:02:31.980-0400 I  CONTROL  [initandlisten]  **          Start the server with --bind_ip <address> to specify which IP  
2020-03-18T00:02:31.980-0400 I  CONTROL  [initandlisten]  **          addresses it should serve responses from, or with --bind_ip_all to 
2020-03-18T00:02:31.980-0400 I  CONTROL  [initandlisten]  **          bind to all interfaces. If this behavior is desired, start the 
2020-03-18T00:02:31.980-0400 I  CONTROL  [initandlisten]  **          server with --bind_ip 127.0.0.1 to disable this warning. 
2020-03-18T00:02:31.980-0400 I  CONTROL  [initandlisten]   
2020-03-18T00:02:31.980-0400 I  CONTROL  [initandlisten]   
2020-03-18T00:02:31.980-0400 I  CONTROL  [initandlisten]  ** WARNING: soft rlimits too low. Number of files is {rlnofile_rlim_cur}, should be at least {minNumFiles} rlnofile_rlim_cur: 1024 minNumFiles: 64000

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