From 9b9708a9c484c02ad8ef27060370ae605a83942c Mon Sep 17 00:00:00 2001 From: murgatroid99 Date: Wed, 1 Jun 2016 11:42:20 -0700 Subject: [PATCH 1/4] Allow Node users to set a custom logger and log verbosity. Defaults to existing core logger --- src/node/ext/node_grpc.cc | 117 ++++++++++++++++++++++++++++++++++++ src/node/index.js | 33 ++++++++++ src/node/src/common.js | 21 +++++++ src/node/src/credentials.js | 4 +- 4 files changed, 174 insertions(+), 1 deletion(-) diff --git a/src/node/ext/node_grpc.cc b/src/node/ext/node_grpc.cc index 6b6e42737b5..45762cad2e6 100644 --- a/src/node/ext/node_grpc.cc +++ b/src/node/ext/node_grpc.cc @@ -31,12 +31,15 @@ * */ +#include + #include #include #include #include "grpc/grpc.h" #include "grpc/grpc_security.h" #include "grpc/support/alloc.h" +#include "grpc/support/log.h" #include "call.h" #include "call_credentials.h" @@ -49,10 +52,22 @@ using v8::FunctionTemplate; using v8::Local; using v8::Value; +using v8::Number; using v8::Object; using v8::Uint32; using v8::String; +typedef struct logger_state { + Nan::Callback *callback; + std::list *pending_args; + uv_mutex_t mutex; + uv_async_t async; + // Indicates that a logger has been set + bool logger_set; +} logger_state; + +logger_state grpc_logger_state; + static char *pem_root_certs = NULL; void InitStatusConstants(Local exports) { @@ -235,6 +250,18 @@ void InitWriteFlags(Local exports) { Nan::Set(write_flags, Nan::New("NO_COMPRESS").ToLocalChecked(), NO_COMPRESS); } +void InitLogConstants(Local exports) { + Nan::HandleScope scope; + Local log_verbosity = Nan::New(); + Nan::Set(exports, Nan::New("logVerbosity").ToLocalChecked(), log_verbosity); + Local DEBUG(Nan::New(GPR_LOG_SEVERITY_DEBUG)); + Nan::Set(log_verbosity, Nan::New("DEBUG").ToLocalChecked(), DEBUG); + Local INFO(Nan::New(GPR_LOG_SEVERITY_INFO)); + Nan::Set(log_verbosity, Nan::New("INFO").ToLocalChecked(), INFO); + Local ERROR(Nan::New(GPR_LOG_SEVERITY_ERROR)); + Nan::Set(log_verbosity, Nan::New("ERROR").ToLocalChecked(), ERROR); +} + NAN_METHOD(MetadataKeyIsLegal) { if (!info[0]->IsString()) { return Nan::ThrowTypeError( @@ -298,16 +325,98 @@ NAN_METHOD(SetDefaultRootsPem) { } } +NAUV_WORK_CB(LogMessagesCallback) { + Nan::HandleScope scope; + std::list args; + uv_mutex_lock(&grpc_logger_state.mutex); + args.splice(args.begin(), *grpc_logger_state.pending_args); + uv_mutex_unlock(&grpc_logger_state.mutex); + /* Call the callback with each log message */ + while (!args.empty()) { + gpr_log_func_args *arg = args.front(); + args.pop_front(); + Local file = Nan::New(arg->file).ToLocalChecked(); + Local line = Nan::New(arg->line); + Local severity = Nan::New( + gpr_log_severity_string(arg->severity)).ToLocalChecked(); + Local message = Nan::New(arg->message).ToLocalChecked(); + const int argc = 4; + Local argv[argc] = {file, line, severity, message}; + grpc_logger_state.callback->Call(argc, argv); + delete[] arg->message; + delete arg; + } +} + +void node_log_func(gpr_log_func_args *args) { + // TODO(mlumish): Use the core's log formatter when it becomes available + gpr_log_func_args *args_copy = new gpr_log_func_args; + size_t message_len = strlen(args->message) + 1; + char *message = new char[message_len]; + memcpy(message, args->message, message_len); + memcpy(args_copy, args, sizeof(gpr_log_func_args)); + args_copy->message = message; + + uv_mutex_lock(&grpc_logger_state.mutex); + grpc_logger_state.pending_args->push_back(args_copy); + uv_mutex_unlock(&grpc_logger_state.mutex); + + uv_async_send(&grpc_logger_state.async); +} + +void init_logger() { + memset(&grpc_logger_state, 0, sizeof(logger_state)); + grpc_logger_state.pending_args = new std::list(); + uv_mutex_init(&grpc_logger_state.mutex); + uv_async_init(uv_default_loop(), + &grpc_logger_state.async, + LogMessagesCallback); + uv_unref((uv_handle_t*)&grpc_logger_state.async); + grpc_logger_state.logger_set = false; + + gpr_log_verbosity_init(); +} + +/* This registers a JavaScript logger for messages from the gRPC core. Because + that handler has to be run in the context of the JavaScript event loop, it + will be run asynchronously. To minimize the problems that could cause for + debugging, we leave core to do its default synchronous logging until a + JavaScript logger is set */ +NAN_METHOD(SetDefaultLoggerCallback) { + if (!info[0]->IsFunction()) { + return Nan::ThrowTypeError( + "setDefaultLoggerCallback's argument must be a function"); + } + if (!grpc_logger_state.logger_set) { + gpr_set_log_function(node_log_func); + grpc_logger_state.logger_set = true; + } + grpc_logger_state.callback = new Nan::Callback(info[0].As()); +} + +NAN_METHOD(SetLogVerbosity) { + if (!info[0]->IsUint32()) { + return Nan::ThrowTypeError( + "setLogVerbosity's argument must be a number"); + } + gpr_log_severity severity = static_cast( + Nan::To(info[0]).FromJust()); + gpr_set_log_verbosity(severity); +} + void init(Local exports) { Nan::HandleScope scope; grpc_init(); grpc_set_ssl_roots_override_callback(get_ssl_roots_override); + init_logger(); + InitStatusConstants(exports); InitCallErrorConstants(exports); InitOpTypeConstants(exports); InitPropagateConstants(exports); InitConnectivityStateConstants(exports); InitWriteFlags(exports); + InitLogConstants(exports); grpc::node::Call::Init(exports); grpc::node::CallCredentials::Init(exports); @@ -333,6 +442,14 @@ void init(Local exports) { Nan::GetFunction( Nan::New(SetDefaultRootsPem) ).ToLocalChecked()); + Nan::Set(exports, Nan::New("setDefaultLoggerCallback").ToLocalChecked(), + Nan::GetFunction( + Nan::New(SetDefaultLoggerCallback) + ).ToLocalChecked()); + Nan::Set(exports, Nan::New("setLogVerbosity").ToLocalChecked(), + Nan::GetFunction( + Nan::New(SetLogVerbosity) + ).ToLocalChecked()); } NODE_MODULE(grpc_node, init) diff --git a/src/node/index.js b/src/node/index.js index 66664d94b5a..b85cec68414 100644 --- a/src/node/index.js +++ b/src/node/index.js @@ -46,6 +46,8 @@ var client = require('./src/client.js'); var server = require('./src/server.js'); +var common = require('./src/common.js'); + var Metadata = require('./src/metadata.js'); var grpc = require('./src/grpc_extension'); @@ -122,6 +124,32 @@ exports.load = function load(filename, format, options) { return loadObject(builder.ns, options); }; +/** + * Sets the logger function for the gRPC module. For debugging purposes, the C + * core will log synchronously directly to stdout unless this function is + * called. Note: the output format here is intended to be informational, and + * is not guaranteed to stay the same in the future. + * Logs will be directed to logger.error. + * @param {Console} logger A Console-like object. + */ +exports.setLogger = function setLogger(logger) { + common.logger = logger; + grpc.setDefaultLoggerCallback(function(file, line, severity, message) { + file = path.basename(file); + logger.error(severity + '\t' + file + ':' + line + ']\t' + message); + }); +}; + +/** + * Sets the logger verbosity for gRPC module logging. The options are members + * of the grpc.logVerbosity map. + * @param {Number} verbosity The minimum severity to log + */ +exports.setLogVerbosity = function setLogVerbosity(verbosity) { + common.logVerbosity = verbosity; + grpc.setLogVerbosity(verbosity); +}; + /** * @see module:src/server.Server */ @@ -152,6 +180,11 @@ exports.callError = grpc.callError; */ exports.writeFlags = grpc.writeFlags; +/** + * Log verbosity setting name to code number mapping + */ +exports.logVerbosity = grpc.logVerbosity; + /** * Credentials factories */ diff --git a/src/node/src/common.js b/src/node/src/common.js index 8cf43b7a84c..e2d1a50df4a 100644 --- a/src/node/src/common.js +++ b/src/node/src/common.js @@ -157,3 +157,24 @@ exports.getProtobufServiceAttrs = function getProtobufServiceAttrs(service, }]; })); }; + +/** + * The logger object for the gRPC module. Defaults to console. + */ +exports.logger = console; + +/** + * The current logging verbosity. UNSET corresponds to logging everything + */ +exports.logVerbosity = -1; + +/** + * Log a message if the severity is at least as high as the current verbosity + * @param {Number} severity A value of the grpc.logVerbosity map + * @param {String} message The message to log + */ +exports.log = function log(severity, message) { + if (severity >= exports.logVerbosity) { + exports.logger.error(message); + } +}; diff --git a/src/node/src/credentials.js b/src/node/src/credentials.js index a12eade4e1f..b746d0625df 100644 --- a/src/node/src/credentials.js +++ b/src/node/src/credentials.js @@ -69,6 +69,8 @@ var ChannelCredentials = grpc.ChannelCredentials; var Metadata = require('./metadata.js'); +var common = require('./common.js'); + /** * Create an SSL Credentials object. If using a client-side certificate, both * the second and third arguments must be passed. @@ -120,7 +122,7 @@ exports.createFromGoogleCredential = function(google_credential) { var service_url = auth_context.service_url; google_credential.getRequestMetadata(service_url, function(err, header) { if (err) { - console.log('Auth error:', err); + common.log(grpc.logVerbosity.INFO, 'Auth error:' + err); callback(err); return; } From 4a43fe4a2fc62ab179e6fff7ca10f2c9c13dd1fc Mon Sep 17 00:00:00 2001 From: murgatroid99 Date: Wed, 1 Jun 2016 16:05:48 -0700 Subject: [PATCH 2/4] Minor change to common.js --- src/node/src/common.js | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/node/src/common.js b/src/node/src/common.js index e2d1a50df4a..22159dd39f7 100644 --- a/src/node/src/common.js +++ b/src/node/src/common.js @@ -164,9 +164,9 @@ exports.getProtobufServiceAttrs = function getProtobufServiceAttrs(service, exports.logger = console; /** - * The current logging verbosity. UNSET corresponds to logging everything + * The current logging verbosity. 0 corresponds to logging everything */ -exports.logVerbosity = -1; +exports.logVerbosity = 0; /** * Log a message if the severity is at least as high as the current verbosity From 1d2f28913e93481cc4b425c608dc7c59ebe026e4 Mon Sep 17 00:00:00 2001 From: murgatroid99 Date: Thu, 2 Jun 2016 14:33:22 -0700 Subject: [PATCH 3/4] Add timestamps to custom log output --- src/node/ext/node_grpc.cc | 38 ++++++++++++++++++++++++-------------- src/node/index.js | 16 +++++++++++++--- 2 files changed, 37 insertions(+), 17 deletions(-) diff --git a/src/node/ext/node_grpc.cc b/src/node/ext/node_grpc.cc index 45762cad2e6..6daa1039342 100644 --- a/src/node/ext/node_grpc.cc +++ b/src/node/ext/node_grpc.cc @@ -40,6 +40,7 @@ #include "grpc/grpc_security.h" #include "grpc/support/alloc.h" #include "grpc/support/log.h" +#include "grpc/support/time.h" #include "call.h" #include "call_credentials.h" @@ -48,6 +49,7 @@ #include "server.h" #include "completion_queue_async_worker.h" #include "server_credentials.h" +#include "timeval.h" using v8::FunctionTemplate; using v8::Local; @@ -57,9 +59,14 @@ using v8::Object; using v8::Uint32; using v8::String; +typedef struct log_args { + gpr_log_func_args core_args; + gpr_timespec timestamp; +} log_args; + typedef struct logger_state { Nan::Callback *callback; - std::list *pending_args; + std::list *pending_args; uv_mutex_t mutex; uv_async_t async; // Indicates that a logger has been set @@ -327,35 +334,38 @@ NAN_METHOD(SetDefaultRootsPem) { NAUV_WORK_CB(LogMessagesCallback) { Nan::HandleScope scope; - std::list args; + std::list args; uv_mutex_lock(&grpc_logger_state.mutex); args.splice(args.begin(), *grpc_logger_state.pending_args); uv_mutex_unlock(&grpc_logger_state.mutex); /* Call the callback with each log message */ while (!args.empty()) { - gpr_log_func_args *arg = args.front(); + log_args *arg = args.front(); args.pop_front(); - Local file = Nan::New(arg->file).ToLocalChecked(); - Local line = Nan::New(arg->line); + Local file = Nan::New(arg->core_args.file).ToLocalChecked(); + Local line = Nan::New(arg->core_args.line); Local severity = Nan::New( - gpr_log_severity_string(arg->severity)).ToLocalChecked(); - Local message = Nan::New(arg->message).ToLocalChecked(); - const int argc = 4; - Local argv[argc] = {file, line, severity, message}; + gpr_log_severity_string(arg->core_args.severity)).ToLocalChecked(); + Local message = Nan::New(arg->core_args.message).ToLocalChecked(); + Local timestamp = Nan::New( + grpc::node::TimespecToMilliseconds(arg->timestamp)).ToLocalChecked(); + const int argc = 5; + Local argv[argc] = {file, line, severity, message, timestamp}; grpc_logger_state.callback->Call(argc, argv); - delete[] arg->message; + delete[] arg->core_args.message; delete arg; } } void node_log_func(gpr_log_func_args *args) { // TODO(mlumish): Use the core's log formatter when it becomes available - gpr_log_func_args *args_copy = new gpr_log_func_args; + log_args *args_copy = new log_args; size_t message_len = strlen(args->message) + 1; char *message = new char[message_len]; memcpy(message, args->message, message_len); - memcpy(args_copy, args, sizeof(gpr_log_func_args)); - args_copy->message = message; + memcpy(&args_copy->core_args, args, sizeof(gpr_log_func_args)); + args_copy->core_args.message = message; + args_copy->timestamp = gpr_now(GPR_CLOCK_REALTIME); uv_mutex_lock(&grpc_logger_state.mutex); grpc_logger_state.pending_args->push_back(args_copy); @@ -366,7 +376,7 @@ void node_log_func(gpr_log_func_args *args) { void init_logger() { memset(&grpc_logger_state, 0, sizeof(logger_state)); - grpc_logger_state.pending_args = new std::list(); + grpc_logger_state.pending_args = new std::list(); uv_mutex_init(&grpc_logger_state.mutex); uv_async_init(uv_default_loop(), &grpc_logger_state.async, diff --git a/src/node/index.js b/src/node/index.js index b85cec68414..9fb6faa5d7c 100644 --- a/src/node/index.js +++ b/src/node/index.js @@ -124,6 +124,10 @@ exports.load = function load(filename, format, options) { return loadObject(builder.ns, options); }; +var log_template = _.template( + '{severity} {timestamp}\t{file}:{line}]\t{message}', + {interpolate: /{([\s\S]+?)}/g}); + /** * Sets the logger function for the gRPC module. For debugging purposes, the C * core will log synchronously directly to stdout unless this function is @@ -134,9 +138,15 @@ exports.load = function load(filename, format, options) { */ exports.setLogger = function setLogger(logger) { common.logger = logger; - grpc.setDefaultLoggerCallback(function(file, line, severity, message) { - file = path.basename(file); - logger.error(severity + '\t' + file + ':' + line + ']\t' + message); + grpc.setDefaultLoggerCallback(function(file, line, severity, + message, timestamp) { + logger.error(log_template({ + file: path.basename(file), + line: line, + severity: severity, + message: message, + timestamp: timestamp.toISOString() + })); }); }; From 04e47f308ec57c42ec9a0dcdc25e72c03b66bc9e Mon Sep 17 00:00:00 2001 From: murgatroid99 Date: Mon, 20 Jun 2016 11:03:15 -0700 Subject: [PATCH 4/4] Direct additional log statement through custom logger --- src/node/src/server.js | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/node/src/server.js b/src/node/src/server.js index fd5153f1244..b3b414969ab 100644 --- a/src/node/src/server.js +++ b/src/node/src/server.js @@ -735,8 +735,8 @@ Server.prototype.addService = function(service, implementation) { } var impl; if (implementation[name] === undefined) { - console.warn('Method handler for %s expected but not provided', - attrs.path); + common.log(grpc.logVerbosity.ERROR, 'Method handler for ' + + attrs.path + ' expected but not provided'); impl = defaultHandler[method_type]; } else { impl = _.bind(implementation[name], implementation);