Navigation Menu

Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

server is outputting all of the 'info:' lines on STDERR #3040

Closed
larkost opened this issue Sep 12, 2014 · 12 comments
Closed

server is outputting all of the 'info:' lines on STDERR #3040

larkost opened this issue Sep 12, 2014 · 12 comments
Milestone

Comments

@larkost
Copy link
Collaborator

larkost commented Sep 12, 2014

When the server is starting up all of the info: lines are currently going to STDERR rather than STDOUT. In normal operation we don't have anything on STDOUT at all. I talked to @gchpaco and @mlucy about this, and we are in agreement about the following:

  1. The info lines should be printed to STDOUT. warn and above should stay on STDERR.
  2. At least for STDOUT we can probably drop the info: text. The log_file should keep the designation.
  3. The current info level should probably be split into info and notice levels (consistent with syslog) with things like semilattice change and cluster connection messages remaining in the lower info level while important notices like the connection ports getting bumped to notice.
  4. info level messages should not (by default) go to STDOUT. They should still be in the log_file, and if desired we can add a --verbose flag to output these. notice would go out on STDOUT.

The goal would be to have a normal server startup output nothing to STDERR (because there were no errors/warnings).

@coffeemug coffeemug added this to the subsequent milestone Sep 16, 2014
@sturmer
Copy link

sturmer commented Sep 19, 2014

I'd be glad to work on this to get my feet wet.

@coffeemug
Copy link
Contributor

@sturmer -- that'd be awesome!

sturmer pushed a commit to sturmer/rethinkdb that referenced this issue Sep 20, 2014
- Introduce "notice" log level
- info and notice levels go on stdout, not on stderr
- Label "info:" doesn't get printed on stdout (but does to log file)
@sturmer
Copy link

sturmer commented Sep 20, 2014

Just proposed a pull request. Could anyone comment on it?

@timmaxw timmaxw mentioned this issue Sep 22, 2014
sturmer pushed a commit to sturmer/rethinkdb that referenced this issue Sep 23, 2014
- Introduce "notice" log level
- info and notice levels go on stdout, not on stderr
- Label "info:" doesn't get printed on stdout (but does to log file)
sturmer pushed a commit to sturmer/rethinkdb that referenced this issue Sep 29, 2014
- Introduce "notice" log level
- info and notice levels go on stdout, not on stderr
- Label "info:" doesn't get printed on stdout (but does to log file)
@timmaxw
Copy link
Member

timmaxw commented Sep 30, 2014

There are a lot of things that the user should see on the console that wouldn't be considered notices according to the syslog criteria. For example, it's important that we print the server's ports to the console (for the convenience of people who are running the server interactively) but that's clearly "info" rather than "notice" according to the syslog criteria.

I wonder if instead of splitting "info" into "info" and "notice" we should split it into "info (on console)" and "info (not on console)". It seems like that's the important distinction.

@larkost
Copy link
Collaborator Author

larkost commented Sep 30, 2014

@timmaxw I am not sure where wikipedia is coming up with the "General Description" column on their page, and does not describe how OS treat the "info" and "notice" levels. The actual RFC just has the information in the "Description" column, and the proposed usage maps nicely to that text: 'Notice: normal but significant condition'

http://tools.ietf.org/html/rfc5424

Search for Emergency: system is unusable

As an example, on MacOS "notice" messages go to the console (written into '/var/log/system.log'), but "info" level get dropped immediately upon being reported to asl unless they are explicitly saved by a non-standard rule (vs. debug which never make it out of the caller unless it is set specifically).

Apple's explanation can be found on this page:

https://developer.apple.com/library/mac/documentation/MacOSX/Conceptual/BPSystemStartup/Chapters/LoggingErrorsAndWarnings.html#//apple_ref/doc/uid/10000172i-SW8-SW3

Look for Alert (level 1) to skip to the relevant chart.

Using "info" and "notice" both follows more closely to what systems do in practice, but also allows us to easily map into a real logger when that gets put into place. Trying to split "info" in two is just going to add complexity later without really getting us any benefit.

@timmaxw
Copy link
Member

timmaxw commented Sep 30, 2014

That sounds reasonable.

@timmaxw
Copy link
Member

timmaxw commented Sep 30, 2014

Specifically, it seems like if we use "notice" to mean "things the user wants to see on the console", then this is compatible with RFC 5424's definition of "notice", even if not compatible with Wikipedia's description.

@sturmer
Copy link

sturmer commented Oct 1, 2014

I think I get what you mean. I'll try to adjust the code accordingly. Thanks for the comments @timmaxw and @larkost.

sturmer pushed a commit to sturmer/rethinkdb that referenced this issue Oct 1, 2014
- Introduce "notice" log level
- info and notice levels go on stdout, not on stderr
- Label "info:" doesn't get printed on stdout (but does to log file)
sturmer pushed a commit to sturmer/rethinkdb that referenced this issue Oct 1, 2014
Promoted some of the worse situations' messages into WARNING, as per
the discussion on rethinkdb#3040.
@timmaxw
Copy link
Member

timmaxw commented Oct 1, 2014

@larkost: Are you sure that connection messages should remain info? The info vs. notice distinction is mostly useful for novice users who are running RethinkDB from the console and reading the output. The connection messages are helpful to reassure those users that their RethinkDB instances are connecting to each other correctly.

@larkost
Copy link
Collaborator Author

larkost commented Oct 1, 2014

I am ambivalent about the level on inter-cluster connection messages. I see their importance in some troubleshooting, and so would not object to them still being notice, but most of the time if I was doing that sort of troubleshooting I would want timestamps on things, so would head to the logs (syslog being my preferred, but we don't do that yet).

@timmaxw
Copy link
Member

timmaxw commented Oct 1, 2014

I'm not talking about troubleshooting. I'm imagining a complete novice, who downloads RethinkDB for the first time and starts up two instances and tells them to connect to each other, and she isn't sure if it worked properly. I think the connection messages are very useful for reassuring that sort of novice user that their RethinkDB instances found each other. The way I see it, the way to decide if something should be notice or info is to ask, "Is this message useful for a user running RethinkDB manually?"

sturmer pushed a commit to sturmer/rethinkdb that referenced this issue Oct 7, 2014
- Introduce "notice" log level
- info and notice levels go on stdout, not on stderr
- Label "info:" doesn't get printed on stdout (but does to log file)
sturmer pushed a commit to sturmer/rethinkdb that referenced this issue Oct 7, 2014
Promoted some of the worse situations' messages into WARNING, as per
the discussion on rethinkdb#3040.
@sturmer
Copy link

sturmer commented Oct 7, 2014

@timmaxw, @larkost, I've gone through the code and tried to apply your observations, which I agree with.

sturmer pushed a commit to sturmer/rethinkdb that referenced this issue Oct 8, 2014
Promoted some of the worse situations' messages into WARNING, as per
the discussion on rethinkdb#3040.
@timmaxw timmaxw closed this as completed in 3110f5a Oct 8, 2014
@AtnNn AtnNn modified the milestones: 1.16, subsequent Oct 8, 2014
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

5 participants