diff --git a/src/node/ext/node_grpc.cc b/src/node/ext/node_grpc.cc index f18ce01c6fd..ce988f9dfa9 100644 --- a/src/node/ext/node_grpc.cc +++ b/src/node/ext/node_grpc.cc @@ -31,12 +31,16 @@ * */ +#include + #include #include #include #include "grpc/grpc.h" #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" @@ -45,14 +49,32 @@ #include "server.h" #include "completion_queue_async_worker.h" #include "server_credentials.h" +#include "timeval.h" using v8::FunctionTemplate; using v8::Local; using v8::Value; +using v8::Number; 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; + 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 +257,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 +332,101 @@ 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()) { + log_args *arg = args.front(); + args.pop_front(); + 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->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->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 + 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->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); + 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 +452,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..9fb6faa5d7c 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,42 @@ 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 + * 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, timestamp) { + logger.error(log_template({ + file: path.basename(file), + line: line, + severity: severity, + message: message, + timestamp: timestamp.toISOString() + })); + }); +}; + +/** + * 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 +190,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..22159dd39f7 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. 0 corresponds to logging everything + */ +exports.logVerbosity = 0; + +/** + * 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; } 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);