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

Fix #3040 #3078

Merged
merged 7 commits into from Oct 8, 2014
Merged

Fix #3040 #3078

merged 7 commits into from Oct 8, 2014

Conversation

@sturmer
Copy link

@sturmer sturmer commented 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)
@neumino
Copy link
Member

@neumino neumino commented Sep 21, 2014

Thanks @sturmer!

Could you sign the CLA if you haven't already so we can review the commit? (http://rethinkdb.com/community/cla/)

@sturmer
Copy link
Author

@sturmer sturmer commented Sep 22, 2014

Hi @neumino,

Done! I look forward to some criticism :)

if (write_res != static_cast<ssize_t>(console_formatted.length())) {
error_out->assign("cannot write to standard error: " + errno_string(get_errno()));
error_out->assign("cannot write to write stream: " + errno_string(get_errno()));

This comment has been minimized.

@timmaxw

timmaxw Sep 22, 2014
Member

This error could be shown to the user, so it should be clear. write stream is vague. How about cannot write to stdout/stderr?

if (res != 0 && !(get_errno() == EROFS || get_errno() == EINVAL)) {
error_out->assign("cannot flush stderr: " + errno_string(get_errno()));
error_out->assign("cannot flush output stream: " + errno_string(get_errno()));

This comment has been minimized.

@timmaxw

timmaxw Sep 22, 2014
Member

This should be updated as well.

case log_level_debug:
case log_level_warn:
case log_level_error:
default:

This comment has been minimized.

@timmaxw

timmaxw Sep 22, 2014
Member

The default case should call unreachable(), just like in format_log_level().

@@ -57,7 +58,9 @@ std::string format_log_message(const log_message_t &m, bool for_console) {
m.uptime.tv_nsec / THOUSAND,
format_log_level(m.level).c_str());
} else {
prepend = strprintf("%s: ", format_log_level(m.level).c_str());
if (m.level != log_level_info) {

This comment has been minimized.

@timmaxw

timmaxw Sep 22, 2014
Member

We should also omit the text when printing to stdout for log_level_notice, according to #3040.


ssize_t write_res = ::write(STDERR_FILENO, console_formatted.data(), console_formatted.length());
ssize_t write_res = ::write(fileno, console_formatted.data(), console_formatted.length());

This comment has been minimized.

@timmaxw

timmaxw Sep 22, 2014
Member

According to #3040, info messages should be written only to the log file, and not to stdout or stderr at all.

@@ -5,7 +5,7 @@
#include <stdio.h>
#include <string>

enum log_level_t { log_level_debug = 0, log_level_info = 1, log_level_warn, log_level_error };
enum log_level_t { log_level_debug = 0, log_level_info = 1, log_level_notice, log_level_warn, log_level_error };

This comment has been minimized.

@timmaxw

timmaxw Sep 22, 2014
Member

Now that we have a new log level, we probably also want logNTC and vlogNTC functions to go along with it. (See logINF, vlogINF, etc. below in this file.)

@timmaxw
Copy link
Member

@timmaxw timmaxw commented Sep 22, 2014

Hi @sturmer! Thanks for your pull request. I've left some comments on the changes.

There's also one more thing to do, which is to convert some of the existing info messages into notice messages where appropriate.

@sturmer
Copy link
Author

@sturmer sturmer commented Sep 23, 2014

Hi @timmaxw, thanks for your comments, they're really helpful. I'm working on them.

@sturmer sturmer force-pushed the sturmer:3040-server-outputs-info-on-stderr branch from a260e72 to 5110c1f Sep 23, 2014
@sturmer
Copy link
Author

@sturmer sturmer commented Sep 23, 2014

Started to address your considerations @timmaxw, got to find a little more time to separate info messages into info/notice. When you have time, do you mind having another look to see if I got right your comments?

@timmaxw
Copy link
Member

@timmaxw timmaxw commented Sep 23, 2014

The changes look good so far.

Don't forget to omit the notice: text when formatting a log message for stdout. Since we should never write an info message to the console, format_log_message() should assert that the log level isn't log_level_info when writing to the console. You can use the guarantee() function for this.

@sturmer sturmer force-pushed the sturmer:3040-server-outputs-info-on-stderr branch from 4977710 to d17bed9 Sep 29, 2014
@sturmer
Copy link
Author

@sturmer sturmer commented Sep 29, 2014

Hi @timmaxw, I made another iteration over the code after your comments. About notice:, I tweaked the test that is done when writing a label before the message itself (the prepend variable, see commit fa54664).

Re: the separation between info and notice levels, I've tried to separate them with the criteria shown in the Wikipedia entry for syslog (see commit 7b8c3ee).

Any comments are welcome, as usual.

@timmaxw
Copy link
Member

@timmaxw timmaxw commented Sep 30, 2014

@sturmer: I realized that there are some problems with using syslog's criteria for info/notice. See my comment on #3040.

@timmaxw
Copy link
Member

@timmaxw timmaxw commented Sep 30, 2014

Following the discussion in #3040, I think we should decide whether something is a "notice" or "info" by considering whether the user wants to see it on the console or not. So most of the messages that RethinkDB prints at startup should be "notice", but the error messages for bad HTTP input should be "info" (or maybe "warning").

@sturmer sturmer force-pushed the sturmer:3040-server-outputs-info-on-stderr branch from 7b8c3ee to 16494b4 Oct 1, 2014
@sturmer
Copy link
Author

@sturmer sturmer commented Oct 1, 2014

@timmaxw: I've tried to follow the updated criteria. I might be not completely aware of the role of "the user", so the distinction that I've coded and the one you were stating in the previous comments might be misaligned. Please let me know if you feel it may be useful to discuss this on IRC.

@timmaxw
Copy link
Member

@timmaxw timmaxw commented Oct 1, 2014

Hi @sturmer. Your changes are mostly in line with what I was thinking of, but there are a few things I would do differently:

  • The Listening for intracluster connections, Listening for administrative HTTP connections, and Listening for client driver connections messages should definitely be logNTC. These are very useful for users who are running RethinkDB manually to see what ports RethinkDB is using.
  • The sequence of three messages starting with To fully expose RethinkDB should probably be logNTC.
  • Loading data from directory and Initializing directory should probably be logNTC.
  • Maybe the Connected to server and Disconnected from server and Connected to proxy and Disconnected from proxy messages should be logNTC. See discussion in #3040 again.
@larkost
Copy link
Collaborator

@larkost larkost commented Oct 1, 2014

The To fully expose RethinkDB lines should probably be a warning. I hate the message, and it should be re-writtent into a single line (separate issue), but they are warning the user about a potentially problematic state.

@sturmer sturmer force-pushed the sturmer:3040-server-outputs-info-on-stderr branch from 16494b4 to 3e78aa6 Oct 7, 2014
@timmaxw
Copy link
Member

@timmaxw timmaxw commented Oct 7, 2014

The info/notice separation looks good, but I'm getting a crash on startup:

Running rethinkdb 1.15.1-136-g3e78aa (debug) (CLANG 3.4 (tags/RELEASE_34/final))...
Running on Linux 3.13.0-24-generic x86_64
Version: rethinkdb 1.15.1-136-g3e78aa (debug) (CLANG 3.4 (tags/RELEASE_34/final))
error: Error in ../src/clustering/administration/logger.cc at line 51:
error: Guarantee failed: [!(for_console && m.level == log_level_info)] 
error: Backtrace:
error: Tue Oct  7 13:44:06 2014

       1: rethinkdb_backtrace(void**, int) at rethinkdb_backtrace.cc:100
       2: backtrace_t::backtrace_t() at backtrace.cc:203
       3: lazy_backtrace_formatter_t::lazy_backtrace_formatter_t() at backtrace.cc:283
       4: format_backtrace(bool) at backtrace.cc:198
       5: report_fatal_error(char const*, int, char const*, ...) at errors.cc:83
       6: format_log_message(log_message_t const&, bool) at logger.cc:51
       7: fallback_log_writer_t::write(log_message_t const&, std::string*) at logger.cc:344
       8: fallback_log_writer_t::initiate_write(log_level_t, std::string const&) at logger.cc:414
       9: vlog_internal(char const*, int, log_level_t, char const*, __va_list_tag*) at logger.cc:563
       10: log_internal(char const*, int, log_level_t, char const*, ...) at logger.cc:550
       11: run_rethinkdb_serve(base_path_t const&, serve_info_t*, file_direct_io_mode_t, int, unsigned long, uuid_u const*, cluster_semilattice_metadata_t const*, directory_lock_t*, bool*) at command_line.cc:789
       12: run_rethinkdb_porcelain(base_path_t const&, name_string_t const&, file_direct_io_mode_t, int, unsigned long, bool, serve_info_t*, directory_lock_t*, bool*) at command_line.cc:880
       13: void std::_Bind<void (*(base_path_t, name_string_t, file_direct_io_mode_t, int, unsigned long, bool, serve_info_t*, directory_lock_t*, bool*))(base_path_t const&, name_string_t const&, file_direct_io_mode_t, int, unsigned long, bool, serve_info_t*, directory_lock_t*, bool*)>::__call<void, , 0, 1, 2, 3, 4, 5, 6, 7, 8>(std::tuple<>&&, std::_Index_tuple<0, 1, 2, 3, 4, 5, 6, 7, 8>) at functional:1146
       14: void std::_Bind<void (*(base_path_t, name_string_t, file_direct_io_mode_t, int, unsigned long, bool, serve_info_t*, directory_lock_t*, bool*))(base_path_t const&, name_string_t const&, file_direct_io_mode_t, int, unsigned long, bool, serve_info_t*, directory_lock_t*, bool*)>::operator()<, void>() at functional:1204
       15: std::_Function_handler<void (), std::_Bind<void (*(base_path_t, name_string_t, file_direct_io_mode_t, int, unsigned long, bool, serve_info_t*, directory_lock_t*, bool*))(base_path_t const&, name_string_t const&, file_direct_io_mode_t, int, unsigned long, bool, serve_info_t*, directory_lock_t*, bool*)> >::_M_invoke(std::_Any_data const&) at functional:1780
       16: std::function<void ()>::operator()() const at functional:2161
       17: starter_t::run_wrapper(std::function<void ()> const&) at runtime.cc:61
       18: std::_Mem_fn<void (starter_t::*)(std::function<void ()> const&)>::operator()(starter_t*, std::function<void ()> const&) const at functional:551
       19: void std::_Bind<std::_Mem_fn<void (starter_t::*)(std::function<void ()> const&)> (starter_t*, std::function<void ()>)>::__call<void, , 0, 1>(std::tuple<>&&, std::_Index_tuple<0, 1>) at functional:1146
       20: void std::_Bind<std::_Mem_fn<void (starter_t::*)(std::function<void ()> const&)> (starter_t*, std::function<void ()>)>::operator()<, void>() at functional:1204
       21: std::_Function_handler<void (), std::_Bind<std::_Mem_fn<void (starter_t::*)(std::function<void ()> const&)> (starter_t*, std::function<void ()>)> >::_M_invoke(std::_Any_data const&) at functional:1780
       22: std::function<void ()>::operator()() const at functional:2161
       23: callable_action_instance_t<std::function<void ()>&>::run_action() at callable_action.hpp:31
       24: callable_action_wrapper_t::run() at runtime_utils.cc:43
       25: coro_t::run() at coroutines.cc:197
       26: coro_t* coro_t::spawn_sometime<std::function<void ()>&>(std::function<void ()>&) at coroutines.hpp:58
       27: starter_t::on_thread_switch() at runtime.cc:57
       28: linux_message_hub_t::on_event(int) at message_hub.cc:154
       29: epoll_event_queue_t::run() at epoll.cc:115
       30: linux_thread_pool_t::start_thread(void*) at thread_pool.cc:155
       31: /lib/x86_64-linux-gnu/libpthread.so.0(+0x8182) [0x7effba8cb182] at 0x7effba8cb182 (/lib/x86_64-linux-gnu/libpthread.so.0)
       32: clone+0x6d at 0x7effba5f838d (/lib/x86_64-linux-gnu/libc.so.6)
error: Exiting.
Trace/breakpoint trap (core dumped)
@sturmer
Copy link
Author

@sturmer sturmer commented Oct 8, 2014

Hi @timmaxw, I think I've seen the problem. Next time I'll make sure to run the server before claiming anything done :$

sturmer added 6 commits 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)
It remains to substitute the level of some of the messages from `info'
to `notice'.
Also solve minor compilation errors.
Promoted some of the worse situations' messages into WARNING, as per
the discussion on #3040.
The agreement should be, as per @timmaxv's latest comment: a message
goes to NOTICE if the answer to the question "Is this message useful
for a user running RethinkDB manually?" is yes.
@sturmer sturmer force-pushed the sturmer:3040-server-outputs-info-on-stderr branch from 25b5b57 to cb4643f Oct 8, 2014
@sturmer
Copy link
Author

@sturmer sturmer commented Oct 8, 2014

@timmaxw, do you mind trying it again?

@timmaxw timmaxw merged commit cb4643f into rethinkdb:next Oct 8, 2014
@timmaxw
Copy link
Member

@timmaxw timmaxw commented Oct 8, 2014

OK, everything looks good. I've merged it into rethinkdb:next and it will be released as part of 1.16. Thank you @sturmer.

@AtnNn AtnNn added this to the 1.16 milestone Oct 8, 2014
@sturmer
Copy link
Author

@sturmer sturmer commented Oct 14, 2014

Hi @timmaxw, @AtnNn, @larkost, @neumino thank you for your input! I look forward to my next contribution!

@sturmer sturmer deleted the sturmer:3040-server-outputs-info-on-stderr branch Oct 14, 2014
@sturmer sturmer restored the sturmer:3040-server-outputs-info-on-stderr branch Dec 12, 2014
@sturmer sturmer deleted the sturmer:3040-server-outputs-info-on-stderr branch Dec 12, 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
Linked issues

Successfully merging this pull request may close these issues.

None yet

5 participants